search

mautrix / imessage

A Matrix-iMessage puppeting bridge
https://go.mau.fi/mautrix-imessage/
GNU Affero General Public License v3.0
332 stars 36 forks source link

bluebubbles: Direct message replies hang message conversation and fail to send #171

Closed wastingoctober closed 4 months ago

wastingoctober commented 5 months ago

When trying to reply to a direct message in beeper, the outbound message hangs for a minute or two. While it's hanging, inbound messages are not received in that thread (the bridge works for other conversations). Once the message fails to send, the conversation catches back up. Tested with the latest commit to the bluebubbles branch. Sample log of this (phone number obfuscated):

2024-01-19T12:02:06-06:00 DBG Starting handling of transaction content={"edu":1,"pdu":0} req_id=30 transaction_id=e319425_d26431_r306587_t529353->e319425_d26431_r306587_t529354 ws_command=transaction
2024-01-19T12:02:06-06:00 DBG Finished dispatching events from transaction req_id=30 transaction_id=e319425_d26431_r306587_t529353->e319425_d26431_r306587_t529354 ws_command=transaction
2024-01-19T12:02:06-06:00 DBG Sending typing stop notification portal_guid=iMessage;-;+1<phonenumber>
2024-01-19T12:02:06-06:00 DBG Sent response to transaction req_id=30 transaction_id=e319425_d26431_r306587_t529353->e319425_d26431_r306587_t529354 ws_command=transaction
2024-01-19T12:02:06-06:00 DBG Typing update sent portal_guid=iMessage;-;+1<phonenumber>
2024-01-19T12:02:06-06:00 DBG Starting handling of transaction content={"pdu":1} req_id=31 transaction_id=e319425_d26431_r306587_t529354->e319426_d26431_r306588_t529354 ws_command=transaction
2024-01-19T12:02:06-06:00 DBG Finished dispatching events from transaction req_id=31 transaction_id=e319425_d26431_r306587_t529354->e319426_d26431_r306588_t529354 ws_command=transaction
2024-01-19T12:02:06-06:00 DBG Decrypting received event event_id=$eNvgpf59TgYpGh4rIXhZ-Sd_i8g00LyfiweLnZjMvk4:beeper.local session_id=ApRlit3A7QUq3MAfcL1yX3ZNusceO4Ox+tp+Z2aGO1s
2024-01-19T12:02:06-06:00 DBG Sent response to transaction req_id=31 transaction_id=e319425_d26431_r306587_t529354->e319426_d26431_r306588_t529354 ws_command=transaction
2024-01-19T12:02:06-06:00 DBG Sent message checkpoint message_checkpoint={"event_id":"$eNvgpf59TgYpGh4rIXhZ-Sd_i8g00LyfiweLnZjMvk4:beeper.local","event_type":"m.room.encrypted","reported_by":"BRIDGE","retry_num":0,"room_id":"!DDQeq2STp3XwuwB2mWTF:beeper.local","status":"SUCCESS","step":"BRIDGE","timestamp":1705687326449}
2024-01-19T12:02:06-06:00 INF Ratcheted session forward action="decrypt megolm event" component=crypto event_id=$eNvgpf59TgYpGh4rIXhZ-Sd_i8g00LyfiweLnZjMvk4:beeper.local lost_indices=[] max_messages=10000 missed_indices=[] new_ratchet_index=9 next_new_index=9 prev_ratchet_index=8 sender=@rushinburrito:beeper.com sender_key=34woETa/SPRTdSit16tAygb4WsZ3iTjiRAEdkFyQkn8 session_id=ApRlit3A7QUq3MAfcL1yX3ZNusceO4Ox+tp+Z2aGO1s
2024-01-19T12:02:06-06:00 DBG Event decrypted successfully action="decrypt megolm event" component=crypto decrypted_event_type="m.room.message (message)" event_id=$eNvgpf59TgYpGh4rIXhZ-Sd_i8g00LyfiweLnZjMvk4:beeper.local message_index=8 sender=@rushinburrito:beeper.com sender_key=34woETa/SPRTdSit16tAygb4WsZ3iTjiRAEdkFyQkn8 session_id=ApRlit3A7QUq3MAfcL1yX3ZNusceO4Ox+tp+Z2aGO1s
2024-01-19T12:02:06-06:00 DBG Starting handling Matrix message $eNvgpf59TgYpGh4rIXhZ-Sd_i8g00LyfiweLnZjMvk4:beeper.local portal_guid=iMessage;-;+1<phonenumber>
2024-01-19T12:02:06-06:00 DBG Sent message checkpoint message_checkpoint={"event_id":"$eNvgpf59TgYpGh4rIXhZ-Sd_i8g00LyfiweLnZjMvk4:beeper.local","event_type":"m.room.message","message_type":"m.text","reported_by":"BRIDGE","retry_num":0,"room_id":"!DDQeq2STp3XwuwB2mWTF:beeper.local","status":"SUCCESS","step":"DECRYPTED","timestamp":1705687326460}
2024-01-19T12:02:10-06:00 DBG Request completed as_user_id=@sh-imessage_1<phonenumber>:beeper.local beeper_request_id=cmlbi8lb7imc73co9590 duration=541.031237 method=PUT req_body={"timeout":60000,"typing":false} req_id=190 response_length=3 response_mime=application/json status_code=200 url=https://user.eu-outrageous-flower.edge.beeper.com/rushinburrito/_matrix/client/v3/rooms/%21DDQeq2STp3XwuwB2mWTF:beeper.local/typing/@sh-imessage_1<phonenumber>:beeper.local?user_id=%40sh-imessage_1<phonenumber>%3Abeeper.local
2024-01-19T12:02:10-06:00 DBG Handled typing notification in 541.188684ms (queued: 0m/0r/0t/0ch/0ct/0s/0b) module=iMessage
2024-01-19T12:02:15-06:00 DBG Received ping from BlueBubbles websocket component=bluebubbles

