From 86b258321e899ea2e884f96d199a45d2506ffc5a Mon Sep 17 00:00:00 2001 From: Michel Hollands Date: Tue, 14 Jun 2022 15:48:53 +0100 Subject: [PATCH 1/6] Add more logging for delete requests Signed-off-by: Michel Hollands --- .../compactor/deletion/delete_request.go | 19 ++++++++++++++++++- .../deletion/delete_requests_manager.go | 17 +++++++++++++++++ 2 files changed, 35 insertions(+), 1 deletion(-) diff --git a/pkg/storage/stores/shipper/compactor/deletion/delete_request.go b/pkg/storage/stores/shipper/compactor/deletion/delete_request.go index 5e4dc1a11874c..9b71058026fd6 100644 --- a/pkg/storage/stores/shipper/compactor/deletion/delete_request.go +++ b/pkg/storage/stores/shipper/compactor/deletion/delete_request.go @@ -97,13 +97,30 @@ func (d *DeleteRequest) IsDeleted(entry retention.ChunkEntry) (bool, []retention return false, nil } + level.Debug(util_log.Logger).Log( + "msg", "starting filter function", + "delete_request_id", d.RequestID, + "userID", d.UserID, "labels", + entry.Labels.String(), + ) ff, err := d.FilterFunction(entry.Labels) if err != nil { // The query in the delete request is checked when added to the table. // So this error should not occur. - level.Error(util_log.Logger).Log("msg", "unexpected error getting filter function", "err", err) + level.Error(util_log.Logger).Log( + "msg", "unexpected error getting filter function", + "delete_request_id", d.RequestID, + "userID", d.UserID, + "err", err, + ) return false, nil } + level.Debug(util_log.Logger).Log( + "msg", "finished filter function", + "delete_request_id", d.RequestID, + "userID", d.UserID, + "labels", entry.Labels.String(), + ) if d.StartTime <= entry.From && d.EndTime >= entry.Through { // if the logSelectorExpr has a filter part return the chunk boundaries as intervals diff --git a/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go b/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go index e5c0759d66e77..969f7be4d4658 100644 --- a/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go +++ b/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go @@ -148,6 +148,11 @@ func (d *DeleteRequestsManager) Expired(ref retention.ChunkEntry, _ model.Time) }) for _, deleteRequest := range d.deleteRequestsToProcess { + level.Info(util_log.Logger).Log( + "msg", "started processing delete request", + "delete_request_id", deleteRequest.RequestID, + "userID", deleteRequest.UserID, + ) rebuiltIntervals := make([]retention.IntervalFilter, 0, len(d.chunkIntervalsToRetain)) for _, ivf := range d.chunkIntervalsToRetain { entry := ref @@ -163,9 +168,19 @@ func (d *DeleteRequestsManager) Expired(ref retention.ChunkEntry, _ model.Time) d.chunkIntervalsToRetain = rebuiltIntervals if len(d.chunkIntervalsToRetain) == 0 { + level.Info(util_log.Logger).Log( + "msg", "no chunks to retain for deleted request", + "delete_request_id", deleteRequest.RequestID, + "userID", deleteRequest.UserID, + ) d.metrics.deleteRequestsChunksSelectedTotal.WithLabelValues(string(ref.UserID)).Inc() return true, nil } + level.Info(util_log.Logger).Log( + "msg", "finished processing delete request", + "delete_request_id", deleteRequest.RequestID, + "userID", deleteRequest.UserID, + ) } if len(d.chunkIntervalsToRetain) == 1 && d.chunkIntervalsToRetain[0].Interval.Start == ref.From && d.chunkIntervalsToRetain[0].Interval.End == ref.Through { @@ -199,6 +214,8 @@ func (d *DeleteRequestsManager) MarkPhaseFinished() { for _, deleteRequest := range d.deleteRequestsToProcess { if err := d.deleteRequestsStore.UpdateStatus(context.Background(), deleteRequest.UserID, deleteRequest.RequestID, StatusProcessed); err != nil { level.Error(util_log.Logger).Log("msg", fmt.Sprintf("failed to mark delete request %s for user %s as processed", deleteRequest.RequestID, deleteRequest.UserID), "err", err) + } else { + level.Info(util_log.Logger).Log("msg", fmt.Sprintf("delete request %s for user %s marked as processed", deleteRequest.RequestID, deleteRequest.UserID)) } d.metrics.deleteRequestsProcessedTotal.WithLabelValues(deleteRequest.UserID).Inc() } From 37be992d8453ba74970657bb0ff77e361f864f3f Mon Sep 17 00:00:00 2001 From: Michel Hollands Date: Tue, 14 Jun 2022 15:51:36 +0100 Subject: [PATCH 2/6] Fix typo Signed-off-by: Michel Hollands --- .../shipper/compactor/deletion/delete_requests_manager.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go b/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go index 969f7be4d4658..8f524705f740b 100644 --- a/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go +++ b/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go @@ -169,7 +169,7 @@ func (d *DeleteRequestsManager) Expired(ref retention.ChunkEntry, _ model.Time) d.chunkIntervalsToRetain = rebuiltIntervals if len(d.chunkIntervalsToRetain) == 0 { level.Info(util_log.Logger).Log( - "msg", "no chunks to retain for deleted request", + "msg", "no chunks to retain for delete request", "delete_request_id", deleteRequest.RequestID, "userID", deleteRequest.UserID, ) From cd5d874cfb1db98b8b7dc0bcab436cdcbeaa1e75 Mon Sep 17 00:00:00 2001 From: Michel Hollands Date: Wed, 15 Jun 2022 09:25:33 +0100 Subject: [PATCH 3/6] Rephrase logging message and add chunk ID Signed-off-by: Michel Hollands --- .../shipper/compactor/deletion/delete_requests_manager.go | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go b/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go index 8f524705f740b..b1a0e477ba7a3 100644 --- a/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go +++ b/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go @@ -169,9 +169,10 @@ func (d *DeleteRequestsManager) Expired(ref retention.ChunkEntry, _ model.Time) d.chunkIntervalsToRetain = rebuiltIntervals if len(d.chunkIntervalsToRetain) == 0 { level.Info(util_log.Logger).Log( - "msg", "no chunks to retain for delete request", + "msg", "no chunks to retain: the whole chunk is deleted", "delete_request_id", deleteRequest.RequestID, "userID", deleteRequest.UserID, + "chunkID", string(ref.ChunkID), ) d.metrics.deleteRequestsChunksSelectedTotal.WithLabelValues(string(ref.UserID)).Inc() return true, nil From a1c4e86775ff3a6ab13dbb5da334e31040eeb657 Mon Sep 17 00:00:00 2001 From: Michel Hollands Date: Wed, 15 Jun 2022 10:16:54 +0100 Subject: [PATCH 4/6] Rename userID field to user Signed-off-by: Michel Hollands --- .../shipper/compactor/deletion/delete_requests_manager.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go b/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go index b1a0e477ba7a3..df52e30fd30cc 100644 --- a/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go +++ b/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go @@ -151,7 +151,7 @@ func (d *DeleteRequestsManager) Expired(ref retention.ChunkEntry, _ model.Time) level.Info(util_log.Logger).Log( "msg", "started processing delete request", "delete_request_id", deleteRequest.RequestID, - "userID", deleteRequest.UserID, + "user", deleteRequest.UserID, ) rebuiltIntervals := make([]retention.IntervalFilter, 0, len(d.chunkIntervalsToRetain)) for _, ivf := range d.chunkIntervalsToRetain { @@ -171,7 +171,7 @@ func (d *DeleteRequestsManager) Expired(ref retention.ChunkEntry, _ model.Time) level.Info(util_log.Logger).Log( "msg", "no chunks to retain: the whole chunk is deleted", "delete_request_id", deleteRequest.RequestID, - "userID", deleteRequest.UserID, + "user", deleteRequest.UserID, "chunkID", string(ref.ChunkID), ) d.metrics.deleteRequestsChunksSelectedTotal.WithLabelValues(string(ref.UserID)).Inc() @@ -180,7 +180,7 @@ func (d *DeleteRequestsManager) Expired(ref retention.ChunkEntry, _ model.Time) level.Info(util_log.Logger).Log( "msg", "finished processing delete request", "delete_request_id", deleteRequest.RequestID, - "userID", deleteRequest.UserID, + "user", deleteRequest.UserID, ) } From 27def87b111f6a2acaeafa3fac105d53f283d841 Mon Sep 17 00:00:00 2001 From: Michel Hollands Date: Wed, 15 Jun 2022 10:23:40 +0100 Subject: [PATCH 5/6] rename more userID Signed-off-by: Michel Hollands --- .../stores/shipper/compactor/deletion/delete_request.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/pkg/storage/stores/shipper/compactor/deletion/delete_request.go b/pkg/storage/stores/shipper/compactor/deletion/delete_request.go index 9b71058026fd6..e0acf28f95673 100644 --- a/pkg/storage/stores/shipper/compactor/deletion/delete_request.go +++ b/pkg/storage/stores/shipper/compactor/deletion/delete_request.go @@ -100,7 +100,7 @@ func (d *DeleteRequest) IsDeleted(entry retention.ChunkEntry) (bool, []retention level.Debug(util_log.Logger).Log( "msg", "starting filter function", "delete_request_id", d.RequestID, - "userID", d.UserID, "labels", + "user", d.UserID, "labels", entry.Labels.String(), ) ff, err := d.FilterFunction(entry.Labels) @@ -110,7 +110,7 @@ func (d *DeleteRequest) IsDeleted(entry retention.ChunkEntry) (bool, []retention level.Error(util_log.Logger).Log( "msg", "unexpected error getting filter function", "delete_request_id", d.RequestID, - "userID", d.UserID, + "user", d.UserID, "err", err, ) return false, nil @@ -118,7 +118,7 @@ func (d *DeleteRequest) IsDeleted(entry retention.ChunkEntry) (bool, []retention level.Debug(util_log.Logger).Log( "msg", "finished filter function", "delete_request_id", d.RequestID, - "userID", d.UserID, + "user", d.UserID, "labels", entry.Labels.String(), ) From 9c8fcb7b79eb0b9a451c3e3a7bfb084533e269e3 Mon Sep 17 00:00:00 2001 From: Michel Hollands Date: Wed, 15 Jun 2022 10:33:45 +0100 Subject: [PATCH 6/6] Fix existing log messages Signed-off-by: Michel Hollands --- .../shipper/compactor/deletion/delete_request.go | 4 ++-- .../compactor/deletion/delete_requests_manager.go | 14 +++++++++++--- 2 files changed, 13 insertions(+), 5 deletions(-) diff --git a/pkg/storage/stores/shipper/compactor/deletion/delete_request.go b/pkg/storage/stores/shipper/compactor/deletion/delete_request.go index e0acf28f95673..d6640ee4ea615 100644 --- a/pkg/storage/stores/shipper/compactor/deletion/delete_request.go +++ b/pkg/storage/stores/shipper/compactor/deletion/delete_request.go @@ -100,8 +100,8 @@ func (d *DeleteRequest) IsDeleted(entry retention.ChunkEntry) (bool, []retention level.Debug(util_log.Logger).Log( "msg", "starting filter function", "delete_request_id", d.RequestID, - "user", d.UserID, "labels", - entry.Labels.String(), + "user", d.UserID, + "labels", entry.Labels.String(), ) ff, err := d.FilterFunction(entry.Labels) if err != nil { diff --git a/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go b/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go index df52e30fd30cc..f88e96d8cad81 100644 --- a/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go +++ b/pkg/storage/stores/shipper/compactor/deletion/delete_requests_manager.go @@ -2,7 +2,6 @@ package deletion import ( "context" - "fmt" "sync" "time" @@ -214,9 +213,18 @@ func (d *DeleteRequestsManager) MarkPhaseFinished() { for _, deleteRequest := range d.deleteRequestsToProcess { if err := d.deleteRequestsStore.UpdateStatus(context.Background(), deleteRequest.UserID, deleteRequest.RequestID, StatusProcessed); err != nil { - level.Error(util_log.Logger).Log("msg", fmt.Sprintf("failed to mark delete request %s for user %s as processed", deleteRequest.RequestID, deleteRequest.UserID), "err", err) + level.Error(util_log.Logger).Log( + "msg", "failed to mark delete request for user as processed", + "delete_request_id", deleteRequest.RequestID, + "user", deleteRequest.UserID, + "err", err, + ) } else { - level.Info(util_log.Logger).Log("msg", fmt.Sprintf("delete request %s for user %s marked as processed", deleteRequest.RequestID, deleteRequest.UserID)) + level.Info(util_log.Logger).Log( + "msg", "delete request for user marked as processed", + "delete_request_id", deleteRequest.RequestID, + "user", deleteRequest.UserID, + ) } d.metrics.deleteRequestsProcessedTotal.WithLabelValues(deleteRequest.UserID).Inc() }