issue 611: add debug logging that periodically dumps remaining time, from daemon's perspective

daemon/snapper/snapper.go

@@ -203,16 +203,8 @@ func syncUp(a args, u updater) state {
 	u(func(s *Snapper) {
 		s.sleepUntil = syncPoint
 	})
-	t := time.NewTimer(time.Until(syncPoint))
+
-	defer t.Stop()
+	return waitUntilThenTransitionToPlanning(a, u, syncPoint)
-	select {
-	case <-t.C:
-		return u(func(s *Snapper) {
-			s.state = Planning
-		}).sf()
-	case <-a.ctx.Done():
-		return onMainCtxDone(a.ctx, u)
-	}
 }
 
 func plan(a args, u updater) state {
@@ -370,16 +362,32 @@ func wait(a args, u updater) state {
 		logFunc("enter wait-state after error")
 	})
 
-	t := time.NewTimer(time.Until(sleepUntil))
+	return waitUntilThenTransitionToPlanning(a, u, sleepUntil)
-	defer t.Stop()
+}
 
-	select {
+func waitUntilThenTransitionToPlanning(a args, u updater, sleepUntil time.Time) state {
-	case <-t.C:
+
-		return u(func(snapper *Snapper) {
+	ticker := time.NewTicker(333 * time.Millisecond)
-			snapper.state = Planning
+	defer ticker.Stop()
-		}).sf()
+	lastLog := time.Now()
-	case <-a.ctx.Done():
+	for {
-		return onMainCtxDone(a.ctx, u)
+		select {
+		case <-ticker.C:
+			now := time.Now()
+			if now.Before(sleepUntil) {
+				// rate limit loggin to once per minute
+				if (now.Sub(lastLog)) > envconst.Duration("ZREPL_SNAPPER_DEBUG_LOG_ISSUE_611", 1*time.Minute) {
+					getLogger(a.ctx).WithField("sleep_until", sleepUntil).WithField("remaining", sleepUntil.Sub(now)).Error("DEBUG-LOG-ZREPL-ISSUE-611")
+					lastLog = now
+				}
+				continue // continue with ticker
+			}
+			return u(func(snapper *Snapper) {
+				snapper.state = Planning
+			}).sf()
+		case <-a.ctx.Done():
+			return onMainCtxDone(a.ctx, u)
+		}
 	}
 }