Specific Matrix->Signal Messages Time Out

[TheBlueMatt]

Upgraded maybe a week ago to the go-based bridge, and today some of the M->S messages are timing out sending after 5m, but then a new message queued up immediately behind it with identical content goes through instantly. While it could be a networking issue, signal-desktop and signal-mobile from the same network are connected fine and the bridge seems to have a fine connection to signal, at least judging by the fact that the second message goes through instantly after the WS disconnects.

First the message is received from Matrix:

Apr 22 01:25:19 signal-puppet mautrix-signal[7296]: 2024-04-22T01:25:19Z DBG Sending event to Signal action="send signal message" chat_id=... event_id=... event_type=m.room.message portal_chat_id=... room_id=...
Apr 22 01:25:19 signal-puppet mautrix-signal[7296]: 2024-04-22T01:25:19Z DBG Sending event to Signal action="send signal message" chat_id=65c27... event_id=$Wgja... event_type=m.room.message portal_chat_id=65c27... room_id=...

... the bridge responds with the usual matrix handling, then after a while the message fails to send:

Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z INF readLoop exited action="start receive loops" loop=signal_websocket_connect_loop user_id=... websocket_type=unauthed
Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z INF received loopCtx done action="start receive loops" loop=signal_websocket_connect_loop user_id=... websocket_type=unauthed
Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z ERR loopCtx error error="error in readLoop: error reading message: failed to read protobuf message: failed to get reader: failed to read frame header: EOF" action="start receive loops" loop=signal_websocket_connect_loop user_id=... websocket_type=unauthed
Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z INF writeLoop exited action="start receive loops" loop=signal_websocket_connect_loop user_id=... websocket_type=unauthed
Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z INF Read or write loop exited action="start receive loops" loop=signal_websocket_connect_loop user_id=... websocket_type=unauthed
Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z INF Unauthed websocket disconnected action="start receive loops" user_id=...
Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z DBG Finished websocket cleanup action="start receive loops" loop=signal_websocket_connect_loop user_id=... websocket_type=unauthed
Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z INF Sending connection status action="start receive loops" status_to_send={"Err":null,"Event":2} user_id=...
Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z DBG Received SignalConnectionEventDisconnected user_id=...
Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z WRN Received nil response, retrying recursively action="send content" chat_id=... event_id=$Wgja... event_type=m.room.message portal_chat_id=65c27... recipient=65c27... retry_count=0 room_id=... timestamp=1713749119359
Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z INF Waiting for read or write loop to exit action="start receive loops" loop=signal_websocket_connect_loop user_id=... websocket_type=unauthed
Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z INF Unauthed websocket connected action="start receive loops" current_status={"Err":null,"Event":1} last_auth_status={"Err":null,"Event":1} last_unauth_status={"Err":null,"Event":1} user_id=...
Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z INF writeLoop exited action="start receive loops" loop=signal_websocket_connect_loop user_id=... websocket_type=unauthed
Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z INF Sending connection status action="start receive loops" status_to_send={"Err":null,"Event":1} user_id=...
Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z DBG Using peeked connectionStatus event peeked_connection_status_event=SignalConnectionEventConnected user_id=...
Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z DBG Sending Connected BridgeState user_id=...
Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z INF received loopCtx done action="start receive loops" loop=signal_websocket_connect_loop user_id=...websocket_type=unauthed
Apr 22 01:30:59 signal-puppet mautrix-signal[7296]: 2024-04-22T01:30:59Z ERR loopCtx error error="error in writeLoop: Took too long, not sending (elapsed: 5m40.369359035s)" action="start receive loops" loop=signal_websocket_connect_loop user_id=... websocket_type=unauthed

... repeats a few times until we give up:

Apr 22 01:31:00 signal-puppet mautrix-signal[7296]: 2024-04-22T01:31:00Z ERR Sending message metrics for event error="Retried 3 times, giving up" chat_id=65c27... event_id=$Wgja... event_type=m.room.message handling_step="Error sending" room_id=... sender=...

