From 550ec7afc488e75003c8da69255e01b49fa6543b Mon Sep 17 00:00:00 2001 From: "Grot (@grafanabot)" <43478413+grafanabot@users.noreply.github.com> Date: Thu, 23 Jun 2022 06:47:34 -0400 Subject: [PATCH] Add more logging for delete requests (#6394) (#6473) * Add more logging for delete requests Signed-off-by: Michel Hollands * Fix typo Signed-off-by: Michel Hollands * Rephrase logging message and add chunk ID Signed-off-by: Michel Hollands * Rename userID field to user Signed-off-by: Michel Hollands * rename more userID Signed-off-by: Michel Hollands * Fix existing log messages Signed-off-by: Michel Hollands (cherry picked from commit 20db4df542a10bef2f32a4bdb5487465a4ec6bb7) Co-authored-by: Michel Hollands <42814411+MichelHollands@users.noreply.github.com> (cherry picked from commit c707faf285c4766894058118a060c28f5f7836d4) --- .../compactor/deletion/delete_request.go | 19 +++++++++++- .../deletion/delete_requests_manager.go | 30 +++++++++++++++++-- 2 files changed, 46 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 5e4dc1a11874..d6640ee4ea61 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, + "user", 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, + "user", d.UserID, + "err", err, + ) return false, nil } + level.Debug(util_log.Logger).Log( + "msg", "finished filter function", + "delete_request_id", d.RequestID, + "user", 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 b2f7ef18a9ac..04ac03357ea3 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" @@ -148,6 +147,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, + "user", deleteRequest.UserID, + ) rebuiltIntervals := make([]retention.IntervalFilter, 0, len(d.chunkIntervalsToRetain)) for _, ivf := range d.chunkIntervalsToRetain { entry := ref @@ -163,9 +167,20 @@ 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: the whole chunk is deleted", + "delete_request_id", deleteRequest.RequestID, + "user", deleteRequest.UserID, + "chunkID", string(ref.ChunkID), + ) 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, + "user", deleteRequest.UserID, + ) } if len(d.chunkIntervalsToRetain) == 1 && d.chunkIntervalsToRetain[0].Interval.Start == ref.From && d.chunkIntervalsToRetain[0].Interval.End == ref.Through { @@ -198,7 +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", "delete request for user marked as processed", + "delete_request_id", deleteRequest.RequestID, + "user", deleteRequest.UserID, + ) } d.metrics.deleteRequestsProcessedTotal.WithLabelValues(deleteRequest.UserID).Inc() }