Error connecting to Electric: errorType: INVALID_REQUEST when pressing back button on main screen and reopening the app

maloni-leonardo commented 6 months ago

Device: Android (14)

Flutter version/SDK: Flutter 3.22.0 (stable channel)

Plugin version: Tested both on v0.6.0 and v0.7.0 versions

Issue: Running the todos_flutter Flutter app following the todos_electrified instructions will generate an INVALID_REQUEST error when trying to reconnect to Electric after pressing the system back button and reopening the app from background. This might be an issue on newer Android version that the app would not retain its state upon waking from sleep.

Expected behaviour: After the first initialization, pressing the back button in the main screen (leaving the app running in background) and then reopening it should reconnect to Electric (like on a normal startup)

How to reproduce the issue: After initializing the example docker and project following the README:

Open the app
Let it connect to electric
Press the back button on the device, then reopen the app (without closing it first)
The error will occur

Stack log (client):

Connecting to VM Service at ws://127.0.0.1:49634/vAFa1zbMXhQ=/ws
D/VRI[MainActivity](15904): Cancelling draw. cancelDueToPreDrawListener=true cancelDueToSync=false
I/Gralloc4(15904): Adding additional valid usage bits: 0x8202000
D/VRI[MainActivity](15904): Cancelling draw. cancelDueToPreDrawListener=true cancelDueToSync=false
I/flutter (15904): Using todos database at path /data/user/0/com.example.todos_electrified/app_flutter/todos-electric/todos.db
D/VRI[MainActivity](15904): Cancelling draw. cancelDueToPreDrawListener=true cancelDueToSync=false
I/flutter (15904): Dummy onCreate
I/flutter (15904): Electrifying database...
I/flutter (15904): Electric URL: http://192.168.11.245:5133
I/flutter (15904): [Electric] INFO:  10:48:48.479 Using SQLite version: 3.45.3 
I/flutter (15904): [Electric] INFO:  10:48:48.513 applying migration: 0 
I/flutter (15904): [Electric] INFO:  10:48:48.544 applying migration: 20230924100310 
I/flutter (15904): [Electric] INFO:  10:48:48.563 applying migration: 20230924100404 
I/flutter (15904): [Electric] INFO:  10:48:48.632 no lsn retrieved from store 
I/flutter (15904): Database electrified!
I/flutter (15904): [Electric] DEBUG: 10:48:48.729 notifying Electric of database changes. Changed tables: {todolist} 
I/flutter (15904): [Electric] INFO:  10:48:49.213 connecting to electric server 
I/flutter (15904): [Electric] DEBUG: 10:48:49.825 [rpc] send: #SatAuthReq{id: 956a17af-751b-4f62-af5a-6dbbc13ecb2b, token: eyJhbGciOiJub25lIn0=.eyJzdWIiOiJjNTVmMWYyOC1mNzQzLTQ3YjctYjY3MC0zOWY4YjY0MTg5M2UifQ==.} 
I/flutter (15904): [Electric] DEBUG: 10:48:49.834 [proto] send: #SatRpcRequest{method: authenticate, requestId: 1} 
I/flutter (15904): [Electric] DEBUG: 10:48:49.867 notifying client of database changes. Changed tables: [todolist]. Origin: local 
I/flutter (15904): [Electric] DEBUG: 10:48:49.907 [proto] recv: #SatRpcResponse{method: authenticate, requestId: 1} 
I/flutter (15904): [Electric] DEBUG: 10:48:49.912 [rpc] recv: #SatAuthResp{id: d4972d63-cc43-411c-b669-1a40bde4a74d} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.148 [proto] recv: #SatRpcRequest{method: startReplication, requestId: 0} 
I/flutter (15904): [Electric] INFO:  10:48:50.161 Server sent a replication request to start from 0, and options () 
I/flutter (15904): [Electric] DEBUG: 10:48:50.167 [proto] send: #SatRpcResponse{method: startReplication, requestId: 0} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.194 [proto] send: #SatRelation{for: public.todolist, as: 0, cols: id: TEXT, filter: TEXT, editing: TEXT} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.230 [proto] send: #SatOpLog{ops: [#Begin{lsn: AAAAAQ==, ts: 1715849328747, isMigration: false}, #Insert{for: 0, tags: [], new: ["LIST-ID-SAMPLE", ∅, ∅]}, #Commit{lsn: }]} 
I/flutter (15904): [Electric] INFO:  10:48:50.250 no previous LSN, start replication from scratch 
I/flutter (15904): [Electric] DEBUG: 10:48:50.252 [rpc] send: #SatInStartReplicationReq{lsn: , schema: 20230924100404, subscriptions: []} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.255 [proto] send: #SatRpcRequest{method: startReplication, requestId: 2} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.279 [proto] recv: #SatRpcResponse{method: startReplication, requestId: 2} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.283 [rpc] recv: #SatInStartReplicationResp{} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.412 [rpc] send: #SatSubsReq{id: ceeb9690-3883-44ba-863e-f2ace3cc9c4c, shapes: [{"1":"f22d7a4a-38b5-4254-b87d-9ab817cbf557","2":{"1":[{"1":"todolist","3":[{"1":["listid"],"2":{"1":"todo"}}]}]}}]} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.412 [proto] send: #SatRpcRequest{method: subscribe, requestId: 3} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.512 [proto] recv: #SatRpcResponse{method: subscribe, requestId: 3} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.520 [rpc] recv: #SatSubsResp{id: ceeb9690-3883-44ba-863e-f2ace3cc9c4c} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.523 [proto] recv: #SatOpLog{ops: [#Begin{lsn: MjY5Mjk4MTY=, ts: 1715849328747, isMigration: false}, #Commit{lsn: MjY5Mjk4MTY=}]} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.534 [proto] recv: #SatRelation{for: public.todolist, as: 16821, cols: id: text PK, filter: text, editing: text} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.536 [proto] recv: #SatSubsDataBegin{id: ceeb9690-3883-44ba-863e-f2ace3cc9c4c, lsn: MjY5MzIyNjQ=} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.539 [proto] recv: #SatShapeDataBegin{id: f22d7a4a-38b5-4254-b87d-9ab817cbf557} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.541 [proto] recv: #SatOpLog{ops: [#Insert{for: 16821, tags: [f1c3addf-a1ae-43e0-93e8-c6b1d1aa8eb6@1715847403745, 956a17af-751b-4f62-af5a-6dbbc13ecb2b@1715849328747], new: ["LIST-ID-SAMPLE", ∅, ∅]}]} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.542 [proto] recv: #SatShapeDataEnd{} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.542 [proto] recv: #SatSubsDataEnd{} 
I/flutter (15904): [Electric] DEBUG: 10:48:50.592 notifying client of database changes. Changed tables: [todolist]. Origin: initial 
I/flutter (15904): [Electric] DEBUG: 10:48:50.594 notifying Drift of database changes: Changed tables: {todolist}. Origin: initial 
I/flutter (15904): [Electric] DEBUG: 10:48:50.596 [proto] send: #SatOpLogAck{lsn: MjY5Mjk4MTY=, txid: 762} 
W/dos_electrified(15904): ApkAssets: Deleting an ApkAssets object '<empty> and /data/app/~~wvIKYnQN8Z6uwyHGNzBTcA==/com.google.android.marvin.talkback-lSfObUgBlT6vOfsmG0LA2w==/base.apk' with 1 weak references
W/dos_electrified(15904): ApkAssets: Deleting an ApkAssets object '<empty> and /data/app/~~wvIKYnQN8Z6uwyHGNzBTcA==/com.google.android.marvin.talkback-lSfObUgBlT6vOfsmG0LA2w==/split_config.arm64_v8a.apk' with 1 weak references

