Failing test_network_disconnect_small_buffer

[mkaruza]

https://github.com/dragonflydb/dragonfly/actions/runs/18985144411/job/54227009206

>       assert len(lines) > 0
E       assert 0 > 0
E        +  where 0 = len([])

[abhijat]

The problem with this test might be that the connection drop happens while the second attempt is starting, when we expect to find the LSN out of the journal, but the connection drop causes the replica to not send the LSN and start from scratch, so the partial sync error is never reached:

I20251031 21:41:15.946337 26127 replica.cc:838] Sending on flow 87a88b773627f6aa9669de9d9d883b1cc0eb67a8 SYNC2 0 lsn: 1482
I20251031 21:41:15.946339 26129 replica.cc:838] Sending on flow 87a88b773627f6aa9669de9d9d883b1cc0eb67a8 SYNC2 2 lsn: 1335
I20251031 21:41:15.946503 26128 replica.cc:838] Sending on flow 87a88b773627f6aa9669de9d9d883b1cc0eb67a8 SYNC2 1 lsn: 1351
I20251031 21:41:15.951839 26134 main_service.cc:2943] OnConnectionClose: repl_ctrl_2, repl_session_id: 2
I20251031 21:41:15.951862 26134 dflycmd.cc:779] Stopping replication for sync_id: 2
I20251031 21:41:15.951879 26134 dflycmd.cc:117] Disconnecting from replica 127.0.0.1:44391
W20251031 21:41:15.951894 26134 common.cc:341] ReportError: Operation canceled: ExecutionState cancelled
I20251031 21:41:15.951939 26134 dflycmd.cc:739] Replication error: Operation canceled: ExecutionState cancelled
I20251031 21:41:15.952033 26134 dflycmd.cc:779] Stopping replication for sync_id: 2
I20251031 21:41:15.954558 26134 dflycmd.cc:135] Disconnecting replica 127.0.0.1:44391
I20251031 21:41:15.957381 26135 dflycmd.cc:255] Got DFLY FLOW master_id: 87a88b773627f6aa9669de9d9d883b1cc0eb67a8 sync_id: SYNC2 flow: 0 seq: 1482
W20251031 21:41:15.957476 26135 main_service.cc:1670]  DFLY FLOW 87a88b773627f6aa9669de9d9d883b1cc0eb67a8 SYNC2 0 1482 failed with reason: syncid not found
I20251031 21:41:15.957944 26132 dflycmd.cc:255] Got DFLY FLOW master_id: 87a88b773627f6aa9669de9d9d883b1cc0eb67a8 sync_id: SYNC2 flow: 2 seq: 1335
E20251031 21:41:15.958788 26129 replica.cc:864] Bad response to "": "-ERR syncid not found\r\n"
W20251031 21:41:15.958999 26129 common.cc:341] ReportError: Bad message
E20251031 21:41:15.959990 26127 replica.cc:864] Bad response to "": "-ERR syncid not found\r\n"
I20251031 21:41:15.961468 26133 dflycmd.cc:255] Got DFLY FLOW master_id: 87a88b773627f6aa9669de9d9d883b1cc0eb67a8 sync_id: SYNC2 flow: 1 seq: 1351
E20251031 21:41:15.961911 26128 replica.cc:864] Bad response to "": "-ERR syncid not found\r\n"
E20251031 21:41:15.963243 26127 replica.cc:626] Error while calling exec_st_.GetError(): Bad message
W20251031 21:41:15.963284 26127 replica.cc:271] Error syncing with localhost:1113 (phase: INITIAL_SYNC): generic:74 Bad message, socket state: State: CLOSE_WAIT, Local: 127.0.0.1:38698, Remote: 127.0.0.1:1113, Inode: 405054
I20251031 21:41:16.006875 26127 engine_shard.cc:372] This heartbeat step took 55ms
W20251031 21:41:15.964910 26129 protocol_client.cc:239] Socket error: Bad message in localhost:1113, socket info: State: CLOSE_WAIT, Local: 127.0.0.1:38698, Remote: 127.0.0.1:1113, Inode: 405054
I20251031 21:41:16.008492 26129 engine_shard.cc:372] This heartbeat step took 54ms
I20251031 21:41:16.515199 26127 protocol_client.cc:147] Resolved endpoint localhost:1113 to 127.0.0.1:1113
I20251031 21:41:16.515367 26127 replica.cc:242] Replica socket connected
I20251031 21:41:16.515398 26127 replica.cc:308] greeting message handling
I20251031 21:41:16.518412 26134 dflycmd.cc:749] Registered replica 127.0.0.1:44391
I20251031 21:41:16.519038 26127 replica.cc:388] Master id: 87a88b773627f6aa9669de9d9d883b1cc0eb67a8, sync id: SYNC3, num journals: 3, version: 4
I20251031 21:41:16.519819 26134 dflycmd.cc:941] Client version for session_id=3 is 4
I20251031 21:41:16.520576 26127 replica.cc:838] Sending on flow 87a88b773627f6aa9669de9d9d883b1cc0eb67a8 SYNC3 0 lsn: 18446744073709551615
I20251031 21:41:16.520581 26128 replica.cc:838] Sending on flow 87a88b773627f6aa9669de9d9d883b1cc0eb67a8 SYNC3 1 lsn: 18446744073709551615
I20251031 21:41:16.520586 26129 replica.cc:838] Sending on flow 87a88b773627f6aa9669de9d9d883b1cc0eb67a8 SYNC3 2 lsn: 18446744073709551615
I20251031 21:41:16.523973 26135 dflycmd.cc:255] Got DFLY FLOW master_id: 87a88b773627f6aa9669de9d9d883b1cc0eb67a8 sync_id: SYNC3 flow: 0 seq: 18446744073709551615
I20251031 21:41:16.524143 26132 dflycmd.cc:255] Got DFLY FLOW master_id: 87a88b773627f6aa9669de9d9d883b1cc0eb67a8 sync_id: SYNC3 flow: 2 seq: 18446744073709551615
I20251031 21:41:16.524212 26133 dflycmd.cc:255] Got DFLY FLOW master_id: 87a88b773627f6aa9669de9d9d883b1cc0eb67a8 sync_id: SYNC3 flow: 1 seq: 18446744073709551615

Note above when connecting with sync id 2, soon after registering the replica, there is a disconnection:

I20251031 21:41:15.951862 26134 dflycmd.cc:779] Stopping replication for sync_id: 2

and master erases sync id 2 from its map. So the attempt to check for the LSN is never reached, the next attempt is sync3 which has an unset LSN.

[abhijat]

Maybe the body of the test should be repeated for a timeout until the error is seen, as it is the test can randomly fail depending on when the connection is dropped.