...and then after responding with the matrix "Your message may not have been bridged: Retried 3 times, giving up" message we immediately succeed in sending the next message which was queued up while the first was retrying:

Apr 22 01:31:00 signal-puppet mautrix-signal[7296]: 2024-04-22T01:31:00Z DBG Outgoing message action="send content" chat_id=65c27... content_fields="dataMessage (message), { body (string), timestamp (uint64), } " event_id=$cUJ... event_type=m.room.message portal_chat_id=65c27... recipient=65c27... room_id=... timestamp=1713749285779
Apr 22 01:31:00 signal-puppet mautrix-signal[7296]: 2024-04-22T01:31:00Z INF Waiting for read or write loop to exit action="start receive loops" loop=signal_websocket_connect_loop user_id=... websocket_type=unauthed
Apr 22 01:31:00 signal-puppet mautrix-signal[7296]: 2024-04-22T01:31:00Z INF Unauthed websocket connected action="start receive loops" current_status={"Err":null,"Event":1} last_auth_status={"Err":null,"Event":1} last_unauth_status={"Err":null,"Event":1} user_id=...
Apr 22 01:31:00 signal-puppet mautrix-signal[7296]: 2024-04-22T01:31:00Z INF Sending connection status action="start receive loops" status_to_send={"Err":null,"Event":1} user_id=...
Apr 22 01:31:00 signal-puppet mautrix-signal[7296]: 2024-04-22T01:31:00Z DBG Using peeked connectionStatus event peeked_connection_status_event=SignalConnectionEventConnected user_id=...
Apr 22 01:31:00 signal-puppet mautrix-signal[7296]: 2024-04-22T01:31:00Z DBG Sending WS request action="start receive loops" elapsed=252.034152 loop=signal_websocket_write_loop request_id=1 request_path=/v1/messages/... request_verb=PUT user_id=... websocket_type=unauthed
Apr 22 01:31:00 signal-puppet mautrix-signal[7296]: 2024-04-22T01:31:00Z DBG Sending Connected BridgeState user_id=...
Apr 22 01:31:00 signal-puppet mautrix-signal[7296]: 2024-04-22T01:31:00Z DBG Received WS response action="start receive loops" loop=signal_websocket_read_loop response_id=1 response_status=200 user_id=... websocket_type=unauthed
Apr 22 01:31:00 signal-puppet mautrix-signal[7296]: 2024-04-22T01:31:00Z DBG Deleted response channel for ID action="start receive loops" loop=signal_websocket_read_loop response_id=1 user_id=... websocket_type=unauthed
Apr 22 01:31:00 signal-puppet mautrix-signal[7296]: 2024-04-22T01:31:00Z DBG DEBUG: message send response data action="send content" chat_id=65c27... event_id=$cUJ... event_type=m.room.message portal_chat_id=65c27... recipient=65c27... response_body={"needsSync":false} response_id=1 response_status=200 room_id=... timestamp=1713749285779
Apr 22 01:31:00 signal-puppet mautrix-signal[7296]: 2024-04-22T01:31:00Z DBG Outgoing message action="send content" chat_id=65c27... content_fields="syncMessage (message), { sent (message), { timestamp (uint64), destinationServiceId (string), message (message), { body (string), profileKey (bytes), timestamp (uint64), } unidentifiedStatus (message), [ { destinationServiceId (string), unidentified (bool), } ] } } " event_id=$cUJ... event_type=m.room.message portal_chat_id=65c27... recipient=12172... room_id=... timestamp=1713749285779
Apr 22 01:31:00 signal-puppet mautrix-signal[7296]: 2024-04-22T01:31:00Z INF Building PreKeyWhisperMessage for: 12172....2 with preKeyId: ... (session created at ...) component=libsignal file=rust/protocol/src/session_cipher.rs line=74 target=libsignal_protocol::session_cipher