Can't send messages

[direc85]

Now that #263 is merged, I can't send messages any more with Whiperfish (built with "unofficial" Rust 1.72) running in Sailfish Emulator. Reverting to afb5114 works, so there seems to be a bug in that PR.

Whisperfish output on 88d9680

With a little cleanup to improve readability.

[TRACE] whisperfish::worker::client: MessageActor::handle(QueueMessage { session_id: 1, message: "abc", quote: -1, attachment: "" })
[TRACE] whisperfish_store::store: Called fetch_recipient_by_id(1)
[TRACE] whisperfish_store::store: Called create_message(..) for session 1
[TRACE] whisperfish_store::store: Creating message for timestamp 2023-11-26 17:33:39.896
[TRACE] whisperfish_store::store: Called mark_session_archived(1, false)
[TRACE] whisperfish_store::store: Inserted message id 8
[INFO] ClientActor::SendMessage(8)
[TRACE] whisperfish_store::store: Called fetch_message_by_id(8)
[TRACE] whisperfish::worker::client: Sending for session: Session { id: 1, _has_draft: false, type: DirectMessage { recipient: Recipient { id: 2, name: "Matti Viljanen", uuid: "9d44[...]", pni: unavailable } } }
[TRACE] whisperfish::worker::client: Sending message: Message { id: 8, session_id: 1, text: "abc" }
[TRACE] libsignal_service_actix::websocket: Will start websocket at Url { scheme: "wss", cannot_be_a_base: false, username: "", password: None, host: Some(Domain("chat.signal.org")), port: None, path: "/v1/websocket/", query: None, fragment: None }
[DEBUG] whisperfish::model::messages: Handling insertion event
[DEBUG] libsignal_service_actix::websocket: WebSocket connected: 
ClientResponse HTTP/1.1 101 Switching Protocols
  headers:
    "connection": "upgrade"
    "date": "Sun, 26 Nov 2023 17:33:40 GMT"
    "sec-websocket-accept": "O/yBQkPpb4UpB+/qHvv9fgJy5EM="
    "upgrade": "websocket"
    "vary": "Origin"

[TRACE] whisperfish::worker::client: Transmitting DataMessage(DataMessage { body: Some("abc"), attachments: [], group_v2: None, flags: None, expire_timer: None, profile_key: Some([203, 232, 158, 105, 55, 168, 251, 158, 2, 254, 218, 229, 83, 200, 111, 250, 39, 31, 233, 148, 249, 147, 207, 122, 192, 148, 29, 158, 99, 93, 238, 202]), timestamp: Some(1701020019896), 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, story_context: None, gift_badge: None }) with timestamp 1701020019896
[TRACE] libsignal_service_actix::websocket: Will start websocket at Url { scheme: "wss", cannot_be_a_base: false, username: "", password: None, host: Some(Domain("chat.signal.org")), port: None, path: "/v1/websocket/", query: None, fragment: None }
[TRACE] libsignal_service_actix::websocket: Triggering keep-alive
[TRACE] libsignal_service::websocket: keep alive is disabled: ignoring request
[DEBUG] libsignal_service_actix::websocket: WebSocket connected: 
    "date": "Sun, 26 Nov 2023 17:33:41 GMT"
    "sec-websocket-accept": "fKZKWH0qjmqXFk4sQoH0nfRo8Sk="
