Add more logging for delete requests (#6394) (#6473)

* Add more logging for delete requests

Signed-off-by: Michel Hollands <michel.hollands@grafana.com>

* Fix typo

Signed-off-by: Michel Hollands <michel.hollands@grafana.com>

* Rephrase logging message and add chunk ID

Signed-off-by: Michel Hollands <michel.hollands@grafana.com>

* Rename userID field to user

Signed-off-by: Michel Hollands <michel.hollands@grafana.com>

* rename more userID

Signed-off-by: Michel Hollands <michel.hollands@grafana.com>

* Fix existing log messages

Signed-off-by: Michel Hollands <michel.hollands@grafana.com>
(cherry picked from commit 20db4df)

Co-authored-by: Michel Hollands <42814411+MichelHollands@users.noreply.github.com>
(cherry picked from commit c707faf)

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

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()
 	}