store: Handle unexpected event-poll errors by reloading store, with backoff

This fixes #563.  We'll follow up with a few more commits that give
more-informative errors in some cases, or change the handling of others
from retrying getEvents to reloading the data from scratch.

The if-disposed and store.isLoading lines have no effect in the case
of a BAD_EVENT_QUEUE_ID error, because those can only come from the
getEvents request, and then the inner catch block will have already
taken the same steps.

Fixes: #563

Author: gnprice

lib/model/store.dart

@@ -993,6 +993,18 @@ class UpdateMachine {
     }());
   }
 
+  // This is static so that it persists through new UpdateMachine instances
+  // as we attempt to fix things by reloading data from scratch.  In principle
+  // it could also be per-account (or per-realm or per-server); but currently
+  // we skip that complication, as well as attempting to reset backoff on
+  // later success.  After all, these unexpected errors should be uncommon;
+  // ideally they'd never happen.
+  static BackoffMachine get _unexpectedErrorBackoffMachine {
+    return __unexpectedErrorBackoffMachine
+      ??= BackoffMachine(maxBound: const Duration(seconds: 60));
+  }
+  static BackoffMachine? __unexpectedErrorBackoffMachine;
+
   /// This controls when we start to report transient errors to the user when
   /// polling.
   ///
@@ -1113,13 +1125,42 @@ class UpdateMachine {
         }
       }
     } catch (e) {
+      if (_disposed) return;
+
+      // An error occurred, other than the request errors we retry on.
+      // This means either a lost/expired event queue on the server (which is
+      // normal after the app is offline for a period like 10 minutes),
+      // or an unexpected exception representing a bug in our code or the server.
+      // Either way, the show must go on.  So reload server data from scratch.
+
+      // First, log what happened.
+      store.isLoading = true;
+      bool isUnexpected;
       switch (e) {
         case ZulipApiException(code: 'BAD_EVENT_QUEUE_ID'):
           assert(debugLog('Lost event queue for $store.  Replacing…'));
           // The old event queue is gone, so we need a new one.  This is normal.
+          isUnexpected = false;
 
         default:
-          rethrow; // TODO(#563) try to recover instead
+          assert(debugLog('BUG: Unexpected error in event polling: $e\n' // TODO(log)
+            'Replacing event queue…'));
+          _reportToUserErrorConnectingToServer(e);
+          // We can't just continue with the next event, because our state
+          // may be garbled due to failing to apply this one (and worse,
+          // any invariants that were left in a broken state from where
+          // the exception was thrown).  So reload from scratch.
+          // Hopefully (probably?) the bug only affects our implementation of
+          // the *change* in state represented by the event, and when we get the
+          // new state in a fresh InitialSnapshot we'll handle that just fine.
+          isUnexpected = true;
+      }
+
+      if (isUnexpected) {
+        // We don't know the cause of the failure; it might well keep happening.
+        // Avoid creating a retry storm.
+        await _unexpectedErrorBackoffMachine.wait();
+        if (_disposed) return;
       }
 
       // This disposes the store, which disposes this update machine.

test/example_data.dart

@@ -18,6 +18,10 @@ void _checkPositive(int? value, String description) {
   assert(value == null || value > 0, '$description should be positive');
 }
 
+Object nullCheckError() {
+  try { null!; } catch (e) { return e; } // ignore: null_check_always_fails
+}
+
 ////////////////////////////////////////////////////////////////
 // Realm-wide (or server-wide) metadata.
 //

test/model/store_test.dart

@@ -639,16 +639,25 @@ void main() {
       check(store.userSettings!.twentyFourHourTime).isTrue();
     }));
 
