Expected PASS Test failure: investigation

[MathieuBordere]

run: https://github.com/canonical/jepsen.dqlite/actions/runs/4922511326/jobs/8793367884
artifact: https://github.com/canonical/jepsen.dqlite/suites/12764379008/artifacts/686343848
error: on node n4 2023/05/09 05:09:17.489030 create schema: call exec-sql (budget 0s): receive: header: EOF looks like the node is hitting:

jepsen.dqlite/resources/app.go

Line 666 in 5840c71

log.Fatalf("create schema: %v", err)

the app.log on node n4 stops after hitting that issue. The jepsen suite reports cluster is not healthy, I suspect these 2 things are related.

[MathieuBordere]

n4 receives AppendEntriesRPCs from n3 but rejects them

LIBRAFT   1683608955270278903 src/replication.c:960 no entry at index 4583 -> reject
LIBRAFT   1683608955270284303 src/uv_send.c:213 no connection available -> enqueue message
LIBRAFT   1683608955270292704 src/recv_append_entries.c:36 self:12257605249982645204 from:12374568281597593130@10.2.1.13:8081 leader_commit:4583 n_entries:0 prev_log_index:4583 prev_log_term:17, term:17  
LIBRAFT   1683608955270295904 src/replication.c:960 no entry at index 4583 -> reject
LIBRAFT   1683608955270298804 src/uv_send.c:213 no connection available -> enqueue message
LIBRAFT   1683608955270304305 src/recv_append_entries.c:36 self:12257605249982645204 from:12374568281597593130@10.2.1.13:8081 leader_commit:4583 n_entries:0 prev_log_index:4583 prev_log_term:17, term:17
LIBRAFT   1683608955270307205 src/replication.c:960 no entry at index 4583 -> reject
LIBRAFT   1683608955270310105 src/uv_send.c:213 no connection available -> enqueue message
LIBRAFT   1683608955270315506 src/recv_append_entries.c:36 self:12257605249982645204 from:12374568281597593130@10.2.1.13:8081 leader_commit:4583 n_entries:0 prev_log_index:4583 prev_log_term:17, term:17
LIBRAFT   1683608955270318206 src/replication.c:960 no entry at index 4583 -> reject
LIBRAFT   1683608955270321106 src/uv_send.c:213 no connection available -> enqueue message
LIBRAFT   1683608955270326607 src/recv_append_entries.c:36 self:12257605249982645204 from:12374568281597593130@10.2.1.13:8081 leader_commit:4583 n_entries:0 prev_log_index:4583 prev_log_term:17, term:17
LIBRAFT   1683608955270329307 src/replication.c:960 no entry at index 4583 -> reject
LIBRAFT   1683608955270332107 src/uv_send.c:213 no connection available -> enqueue message
LIBRAFT   1683608955273198751 src/recv_append_entries.c:36 self:12257605249982645204 from:12374568281597593130@10.2.1.13:8081 leader_commit:4583 n_entries:0 prev_log_index:4583 prev_log_term:17, term:17
LIBRAFT   1683608955273208952 src/replication.c:960 no entry at index 4583 -> reject
LIBRAFT   1683608955273213053 src/uv_send.c:213 no connection available -> enqueue message 

and n3 does nothing with the rejection

LIBRAFT   1683608955614349839 src/recv_append_entries_result.c:24 self:12374568281597593130 from:12257605249982645204@10.2.1.14:8081 last_log_index:4578 rejected:4583 term:17
LIBRAFT   1683608955614365540 src/progress.c:238 rejected index 4583 different from next index 1 -> ignore                                                                                    
LIBRAFT   1683608955614371441 src/recv_append_entries_result.c:24 self:12374568281597593130 from:12257605249982645204@10.2.1.14:8081 last_log_index:4578 rejected:4583 term:17                
LIBRAFT   1683608955614374141 src/progress.c:238 rejected index 4583 different from next index 1 -> ignore 
LIBRAFT   1683608955614379241 src/recv_append_entries_result.c:24 self:12374568281597593130 from:12257605249982645204@10.2.1.14:8081 last_log_index:4578 rejected:4583 term:17                
LIBRAFT   1683608955614381842 src/progress.c:238 rejected index 4583 different from next index 1 -> ignore 
LIBRAFT   1683608955614386942 src/recv_append_entries_result.c:24 self:12374568281597593130 from:12257605249982645204@10.2.1.14:8081 last_log_index:4578 rejected:4583 term:17
LIBRAFT   1683608955614389542 src/progress.c:238 rejected index 4583 different from next index 1 -> ignore                                                                                    
LIBRAFT   1683608955614394643 src/recv_append_entries_result.c:24 self:12374568281597593130 from:12257605249982645204@10.2.1.14:8081 last_log_index:4578 rejected:4583 term:17                
LIBRAFT   1683608955614397243 src/progress.c:238 rejected index 4583 different from next index 1 -> ignore 
LIBRAFT   1683608955614402143 src/recv_append_entries_result.c:24 self:12374568281597593130 from:12257605249982645204@10.2.1.14:8081 last_log_index:4578 rejected:4583 term:17                
LIBRAFT   1683608955614404744 src/progress.c:238 rejected index 4583 different from next index 1 -> ignore 
LIBRAFT   1683608955614409944 src/recv_append_entries_result.c:24 self:12374568281597593130 from:12257605249982645204@10.2.1.14:8081 last_log_index:4578 rejected:4584 term:17
LIBRAFT   1683608955614412544 src/progress.c:238 rejected index 4584 different from next index 1 -> ignore     

Need to check if timestamps line up above, this is more a bit of a stream of consciousness...

edit: This doesn't seem relevant.

[MathieuBordere]

Could be same issue as canonical/go-dqlite#182

[cole-miller]

Is this closed by canonical/go-dqlite#186?

[MathieuBordere]

Is this closed by canonical/go-dqlite#186?

should be