Merge pull request #866 from gotd/refactor/update-debug-logs

telegram/updates: additional debug logging

telegram/updates/sequence_box.go

@@ -47,7 +47,7 @@ func newSequenceBox(cfg sequenceConfig) *sequenceBox {
 func (s *sequenceBox) Handle(u update) error {
 	log := s.log.With(zap.Int("upd_from", u.start()), zap.Int("upd_to", u.end()))
 	if checkGap(s.state, u.State, u.Count) == gapIgnore {
-		log.Debug("Outdated update, skip", zap.Int("state", s.state))
+		log.Debug("Outdated update, skipping", zap.Int("state", s.state))
 		return nil
 	}
 
@@ -80,7 +80,7 @@ func (s *sequenceBox) Handle(u update) error {
 		}
 
 		log.Debug("Accepted")
-		s.state = u.State
+		s.setState(u.State, "update")
 		return nil
 
 	case gapRefetch:
@@ -159,13 +159,22 @@ loop:
 		zap.Int("accepted_count", len(accepted)),
 	)
 
-	s.state = state
+	s.setState(state, "pending updates")
 	return nil
 }
 
 func (s *sequenceBox) State() int { return s.state }
 
-func (s *sequenceBox) SetState(state int) {
-	s.log.Debug("Forced set state", zap.Int("state", state))
+func (s *sequenceBox) SetState(state int, reason string) {
+	s.setState(state, reason)
+}
+
+func (s *sequenceBox) setState(state int, reason string) {
+	old := s.state
 	s.state = state
+	s.log.Debug("State changed",
+		zap.Int("old", old),
+		zap.Int("new", state),
+		zap.String("reason", reason),
+	)
 }

telegram/updates/state.go

@@ -339,14 +339,14 @@ func (s *state) getDifference() error {
 
 	s.log.Debug("Getting difference")
 
-	setState := func(state tg.UpdatesState) {
+	setState := func(state tg.UpdatesState, reason string) {
 		if err := s.storage.SetState(s.selfID, State{}.fromRemote(&state)); err != nil {
 			s.log.Warn("SetState error", zap.Error(err))
 		}
 
-		s.pts.SetState(state.Pts)
-		s.qts.SetState(state.Qts)
-		s.seq.SetState(state.Seq)
+		s.pts.SetState(state.Pts, reason)
+		s.qts.SetState(state.Qts, reason)
+		s.seq.SetState(state.Seq, reason)
 		s.date = state.Date
 	}
 
@@ -384,7 +384,7 @@ func (s *state) getDifference() error {
 			}
 		}
 
-		setState(diff.State)
+		setState(diff.State, "updates.Difference")
 		return nil
 
 	// No events.
@@ -394,7 +394,7 @@ func (s *state) getDifference() error {
 		}
 
 		s.date = diff.Date
-		s.seq.SetState(diff.Seq)
+		s.seq.SetState(diff.Seq, "updates.differenceEmpty")
 		return nil
 
 	// Incomplete list of occurred events.
@@ -423,15 +423,15 @@ func (s *state) getDifference() error {
 			}
 		}
 
-		setState(diff.IntermediateState)
+		setState(diff.IntermediateState, "updates.differenceSlice")
 		return s.getDifference()
 
 	// The difference is too long, and the specified state must be used to refetch updates.
 	case *tg.UpdatesDifferenceTooLong:
 		if err := s.storage.SetPts(s.selfID, diff.Pts); err != nil {
 			s.log.Error("SetPts error", zap.Error(err))
 		}
-		s.pts.SetState(diff.Pts)
+		s.pts.SetState(diff.Pts, "updates.differenceTooLong")
 		return s.getDifference()
 
 	default:

telegram/updates/state_apply.go

@@ -109,7 +109,7 @@ func (s *state) applyCombined(ctx context.Context, comb *tg.UpdatesCombined) (pt
 		}
 
 		s.date = comb.Date
-		s.seq.SetState(comb.Seq)
+		s.seq.SetState(comb.Seq, "seq update")
 	case setDate:
 		if err := s.storage.SetDate(s.selfID, comb.Date); err != nil {
 			s.log.Error("SetDate error", zap.Error(err))
@@ -119,7 +119,7 @@ func (s *state) applyCombined(ctx context.Context, comb *tg.UpdatesCombined) (pt
 		if err := s.storage.SetSeq(s.selfID, comb.Seq); err != nil {
 			s.log.Error("SetSeq error", zap.Error(err))
 		}
-		s.seq.SetState(comb.Seq)
+		s.seq.SetState(comb.Seq, "seq update")
 	}
 
 	return ptsChanged, nil

telegram/updates/state_channel.go

@@ -271,7 +271,7 @@ func (s *channelState) getDifference() error {
 			s.log.Warn("SetChannelPts error", zap.Error(err))
 		}
 
-		s.pts.SetState(diff.Pts)
+		s.pts.SetState(diff.Pts, "updates.channelDifference")
 		if seconds, ok := diff.GetTimeout(); ok {
 			s.diffTimeout = time.Now().Add(time.Second * time.Duration(seconds))
 		}
@@ -287,7 +287,7 @@ func (s *channelState) getDifference() error {
 			s.log.Warn("SetChannelPts error", zap.Error(err))
 		}
 
-		s.pts.SetState(diff.Pts)
+		s.pts.SetState(diff.Pts, "updates.channelDifferenceEmpty")
 		if seconds, ok := diff.GetTimeout(); ok {
 			s.diffTimeout = time.Now().Add(time.Second * time.Duration(seconds))
 		}
@@ -307,7 +307,7 @@ func (s *channelState) getDifference() error {
 				s.log.Warn("SetChannelPts error", zap.Error(err))
 			}
 
-			s.pts.SetState(remotePts)
+			s.pts.SetState(remotePts, "updates.channelDifferenceTooLong dialog new pts")
 		}
 
 		s.onTooLong(s.channelID)