search

mautrix / signal

A Matrix-Signal puppeting bridge
GNU Affero General Public License v3.0
484 stars 74 forks source link

error: "3: unexpected panic: previously validated: ZkGroupDeserializationFailure" #487

Closed Marcool04 closed 2 months ago

Marcool04 commented 3 months ago

Hi all,

Using synapse 1.102.0, the x86_64 binary of 0.5.1 from the releases here on Arch Linux.

I previously had the bridge installed in its python version, and I then removed the bridge, deleted all the portals (using the synapse admin API via https://github.com/Awesome-Technologies/synapse-admin), created a fresh mautrix-signal database, installed the new mautrix-signal and fired it up, the bridge bot appears, I login, but then no portals are created for my existing Signal chats.

When a message arrives in Signal, as happened this morning, I get this in a mautrix-signal debug log:

2024-03-24T09:30:57+01:00 DBG Received WS request action="start receive loops" loop=signal_websocket_read_loop request_id=242672216981547648 request_path=/api/v1/message request_verb=PUT user_id=@mark:HOMESERVER.DOMAIN.NAME username=USERNAME_1 websocket_type=authed
2024-03-24T09:30:57+01:00 INF deserialized UnidentifiedSenderMessageContent from SIGNAL_UUID_1.1 with type SenderKey component=libsignal file=rust/protocol/src/sealed_sender.rs line=441 target=libsignal_protocol::sealed_sender
2024-03-24T09:30:57+01:00 DBG Decrypted message action="start receive loops" handler="incoming request handler" handler_type="incoming API message handler" path=/api/v1/message sender_device_id=1 sender_e164= sender_name=SIGNAL_UUID_1 sender_uuid=SIGNAL_UUID_1 user_id=@mark:HOMESERVER.DOMAIN.NAME username=USERNAME_1 verb=PUT websocket_type=authed
2024-03-24T09:30:57+01:00 DBG Decrypted content fields action="start receive loops" content_fields="dataMessage (message), { body (string), groupV2 (message), { masterKey (bytes), revision (uint32), } expireTimer (uint32), profileKey (bytes), timestamp (uint64), requiredProtocolVersion (uint32), } " handler="incoming request handler" handler_type="incoming API message handler" path=/api/v1/message sender_device_id=1 sender_e164= sender_name=SIGNAL_UUID_1 sender_uuid=SIGNAL_UUID_1 user_id=@mark:HOMESERVER.DOMAIN.NAME username=USERNAME_1 verb=PUT websocket_type=authed
2024-03-24T09:30:57+01:00 DBG Fetching contact info to update puppet action="handle signal data message" chat_id=CHAT_ID_1 function=Puppet.UpdateInfo msg_ts=1711269057726 signal_user_id=SIGNAL_UUID_1
2024-03-24T09:30:57+01:00 DBG Outgoing message action="send content" content_fields="receiptMessage (message), { timestamp (uint64), [ <>, ] type (enum), } " handler="incoming request handler" handler_type="incoming API message handler" path=/api/v1/message recipient=SIGNAL_UUID_1 sender_device_id=1 sender_e164= sender_name=SIGNAL_UUID_1 sender_uuid=SIGNAL_UUID_1 timestamp=1711269057246 user_id=@mark:HOMESERVER.DOMAIN.NAME username=USERNAME_1 verb=PUT websocket_type=authed
2024-03-24T09:30:57+01:00 DBG updating existing contact action="fetch contact then try and update with profile" chat_id=CHAT_ID_1 function=Puppet.UpdateInfo msg_ts=1711269057726 profile_uuid=SIGNAL_UUID_1 signal_user_id=SIGNAL_UUID_1
2024-03-24T09:30:57+01:00 DBG Fetching group info to update portal action="handle signal data message" chat_id=CHAT_ID_1 function=UpdateGroupInfo msg_ts=1711269057726 revision=41 source_user_mxid=@mark:HOMESERVER.DOMAIN.NAME
2024-03-24T09:30:57+01:00 ERR ReceiveAuthCredentialWithPni error error="3: unexpected panic: previously validated: ZkGroupDeserializationFailure" action="get authorization for today" chat_id=CHAT_ID_1 msg_ts=1711269057726
2024-03-24T09:30:57+01:00 ERR Failed to fetch group info error="3: unexpected panic: previously validated: ZkGroupDeserializationFailure" action="handle signal data message" chat_id=CHAT_ID_1 function=UpdateGroupInfo msg_ts=1711269057726 revision=41 source_user_id=@mark:HOMESERVER.DOMAIN.NAME source_user_mxid=@mark:HOMESERVER.DOMAIN.NAME
2024-03-24T09:30:57+01:00 DBG Creating Matrix room from incoming message action="handle signal message" chat_id=CHAT_ID_1 msg_ts=1711269057726 sender_uuid=SIGNAL_UUID_1
2024-03-24T09:30:57+01:00 DBG Creating matrix room chat_id=CHAT_ID_1
2024-03-24T09:30:57+01:00 DBG Fetching group info to update portal action="handle signal message" chat_id=CHAT_ID_1 function=UpdateGroupInfo msg_ts=1711269057726 revision=41 sender_uuid=SIGNAL_UUID_1 source_user_mxid=@mark:HOMESERVER.DOMAIN.NAME
2024-03-24T09:30:57+01:00 ERR ReceiveAuthCredentialWithPni error error="3: unexpected panic: previously validated: ZkGroupDeserializationFailure" action="get authorization for today" chat_id=CHAT_ID_1 msg_ts=1711269057726 sender_uuid=SIGNAL_UUID_1
2024-03-24T09:30:57+01:00 ERR Failed to fetch group info error="3: unexpected panic: previously validated: ZkGroupDeserializationFailure" action="handle signal message" chat_id=CHAT_ID_1 function=UpdateGroupInfo msg_ts=1711269057726 revision=41 sender_uuid=SIGNAL_UUID_1 source_user_id=@mark:HOMESERVER.DOMAIN.NAME source_user_mxid=@mark:HOMESERVER.DOMAIN.NAME
2024-03-24T09:30:57+01:00 ERR Didn't get group info after updating portal chat_id=CHAT_ID_1
2024-03-24T09:30:57+01:00 ERR Failed to create portal room error="failed to get group info" action="handle signal message" chat_id=CHAT_ID_1 msg_ts=1711269057726 sender_uuid=SIGNAL_UUID_1
2024-03-24T09:30:57+01:00 DBG Sending WS request action="start receive loops" elapsed=0.005395 loop=signal_websocket_write_loop request_id=8 request_path=/v1/messages/bc4ab8e9-e210-4401-8c51-4d3 request_verb=PUT user_id=@mark:HOMESERVER.DOMAIN.NAME websocket_type=unauthed
2024-03-24T09:30:57+01:00 DBG Received WS response action="start receive loops" loop=signal_websocket_read_loop response_id=8 response_status=200 user_id=@mark:HOMESERVER.DOMAIN.NAME websocket_type=unauthed
2024-03-24T09:30:57+01:00 DBG Deleted response channel for ID action="start receive loops" loop=signal_websocket_read_loop response_id=8 user_id=@mark:HOMESERVER.DOMAIN.NAME websocket_type=unauthed
2024-03-24T09:30:57+01:00 DBG DEBUG: message send response data action="send content" handler="incoming request handler" handler_type="incoming API message handler" path=/api/v1/message recipient=SIGNAL_UUID_1 response_body={"needsSync":false} response_id=8 response_status=200 sender_device_id=1 sender_e164= sender_name=SIGNAL_UUID_1 sender_uuid=SIGNAL_UUID_1 timestamp=1711269057246 user_id=@mark:HOMESERVER.DOMAIN.NAME username=USERNAME_1 verb=PUT websocket_type=authed
2024-03-24T09:30:57+01:00 DBG Sending WS response action="start receive loops" loop=signal_websocket_write_loop request_id=242672216981547648 response_status=200 user_id=@mark:HOMESERVER.DOMAIN.NAME username=USERNAME_1 websocket_type=authed
2024-03-24T09:30:58+01:00 DBG Received WS request action="start receive loops" loop=signal_websocket_read_loop request_id=2323729854519850055 request_path=/api/v1/message request_verb=PUT user_id=@mark:HOMESERVER.DOMAIN.NAME username=USERNAME_1 websocket_type=authed
2024-03-24T09:30:58+01:00 INF deserialized UnidentifiedSenderMessageContent from SIGNAL_UUID_1.1 with type SenderKey component=libsignal file=rust/protocol/src/sealed_sender.rs line=441 target=libsignal_protocol::sealed_sender
2024-03-24T09:30:58+01:00 DBG Decrypted message action="start receive loops" handler="incoming request handler" handler_type="incoming API message handler" path=/api/v1/message sender_device_id=1 sender_e164= sender_name=SIGNAL_UUID_1 sender_uuid=SIGNAL_UUID_1 user_id=@mark:HOMESERVER.DOMAIN.NAME username=USERNAME_1 verb=PUT websocket_type=authed
2024-03-24T09:30:58+01:00 DBG Sending WS response action="start receive loops" loop=signal_websocket_write_loop request_id=2323729854519850055 response_status=200 user_id=@mark:HOMESERVER.DOMAIN.NAME username=USERNAME_1 websocket_type=authed
2024-03-24T09:30:58+01:00 DBG Decrypted content fields action="start receive loops" content_fields="typingMessage (message), { timestamp (uint64), groupId (bytes), action (enum), } " handler="incoming request handler" handler_type="incoming API message handler" path=/api/v1/message sender_device_id=1 sender_e164= sender_name=SIGNAL_UUID_1 sender_uuid=SIGNAL_UUID_1 user_id=@mark:HOMESERVER.DOMAIN.NAME username=USERNAME_1 verb=PUT websocket_type=authed
2024-03-24T09:30:58+01:00 DBG Dropping typing message in chat with no portal chat_id=CHAT_ID_1
2024-03-24T09:30:59+01:00 DBG Received WS request action="start receive loops" loop=signal_websocket_read_loop request_id=2437937448149987945 request_path=/api/v1/message request_verb=PUT user_id=@mark:HOMESERVER.DOMAIN.NAME username=USERNAME_1 websocket_type=authed
2024-03-24T09:30:59+01:00 INF deserialized UnidentifiedSenderMessageContent from SIGNAL_UUID_1.1 with type SenderKey component=libsignal file=rust/protocol/src/sealed_sender.rs line=441 target=libsignal_protocol::sealed_sender
2024-03-24T09:30:59+01:00 DBG Decrypted message action="start receive loops" handler="incoming request handler" handler_type="incoming API message handler" path=/api/v1/message sender_device_id=1 sender_e164= sender_name=SIGNAL_UUID_1 sender_uuid=SIGNAL_UUID_1 user_id=@mark:HOMESERVER.DOMAIN.NAME username=USERNAME_1 verb=PUT websocket_type=authed
2024-03-24T09:30:59+01:00 DBG Sending WS response action="start receive loops" loop=signal_websocket_write_loop request_id=2437937448149987945 response_status=200 user_id=@mark:HOMESERVER.DOMAIN.NAME username=USERNAME_1 websocket_type=authed
2024-03-24T09:30:59+01:00 DBG Decrypted content fields action="start receive loops" content_fields="typingMessage (message), { timestamp (uint64), groupId (bytes), action (enum), } " handler="incoming request handler" handler_type="incoming API message handler" path=/api/v1/message sender_device_id=1 sender_e164= sender_name=SIGNAL_UUID_1 sender_uuid=SIGNAL_UUID_1 user_id=@mark:HOMESERVER.DOMAIN.NAME username=USERNAME_1 verb=PUT websocket_type=authed
2024-03-24T09:30:59+01:00 DBG Dropping typing message in chat with no portal chat_id=CHAT_ID_1

There are no errors in synapse log.

Am available for further debugging or to provide more info if needed.

khanku commented 2 months ago

I am seeing the same error message after upgrading to version 0.5.1 (synapse 1.104.0):

2024-04-10T07:21:58Z DBG Fetching group info to update portal action="handle signal data message" chat_id=FswpNjDfufW60srH3... function=UpdateGroupInfo msg_ts=1712733717698 revision=3 source_user_mxid=@frank:MY.SERVER.TLD
2024-04-10T07:21:58Z ERR ReceiveAuthCredentialWithPni error error="3: unexpected panic: previously validated: ZkGroupDeserializationFailure" action="get authorization for today" chat_id=FswpNjDfufW60srH3... msg_ts=1712733717698
2024-04-10T07:21:58Z ERR Failed to fetch group info error="3: unexpected panic: previously validated: ZkGroupDeserializationFailure" action="handle signal data message" chat_id=FswpNjDfufW60srH3... function=UpdateGroupInfo msg_ts=1712733717698 revision=3 source_user_id=@frank:MY.SERVER.TLD source_user_mxid=@frank:MY.SERVER.TLD
2024-04-10T07:21:58Z DBG Creating Matrix room from incoming message action="handle signal message" chat_id=FswpNjDfufW60srH3... msg_ts=1712733717698 sender_uuid=dced6391-2e8f-...

All group chats are affected while 1-on-1 chats are working fine.

Marcool04 commented 2 months ago

Indeed, just as you @khanku the errors I listed above come from receiving a message in a group. I had in fact not tested single-user chats...

Marcool04 commented 2 months ago

With the recent release of 0.6.0 this error seems to have gone away messages received in groups are now bridging successfully.

Closing now, thanks for all your hard work as always.

Regards, Mark.