Improve missed data resync logic

This commit is contained in:
Tulir Asokan 2024-04-08 12:47:00 +03:00
parent e2c8d92382
commit b131f50e51

57
user.go
View file

@ -77,7 +77,8 @@ type User struct {
pollErrorAlertSent bool pollErrorAlertSent bool
phoneNotRespondingAlertSent bool phoneNotRespondingAlertSent bool
didHackySetActive bool didHackySetActive bool
noDataReceivedRecentlyStart time.Time noDataReceivedRecently bool
lastDataReceived time.Time
loginInProgress atomic.Bool loginInProgress atomic.Bool
pairSuccessChan chan struct{} pairSuccessChan chan struct{}
@ -645,7 +646,8 @@ func (user *User) DeleteSession() {
user.Session = nil user.Session = nil
user.SelfParticipantIDs = []string{} user.SelfParticipantIDs = []string{}
user.didHackySetActive = false user.didHackySetActive = false
user.noDataReceivedRecentlyStart = time.Time{} user.noDataReceivedRecently = false
user.lastDataReceived = time.Time{}
err := user.Update(context.TODO()) err := user.Update(context.TODO())
if err != nil { if err != nil {
user.zlog.Err(err).Msg("Failed to delete session from database") user.zlog.Err(err).Msg("Failed to delete session from database")
@ -680,7 +682,8 @@ func (user *User) hackyResetActive() {
return return
} }
user.didHackySetActive = true user.didHackySetActive = true
user.noDataReceivedRecentlyStart = time.Time{} user.noDataReceivedRecently = false
user.lastDataReceived = time.Time{}
time.Sleep(7 * time.Second) time.Sleep(7 * time.Second)
if !user.ready && user.phoneResponding { if !user.ready && user.phoneResponding {
user.zlog.Warn().Msg("Client is still not ready, trying to re-set active session") user.zlog.Warn().Msg("Client is still not ready, trying to re-set active session")
@ -801,11 +804,13 @@ func (user *User) syncHandleEvent(event any) {
} }
}() }()
case *gmproto.Conversation: case *gmproto.Conversation:
user.noDataReceivedRecentlyStart = time.Time{} user.noDataReceivedRecently = false
user.lastDataReceived = time.Now()
go user.syncConversation(v, "event") go user.syncConversation(v, "event")
//case *gmproto.Message: //case *gmproto.Message:
case *libgm.WrappedMessage: case *libgm.WrappedMessage:
user.noDataReceivedRecentlyStart = time.Time{} user.noDataReceivedRecently = false
user.lastDataReceived = time.Now()
user.zlog.Debug(). user.zlog.Debug().
Str("conversation_id", v.GetConversationID()). Str("conversation_id", v.GetConversationID()).
Str("participant_id", v.GetParticipantID()). Str("participant_id", v.GetParticipantID()).
@ -820,12 +825,16 @@ func (user *User) syncHandleEvent(event any) {
case *gmproto.UserAlertEvent: case *gmproto.UserAlertEvent:
user.handleUserAlert(v) user.handleUserAlert(v)
case *gmproto.Settings: case *gmproto.Settings:
user.noDataReceivedRecentlyStart = time.Time{} // Don't reset last data received until a BROWSER_ACTIVE event if there hasn't been data recently,
// otherwise the resync won't have the right timestamp.
if !user.noDataReceivedRecently {
user.lastDataReceived = time.Now()
}
user.handleSettings(v) user.handleSettings(v)
case *events.AccountChange: case *events.AccountChange:
user.handleAccountChange(v) user.handleAccountChange(v)
case *events.NoDataReceived: case *events.NoDataReceived:
user.noDataReceivedRecentlyStart = time.Time{} user.noDataReceivedRecently = true
default: default:
user.zlog.Trace().Any("data", v).Type("data_type", v).Msg("Unknown event") user.zlog.Trace().Any("data", v).Type("data_type", v).Msg("Unknown event")
} }
@ -874,7 +883,7 @@ func (user *User) aggressiveSetActive() {
} }
} }
func (user *User) fetchAndSyncConversations(noDataReceivedStart time.Time, minimalSync bool) { func (user *User) fetchAndSyncConversations(lastDataReceived time.Time, minimalSync bool) {
user.zlog.Info().Msg("Fetching conversation list") user.zlog.Info().Msg("Fetching conversation list")
resp, err := user.Client.ListConversations(user.bridge.Config.Bridge.InitialChatSyncCount, gmproto.ListConversationsRequest_INBOX) resp, err := user.Client.ListConversations(user.bridge.Config.Bridge.InitialChatSyncCount, gmproto.ListConversationsRequest_INBOX)
if err != nil { if err != nil {
@ -882,19 +891,19 @@ func (user *User) fetchAndSyncConversations(noDataReceivedStart time.Time, minim
return return
} }
user.zlog.Info().Int("count", len(resp.GetConversations())).Msg("Syncing conversations") user.zlog.Info().Int("count", len(resp.GetConversations())).Msg("Syncing conversations")
if !noDataReceivedStart.IsZero() { if !lastDataReceived.IsZero() {
for _, conv := range resp.GetConversations() { for _, conv := range resp.GetConversations() {
lastMessageTS := time.UnixMicro(conv.GetLastMessageTimestamp()) lastMessageTS := time.UnixMicro(conv.GetLastMessageTimestamp())
if lastMessageTS.After(noDataReceivedStart) { if lastMessageTS.After(lastDataReceived) {
user.zlog.Warn(). user.zlog.Warn().
Time("last_message_ts", lastMessageTS). Time("last_message_ts", lastMessageTS).
Time("no_data_received_start", noDataReceivedStart). Time("last_data_received", lastDataReceived).
Msg("Conversation's last message is newer than no data received start time") Msg("Conversation's last message is newer than last data received time")
minimalSync = false minimalSync = false
} }
} }
} else if minimalSync { } else if minimalSync {
user.zlog.Warn().Msg("Minimal sync called without no data received start time") user.zlog.Warn().Msg("Minimal sync called without last data received time")
} }
if minimalSync { if minimalSync {
user.zlog.Debug().Msg("Minimal sync with no recent messages, not syncing conversations") user.zlog.Debug().Msg("Minimal sync with no recent messages, not syncing conversations")
@ -929,9 +938,11 @@ func (user *User) handleUserAlert(v *gmproto.UserAlertEvent) {
ctx := context.TODO() ctx := context.TODO()
user.zlog.Debug().Str("alert_type", v.GetAlertType().String()).Msg("Got user alert event") user.zlog.Debug().Str("alert_type", v.GetAlertType().String()).Msg("Got user alert event")
becameInactive := false becameInactive := false
noDataReceivedStart := user.noDataReceivedRecentlyStart // Don't reset last data received until a BROWSER_ACTIVE event if there hasn't been data recently,
hadNoDataReceived := !noDataReceivedStart.IsZero() // otherwise the resync won't have the right timestamp.
user.noDataReceivedRecentlyStart = time.Time{} if !user.noDataReceivedRecently {
user.lastDataReceived = time.Now()
}
switch v.GetAlertType() { switch v.GetAlertType() {
case gmproto.AlertType_BROWSER_INACTIVE: case gmproto.AlertType_BROWSER_INACTIVE:
user.browserInactiveType = GMBrowserInactive user.browserInactiveType = GMBrowserInactive
@ -943,25 +954,27 @@ func (user *User) handleUserAlert(v *gmproto.UserAlertEvent) {
user.ready = true user.ready = true
newSessionID := user.Client.CurrentSessionID() newSessionID := user.Client.CurrentSessionID()
sessionIDChanged := user.sessionID != newSessionID sessionIDChanged := user.sessionID != newSessionID
if sessionIDChanged || wasInactive || hadNoDataReceived { if sessionIDChanged || wasInactive || user.noDataReceivedRecently {
user.zlog.Debug(). user.zlog.Debug().
Str("old_session_id", user.sessionID). Str("old_session_id", user.sessionID).
Str("new_session_id", newSessionID). Str("new_session_id", newSessionID).
Bool("was_inactive", wasInactive). Bool("was_inactive", wasInactive).
Bool("had_no_data_received", hadNoDataReceived). Bool("had_no_data_received", user.noDataReceivedRecently).
Time("no_data_received_start", noDataReceivedStart). Time("last_data_received", user.lastDataReceived).
Msg("Session ID changed for browser active event, resyncing") Msg("Session ID changed for browser active event, resyncing")
user.sessionID = newSessionID user.sessionID = newSessionID
go user.fetchAndSyncConversations(noDataReceivedStart, !sessionIDChanged && !wasInactive) go user.fetchAndSyncConversations(user.lastDataReceived, !sessionIDChanged && !wasInactive)
go user.sendMarkdownBridgeAlert(ctx, false, "Connected to Google Messages") go user.sendMarkdownBridgeAlert(ctx, false, "Connected to Google Messages")
} else { } else {
user.zlog.Debug(). user.zlog.Debug().
Str("session_id", user.sessionID). Str("session_id", user.sessionID).
Bool("was_inactive", wasInactive). Bool("was_inactive", wasInactive).
Bool("had_no_data_received", hadNoDataReceived). Bool("had_no_data_received", user.noDataReceivedRecently).
Time("no_data_received_start", noDataReceivedStart). Time("last_data_received", user.lastDataReceived).
Msg("Session ID didn't change for browser active event, not resyncing") Msg("Session ID didn't change for browser active event, not resyncing")
} }
user.noDataReceivedRecently = false
user.lastDataReceived = time.Now()
case gmproto.AlertType_BROWSER_INACTIVE_FROM_TIMEOUT: case gmproto.AlertType_BROWSER_INACTIVE_FROM_TIMEOUT:
user.browserInactiveType = GMBrowserInactiveTimeout user.browserInactiveType = GMBrowserInactiveTimeout
becameInactive = true becameInactive = true