Add debug logging for when distributed tasks are skipped

pkg/controller/appsync/appsync.go

@@ -40,15 +40,19 @@ func (c *Controller) HandleSync() http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		ctx := r.Context()
 
+		logger := logging.FromContext(ctx).Named("appsync.HandleSync")
+
 		ok, err := c.db.TryLock(ctx, appSyncLock, c.config.AppSyncMinPeriod)
 		if err != nil {
+			logger.Errorw("failed to acquire lock", "error", err)
 			c.h.RenderJSON(w, http.StatusInternalServerError, &AppSyncResult{
 				OK:     false,
 				Errors: []string{err.Error()},
 			})
 			return
 		}
 		if !ok {
+			logger.Debugw("skipping (too early)")
 			c.h.RenderJSON(w, http.StatusOK, &AppSyncResult{
 				OK:     false,
 				Errors: []string{"too early"},

pkg/controller/cleanup/handle_cleanup.go

@@ -23,7 +23,6 @@ import (
 	"github.com/google/exposure-notifications-verification-server/internal/project"
 	"github.com/google/exposure-notifications-verification-server/pkg/observability"
 	"github.com/hashicorp/go-multierror"
-	"go.opencensus.io/stats"
 	"go.opencensus.io/tag"
 )
 
@@ -42,22 +41,21 @@ func (c *Controller) HandleCleanup() http.Handler {
 
 		ok, err := c.db.TryLock(ctx, cleanupName, c.config.CleanupMinPeriod)
 		if err != nil {
-			logger.Errorw("failed to run shouldCleanup", "error", err)
+			logger.Errorw("failed to acquire lock", "error", err)
 			c.h.RenderJSON(w, http.StatusInternalServerError, &CleanupResult{
 				OK:     false,
 				Errors: []string{err.Error()},
 			})
 			return
 		}
 		if !ok {
-			stats.RecordWithTags(ctx, []tag.Mutator{observability.ResultNotOK()}, mClaimRequests.M(1))
+			logger.Debugw("skipping (too early)")
 			c.h.RenderJSON(w, http.StatusOK, &CleanupResult{
 				OK:     false,
 				Errors: []string{"too early"},
 			})
 			return
 		}
-		stats.RecordWithTags(ctx, []tag.Mutator{observability.ResultOK()}, mClaimRequests.M(1))
 
 		// Construct a multi-error. If one of the purges fails, we still want to
 		// attempt the other purges.

pkg/controller/rotation/handle_token_rotate.go

@@ -24,7 +24,6 @@ import (
 	"github.com/google/exposure-notifications-verification-server/pkg/database"
 	"github.com/google/exposure-notifications-verification-server/pkg/observability"
 	"github.com/hashicorp/go-multierror"
-	"go.opencensus.io/stats"
 	"go.opencensus.io/tag"
 )
 
@@ -44,22 +43,21 @@ func (c *Controller) HandleRotate() http.Handler {
 
 		ok, err := c.db.TryLock(ctx, tokenRotationLock, c.config.MinTTL)
 		if err != nil {
-			logger.Errorw("failed to run shouldRotate", "error", err)
+			logger.Errorw("failed to acquire lock", "error", err)
 			c.h.RenderJSON(w, http.StatusInternalServerError, &Result{
 				OK:     false,
 				Errors: []string{err.Error()},
 			})
 			return
 		}
 		if !ok {
-			stats.RecordWithTags(ctx, []tag.Mutator{observability.ResultNotOK()}, mClaimRequests.M(1))
+			logger.Debugw("skipping (too early)")
 			c.h.RenderJSON(w, http.StatusOK, &Result{
 				OK:     false,
 				Errors: []string{"too early"},
 			})
 			return
 		}
-		stats.RecordWithTags(ctx, []tag.Mutator{observability.ResultOK()}, mClaimRequests.M(1))
 
 		// Token signing keys
 		func() {

pkg/controller/rotation/handle_verification_rotate.go

@@ -22,14 +22,11 @@ import (
 
 	"github.com/google/exposure-notifications-verification-server/internal/project"
 	"github.com/google/exposure-notifications-verification-server/pkg/database"
-	"github.com/google/exposure-notifications-verification-server/pkg/observability"
 	"github.com/google/exposure-notifications-verification-server/pkg/pagination"
 
 	"github.com/google/exposure-notifications-server/pkg/logging"
 
 	"github.com/hashicorp/go-multierror"
-	"go.opencensus.io/stats"
-	"go.opencensus.io/tag"
 )
 
 // HandleVerificationRotate handles verification certificate key rotation.
@@ -47,22 +44,21 @@ func (c *Controller) HandleVerificationRotate() http.Handler {
 
 		ok, err := c.db.TryLock(ctx, verificationRotationLock, c.config.MinTTL)
 		if err != nil {
-			logger.Errorw("failed to obtain lock", "lock", verificationRotationLock, "error", err)
+			logger.Errorw("failed to acquire lock", "error", err)
 			c.h.RenderJSON(w, http.StatusInternalServerError, &Result{
 				OK:     false,
 				Errors: []string{err.Error()},
 			})
 			return
 		}
 		if !ok {
-			stats.RecordWithTags(ctx, []tag.Mutator{observability.ResultNotOK()}, mClaimRequests.M(1))
+			logger.Debugw("skipping (too early)")
 			c.h.RenderJSON(w, http.StatusOK, &Result{
 				OK:     false,
 				Errors: []string{"too early"},
 			})
 			return
 		}
-		stats.RecordWithTags(ctx, []tag.Mutator{observability.ResultOK()}, mClaimRequests.M(1))
 
 		var merr *multierror.Error
 

pkg/controller/statspuller/handle_pull.go

@@ -42,15 +42,19 @@ func (c *Controller) HandlePullStats() http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		ctx := r.Context()
 
+		logger := logging.FromContext(ctx).Named("statspuller.HandlePullStats")
+
 		ok, err := c.db.TryLock(ctx, statsPullerLock, c.config.StatsPullerMinPeriod)
 		if err != nil {
+			logger.Errorw("failed to acquite lock", "error", err)
 			c.h.RenderJSON(w, http.StatusInternalServerError, &Result{
 				OK:     false,
 				Errors: []string{err.Error()},
 			})
 			return
 		}
 		if !ok {
+			logger.Debugw("skipping (too early)")
 			c.h.RenderJSON(w, http.StatusOK, &Result{
 				OK:     false,
 				Errors: []string{"too early"},
@@ -65,7 +69,6 @@ func (c *Controller) HandlePullStats() http.Handler {
 			return
 		}
 
-		logger := logging.FromContext(ctx).Named("rotation.HandlePullStats")
 		for _, realmStat := range statsConfigs {
 			realmID := realmStat.RealmID