// WAITING FOR MESSAGE TO FAIL //

2024-01-19T12:04:06-06:00 ERR Failure when sending message to BlueBubbles component=bluebubbles response={"data":{"handle":{}},"error":{"message":"Transaction timeout","type":"iMessage Error"},"message":"Message Send Error","status":500}
2024-01-19T12:04:06-06:00 ERR Error sending to iMessage: could not send message portal_guid=iMessage;-;+1<phonenumber>
2024-01-19T12:04:06-06:00 DBG Sent message checkpoint message_checkpoint={"event_id":"$eNvgpf59TgYpGh4rIXhZ-Sd_i8g00LyfiweLnZjMvk4:beeper.local","event_type":"m.room.message","info":"could not send message","message_type":"m.text","reported_by":"BRIDGE","retry_num":0,"room_id":"!DDQeq2STp3XwuwB2mWTF:beeper.local","status":"PERM_FAILURE","step":"REMOTE","timestamp":1705687446472}
2024-01-19T12:04:07-06:00 DBG Request completed as_user_id=@sh-imessagebot:beeper.local beeper_request_id=cmlbj5tb7imc73co95a0 duration=551.453293 method=PUT req_body={"error":"could not send message","m.relates_to":{"event_id":"$eNvgpf59TgYpGh4rIXhZ-Sd_i8g00LyfiweLnZjMvk4:beeper.local","rel_type":"m.reference"},"network":"fi.mau.imessage://imessage/iMessage;-;+1<phonenumber>","reason":"m.event_not_handled","status":"FAIL_RETRIABLE"} req_id=191 response_length=73 response_mime=application/json status_code=200 url=https://user.eu-outrageous-flower.edge.beeper.com/rushinburrito/_matrix/client/v3/rooms/%21DDQeq2STp3XwuwB2mWTF:beeper.local/send/com.beeper.message_send_status/mautrix-go_1705687446475075000_8?user_id=%40sh-imessagebot%3Abeeper.local
2024-01-19T12:04:07-06:00 DBG Handled Matrix message in 2m0.564677116s (queued: 0i/0r/0m/0s) portal_guid=iMessage;-;+1<phonenumber>
cnuss commented 5 months ago

@wastingoctober i just pushed some updates to message sending. i saw the hangs as well when using "private-api" the BlueBubbles was hanging on the request

I've switched to use a conditional around private API.

kgr17 commented 5 months ago

Still unable to send direct replies on the [488bb6b6] commit.

