Error sending message blocks refreshing sessions in QML
Setup
- Device: X10III (others)
- SailfishOS version: 4.4.0.64
- Whisperfish version: !234 (closed) and b1864, most likely goes further back
- Clean Whisperfish install from waaay back
Summary
Sending a message updates MainPage.qml session list - but only if sending the message is successful. If there's an error sending the message, the code anyhow::bail!()
s out and the subsequent action to update the sessions doesn't get called. In my case the error is Sending message: Error sending message: protocol error: untrusted identity for address [UUID].1
.
This seems reproducible on #whisperfishes for at least one other user than myself. The message still gets sent to all other recipients (observably, as the conversation carries on), but the QML update still gets blocked.
The bug seems to be a code flow issue in src/worker/client.rs
in impl Handler<SendMessage> for ClientActor
which calls anyhow::bail!()
if send_message_to_group
(or send_message
or upload_attachment
) fails. The subsequent code triggers reloading all sessions (side note: could this be just reloading the single session instead?) which obviously isn't reached if the code bails out. If I use trace::log!()
instead of anyhow::bail!()
in src/worker/client.rs, the code execution continues and the sessions get reloaded, which proves the point of failure - but that is not a fix.
The desync is fixed by the next incoming message (in whatever session, I think) (or by restarting Whisperfish).
Trace log
Note: rows shortened for increased readability
Note: contains non-pushed changes in error messages
Current status, QML doesn't update on message send:
[10:10:16Z TRACE actor::messageactor] MessageActor::handle(GroupV2Message { group_id: "GROUP_ID", message: "This message doesn't work", attachment: "" })
[10:10:16Z TRACE store] Called create_message(..) for session 9
[10:10:16Z TRACE store] Creating message for timestamp 2022-05-29 10:10:16.356
[10:10:16Z TRACE store] Called mark_session_archived(9, false)
[10:10:16Z TRACE store] Inserted message id 19961
[10:10:16Z TRACE model::message] Inserting new message to QML
[10:10:16Z INFO worker::client] ClientActor::SendMessage(19961)
[10:10:16Z TRACE store] Called fetch_message_by_id(19961)
[10:10:16Z TRACE worker::client] Sending for session: Session { id: 9, is_archived: false, is_pinned: false, is_silent: false, is_muted: false, expiring_message_timeout: None, draft: None, type: GroupV2(GroupV2 { id: "GROUP_ID", name: "#whisperfishers", master_key: "MASTER_KEY", revision: 9, invite_link_password: Some([...]), access_required_for_attributes: 2, access_required_for_members: 2, access_required_for_add_from_invite_link: 1 }) }
[10:10:16Z TRACE worker::client] Sending message: Message { id: 19961, session_id: 9, text: Some("This message doesn't work"), sender_recipient_id: None, received_timestamp: None, sent_timestamp: None, server_timestamp: 2022-05-29T10:10:16.356, is_read: true, is_outbound: true, flags: 0, expires_in: None, expiry_started: None, schedule_send_time: None, is_bookmarked: false, use_unidentified: false, is_remote_deleted: false }
[10:10:16Z TRACE worker::client] Transmitting DataMessage { body: Some("This message doesn't work"), attachments: [], group: None, group_v2: Some(GroupContextV2 { master_key: Some([...]), revision: Some(9), group_change: None }), flags: None, expire_timer: None, profile_key: Some([...]), timestamp: Some(1653819016356), quote: None, contact: [], preview: [], sticker: None, required_protocol_version: Some(0), is_view_once: None, reaction: None, delete: None, body_ranges: [], group_call_update: None, payment: None } with timestamp 1653819016356
[10:10:16Z TRACE libsignal_service::sender] sending message to default device
[10:10:16Z TRACE libsignal_service::sender] encrypting message for ProtocolAddress { name: "UUID", device_id: 1 }
[10:10:16Z TRACE libsignal_service::sender] sending message to device 2
[10:10:16Z TRACE libsignal_service::sender] encrypting message for ProtocolAddress { name: "UUID", device_id: 2 }
[...]
[10:10:18Z DEBUG libsignal_service_actix::push_service] AwcPushService::put response:
ClientResponse HTTP/1.1 200 OK
headers:
"content-length": "19"
"connection": "keep-alive"
"date": "Sun, 29 May 2022 10:10:13 GMT"
"x-signal-timestamp": "1653819013895"
"content-type": "application/json"
[10:10:18Z DEBUG libsignal_service_actix::push_service] PUT response: "{\"needsSync\":false}"
[10:10:18Z DEBUG libsignal_service::sender] message sent!
[10:10:18Z ERROR worker::client] Sending message: Error sending message: protocol error: untrusted identity for address UUID.1
[10:10:18Z TRACE libsignal_service::messagepipe] Decoded WebSocketMessage { r#type: Some(Request), request: Some(WebSocketRequestMessage { verb: Some("PUT"), path: Some("/api/v1/message"), body: Some([...]), headers: ["X-Signal-Key: false", "X-Signal-Timestamp:1653819014016"], id: Some(ID) }), response: None }
[10:10:18Z TRACE libsignal_service::envelope] Envelope::decrypt: not encrypted
[10:10:18Z INFO worker::client] Received receipt: 1653819016356
[10:10:18Z TRACE worker::client] Marking message from ServiceAddress(PHONE) at 2022-05-29 10:10:16.356 (1653819016356) as received.
[10:10:18Z TRACE store] receipt already exists, updating record
[10:10:18Z TRACE store] Called fetch_message_by_id(19961)
[10:10:18Z TRACE model::message] Mark message 19961 received 'true'
[10:10:18Z TRACE model::session] STUB: Mark received called
[10:10:18Z WARN worker::client] Empty envelope
[10:10:18Z TRACE libsignal_service::messagepipe] Decoded WebSocketMessage { r#type: Some(Request), request: Some(WebSocketRequestMessage { verb: Some("PUT"), path: Some("/api/v1/message"), body: Some([...]), headers: ["X-Signal-Key: false", "X-Signal-Timestamp:1653819014152"], id: Some(ID) }), response: None }
With log::trace!()
instead of anyhow::bail!()
:
[11:07:18Z TRACE actor::messageactor] MessageActor::handle(GroupV2Message { group_id: "UUID", message: "Ugly proof-of-concept hack test", attachment: "" })
[11:07:18Z TRACE store] Called create_message(..) for session 9
[11:07:18Z TRACE store] Creating message for timestamp 2022-05-29 11:07:18.401
[11:07:18Z TRACE store] Called mark_session_archived(9, false)
[11:07:18Z TRACE store] Inserted message id 19968
[11:07:18Z TRACE model::message] Inserting new message to conversation
[11:07:18Z INFO worker::client] ClientActor::SendMessage(19968)
[11:07:18Z TRACE store] Called fetch_message_by_id(19968)
[11:07:18Z TRACE worker::client] Sending for session: Session { id: 9, is_archived: false, is_pinned: false, is_silent: false, is_muted: false, expiring_message_timeout: None, draft: None, type: GroupV2(GroupV2 { id: "UUID", name: "#whisperfishers", master_key: "UUID", revision: 9, invite_link_password: Some([...]), access_required_for_attributes: 2, access_required_for_members: 2, access_required_for_add_from_invite_link: 1 }) }
[11:07:18Z TRACE worker::client] Sending message: Message { id: 19968, session_id: 9, text: Some("Ugly proof-of-concept hack test"), sender_recipient_id: None, received_timestamp: None, sent_timestamp: None, server_timestamp: 2022-05-29T11:07:18.401, is_read: true, is_outbound: true, flags: 0, expires_in: None, expiry_started: None, schedule_send_time: None, is_bookmarked: false, use_unidentified: false, is_remote_deleted: false }
[11:07:18Z TRACE worker::client] Transmitting DataMessage { body: Some("Ugly proof-of-concept hack test"), attachments: [], group: None, group_v2: Some(GroupContextV2 { master_key: Some([...]), revision: Some(9), group_change: None }), flags: None, expire_timer: None, profile_key: Some([...]), timestamp: Some(1653822438401), quote: None, contact: [], preview: [], sticker: None, required_protocol_version: Some(0), is_view_once: None, reaction: None, delete: None, body_ranges: [], group_call_update: None, payment: None } with timestamp 1653822438401
[...]
[11:07:20Z DEBUG libsignal_service_actix::push_service] HTTP request PUT https://chat.signal.org/v1/messages/UUID
[11:07:20Z DEBUG libsignal_service_actix::push_service] AwcPushService::put response:
ClientResponse HTTP/1.1 200 OK
headers:
"x-signal-timestamp": "1653822436010"
"content-type": "application/json"
"content-length": "19"
"connection": "keep-alive"
"date": "Sun, 29 May 2022 11:07:16 GMT"
[11:07:20Z DEBUG libsignal_service_actix::push_service] PUT response: "{\"needsSync\":false}"
[11:07:20Z DEBUG libsignal_service::sender] message sent!
[11:07:20Z TRACE worker::client] Error sending message to GroupV2: protocol error: untrusted identity for address UUID.1
[11:07:20Z TRACE model::session] STUB: Mark sent called
[11:07:20Z TRACE model::message] Mark message 19968 sent 'true'
[11:07:20Z TRACE libsignal_service::messagepipe] Decoded WebSocketMessage { r#type: Some(Request), request: Some(WebSocketRequestMessage { verb: Some("PUT"), path: Some("/api/v1/message"), body: Some([...]), headers: ["X-Signal-Key: false", "X-Signal-Timestamp:1653822436060"], id: Some(...) }), response: None }
[11:07:20Z TRACE libsignal_service::envelope] Envelope::decrypt: not encrypted
[11:07:20Z INFO worker::client] Received receipt: 1653822438401
[11:07:20Z TRACE worker::client] Marking message from ServiceAddress(PHONE) at 2022-05-29 11:07:18.401 (1653822438401) as received.
[11:07:20Z TRACE store] Called fetch_message_by_id(19968)
[11:07:20Z TRACE model::message] Mark message 19968 received 'true'
[11:07:20Z TRACE model::session] STUB: Mark received called
[11:07:20Z WARN worker::client] Empty envelope
[11:07:20Z TRACE libsignal_service::messagepipe] Decoded WebSocketMessage { r#type: Some(Request), request: Some(WebSocketRequestMessage { verb: Some("PUT"), path: Some("/api/v1/message"), body: Some([...]), headers: ["X-Signal-Key: false", "X-Signal-Timestamp:1653822436060"], id: Some(...) }), response: None }
[11:07:20Z TRACE libsignal_service::envelope] Envelope::decrypt: not encrypted
[11:07:20Z TRACE libsignal_service::messagepipe] Decoded WebSocketMessage { r#type: Some(Request), request: Some(WebSocketRequestMessage { verb: Some("PUT"), path: Some("/api/v1/message"), body: Some([...]), headers: ["X-Signal-Key: false", "X-Signal-Timestamp:1653822436060"], id: Some(...) }), response: None }
[11:07:20Z TRACE libsignal_service::envelope] Envelope::decrypt: not encrypted
[11:07:20Z INFO worker::client] Received receipt: 1653822438401
[11:07:20Z TRACE worker::client] Marking message from ServiceAddress(PHONE) at 2022-05-29 11:07:18.401 (1653822438401) as received.
[11:07:20Z TRACE store] receipt already exists, updating record
[11:07:20Z TRACE store] Called fetch_message_by_id(19968)
[11:07:20Z TRACE model::message] Mark message 19968 received 'true'
[11:07:20Z TRACE model::session] STUB: Mark received called
[11:07:20Z INFO worker::client] Received receipt: 1653822438401
[11:07:20Z TRACE worker::client] Marking message from ServiceAddress(PHONE) at 2022-05-29 11:07:18.401 (1653822438401) as received.
[11:07:20Z TRACE store] receipt already exists, updating record
[11:07:20Z TRACE store] Called fetch_message_by_id(19968)
[11:07:20Z TRACE model::message] Mark message 19968 received 'true'
[11:07:20Z TRACE model::session] STUB: Mark received called
[11:07:20Z WARN worker::client] Empty envelope
[11:07:20Z WARN worker::client] Empty envelope
[D] onOriginalMessageChanged:42 - (message text)
[D] onOriginalMessageChanged:42 - (message text) <== The MainPage.qml contents getting updated
[D] onOriginalMessageChanged:42 - (message text) (console.log() triggered by model.message changing in SessionDelegate.qml)
[D] onOriginalMessageChanged:42 - (message text)
[...]