# Reopening the app after back button press

W/WindowOnBackDispatcher(15904): sendCancelIfRunning: isInProgress=falsecallback=android.view.ViewRootImpl$$ExternalSyntheticLambda17@72cd5ff
I/AdrenoGLES-0(15904): QUALCOMM build                   : 329cf4c2a7, I63533b1e29
I/AdrenoGLES-0(15904): Build Date                       : 01/31/23
I/AdrenoGLES-0(15904): OpenGL ES Shader Compiler Version: EV031.35.01.12
I/AdrenoGLES-0(15904): Local Branch                     :
I/AdrenoGLES-0(15904): Remote Branch                    : refs/tags/AU_LINUX_ANDROID_LA.UM.9.14.11.00.00.571.148
I/AdrenoGLES-0(15904): Remote Branch                    : NONE
I/AdrenoGLES-0(15904): Reconstruct Branch               : NOTHING
I/AdrenoGLES-0(15904): Build Config                     : S P 10.0.7 AArch64
I/AdrenoGLES-0(15904): Driver Path                      : /vendor/lib64/egl/libGLESv2_adreno.so
I/AdrenoGLES-0(15904): PFP: 0x016dc094, ME: 0x00000000
E/OpenGLRenderer(15904): Unable to match the desired swap behavior.
D/VRI[MainActivity](15904): Cancelling draw. cancelDueToPreDrawListener=true cancelDueToSync=false
I/flutter (15904): Using todos database at path /data/user/0/com.example.todos_electrified/app_flutter/todos-electric/todos.db
I/flutter (15904): Electrifying database...
I/flutter (15904): Electric URL: http://192.168.11.245:5133
I/flutter (15904): [Electric] INFO:  10:50:09.082 Using SQLite version: 3.45.3 
I/flutter (15904): [Electric] INFO:  10:50:09.175 retrieved lsn [50, 54, 57, 51, 50, 50, 54, 52] 
I/flutter (15904): Database electrified!
I/flutter (15904): [Electric] INFO:  10:50:09.690 connecting to electric server 
I/flutter (15904): [Electric] DEBUG: 10:50:10.388 [rpc] send: #SatAuthReq{id: 956a17af-751b-4f62-af5a-6dbbc13ecb2b, token: eyJhbGciOiJub25lIn0=.eyJzdWIiOiJmMGVjMTUzNi04NTU1LTRmNmYtYTI4ZS00M2FhNTJhYzk1ZWIifQ==.} 
I/flutter (15904): [Electric] DEBUG: 10:50:10.398 [proto] send: #SatRpcRequest{method: authenticate, requestId: 1} 
I/flutter (15904): [Electric] DEBUG: 10:50:11.752 [proto] recv: #SatRpcResponse{method: authenticate, requestId: 1, error: #SatErrorResp{type: INVALID_REQUEST}} 
I/flutter (15904): [Electric] WARN:  10:50:11.753 RPC call authenticate/1 failed with #SatErrorResp{type: INVALID_REQUEST} 
I/flutter (15904): [Electric] DEBUG: 10:50:11.763 server returned an error while establishing connection: errorType: INVALID_REQUEST
I/flutter (15904):  
I/flutter (15904): [Electric] DEBUG: 10:50:11.764 connectAndStartRetryHandler was cancelled: errorType: INVALID_REQUEST
I/flutter (15904):  
I/flutter (15904): Error connecting to Electric: errorType: INVALID_REQUEST
I/flutter (15904):
I/flutter (15904): [Electric] WARN:  10:50:11.783 an error occurred in satellite: socket closed 
I/flutter (15904): [Electric] WARN:  10:50:11.784 Client disconnected with a non fatal error, reconnecting 
I/flutter (15904): [Electric] INFO:  10:50:11.785 connecting to electric server 
I/flutter (15904): [Electric] DEBUG: 10:50:11.900 [rpc] send: #SatAuthReq{id: 956a17af-751b-4f62-af5a-6dbbc13ecb2b, token: eyJhbGciOiJub25lIn0=.eyJzdWIiOiJmMGVjMTUzNi04NTU1LTRmNmYtYTI4ZS00M2FhNTJhYzk1ZWIifQ==.} 
I/flutter (15904): [Electric] DEBUG: 10:50:11.901 [proto] send: #SatRpcRequest{method: authenticate, requestId: 2} 
I/flutter (15904): [Electric] DEBUG: 10:50:12.947 [proto] recv: #SatRpcResponse{method: authenticate, requestId: 2, error: #SatErrorResp{type: INVALID_REQUEST}} 
I/flutter (15904): [Electric] WARN:  10:50:12.948 RPC call authenticate/2 failed with #SatErrorResp{type: INVALID_REQUEST} 
I/flutter (15904): [Electric] DEBUG: 10:50:12.952 server returned an error while establishing connection: errorType: INVALID_REQUEST
I/flutter (15904):  
I/flutter (15904): [Electric] DEBUG: 10:50:12.953 connectAndStartRetryHandler was cancelled: errorType: INVALID_REQUEST
I/flutter (15904):  
I/flutter (15904): [Electric] WARN:  10:50:12.960 an error occurred in satellite: socket closed 
I/flutter (15904): [Electric] WARN:  10:50:12.962 Client disconnected with a non fatal error, reconnecting 
I/flutter (15904): [Electric] INFO:  10:50:12.963 connecting to electric server 
I/flutter (15904): [Electric] DEBUG: 10:50:12.984 [rpc] send: #SatAuthReq{id: 956a17af-751b-4f62-af5a-6dbbc13ecb2b, token: eyJhbGciOiJub25lIn0=.eyJzdWIiOiJmMGVjMTUzNi04NTU1LTRmNmYtYTI4ZS00M2FhNTJhYzk1ZWIifQ==.} 
I/flutter (15904): [Electric] DEBUG: 10:50:12.985 [proto] send: #SatRpcRequest{method: authenticate, requestId: 3} 
I/flutter (15904): [Electric] DEBUG: 10:50:14.171 [proto] recv: #SatRpcResponse{method: authenticate, requestId: 3, error: #SatErrorResp{type: INVALID_REQUEST}} 
I/flutter (15904): [Electric] WARN:  10:50:14.172 RPC call authenticate/3 failed with #SatErrorResp{type: INVALID_REQUEST} 
I/flutter (15904): [Electric] DEBUG: 10:50:14.174 server returned an error while establishing connection: errorType: INVALID_REQUEST
I/flutter (15904):  
I/flutter (15904): [Electric] DEBUG: 10:50:14.175 connectAndStartRetryHandler was cancelled: errorType: INVALID_REQUEST
I/flutter (15904):  
I/flutter (15904): [Electric] WARN:  10:50:14.178 an error occurred in satellite: socket closed 
I/flutter (15904): [Electric] WARN:  10:50:14.178 Client disconnected with a non fatal error, reconnecting 
I/flutter (15904): [Electric] INFO:  10:50:14.179 connecting to electric server 
I/flutter (15904): [Electric] DEBUG: 10:50:14.206 [rpc] send: #SatAuthReq{id: 956a17af-751b-4f62-af5a-6dbbc13ecb2b, token: eyJhbGciOiJub25lIn0=.eyJzdWIiOiJmMGVjMTUzNi04NTU1LTRmNmYtYTI4ZS00M2FhNTJhYzk1ZWIifQ==.} 
I/flutter (15904): [Electric] DEBUG: 10:50:14.206 [proto] send: #SatRpcRequest{method: authenticate, requestId: 4} 
I/flutter (15904): [Electric] DEBUG: 10:50:15.400 [proto] recv: #SatRpcResponse{method: authenticate, requestId: 4, error: #SatErrorResp{type: INVALID_REQUEST}} 
I/flutter (15904): [Electric] WARN:  10:50:15.401 RPC call authenticate/4 failed with #SatErrorResp{type: INVALID_REQUEST} 
I/flutter (15904): [Electric] DEBUG: 10:50:15.403 server returned an error while establishing connection: errorType: INVALID_REQUEST
I/flutter (15904):  
I/flutter (15904): [Electric] DEBUG: 10:50:15.405 connectAndStartRetryHandler was cancelled: errorType: INVALID_REQUEST
I/flutter (15904):  
I/flutter (15904): [Electric] WARN:  10:50:15.407 an error occurred in satellite: socket closed 
I/flutter (15904): [Electric] WARN:  10:50:15.408 Client disconnected with a non fatal error, reconnecting 
I/flutter (15904): [Electric] INFO:  10:50:15.408 connecting to electric server 
I/flutter (15904): [Electric] DEBUG: 10:50:15.445 [rpc] send: #SatAuthReq{id: 956a17af-751b-4f62-af5a-6dbbc13ecb2b, token: eyJhbGciOiJub25lIn0=.eyJzdWIiOiJmMGVjMTUzNi04NTU1LTRmNmYtYTI4ZS00M2FhNTJhYzk1ZWIifQ==.} 
I/flutter (15904): [Electric] DEBUG: 10:50:15.447 [proto] send: #SatRpcRequest{method: authenticate, requestId: 5} 
I/flutter (15904): [Electric] DEBUG: 10:50:16.627 [proto] recv: #SatRpcResponse{method: authenticate, requestId: 5, error: #SatErrorResp{type: INVALID_REQUEST}} 
I/flutter (15904): [Electric] WARN:  10:50:16.629 RPC call authenticate/5 failed with #SatErrorResp{type: INVALID_REQUEST} 
I/flutter (15904): [Electric] DEBUG: 10:50:16.632 server returned an error while establishing connection: errorType: INVALID_REQUEST
I/flutter (15904):  
I/flutter (15904): [Electric] DEBUG: 10:50:16.633 connectAndStartRetryHandler was cancelled: errorType: INVALID_REQUEST
I/flutter (15904):  
I/flutter (15904): [Electric] WARN:  10:50:16.636 an error occurred in satellite: socket closed 
I/flutter (15904): [Electric] WARN:  10:50:16.637 Client disconnected with a non fatal error, reconnecting 

