Bridge Stuck After Outgoing Message Reaction (RCS)

[jasonlaguidice]

The bridge becomes stuck after sending a reaction in an RCS conversation. When in the stuck state messages will be stuck at waiting to send forever. Incoming messages are not received and not backfilled when the bridge is restarted, leaving them lost.

Below is a console snippet of the bridge running normally, sending a heart react to a message, then attempting to send a standard text message in an RCS chat.

The heart react never shows up on the Google Messages side, nor does the outgoing message.

The bot seems to still respond in its management room while it's stuck, leading me to believe this is a per-conversation stuck state.

2024-02-25T21:41:35Z DBG Starting handling of transaction content={"pdu":1} req_id=50 transaction_id=e204172_d72026_r198809_t177485->e204173_d72026_r198810_t177485 ws_command=transaction
2024-02-25T21:41:35Z DBG Finished dispatching events from transaction req_id=50 transaction_id=e204172_d72026_r198809_t177485->e204173_d72026_r198810_t177485 ws_command=transaction
2024-02-25T21:41:35Z DBG Sent message checkpoint message_checkpoint={"event_id":"$hYIwGcLHgteHr9z_8XJgitN9S5t556cwW7CrYUNKlTI:beeper.local","event_type":"m.reaction","reported_by":"BRIDGE","retry_num":0,"room_id":"!mjXgmzoZqMF6ikTF7NWi:beeper.local","status":"SUCCESS","step":"BRIDGE","timestamp":1708897295907}
2024-02-25T21:41:35Z DBG Handling Matrix reaction action="handle matrix reaction" event_id=$hYIwGcLHgteHr9z_8XJgitN9S5t556cwW7CrYUNKlTI:beeper.local portal_id=664 portal_receiver=1 room_id=!mjXgmzoZqMF6ikTF7NWi:beeper.local target_event_id=$9masO3sWzC9F7QOKQN5-nm4mUU8kAUsqj4LHtbociAs:messages.google.com
2024-02-25T21:41:35Z DBG Sent response to transaction req_id=50 transaction_id=e204172_d72026_r198809_t177485->e204173_d72026_r198810_t177485 ws_command=transaction
2024-02-25T21:41:38Z DBG Starting handling of transaction content={"pdu":0,"to_device":1} req_id=51 transaction_id=e204173_d72026_r198810_t177485->e204173_d72073_r198810_t177485 ws_command=transaction
2024-02-25T21:41:38Z DBG Finished dispatching events from transaction req_id=51 transaction_id=e204173_d72026_r198810_t177485->e204173_d72073_r198810_t177485 ws_command=transaction
2024-02-25T21:41:38Z DBG Sent response to transaction req_id=51 transaction_id=e204173_d72026_r198810_t177485->e204173_d72073_r198810_t177485 ws_command=transaction
2024-02-25T21:41:38Z DBG Trying to decrypt olm message component=crypto olm_session_id=z8N/BeIFvqP86Q4DZKDNW/xxFCSSYVUQhNzyaRmE/IA sender=@shadowdrake:beeper.com session_description="sender chain index: 30 receiver chain indices: 1 skipped message keys:" trace_id=21:41:38.457643 type=m.room.encrypted
2024-02-25T21:41:38Z DBG Decrypted olm message component=crypto olm_session_id=z8N/BeIFvqP86Q4DZKDNW/xxFCSSYVUQhNzyaRmE/IA sender=@shadowdrake:beeper.com trace_id=21:41:38.457643 type=m.room.encrypted
2024-02-25T21:41:38Z DBG Redacting previous megolm sessions from sender in room algorithm=m.megolm.v1.aes-sha2 component=crypto room_id=!mjXgmzoZqMF6ikTF7NWi:beeper.local sender=@shadowdrake:beeper.com session_id=7EASAYUtrX7Lfp5TeOhc78eTAZFN2cRmfyZluibgxI8 trace_id=21:41:38.457643 type=m.room.encrypted
2024-02-25T21:41:38Z INF Redacted previous megolm sessions algorithm=m.megolm.v1.aes-sha2 component=crypto room_id=!mjXgmzoZqMF6ikTF7NWi:beeper.local sender=@shadowdrake:beeper.com session_id=7EASAYUtrX7Lfp5TeOhc78eTAZFN2cRmfyZluibgxI8 session_ids=[] trace_id=21:41:38.457643 type=m.room.encrypted
2024-02-25T21:41:38Z DBG Received inbound group session component=crypto is_scheduled=false max_age=720h0m0s max_messages=10000 sender=@shadowdrake:beeper.com sender_key=kouTF015MR6gnGT+iq+wIOs8GyUBjfkmghHOnqdEIhU session_id=7EASAYUtrX7Lfp5TeOhc78eTAZFN2cRmfyZluibgxI8 trace_id=21:41:38.457643 type=m.room.encrypted
2024-02-25T21:41:38Z DBG Starting handling of transaction content={"edu":1,"pdu":0} req_id=52 transaction_id=e204173_d72073_r198810_t177485->e204173_d72073_r198810_t177486 ws_command=transaction
2024-02-25T21:41:38Z DBG Finished dispatching events from transaction req_id=52 transaction_id=e204173_d72073_r198810_t177485->e204173_d72073_r198810_t177486 ws_command=transaction
2024-02-25T21:41:38Z DBG Sent response to transaction req_id=52 transaction_id=e204173_d72073_r198810_t177485->e204173_d72073_r198810_t177486 ws_command=transaction
2024-02-25T21:41:39Z DBG Starting handling of transaction content={"pdu":0,"to_device":1} req_id=53 transaction_id=e204173_d72073_r198810_t177486->e204173_d72074_r198810_t177486 ws_command=transaction
2024-02-25T21:41:39Z DBG Finished dispatching events from transaction req_id=53 transaction_id=e204173_d72073_r198810_t177486->e204173_d72074_r198810_t177486 ws_command=transaction
2024-02-25T21:41:39Z DBG Starting handling to-device event component=crypto sender=@shadowdrake:beeper.com trace_id=21:41:39.038239 type=com.beeper.room_key.ack
2024-02-25T21:41:39Z DBG Sent response to transaction req_id=53 transaction_id=e204173_d72073_r198810_t177486->e204173_d72074_r198810_t177486 ws_command=transaction
2024-02-25T21:41:39Z DBG Received room key ack component=crypto first_message_index=0 inbound=false own_identity=3p06z8DQ4eTJ1w7PhzsY5+c9Skkj0Jtl57/cW5u9iGU room_id=!mjXgmzoZqMF6ikTF7NWi:beeper.local sender=@shadowdrake:beeper.com sender_key=kouTF015MR6gnGT+iq+wIOs8GyUBjfkmghHOnqdEIhU session_id=7EASAYUtrX7Lfp5TeOhc78eTAZFN2cRmfyZluibgxI8 trace_id=21:41:39.038239 type=com.beeper.room_key.ack
2024-02-25T21:41:39Z DBG Finished handling to-device event component=crypto sender=@shadowdrake:beeper.com trace_id=21:41:39.038239 type=com.beeper.room_key.ack
2024-02-25T21:41:40Z DBG Starting handling of transaction content={"edu":1,"pdu":0} req_id=54 transaction_id=e204173_d72074_r198810_t177486->e204173_d72026_r198810_t177487 ws_command=transaction
2024-02-25T21:41:40Z DBG Finished dispatching events from transaction req_id=54 transaction_id=e204173_d72074_r198810_t177486->e204173_d72026_r198810_t177487 ws_command=transaction
2024-02-25T21:41:40Z DBG Sent response to transaction req_id=54 transaction_id=e204173_d72074_r198810_t177486->e204173_d72026_r198810_t177487 ws_command=transaction
2024-02-25T21:41:41Z DBG Ditto ping wait short-circuited component=libgm listen_id=3 user_id=@shadowdrake:beeper.com
2024-02-25T21:41:41Z DBG Starting handling of transaction content={"pdu":1} req_id=55 transaction_id=e204173_d72026_r198810_t177487->e204174_d72026_r198811_t177487 ws_command=transaction
2024-02-25T21:41:41Z DBG Finished dispatching events from transaction req_id=55 transaction_id=e204173_d72026_r198810_t177487->e204174_d72026_r198811_t177487 ws_command=transaction
2024-02-25T21:41:41Z DBG Decrypting received event event_id=$Se8O0Yrg68dKarED0ihoxuEoXUK-2lFew1gb52BEZMw:beeper.local session_id=7EASAYUtrX7Lfp5TeOhc78eTAZFN2cRmfyZluibgxI8
2024-02-25T21:41:41Z DBG Sent response to transaction req_id=55 transaction_id=e204173_d72026_r198810_t177487->e204174_d72026_r198811_t177487 ws_command=transaction
2024-02-25T21:41:41Z DBG Sent message checkpoint message_checkpoint={"event_id":"$Se8O0Yrg68dKarED0ihoxuEoXUK-2lFew1gb52BEZMw:beeper.local","event_type":"m.room.encrypted","reported_by":"BRIDGE","retry_num":0,"room_id":"!mjXgmzoZqMF6ikTF7NWi:beeper.local","status":"SUCCESS","step":"BRIDGE","timestamp":1708897301217}
2024-02-25T21:41:41Z INF Ratcheted session forward action="decrypt megolm event" event_id=$Se8O0Yrg68dKarED0ihoxuEoXUK-2lFew1gb52BEZMw:beeper.local lost_indices=[] max_messages=10000 missed_indices=[] new_ratchet_index=1 next_new_index=1 prev_ratchet_index=0 sender=@shadowdrake:beeper.com sender_key=kouTF015MR6gnGT+iq+wIOs8GyUBjfkmghHOnqdEIhU session_id=7EASAYUtrX7Lfp5TeOhc78eTAZFN2cRmfyZluibgxI8
2024-02-25T21:41:41Z DBG Event decrypted successfully action="decrypt megolm event" decrypted_event_type="m.room.message (message)" event_id=$Se8O0Yrg68dKarED0ihoxuEoXUK-2lFew1gb52BEZMw:beeper.local message_index=0 sender=@shadowdrake:beeper.com sender_key=kouTF015MR6gnGT+iq+wIOs8GyUBjfkmghHOnqdEIhU session_id=7EASAYUtrX7Lfp5TeOhc78eTAZFN2cRmfyZluibgxI8
2024-02-25T21:41:41Z DBG Sent message checkpoint message_checkpoint={"event_id":"$Se8O0Yrg68dKarED0ihoxuEoXUK-2lFew1gb52BEZMw:beeper.local","event_type":"m.room.message","message_type":"m.text","reported_by":"BRIDGE","retry_num":0,"room_id":"!mjXgmzoZqMF6ikTF7NWi:beeper.local","status":"SUCCESS","step":"DECRYPTED","timestamp":1708897301218}
2024-02-25T21:41:42Z DBG Sent acks component=libgm message_ids=["96042bb1-cba6-4697-9a53-8549447ceec4"] user_id=@shadowdrake:beeper.com