-    void checkReload(void Function() prepareError) {
+    void checkReload(FutureOr<void> Function() prepareError, {
+      bool expectBackoff = true,
+    }) {
       awaitFakeAsync((async) async {
         await preparePoll();
         check(globalStore.perAccountSync(store.accountId)).identicalTo(store);
 
-        prepareError();
+        await prepareError();
         updateMachine.debugAdvanceLoop();
         async.elapse(Duration.zero);
         check(store).isLoading.isTrue();
 
+        if (expectBackoff) {
+          // The reload doesn't happen immediately; there's a timer.
+          check(globalStore.perAccountSync(store.accountId)).identicalTo(store);
+          check(async.pendingTimers).length.equals(1);
+          async.flushTimers();
+        }
+
         // The global store has a new store.
         check(globalStore.perAccountSync(store.accountId)).not((it) => it.identicalTo(store));
         updateFromGlobalStore();
@@ -700,6 +709,10 @@ void main() {
 
     // These cases are ordered by how far the request got before it failed.
 
+    void prepareUnexpectedLoopError() {
+      updateMachine.debugPrepareLoopError(eg.nullCheckError());
+    }
+
     void prepareNetworkExceptionSocketException() {
       connection.prepare(exception: const SocketException('failed'));
     }
@@ -753,6 +766,23 @@ void main() {
       });
     }
 
+    Future<void> prepareHandleEventError() async {
+      final stream = eg.stream();
+      await store.addStream(stream);
+      // Set up a situation that breaks our data structures' invariants:
+      // a stream/channel found in the by-ID map is missing in the by-name map.
+      store.streamsByName.remove(stream.name);
+      // Then prepare an event on which handleEvent will throw
+      // because it hits that broken invariant.
+      connection.prepare(json: GetEventsResult(events: [
+        ChannelDeleteEvent(id: 1, streams: [stream]),
+      ], queueId: null).toJson());
+    }
+
+    test('reloads on unexpected error within loop', () {
+      checkReload(prepareUnexpectedLoopError);
+    });
+
     test('retries on NetworkException from SocketException', () {
       // We skip reporting errors on these; check we retry them all the same.
       checkRetry(prepareNetworkExceptionSocketException);
@@ -786,8 +816,12 @@ void main() {
       checkRetry(prepareZulipApiExceptionBadRequest);
     });
 
-    test('reloads on expired queue', () {
-      checkReload(prepareExpiredEventQueue);
+    test('reloads immediately on expired queue', () {
+      checkReload(expectBackoff: false, prepareExpiredEventQueue);
+    });
+
+    test('reloads on handleEvent error', () {
+      checkReload(prepareHandleEventError);
     });
 
     test('expired queue disposes registered MessageListView instances', () => awaitFakeAsync((async) async {
@@ -828,18 +862,20 @@ void main() {
         await preparePoll(lastEventId: 1);
       }
 
-      void pollAndFail(FakeAsync async) {
+      void pollAndFail(FakeAsync async, {bool shouldCheckRequest = true}) {
         updateMachine.debugAdvanceLoop();
         async.elapse(Duration.zero);
-        checkLastRequest(lastEventId: 1);
+        if (shouldCheckRequest) checkLastRequest(lastEventId: 1);
         check(store).isLoading.isTrue();
       }
 
       Subject<String> checkReported(void Function() prepareError) {
         return awaitFakeAsync((async) async {
           await prepare();
           prepareError();
-          pollAndFail(async);
+          // No need to check on the request; there's no later step of this test
+          // for it to be needed as setup for.
+          pollAndFail(async, shouldCheckRequest: false);
           return check(takeLastReportedError()).isNotNull();
         });
       }
@@ -892,6 +928,10 @@ void main() {
         });
       }
 
+      test('report unexpected error within loop', () {
+        checkReported(prepareUnexpectedLoopError);
+      });
+
       test('ignore NetworkException from SocketException', () {
         checkNotReported(prepareNetworkExceptionSocketException);
       });
@@ -941,6 +981,12 @@ void main() {
       test('ignore expired queue', () {
         checkNotReported(prepareExpiredEventQueue);
       });
+
+      test('report handleEvent error', () {
+        checkReported(prepareHandleEventError).startsWith(
+          "Error connecting to Zulip. Retrying…\n"
+          "Error connecting to Zulip at");
+      });
     });
   });