# ^ Reconnection loop and exception happening until manual app termination

Application finished.

Exited (-1).

Stack log (server):

electric-1  | 08:48:49.122 pid=<0.4027.0> [info] GET /ws
electric-1  | 08:48:49.124 pid=<0.4027.0> instance_id=d4972d63-cc43-411c-b669-1a40bde4a74d [info] Sent 101 in 1ms
electric-1  | 08:48:49.305 pid=<0.4027.0> client_id=956a17af-751b-4f62-af5a-6dbbc13ecb2b instance_id=d4972d63-cc43-411c-b669-1a40bde4a74d user_id=c55f1f28-f743-47b7-b670-39f8b641893e [info] Successfully authenticated the client
electric-1  | 08:48:49.305 pid=<0.4027.0> client_id=956a17af-751b-4f62-af5a-6dbbc13ecb2b instance_id=d4972d63-cc43-411c-b669-1a40bde4a74d user_id=c55f1f28-f743-47b7-b670-39f8b641893e [info] Postgres.Client.with_conn(%{database: ~c"todos_electrified", host: ~c"postgres", ip_addr: ~c"****************", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5432, ssl: false, ssl_opts: [server_name_indication: ~c"postgres"], timeout: 5000, username: ~c"postgres"})
electric-1  | 08:48:49.872 pid=<0.4032.0> [info] Postgres.Client.with_conn(%{database: ~c"todos_electrified", host: ~c"postgres", ip_addr: ~c"****************", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5432, ssl: false, ssl_opts: [server_name_indication: ~c"postgres"], timeout: 5000, username: ~c"postgres"})
electric-1  | 08:48:49.898 pid=<0.4034.0> [info] Postgres.Client.with_conn(%{database: ~c"todos_electrified", host: ~c"postgres", ip_addr: ~c"****************", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5432, ssl: false, ssl_opts: [server_name_indication: ~c"postgres"], timeout: 5000, username: ~c"postgres"})
electric-1  | 08:50:04.140 pid=<0.4027.0> client_id=956a17af-751b-4f62-af5a-6dbbc13ecb2b instance_id=d4972d63-cc43-411c-b669-1a40bde4a74d user_id=c55f1f28-f743-47b7-b670-39f8b641893e [info] Client is not responding to ping, disconnecting
electric-1  | 08:50:09.532 pid=<0.4036.0> [info] GET /ws
electric-1  | 08:50:09.532 pid=<0.4036.0> instance_id=d4972d63-cc43-411c-b669-1a40bde4a74d [info] Sent 101 in 194µs
electric-1  | 08:50:10.870 pid=<0.4036.0> client_id=956a17af-751b-4f62-af5a-6dbbc13ecb2b instance_id=d4972d63-cc43-411c-b669-1a40bde4a74d [info] attempted multiple connections from the same client
electric-1  | 08:50:11.338 pid=<0.4037.0> [info] GET /ws
electric-1  | 08:50:11.338 pid=<0.4037.0> instance_id=d4972d63-cc43-411c-b669-1a40bde4a74d [info] Sent 101 in 246µs
electric-1  | 08:50:12.350 pid=<0.4037.0> client_id=956a17af-751b-4f62-af5a-6dbbc13ecb2b instance_id=d4972d63-cc43-411c-b669-1a40bde4a74d [info] attempted multiple connections from the same client
electric-1  | 08:50:12.419 pid=<0.4039.0> [info] GET /ws
electric-1  | 08:50:12.419 pid=<0.4039.0> instance_id=d4972d63-cc43-411c-b669-1a40bde4a74d [info] Sent 101 in 189µs
electric-1  | 08:50:13.435 pid=<0.4039.0> client_id=956a17af-751b-4f62-af5a-6dbbc13ecb2b instance_id=d4972d63-cc43-411c-b669-1a40bde4a74d [info] attempted multiple connections from the same client
electric-1  | 08:50:13.641 pid=<0.4040.0> [info] GET /ws
electric-1  | 08:50:13.642 pid=<0.4040.0> instance_id=d4972d63-cc43-411c-b669-1a40bde4a74d [info] Sent 101 in 377µs
electric-1  | 08:50:14.656 pid=<0.4040.0> client_id=956a17af-751b-4f62-af5a-6dbbc13ecb2b instance_id=d4972d63-cc43-411c-b669-1a40bde4a74d [info] attempted multiple connections from the same client
electric-1  | 08:50:14.879 pid=<0.4041.0> [info] GET /ws
electric-1  | 08:50:14.879 pid=<0.4041.0> instance_id=d4972d63-cc43-411c-b669-1a40bde4a74d [info] Sent 101 in 170µs
electric-1  | 08:50:15.897 pid=<0.4041.0> client_id=956a17af-751b-4f62-af5a-6dbbc13ecb2b instance_id=d4972d63-cc43-411c-b669-1a40bde4a74d [info] attempted multiple connections from the same client
electric-1  | 08:50:16.099 pid=<0.4042.0> [info] GET /ws
electric-1  | 08:50:16.099 pid=<0.4042.0> instance_id=d4972d63-cc43-411c-b669-1a40bde4a74d [info] Sent 101 in 279µs
electric-1  | 08:50:17.119 pid=<0.4042.0> client_id=956a17af-751b-4f62-af5a-6dbbc13ecb2b instance_id=d4972d63-cc43-411c-b669-1a40bde4a74d [info] attempted multiple connections from the same client