[TRACE] whisperfish_store::store::protocol_store: Looking for sub_device sessions for ServiceAddress { uuid: 9d44[...] }
[DEBUG] libsignal_service::sender: sending message to device 3
[DEBUG] libsignal_service::sender: encrypting message for 9d44[...].3
[TRACE] whisperfish_store::store::protocol_store: Loading session for 9d44[...].3
[TRACE] whisperfish_store::store::protocol_store: Storing session for 9d44[...].3
[DEBUG] libsignal_service::sender: sending message to device 2
[DEBUG] libsignal_service::sender: encrypting message for 9d44[...].2
[TRACE] whisperfish_store::store::protocol_store: Loading session for 9d44[...].2
[TRACE] whisperfish_store::store::protocol_store: Storing session for 9d44[...].2
[DEBUG] libsignal_service::sender: sending identified
[TRACE] libsignal_service::websocket: sending request WebSocketRequestMessage { verb: Some("PUT"), path: Some("/v1/messages/9d44[...]"), body: Some([REDACTED]), headers: ["content-type:application/json"], id: Some(18241738124342108760) }
[TRACE] libsignal_service_actix::websocket: Triggering keep-alive
[TRACE] libsignal_service::websocket: keep alive is disabled: ignoring request
[TRACE] libsignal_service::websocket: decoded WebSocketMessage { r#type: Some(Response), request: None, response: Some(WebSocketResponseMessage { id: Some(18241738124342108760), status: Some(409), message: Some("Conflict"), headers: ["Content-Type:application/json", "Content-Length:40"], body: Some([123, 34, 109, 105, 115, 115, 105, 110, 103, 68, 101, 118, 105, 99, 101, 115, 34, 58, 91, 49, 93, 44, 34, 101, 120, 116, 114, 97, 68, 101, 118, 105, 99, 101, 115, 34, 58, 91, 93, 125]) }) }
[DEBUG] libsignal_service::websocket: request_json with non-200 status code. message: Conflict
[DEBUG] libsignal_service::sender: MismatchedDevices { missing_devices: [1], extra_devices: [] }
[DEBUG] libsignal_service::sender: creating session with missing device 1
[DEBUG] libsignal_service_actix::push_service: HTTP request GET https://chat.signal.org/v2/keys/9d44[...]/1?pq=true
[DEBUG] libsignal_service_actix::push_service: AwcPushService::get response: 
ClientResponse HTTP/1.1 200 OK
    "content-type": "application/json"
    "connection": "keep-alive"
    "content-encoding": "gzip"
    "vary": "Origin, Accept-Encoding"
    "content-length": "1982"
    "date": "Sun, 26 Nov 2023 17:33:42 GMT"
    "x-signal-timestamp": "1701020022536"
[DEBUG] libsignal_service_actix::push_service: GET response: "{\"identityKey\":\"REDACTED\",\"devices\":[{\"deviceId\":1,\"registrationId\":REDACTED,\"signedPreKey\":{\"keyId\":REDACTED,\"publicKey\":\"REDACTED\",\"signature\":\"REDACTED\"},\"preKey\":{\"keyId\":REDACTED,\"publicKey\":\"REDACTED\"},\"pqPreKey\":{REDACTED}}]}"
[TRACE] whisperfish_store::store::protocol_store: Loading session for 9d44[...].1
[TRACE] whisperfish_store::store::protocol_store: Reading regid
[TRACE] whisperfish_store::store::utils: Opening file (async) /home/defaultuser/.local/share/be.rubdos/harbour-whisperfish/storage/identity/regid
[TRACE] whisperfish_store::store::utils: Read file /home/defaultuser/.local/share/be.rubdos/harbour-whisperfish/storage/identity/regid with 5 bytes
[TRACE] whisperfish_store::store::protocol_store: Storing session for 9d44[...].1
[TRACE] whisperfish_store::store::protocol_store: Looking for sub_device sessions for ServiceAddress { uuid: 9d44[...] }
[DEBUG] libsignal_service::sender: sending message to device 2
[DEBUG] libsignal_service::sender: encrypting message for 9d44[...].2
[TRACE] whisperfish_store::store::protocol_store: Loading session for 9d44[...].2
[TRACE] whisperfish_store::store::protocol_store: Storing session for 9d44[...].2
[DEBUG] libsignal_service::sender: sending message to device 3
[DEBUG] libsignal_service::sender: encrypting message for 9d44[...].3
[TRACE] whisperfish_store::store::protocol_store: Loading session for 9d44[...].3
[TRACE] whisperfish_store::store::protocol_store: Storing session for 9d44[...].3
[DEBUG] libsignal_service::sender: sending identified
[TRACE] libsignal_service::websocket: sending request WebSocketRequestMessage { verb: Some("PUT"), path: Some("/v1/messages/9d44[...]"), body: Some([REDACTED]), headers: ["content-type:application/json"], id: Some(5193935090830442814) }
[TRACE] libsignal_service::websocket: decoded WebSocketMessage { r#type: Some(Response), request: None, response: Some(WebSocketResponseMessage { id: Some(5193935090830442814), status: Some(409), message: Some("Conflict"), headers: ["Content-Type:application/json", "Content-Length:40"], body: Some([123, 34, 109, 105, 115, 115, 105, 110, 103, 68, 101, 118, 105, 99, 101, 115, 34, 58, 91, 49, 93, 44, 34, 101, 120, 116, 114, 97, 68, 101, 118, 105, 99, 101, 115, 34, 58, 91, 93, 125]) }) }
[DEBUG] libsignal_service::websocket: request_json with non-200 status code. message: Conflict
[DEBUG] libsignal_service::sender: MismatchedDevices { missing_devices: [1], extra_devices: [] }
[DEBUG] libsignal_service::sender: creating session with missing device 1
[DEBUG] libsignal_service_actix::push_service: HTTP request GET https://chat.signal.org/v2/keys/9d44[...]/1?pq=true
    "x-signal-timestamp": "1701020022977"
[TRACE] libsignal_service::websocket: sending request WebSocketRequestMessage { verb: Some("PUT"), path: Some("/v1/messages/9d44[...]"), body: Some([REDACTED]), headers: ["content-type:application/json"], id: Some(1978456167763696498) }
[TRACE] libsignal_service::websocket: decoded WebSocketMessage { r#type: Some(Response), request: None, response: Some(WebSocketResponseMessage { id: Some(1978456167763696498), status: Some(409), message: Some("Conflict"), headers: ["Content-Type:application/json", "Content-Length:40"], body: Some([123, 34, 109, 105, 115, 115, 105, 110, 103, 68, 101, 118, 105, 99, 101, 115, 34, 58, 91, 49, 93, 44, 34, 101, 120, 116, 114, 97, 68, 101, 118, 105, 99, 101, 115, 34, 58, 91, 93, 125]) }) }
[DEBUG] libsignal_service_actix::push_service: AwcPushService::get response: 
    "date": "Sun, 26 Nov 2023 17:33:43 GMT"
    "content-length": "1980"
    "x-signal-timestamp": "1701020023431"
[DEBUG] libsignal_service_actix::push_service: GET response: "{\"identityKey\":\"REDACTED\",\"devices\":[{\"deviceId\":1,\"registrationId\":REDACTED,\"signedPreKey\":{\"keyId\":REDACTED,\"publicKey\":\"REDACTED\",\"signature\":\"REDACTED\"},\"preKey\":{\"keyId\":REDACTED,\"publicKey\":\"REDACTED\"},\"pqPreKey\":{REDACTED}}]}"
[TRACE] whisperfish_store::store::protocol_store: Loading session for 9d44[...].1
[TRACE] whisperfish_store::store::protocol_store: Reading regid
[TRACE] whisperfish_store::store::utils: Opening file (async) /home/defaultuser/.local/share/be.rubdos/harbour-whisperfish/storage/identity/regid
[TRACE] whisperfish_store::store::utils: Read file /home/defaultuser/.local/share/be.rubdos/harbour-whisperfish/storage/identity/regid with 5 bytes
[TRACE] whisperfish_store::store::protocol_store: Storing session for 9d44[...].1
[TRACE] whisperfish_store::store::protocol_store: Looking for sub_device sessions for ServiceAddress { uuid: 9d44[...] }
[DEBUG] libsignal_service::sender: sending message to device 3
[DEBUG] libsignal_service::sender: encrypting message for 9d44[...].3
[TRACE] whisperfish_store::store::protocol_store: Loading session for 9d44[...].3
[TRACE] whisperfish_store::store::protocol_store: Storing session for 9d44[...].3
[DEBUG] libsignal_service::sender: sending message to device 2
[DEBUG] libsignal_service::sender: encrypting message for 9d44[...].2
[TRACE] whisperfish_store::store::protocol_store: Loading session for 9d44[...].2
[TRACE] whisperfish_store::store::protocol_store: Storing session for 9d44[...].2
[DEBUG] libsignal_service::sender: sending identified
[TRACE] libsignal_service::websocket: sending request WebSocketRequestMessage { verb: Some("PUT"), path: Some("/v1/messages/9d44[...]"), body: Some([REDACTED]), headers: ["content-type:application/json"], id: Some(10822147257131386681) }
[TRACE] libsignal_service::websocket: decoded WebSocketMessage { r#type: Some(Response), request: None, response: Some(WebSocketResponseMessage { id: Some(10822147257131386681), status: Some(409), message: Some("Conflict"), headers: ["Content-Type:application/json", "Content-Length:40"], body: Some([123, 34, 109, 105, 115, 115, 105, 110, 103, 68, 101, 118, 105, 99, 101, 115, 34, 58, 91, 49, 93, 44, 34, 101, 120, 116, 114, 97, 68, 101, 118, 105, 99, 101, 115, 34, 58, 91, 93, 125]) }) }
[DEBUG] libsignal_service::websocket: request_json with non-200 status code. message: Conflict
[DEBUG] libsignal_service::sender: MismatchedDevices { missing_devices: [1], extra_devices: [] }
[DEBUG] libsignal_service::sender: creating session with missing device 1
[DEBUG] libsignal_service_actix::push_service: HTTP request GET https://chat.signal.org/v2/keys/9d44[...]/1?pq=true
ClientResponse HTTP/1.1 413 Payload Too Large
    "x-signal-timestamp": "1701020023865"
    "content-length": "453"
    "cache-control": "must-revalidate,no-cache,no-store"
    "retry-after": "600"
    "content-type": "text/html;charset=iso-8859-1"
[ERROR] SignalWebSocket: Websocket error: SignalWebSocket: end of application request stream; socket closing
[TRACE] whisperfish_store::store: Setting message 8 to failed
[ERROR] Could not deliver message: Rate limit exceeded
[ERROR] The above error goes unhandled.
[ERROR] Successfully delivered message to 0 out of 1 recipients
[ERROR] Sending message: Could not deliver message.
[TRACE] whisperfish_store::store: Called fetch_message_by_id(8)
[DEBUG] whisperfish::model::messages: Handling update event.