2024-01-20T22:03:04-08:00 DBG Sending typing start notification portal_guid=iMessage;-;<phone number>
2024-01-20T22:03:04-08:00 DBG Sent response to transaction req_id=20 transaction_id=e492790_d133829_r491184_t786665->e492796_d133829_r491193_t786668 ws_command=transaction
2024-01-20T22:03:04-08:00 DBG Typing update sent portal_guid=iMessage;-;<phone number>
2024-01-20T22:03:11-08:00 DBG Received ping from BlueBubbles websocket component=bluebubbles
2024-01-20T22:03:14-08:00 DBG Starting handling of transaction content={"edu":1,"pdu":0} req_id=21 transaction_id=e492796_d133829_r491193_t786668->e492796_d133829_r491193_t786669 ws_command=transaction
2024-01-20T22:03:14-08:00 DBG Finished dispatching events from transaction req_id=21 transaction_id=e492796_d133829_r491193_t786668->e492796_d133829_r491193_t786669 ws_command=transaction
2024-01-20T22:03:14-08:00 DBG Sending typing stop notification portal_guid=iMessage;-;<phone number>
2024-01-20T22:03:14-08:00 DBG Sent response to transaction req_id=21 transaction_id=e492796_d133829_r491193_t786668->e492796_d133829_r491193_t786669 ws_command=transaction
2024-01-20T22:03:14-08:00 DBG Typing update sent portal_guid=iMessage;-;<phone number>
2024-01-20T22:03:23-08:00 DBG Starting handling of transaction content={"pdu":1} req_id=22 transaction_id=e492796_d133829_r491193_t786669->e492798_d133829_r491195_t786670 ws_command=transaction
2024-01-20T22:03:23-08:00 DBG Finished dispatching events from transaction req_id=22 transaction_id=e492796_d133829_r491193_t786669->e492798_d133829_r491195_t786670 ws_command=transaction
2024-01-20T22:03:23-08:00 DBG Sent response to transaction req_id=22 transaction_id=e492796_d133829_r491193_t786669->e492798_d133829_r491195_t786670 ws_command=transaction
2024-01-20T22:03:23-08:00 DBG Decrypting received event event_id=$Hgk3WlLo46A1z0o2-HP3noffyTwRNEOpiDrlFu-jSBM:beeper.local session_id=TtKIJ1ILnon9a+d1QY/XQae7Q8wyCkpg/JpomGkIbc0
2024-01-20T22:03:23-08:00 DBG Sent message checkpoint message_checkpoint={"event_id":"$Hgk3WlLo46A1z0o2-HP3noffyTwRNEOpiDrlFu-jSBM:beeper.local","event_type":"m.room.encrypted","reported_by":"BRIDGE","retry_num":0,"room_id":"!WDeeqbkCxuZdjKzY96mM:beeper.local","status":"SUCCESS","step":"BRIDGE","timestamp":1705817003115}
2024-01-20T22:03:23-08:00 INF Ratcheted session forward action="decrypt megolm event" component=crypto event_id=$Hgk3WlLo46A1z0o2-HP3noffyTwRNEOpiDrlFu-jSBM:beeper.local lost_indices=[] max_messages=10000 missed_indices=[] new_ratchet_index=4 next_new_index=4 prev_ratchet_index=3 sender=@kgr:beeper.com sender_key=keZ+ZiWe6fCYAhMSAbChiglsKWZ3j5xRtXcAJcO7FUg session_id=TtKIJ1ILnon9a+d1QY/XQae7Q8wyCkpg/JpomGkIbc0
2024-01-20T22:03:23-08:00 DBG Event decrypted successfully action="decrypt megolm event" component=crypto decrypted_event_type="m.room.message (message)" event_id=$Hgk3WlLo46A1z0o2-HP3noffyTwRNEOpiDrlFu-jSBM:beeper.local message_index=3 sender=@kgr:beeper.com sender_key=keZ+ZiWe6fCYAhMSAbChiglsKWZ3j5xRtXcAJcO7FUg session_id=TtKIJ1ILnon9a+d1QY/XQae7Q8wyCkpg/JpomGkIbc0
2024-01-20T22:03:23-08:00 DBG Starting handling Matrix message $Hgk3WlLo46A1z0o2-HP3noffyTwRNEOpiDrlFu-jSBM:beeper.local portal_guid=iMessage;-;<phone number>
2024-01-20T22:03:23-08:00 DBG Sent message checkpoint message_checkpoint={"event_id":"$Hgk3WlLo46A1z0o2-HP3noffyTwRNEOpiDrlFu-jSBM:beeper.local","event_type":"m.room.message","message_type":"m.text","reported_by":"BRIDGE","retry_num":0,"room_id":"!WDeeqbkCxuZdjKzY96mM:beeper.local","status":"SUCCESS","step":"DECRYPTED","timestamp":1705817003172}
2024-01-20T22:03:26-08:00 DBG Request completed as_user_id=@sh-imessage_16729753800:beeper.local beeper_request_id=cmmb7blb7imc73bmfsb0 duration=768.4742 method=PUT req_body={"timeout":60000,"typing":false} req_id=54 response_length=3 response_mime=application/json status_code=200 url=https://user.eu-plucky-sparrow.edge.beeper.com/kgr/_matrix/client/v3/rooms/%21WDeeqbkCxuZdjKzY96mM:beeper.local/typing/@sh-imessage_16729753800:beeper.local?user_id=%40sh-imessage_16729753800%3Abeeper.local
2024-01-20T22:03:26-08:00 DBG Handled typing notification in 768.946597ms (queued: 0m/0r/0t/0ch/0ct/0s/0b) module=iMessage
2024-01-20T22:03:41-08:00 DBG Received ping from BlueBubbles websocket component=bluebubbles
2024-01-20T22:04:11-08:00 DBG Received ping from BlueBubbles websocket component=bluebubbles
2024-01-20T22:04:41-08:00 DBG Received ping from BlueBubbles websocket component=bluebubbles
2024-01-20T22:05:11-08:00 DBG Received ping from BlueBubbles websocket component=bluebubbles
2024-01-20T22:05:23-08:00 ERR Failure when sending message to BlueBubbles component=bluebubbles response={"data":{"handle":{}},"error":{"message":"Transaction timeout","type":"iMessage Error"},"message":"Message Send Error","status":500}
2024-01-20T22:05:23-08:00 ERR Error sending to iMessage: could not send message portal_guid=iMessage;-;<phone number>
2024-01-20T22:05:23-08:00 DBG Sent message checkpoint message_checkpoint={"event_id":"$Hgk3WlLo46A1z0o2-HP3noffyTwRNEOpiDrlFu-jSBM:beeper.local","event_type":"m.room.message","info":"could not send message","message_type":"m.text","reported_by":"BRIDGE","retry_num":0,"room_id":"!WDeeqbkCxuZdjKzY96mM:beeper.local","status":"PERM_FAILURE","step":"REMOTE","timestamp":1705817123200}
2024-01-20T22:05:23-08:00 DBG Request completed as_user_id=@sh-imessagebot:beeper.local beeper_request_id=cmmb88tb7imc73bmfsrg duration=733.910311 method=PUT req_body={"error":"could not send message","m.relates_to":{"event_id":"$Hgk3WlLo46A1z0o2-HP3noffyTwRNEOpiDrlFu-jSBM:beeper.local","rel_type":"m.reference"},"network":"fi.mau.imessage://imessage/iMessage;-;<phone number>","reason":"m.event_not_handled","status":"FAIL_RETRIABLE"} req_id=55 response_length=73 response_mime=application/json status_code=200 url=https://user.eu-plucky-sparrow.edge.beeper.com/kgr/_matrix/client/v3/rooms/%21WDeeqbkCxuZdjKzY96mM:beeper.local/send/com.beeper.message_send_status/mautrix-go_1705817123206245000_6?user_id=%40sh-imessagebot%3Abeeper.local
wastingoctober commented 5 months ago

@wastingoctober i just pushed some updates to message sending. i saw the hangs as well when using "private-api" the BlueBubbles was hanging on the request

I've switched to use a conditional around private API.

Should it be resolved at this point? I'm still seeing the same issue when replying from Beeper.

trek-boldly-go commented 4 months ago

This was a bug in the bluebubbles server and requires BB version 1.9.5 or higher.