davidmartos96 commented 6 months ago

@maloni-leonardo Thank you for reporting! ~~This is the first time we hear about this, I can more or less reproduce in Flutter 3.22, I get a different error when coming from background after a while, which didn't happen before. But I'm not able to reproduce it with 3.19 Could you try on Flutter 3.19?~~

~~The latest stable might have changed something related to resources in the background.~~ (I was able to trigger it in 3.19. It looks to happen only when pressing Back, not when minimizing)

I would expect the websocket connection to close atutomatically, but your server logs are basically saying that the same device is being connected 2 times at the same time. This can happen for example when hot restarting on Web, instead of a full refresh, but we haven't seen this behavior on other platforms.

davidmartos96 commented 6 months ago

@maloni-leonardo Here is a workaround you could use. We aren't yet sure if it's an issue in Flutter, the client or the Electric service.

Easier with hooks, but you can also use AppLifecycleListener (https://api.flutter.dev/flutter/widgets/AppLifecycleListener-class.html)

useOnAppLifecycleStateChange((previous, current) {
  if (current == AppLifecycleState.detached) {
    electricClient.disconnect();
  }
});

maloni-leonardo commented 6 months ago

After doing more research, using a similar (native) Flutter function seems to have solved the issue! Here's the one i used:

AppLifecycleListener(onDetach: () => electricClient.disconnect());

The suggested one works as well, but it requires the flutter_hooks library which i don't use in my code.

maloni-leonardo commented 5 months ago

Hi again, while using the v0.7.1+4 i bumped into the same error, this time with an exception happening on sockets.dart on a Null check:

# Acquiring a "big" table, exception occurs without tracelog

I/flutter (18343): [Electric] WARN:  10:03:27.001 an error occurred in satellite: socket closed 
I/flutter (18343): [Electric] WARN:  10:03:27.002 Client disconnected with a non fatal error, reconnecting 
I/flutter (18343): [Electric] INFO:  10:03:27.002 connecting to electric server 

# 2nd exception, this time mentioning a null check similar to the past one
# meanwhile, "await shape.synced" returned, so the table should be okay

E/flutter (18343): [ERROR:flutter/runtime/dart_vm_initializer.cc(41)] Unhandled Exception: Null check operator used on a null value
E/flutter (18343): #0      WebSocketBase._asyncStart (package:electricsql/src/sockets/sockets.dart:132:37)
E/flutter (18343): <asynchronous suspension>
E/flutter (18343):

Trying to roll back to v0.7.0 still reproduce the same issue...

davidmartos96 commented 5 months ago

@maloni-leonardo Hello! This is the first time we see this issue. Are you able to reproduce it in an isolated example? I don't see how _channel can be null in that line of the code, as it's being assigned right before. Maybe it's because client.disconnect was called while awaiting channel.ready

maloni-leonardo commented 5 months ago

I'm unable to provide a proper isolate example, as the issue happens while syncing a 52M postgres table from a remote database which would be difficult to replicate, but i can provide further details such as:

The exception is thrown right after the table is "synced" (using await shape.synced);
The table itself has been synced successfully by the time the exception is thrown;
Server-side, it looks like the client is being disconnected because of a timeout expiring;
The issue is not present if the "big" table is synced partially (using the where filter).

davidmartos96 commented 5 months ago

@maloni-leonardo You might get more information by sharing the use case with the Electric team over the official Github repository or the Discord. Is the timeout described by the server? (websocket ping timout, or other....)

So, from what you describe, the 52M table is properly replicated, there is no exception in the awaited shape.synced, but the error is thrown in the console. Is that correct?

maloni-leonardo commented 5 months ago

So, from what you describe, the 52M table is properly replicated, there is no exception in the awaited shape.synced, but the error is thrown in the console. Is that correct?

Yes, the exception doesn't get thrown by shape.synced, but from the electric process itself

EDIT: On a second inspection, i've found that the exception gets thrown right after it tries to reconnect to the server

davidmartos96 commented 5 months ago

@maloni-leonardo We've added some logs in a temporary branch based on version 0.7.1+4 to the protobuf message decoding part, which might have something to do with the error you are having.

Just to better organize this, is the shape.synced issue related to the original issue when pressing the back button? If not, it would be better to open a separate issue for that.

In order to try with the new logs, you can use the following. Note that this is based on 0.7.1, so the Electric service needs to be version 0.11.x. If you are using the CLI, it will run that version automatically.

dependency_overrides:
  electricsql:
    git:
      url: https://github.com/SkillDevs/electric_dart
      ref: 3c053cedcc9cae5d31af0bb34f918355551007a6
      path: packages/electricsql

  electricsql_cli:
    git:
      url: https://github.com/SkillDevs/electric_dart
      ref: 3c053cedcc9cae5d31af0bb34f918355551007a6
      path: packages/electricsql_cli

  electricsql_flutter:
    git:
      url: https://github.com/SkillDevs/electric_dart
      ref: 3c053cedcc9cae5d31af0bb34f918355551007a6
      path: packages/electricsql_flutter

maloni-leonardo commented 4 months ago

Just to better organize this, is the shape.synced issue related to the original issue when pressing the back button? If not, it would be better to open a separate issue for that.

It is related to the disconnection problem, but the "trigger" event is not related to the original issue (back button press).

Here's the new log that show the issue using the dependencies overrides as requested:

I/flutter (22242): [Electric] DEBUG: 09:13:48.048 [rpc] send: #SatSubsReq{id: 84297961-aa2a-49b5-9b09-cd8fc3b17cc2, shapes: [{"1":"2f728f19-6f8c-46ab-bc2a-92d23a247ac2","2":{"1":[{"1":"big_table_example"}]}}]} 
I/flutter (22242): [Electric] DEBUG: 09:13:48.049 [proto] send: #SatRpcRequest{method: subscribe, requestId: 6} 
I/flutter (22242): 2024-06-20 09:13:48.109970 INCOMING PROTOBUF SIZE: 54 B
I/flutter (22242): DECODE MESSAGE elapsed: 0:00:00.000112
I/flutter (22242): [Electric] DEBUG: 09:13:48.110 [proto] recv: #SatRpcResponse{method: subscribe, requestId: 6} 
I/flutter (22242): [Electric] DEBUG: 09:13:48.111 [rpc] recv: #SatSubsResp{id: 84297961-aa2a-49b5-9b09-cd8fc3b17cc2} 
I/flutter (22242): 2024-06-20 09:14:03.016372 INCOMING PROTOBUF SIZE: 526 B
I/flutter (22242): DECODE MESSAGE elapsed: 0:00:00.000393

# Recieving table schema

I/flutter (22242): 2024-06-20 09:14:03.020 INCOMING PROTOBUF SIZE: 51 B
I/flutter (22242): DECODE MESSAGE elapsed: 0:00:00.000215
I/flutter (22242): [Electric] DEBUG: 09:14:03.022 [proto] recv: #SatSubsDataBegin{id: 84297961-aa2a-49b5-9b09-cd8fc3b17cc2, lsn: NTIwMDE4ODU5Mg==} 
I/flutter (22242): 2024-06-20 09:14:03.023546 INCOMING PROTOBUF SIZE: 39 B
I/flutter (22242): DECODE MESSAGE elapsed: 0:00:00.000074
I/flutter (22242): [Electric] DEBUG: 09:14:03.024 [proto] recv: #SatShapeDataBegin{id: 2f728f19-6f8c-46ab-bc2a-92d23a247ac2} 
I/flutter (22242): 2024-06-20 09:14:13.556215 INCOMING PROTOBUF SIZE: 45.82 MB
I/flutter (22242): DECODE MESSAGE elapsed: 0:00:02.199925

# Recieving table data

I/flutter (22242): 2024-06-20 09:14:22.630270 INCOMING PROTOBUF SIZE: 1 B
I/flutter (22242): DECODE MESSAGE elapsed: 0:00:00.000046
I/flutter (22242): [Electric] DEBUG: 09:14:22.630 [proto] recv: #SatShapeDataEnd{} 
I/flutter (22242): 2024-06-20 09:14:22.630809 INCOMING PROTOBUF SIZE: 1 B
I/flutter (22242): DECODE MESSAGE elapsed: 0:00:00.000018
I/flutter (22242): [Electric] DEBUG: 09:14:22.630 [proto] recv: #SatSubsDataEnd{} 
I/flutter (22242): 2024-06-20 09:14:28.236229 SOCKET CLOSE
I/flutter (22242): 2024-06-20 09:14:28.267026 CLOSE SOCKET AND REMOVE LISTENERS
I/flutter (22242): 2024-06-20 09:14:28.267494 SOCKET CLOSE
I/flutter (22242): [Electric] DEBUG: 09:14:39.227 notifying client of database changes. Changed tables: [big_table_example]. Origin: initial 
I/flutter (22242): [Electric] DEBUG: 09:14:39.227 notifying Drift of database changes: Changed tables: {big_table_example}. Origin: initial 
I/flutter (22242): [Electric] WARN:  09:14:39.231 an error occurred in satellite: socket closed 
I/flutter (22242): [Electric] WARN:  09:14:39.233 Client disconnected with a non fatal error, reconnecting 
I/flutter (22242): [Electric] INFO:  09:14:39.233 connecting to electric server 
I/flutter (22242): 2024-06-20 09:14:39.234917 WAITING SOCKET CHANNEL READY

# shape.synced is done

I/flutter (22242): 2024-06-20 09:14:39.237163 CLOSE SOCKET AND REMOVE LISTENERS
I/flutter (22242): 2024-06-20 09:14:39.237545 SOCKET CLOSE
I/flutter (22242): 2024-06-20 09:14:39.519751 SOCKET CHANNEL IS READY
E/flutter (22242): [ERROR:flutter/runtime/dart_isolate.cc(1291)] Unhandled exception:
E/flutter (22242): Null check operator used on a null value
E/flutter (22242): #0      WebSocketBase._asyncStart (package:electricsql/src/sockets/sockets.dart:135:37)
E/flutter (22242): <asynchronous suspension>

davidmartos96 commented 4 months ago

@maloni-leonardo Thank you, that's helpful!

Could you provide the server logs as well? We've included more logs related to when the disconnection happens in the client in the commit 173f372c63ee209ad78ad3f47bcc397d79113f76, which you can change in the dependency_overrides

From the logs I can see the following:

Because you are replicating a lot of rows, they all come in a single Protobuf message which is 45 MB of size, which is decoded in the main thread, adding UI lag while this happens, in your case for at least 2 seconds. Some ways this could be improved is splitting the message in smaller parts and/or using an isolate (separate thread) to decode large protobuf messages I believe the server is disconnecting you because of unanswered pings, possibly due to this main thread lag, but better be sure by seeing the server logs. Also note that version 0.12 of the server increased the websocket ping delay to 20 seconds from 5 seconds. It would be nice if you can also try client 0.8.x and server 0.12 to see if that helps, but for the sake of better debugging the client in this issue, better use server 0.11 with client 0.7.x Related: https://github.com/electric-sql/electric/issues/1372
After shape.synced is done, some piece of code is disconnecting the websocket at the same time it's being reconnected. That's why channel is null after .ready resolves. Because of this, it would be helpful to see the logs in the new commit to see who is calling disconnect. https://github.com/SkillDevs/electric_dart/issues/23#issuecomment-2150358677

maloni-leonardo commented 3 months ago

Sorry for the huge delay, here are the requested logs:

Client - using electric_dart v0.7.0 (with the dependency_overrides mentioned before)

I/flutter (29513): [INFO] ===== APPLICATION STARTED =====
I/flutter (29513): [INFO] === LOG SESSION STARTED ===
I/flutter (29513): 2024-07-23 09:21:34.592181 WAITING SOCKET CHANNEL READY
I/flutter (29513): 2024-07-23 09:21:34.732437 SOCKET CHANNEL IS READY
I/flutter (29513): 2024-07-23 09:21:34.767988 INCOMING PROTOBUF SIZE: 57 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000076
I/flutter (29513): 2024-07-23 09:21:34.785332 INCOMING PROTOBUF SIZE: 19 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000023
I/flutter (29513): 2024-07-23 09:21:34.812942 INCOMING PROTOBUF SIZE: 25 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000018
I/flutter (29513): 2024-07-23 09:21:34.873208 INCOMING PROTOBUF SIZE: 54 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000016
I/flutter (29513): 2024-07-23 09:21:35.679270 INCOMING PROTOBUF SIZE: 545 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000278
I/flutter (29513): 2024-07-23 09:21:35.679961 INCOMING PROTOBUF SIZE: 51 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000030
I/flutter (29513): 2024-07-23 09:21:35.680078 INCOMING PROTOBUF SIZE: 39 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000027
I/flutter (29513): 2024-07-23 09:21:36.046525 INCOMING PROTOBUF SIZE: 1.50 MB
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.112442
I/flutter (29513): 2024-07-23 09:21:36.159876 INCOMING PROTOBUF SIZE: 1 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000009
I/flutter (29513): 2024-07-23 09:21:36.159933 INCOMING PROTOBUF SIZE: 1 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000004

# First table data acquired

I/flutter (29513): 2024-07-23 09:21:36.731189 INCOMING PROTOBUF SIZE: 54 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000028
I/flutter (29513): 2024-07-23 09:21:36.746641 INCOMING PROTOBUF SIZE: 736 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000129
I/flutter (29513): 2024-07-23 09:21:36.746989 INCOMING PROTOBUF SIZE: 51 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000017
I/flutter (29513): 2024-07-23 09:21:36.747099 INCOMING PROTOBUF SIZE: 39 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000007
I/flutter (29513): 2024-07-23 09:21:36.747176 INCOMING PROTOBUF SIZE: 189 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000045
I/flutter (29513): 2024-07-23 09:21:36.747347 INCOMING PROTOBUF SIZE: 1 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000014
I/flutter (29513): 2024-07-23 09:21:36.747418 INCOMING PROTOBUF SIZE: 1 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000003

# 2nd table data acquired

I/flutter (29513): 2024-07-23 09:21:36.823609 INCOMING PROTOBUF SIZE: 54 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000067
I/flutter (29513): 2024-07-23 09:21:36.841440 INCOMING PROTOBUF SIZE: 737 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000145
I/flutter (29513): 2024-07-23 09:21:36.841804 INCOMING PROTOBUF SIZE: 51 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000011
I/flutter (29513): 2024-07-23 09:21:36.841904 INCOMING PROTOBUF SIZE: 39 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000013
I/flutter (29513): 2024-07-23 09:21:36.842001 INCOMING PROTOBUF SIZE: 223 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000046
I/flutter (29513): 2024-07-23 09:21:36.842098 INCOMING PROTOBUF SIZE: 1 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000005
I/flutter (29513): 2024-07-23 09:21:36.842149 INCOMING PROTOBUF SIZE: 1 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000003

# 3rd table data acquired

I/flutter (29513): 2024-07-23 09:21:36.911401 INCOMING PROTOBUF SIZE: 54 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000034
I/flutter (29513): 2024-07-23 09:21:52.063934 INCOMING PROTOBUF SIZE: 526 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000127
I/flutter (29513): 2024-07-23 09:21:52.064445 INCOMING PROTOBUF SIZE: 51 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000009
I/flutter (29513): 2024-07-23 09:21:52.064518 INCOMING PROTOBUF SIZE: 39 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000012
I/flutter (29513): 2024-07-23 09:21:56.505775 INCOMING PROTOBUF SIZE: 45.82 MB
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:01.907628
I/flutter (29513): 2024-07-23 09:21:58.438311 INCOMING PROTOBUF SIZE: 1 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000010
I/flutter (29513): 2024-07-23 09:21:58.438424 INCOMING PROTOBUF SIZE: 1 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000002
I/flutter (29513): 2024-07-23 09:22:03.273427 SOCKET CLOSE
I/flutter (29513): 2024-07-23 09:22:03.273674 CLOSE SOCKET AND REMOVE LISTENERS
I/flutter (29513): 2024-07-23 09:22:03.273694 SOCKET CLOSE
I/flutter (29513): [Electric] WARN:  09:22:12.550 an error occurred in satellite: socket closed 
I/flutter (29513): [Electric] WARN:  09:22:12.550 Client disconnected with a non fatal error, reconnecting 
I/flutter (29513): 2024-07-23 09:22:12.551032 WAITING SOCKET CHANNEL READY

# 4th table data acquired, sync end notified to user

I/flutter (29513): 2024-07-23 09:22:12.551203 CLOSE SOCKET AND REMOVE LISTENERS
I/flutter (29513): 2024-07-23 09:22:12.551217 SOCKET CLOSE

# Manual in-app electric restart here

I/flutter (29513): [INFO] === LOG SESSION STARTED ===
I/flutter (29513): 2024-07-23 09:22:12.585395 WAITING SOCKET CHANNEL READY
I/flutter (29513): 2024-07-23 09:22:12.634741 SOCKET CHANNEL IS READY
E/flutter (29513): [ERROR:flutter/runtime/dart_isolate.cc(1291)] Unhandled exception:
E/flutter (29513): Null check operator used on a null value
E/flutter (29513): #0      WebSocketBase._asyncStart (package:electricsql/src/sockets/sockets.dart:135)
E/flutter (29513): <asynchronous suspension>
I/flutter (29513): 2024-07-23 09:22:12.655845 SOCKET CHANNEL IS READY
I/flutter (29513): 2024-07-23 09:22:12.754144 INCOMING PROTOBUF SIZE: 57 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000045
I/flutter (29513): 2024-07-23 09:22:12.754358 INCOMING PROTOBUF SIZE: 19 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000010
I/flutter (29513): 2024-07-23 09:22:14.794890 INCOMING PROTOBUF SIZE: 25 B
I/flutter (29513): DECODE MESSAGE elapsed: 0:00:00.000117

# Load table data, already synced, notify user

I/flutter (29513): 2024-07-23 09:22:21.780504 SOCKET CLOSE
I/flutter (29513): 2024-07-23 09:22:21.780908 CLOSE SOCKET AND REMOVE LISTENERS
I/flutter (29513): 2024-07-23 09:22:21.780962 SOCKET CLOSE
I/flutter (29513): [Electric] WARN:  09:22:21.781 an error occurred in satellite: socket closed 
I/flutter (29513): [INFO][electric > connectivityStateChangesNotifier] Current connectivity status is ConnectivityStatus.disconnected (reason: Satellite Exception (SatelliteErrorCode.socketError) socket closed)
I/flutter (29513): [Electric] WARN:  09:22:21.781 Client disconnected with a non fatal error, reconnecting 
I/flutter (29513): 2024-07-23 09:22:21.781891 WAITING SOCKET CHANNEL READY
I/flutter (29513): 2024-07-23 09:22:21.818714 NOTIFY ERROR AND CLOSE SOCKET failed to stablish a socket connection SatelliteErrorCode.socketError
I/flutter (29513): 2024-07-23 09:22:21.818888 CLOSE SOCKET AND REMOVE LISTENERS
I/flutter (29513): 2024-07-23 09:22:21.818928 SOCKET CLOSE
I/flutter (29513): 2024-07-23 09:22:21.818956 SOCKET CLOSE
I/flutter (29513): 2024-07-23 09:22:24.031885 WAITING SOCKET CHANNEL READY
I/flutter (29513): 2024-07-23 09:22:24.083198 NOTIFY ERROR AND CLOSE SOCKET failed to stablish a socket connection SatelliteErrorCode.socketError
I/flutter (29513): 2024-07-23 09:22:24.083370 CLOSE SOCKET AND REMOVE LISTENERS
I/flutter (29513): 2024-07-23 09:22:24.083413 SOCKET CLOSE
I/flutter (29513): 2024-07-23 09:22:24.083442 SOCKET CLOSE
I/flutter (29513): [INFO][ERROR] electric: Unexpected service closure detected! Restarting service now...
I/flutter (29513): 2024-07-23 09:22:27.956542 WAITING SOCKET CHANNEL READY
I/flutter (29513): 2024-07-23 09:22:28.007474 NOTIFY ERROR AND CLOSE SOCKET failed to stablish a socket connection SatelliteErrorCode.socketError

# Closing app

I/flutter (29513): 2024-07-23 09:22:28.007626 CLOSE SOCKET AND REMOVE LISTENERS
I/flutter (29513): 2024-07-23 09:22:28.007663 SOCKET CLOSE
I/flutter (29513): 2024-07-23 09:22:28.007691 SOCKET CLOSE
Application finished.

Exited (-1).

Server - using Docker image v0.11.0

electric-1  | 07:32:09.469 pid=<0.3059.0> [info] Starting ElectricSQL 0.11.0 in logical_replication mode.
electric-1  | 07:32:09.476 pid=<0.3060.0> [info] Running Electric.Plug.Router with Bandit 1.1.3 at :::5133 (http)
electric-1  | 07:32:09.478 pid=<0.3678.0> origin=postgres_1 [info] Postgres.Client.with_conn(%{database: ~c"electric_test", host: ~c"192.168.112.26", ip_addr: ~c"192.168.112.26", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5432, ssl: true, ssl_opts: [server_name_indication: ~c"192.168.112.26"], timeout: 5000, username: ~c"postgres"})
electric-1  | 07:32:09.527 pid=<0.3678.0> origin=postgres_1 [info] Successfully initialized origin postgres_1 at extension version
electric-1  | 07:32:09.527 pid=<0.3683.0> [info] Starting Proxy server listening on port 65432
electric-1  | 07:32:17.734 pid=<0.3712.0> pg_producer=postgres_1 [info] Starting Elixir.Electric.Postgres.Extension.SchemaCache for postgres_1
electric-1  | 07:32:17.735 pid=<0.3712.0> pg_producer=postgres_1 [warning] SchemaCache "postgres_1" registered as the global instance
electric-1  | 07:32:17.735 pid=<0.3715.0> pg_producer=postgres_1 [info] Starting replication with publication=electric_publication and slots=electric_replication_out_electric_test,electric_replication_out_electric_test_rc}
electric-1  | 07:32:17.825 pid=<0.3719.0> pg_producer=postgres_1 [info] Starting Elixir.Electric.Replication.Postgres.MigrationConsumer using Elixir.Electric.Postgres.Extension.SchemaCache backend
electric-1  | 07:32:17.832 pid=<0.3678.0> origin=postgres_1 [info] Successfully initialized Postgres connector "postgres_1".
electric-1  | 07:32:17.832 pid=<0.3678.0> origin=postgres_1 [info] Postgres.Client.with_conn(%{database: ~c"electric_test", host: ~c"192.168.112.26", ip_addr: ~c"192.168.112.26", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5432, ssl: true, ssl_opts: [server_name_indication: ~c"192.168.112.26"], timeout: 5000, username: ~c"postgres"})
electric-1  | 07:32:17.869 pid=<0.3712.0> pg_producer=postgres_1 [info] CREATE TABLE acknowledged_client_lsns (...)
electric-1  | 07:32:17.877 pid=<0.3678.0> origin=postgres_1 [notice] subscription started for postgres_1
electric-1  | 07:32:22.866 pid=<0.3720.0> origin=postgres_1 pg_slot=postgres_1 [info] Starting replication to postgres_1
electric-1  | 07:33:09.415 pid=<0.2848.0> [notice]     :alarm_handler: {:set, {:process_memory_high_watermark, #PID<0.3697.0>}}
electric-1  | 07:33:12.472 pid=<0.4039.0> [info] GET /ws
electric-1  | 07:33:12.473 pid=<0.4039.0> instance_id=ea3cae36-d067-4655-81c0-265ad0dc5f20 [info] Sent 101 in 785µs
electric-1  | 07:33:12.667 pid=<0.4039.0> client_id=d65f5dad-5397-4978-8f4a-e9a01024b4cf instance_id=ea3cae36-d067-4655-81c0-265ad0dc5f20 user_id=1234567890 [info] Successfully authenticated the client
electric-1  | 07:33:12.667 pid=<0.4039.0> client_id=d65f5dad-5397-4978-8f4a-e9a01024b4cf instance_id=ea3cae36-d067-4655-81c0-265ad0dc5f20 user_id=1234567890 [info] Postgres.Client.with_conn(%{database: ~c"electric_test", host: ~c"192.168.112.26", ip_addr: ~c"192.168.112.26", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5432, ssl: true, ssl_opts: [server_name_indication: ~c"192.168.112.26"], timeout: 5000, username: ~c"postgres"})
electric-1  | 07:33:12.886 pid=<0.4044.0> [info] Postgres.Client.with_conn(%{database: ~c"electric_test", host: ~c"192.168.112.26", ip_addr: ~c"192.168.112.26", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5432, ssl: true, ssl_opts: [server_name_indication: ~c"192.168.112.26"], timeout: 5000, username: ~c"postgres"})
electric-1  | 07:33:12.909 pid=<0.4046.0> [info] Postgres.Client.with_conn(%{database: ~c"electric_test", host: ~c"192.168.112.26", ip_addr: ~c"192.168.112.26", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5432, ssl: true, ssl_opts: [server_name_indication: ~c"192.168.112.26"], timeout: 5000, username: ~c"postgres"})
electric-1  | 07:33:15.519 pid=<0.4049.0> [info] Postgres.Client.with_conn(%{database: ~c"electric_test", host: ~c"192.168.112.26", ip_addr: ~c"192.168.112.26", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5432, ssl: true, ssl_opts: [server_name_indication: ~c"192.168.112.26"], timeout: 5000, username: ~c"postgres"})
electric-1  | 07:33:15.536 pid=<0.4051.0> [info] Postgres.Client.with_conn(%{database: ~c"electric_test", host: ~c"192.168.112.26", ip_addr: ~c"192.168.112.26", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5432, ssl: true, ssl_opts: [server_name_indication: ~c"192.168.112.26"], timeout: 5000, username: ~c"postgres"})
electric-1  | 07:33:15.666 pid=<0.4053.0> [info] Postgres.Client.with_conn(%{database: ~c"electric_test", host: ~c"192.168.112.26", ip_addr: ~c"192.168.112.26", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5432, ssl: true, ssl_opts: [server_name_indication: ~c"192.168.112.26"], timeout: 5000, username: ~c"postgres"})
electric-1  | 07:33:15.683 pid=<0.4055.0> [info] Postgres.Client.with_conn(%{database: ~c"electric_test", host: ~c"192.168.112.26", ip_addr: ~c"192.168.112.26", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5432, ssl: true, ssl_opts: [server_name_indication: ~c"192.168.112.26"], timeout: 5000, username: ~c"postgres"})
electric-1  | 07:33:15.858 pid=<0.4057.0> [info] Postgres.Client.with_conn(%{database: ~c"electric_test", host: ~c"192.168.112.26", ip_addr: ~c"192.168.112.26", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5432, ssl: true, ssl_opts: [server_name_indication: ~c"192.168.112.26"], timeout: 5000, username: ~c"postgres"})
electric-1  | 07:33:15.875 pid=<0.4059.0> [info] Postgres.Client.with_conn(%{database: ~c"electric_test", host: ~c"192.168.112.26", ip_addr: ~c"192.168.112.26", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5432, ssl: true, ssl_opts: [server_name_indication: ~c"192.168.112.26"], timeout: 5000, username: ~c"postgres"})
electric-1  | 07:34:05.724 pid=<0.4071.0> [info] GET /ws
electric-1  | 07:34:05.724 pid=<0.4071.0> instance_id=ea3cae36-d067-4655-81c0-265ad0dc5f20 [info] Sent 101 in 212µs
electric-1  | 07:34:05.758 pid=<0.4072.0> [info] GET /ws
electric-1  | 07:34:05.758 pid=<0.4072.0> instance_id=ea3cae36-d067-4655-81c0-265ad0dc5f20 [info] Sent 101 in 124µs
electric-1  | 07:34:05.796 pid=<0.4072.0> client_id=d65f5dad-5397-4978-8f4a-e9a01024b4cf instance_id=ea3cae36-d067-4655-81c0-265ad0dc5f20 user_id=1234567890 [info] Successfully authenticated the client
electric-1  | 07:34:05.796 pid=<0.4072.0> client_id=d65f5dad-5397-4978-8f4a-e9a01024b4cf instance_id=ea3cae36-d067-4655-81c0-265ad0dc5f20 user_id=1234567890 [info] Postgres.Client.with_conn(%{database: ~c"electric_test", host: ~c"192.168.112.26", ip_addr: ~c"192.168.112.26", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5432, ssl: true, ssl_opts: [server_name_indication: ~c"192.168.112.26"], timeout: 5000, username: ~c"postgres"})
electric-1  | 07:34:15.726 pid=<0.4071.0> instance_id=ea3cae36-d067-4655-81c0-265ad0dc5f20 [info] Client is not responding to ping, disconnecting

Later today i'll send the newer ones using the latest versions of the respective client and server services.

UPDATE: It seems that using the latest v0.8.1 client and electric server v0.12.0 does indeed solve the issue.

SkillDevs / electric_dart

Error connecting to Electric: errorType: INVALID_REQUEST when pressing back button on main screen and reopening the app #23

Client - using electric_dart v0.7.0 (with the dependency_overrides mentioned before)

Server - using Docker image v0.11.0