-
Notifications
You must be signed in to change notification settings - Fork 21
Description
Currently, the itest workflow for CI often errors with the following error:
Error: Received unexpected error: predicate not satisfied after time out
This usually has the following trace:
Error Trace:
/home/runner/work/lightning-node-connect/lightning-node-connect/itest/connection_test.go:178
/home/runner/work/lightning-node-connect/lightning-node-connect/itest/connection_test.go:116
/home/runner/work/lightning-node-connect/lightning-node-connect/itest/test_harness.go:144
/home/runner/work/lightning-node-connect/lightning-node-connect/itest/integration_test.go:43
This always ahppen for the same test, but not always with the same configuration. The test that fails is:
test_server_reconnect. Importantly, the error appears to only happen at random times, and doesn't always fail.
We have cases in the workflow history where the test has failed with all variants of the configurations:
(stagingMailbox:true,grpcClientConn:false)
(stagingMailbox:false,grpcClientConn:false)
(stagingMailbox:true,grpcClientConn:true)
Here is the log for 2 of the fails:
Case 1:
2023-11-13 17:56:33.632 [TRC] GOBN: Got expected data 7
2023-11-13 17:56:33.632 [TRC] GOBN: Got expected data 10
2023-11-13 17:56:33.632 [TRC] GOBN: Got expected data 11
2023-11-13 17:56:33.632 [TRC] GOBN: Received correct ack 7
2023-11-13 17:56:33.632 [TRC] GOBN: Got expected data 8
2023-11-13 17:56:33.632 [DBG] MBOX: conn being closed
2023-11-13 17:56:33.633 [DBG] MBOX: Server connection is closing
2023-11-13 17:56:33.633 [DBG] GOBN: Closing GoBackNConn, isServer=true
2023-11-13 17:56:33.633 [TRC] GOBN: Try sending FIN, isServer=true
2023-11-13 17:56:33.632 [TRC] GOBN: Sending data 12
2023-11-13 17:56:33.633 [DBG] APER: SendStream: Context done, exiting
2023-11-13 17:56:33.633 [DBG] GOBN: sendPacketsForever stopped (isServer=true)
2023-11-13 17:56:33.633 [TRC] GOBN: Received correct ack 8
2023-11-13 17:56:33.633 [DBG] APER: Got error an read stream read: context canceled
2023-11-13 17:56:33.633 [DBG] APER: Returning read stream
2023-11-13 17:56:33.633 [TRC] GOBN: Sending data 13
2023-11-13 17:56:33.633 [DBG] GOBN: receivePacketsForever stopped (isServer=true)
2023-11-13 17:56:33.633 [DBG] GOBN: GBN is closed, isServer=true
2023-11-13 17:56:33.633 [DBG] MBOX: closing receive stream
2023-11-13 17:56:33.633 [DBG] MBOX: closing send stream
2023-11-13 17:56:33.633 [DBG] MBOX: Server connection closed
2023-11-13 17:56:33.633 [TRC] GOBN: Received correct ack 10
2023-11-13 17:56:33.633 [TRC] GOBN: Received correct ack 11
2023-11-13 17:56:33.633 [TRC] GOBN: Received a FIN packet (isServer=false)
2023-11-13 17:56:33.633 [DBG] GOBN: Error in receivePacketsForever (isServer=false): gbn transport is closing
2023-11-13 17:56:33.633 [DBG] GOBN: receivePacketsForever stopped (isServer=false)
2023-11-13 17:56:33.633 [DBG] GOBN: Closing GoBackNConn, isServer=false
2023-11-13 17:56:33.633 [DBG] MBOX: Closing client connection
2023-11-13 17:56:33.633 [DBG] GOBN: sendPacketsForever stopped (isServer=false)
2023-11-13 17:56:33.633 [DBG] GOBN: GBN is closed, isServer=false
2023-11-13 17:56:33.633 [DBG] MBOX: closing receive stream/socket
2023-11-13 17:56:33.633 [DBG] APER: New HashMail stream deletion:
2023-11-13 17:56:33.633 [DBG] APER: Tearing down HashMail stream:
2023-11-13 17:56:33.633 [INF] APER: WS: incoming payload chan closed
2023-11-13 17:56:33.633 [DBG] MBOX: closing send stream/socket
2023-11-13 17:56:33.634 [DBG] APER: Got error an read stream read: context canceled
2023-11-13 17:56:33.634 [DBG] APER: Returning read stream
2023-11-13 17:56:33.634 [INF] APER: WS: incoming payload chan closed
2023-11-13 17:56:33.634 [DBG] APER: SendStream: Exiting write stream RPC stream read: rpc error: code = Canceled desc = context canceled
2023-11-13 17:56:33.634 [DBG] APER: New HashMail stream deletion:
2023-11-13 17:56:33.634 [DBG] APER: Tearing down HashMail stream:
Case 2:
2023-11-15 09:08:06.702 [TRC] GOBN: Received correct ack 8
2023-11-15 09:08:06.702 [TRC] GOBN: Received correct ack 9
2023-11-15 09:08:06.702 [TRC] GOBN: Got expected data 5
2023-11-15 09:08:06.703 [TRC] GOBN: Got expected data 6
2023-11-15 09:08:06.703 [DBG] MBOX: conn being closed
2023-11-15 09:08:06.703 [DBG] MBOX: Server connection is closing
2023-11-15 09:08:06.703 [DBG] GOBN: Closing GoBackNConn, isServer=true
2023-11-15 09:08:06.704 [TRC] GOBN: Try sending FIN, isServer=true
2023-11-15 09:08:06.704 [DBG] GOBN: sendPacketsForever stopped (isServer=true)
2023-11-15 09:08:06.703 [TRC] GOBN: Sending data 10
2023-11-15 09:08:06.704 [TRC] GOBN: Sending data 11
2023-11-15 09:08:06.704 [DBG] MBOX: Server: got failure on receive socket, re-trying: rpc error: code = Canceled desc = context canceled
2023-11-15 09:08:06.704 [DBG] GOBN: Error in receivePacketsForever (isServer=true): error receiving from recvFromStream: context canceled
2023-11-15 09:08:06.704 [DBG] GOBN: receivePacketsForever stopped (isServer=true)
2023-11-15 09:08:06.704 [DBG] GOBN: GBN is closed, isServer=true
2023-11-15 09:08:06.704 [DBG] MBOX: closing receive stream
2023-11-15 09:08:06.704 [DBG] MBOX: closing send stream
2023-11-15 09:08:06.704 [DBG] MBOX: Server connection closed
2023-11-15 09:08:06.789 [TRC] GOBN: Received a FIN packet (isServer=false)
2023-11-15 09:08:06.790 [DBG] GOBN: Error in receivePacketsForever (isServer=false): gbn transport is closing
2023-11-15 09:08:06.790 [DBG] GOBN: receivePacketsForever stopped (isServer=false)
2023-11-15 09:08:06.790 [DBG] GOBN: Closing GoBackNConn, isServer=false
2023-11-15 09:08:06.790 [DBG] GOBN: sendPacketsForever stopped (isServer=false)
2023-11-15 09:08:06.790 [DBG] GOBN: GBN is closed, isServer=false
2023-11-15 09:08:06.790 [DBG] MBOX: Closing client connection
2023-11-15 09:08:06.790 [DBG] MBOX: closing receive stream/socket
2023-11-15 09:08:06.873 [DBG] MBOX: closing send stream/socket
2023-11-15 09:08:06.873 [ERR] MBOX: Error closing send stream/socket: failed to close WebSocket: failed to read frame header: EOF