Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

There was an error decrypting an OMEMO message addressed to this device. See the debug log for details. #186

Open
ZenithElevate opened this issue May 9, 2024 · 10 comments

Comments

@ZenithElevate
Copy link

In my infrastructure, there is a bunch of Pidgin clients on Windows, a bunch of Android phones with Conversation, and my one and only Linux with Pidgin. Some time ago, I migrated all of them from OTR to OMEMO, and everything worked well until a couple days ago when one and only one Windows Pidgin began to fail to deliver messages to my Linux Pidgin.
I can send to it fine. When it sends to me I get:

There was an error decrypting an OMEMO message addressed to this device. See the debug log for details.

This is what corresponds to that error in debug log:

(18:17:45) xmlnode: XML parser error for xmlnode 0x55a5fec21c90: Domain 3, code 100, level 1: xmlns: URI eu.siacs.conversations.axolotl is not absolute
(18:17:45) jabber: Sending (ssl) (~~~~~~@domain.com/PidginLinuxPC): 
<message type='chat' id='purple3bd8fc4e' to='^^^^^@domain.com'>
<active xmlns='http://jabber.org/protocol/chatstates'/>
<encrypted xmlns='eu.siacs.conversations.axolotl'>
<header sid='116#####42'>
<key rid='74#####12'>Mw......sQXg1.......2Dm/rR.....2Nm/R.....d.........a........g.......Q.zedA5ji7/qC.R............................................................................................................HsMFMG/SIcP3....................................EMAA=</key>
<key rid='12######12'>MwhKE....................................................................A5ji7/qCm...........................................................................................hqorP/3wnc.............................XIN/Lvs....................EMAA=</key>
<key rid='627####00'>M....e/w...T/ZKi.........................................................................................bLfQ/1yv...............6h4=</key>
<key rid='160#####48'>MwgdEiEF............................................IQUMJ5x4gf6JUEWIQ9zedA5ji7/qCmR.............................................................................1kE/Ih...n/1F.................................................................QwAA==</key>
<key rid='185#####79'>MwohBT................................................................TO8l/jZj.........Zs/6j/Dq........N//Go...................gGfk=</key>
<iv>5fl..........WOQ</iv>
</header>
<payload>z5FDaw==</payload>
</encrypted>
<encryption xmlns='urn:xmpp:eme:0' namespace='eu.siacs.conversations.axolotl' name='OMEMO'/>
<store xmlns='urn:xmpp:hints'/>
</message>

Pidgin folks don't know what Lurch does, so the question is to you how is it possible that only one way communication suddenly broke from only one client, and how to restore service?

@ZenithElevate
Copy link
Author

Another system now has the same problem.

@gkdr
Copy link
Owner

gkdr commented May 26, 2024

Hi @ZenithElevate, thanks for the report.
This plugin has some dependencies, e.g. it uses libgcrypt for the crypto operations. Do you know if that was updated on any of the machines when it happened?

Regarding the output from the log: Did you put the dots in the keys? If not, this is invalid base64 encoding.
And that seems to be the output on the sending side, could you also paste the log from the receiving side when the error happens?

@ZenithElevate
Copy link
Author

ZenithElevate commented May 26, 2024

No, those libraries have been copied onto each of the machines, from the same location, and never touched since.
Those dots are mine.
The log is from the receiving side.

@ZenithElevate
Copy link
Author

Are you able to confirm whether it is the expected behavior that a few weeks since the activation lurch begins to send corrupted messages?

@gkdr
Copy link
Owner

gkdr commented Jun 11, 2024

That is certainly not expected behaviour.
Do you see any other errors around the time the message arrives? IIRC there should be some additional information in the debug log, especially if the visible error message specifies it.
By the way, I think the log you posted is from the sending side, because it says: (18:17:45) jabber: Sending (ssl) [...] .

One other moving part is the XMPP server. Were there any upgrades/restarts? If the server can't keep the PEP node state right, as has happened in the past, things can get weird.

@ZenithElevate
Copy link
Author

Where does lurch keep its keys?

@gkdr
Copy link
Owner

gkdr commented Jun 11, 2024

There is a per-user sqlite DB. A decryption error is not necessarily related to the key material however, it could simply be failing at the XML parsing step.

@ZenithElevate
Copy link
Author

ZenithElevate commented Jun 13, 2024

Reciver:

(14:51:43) jabber: Recv (ssl)(1371): <message type="chat" id="purplebfbc0bfe" to="client1@******.***/Pidgin003" from="client2@******.***/W006T4"><active xmlns="http://jabber.org/protocol/chatstates"></active><encrypted xmlns="eu.siacs.conversations.axolotl"><header sid="194243931"><key rid="1967527969">Mwg3EiEFb85KOe9K3JjIMsFxjwT/2OJZ18SjgwWLhMfHChiJuEAaIQUKChImKdsZ4E7kzykByLRxt25rMuOWUuC40n4CAPY+ZCJjMwohBWqxPh9Nss1WVZ8Z4a/siQeMBt6qUEbZBE6ZqyT65K0xEIkBGAAiMKLimXfLW0LTWdROKII6VwbSDGciQcRvj6X4tdc+MWe6owiu7hgBwFe16tyNHyy4zCpJNRSyQfOQKNvaz1wwAA==</key><key rid="743671112">MwglEiEFAF9uBhFD1PbeEYyXnHeqbaoafPOkYePKgBmWubLgZS4aIQUKChImKdsZ4E7kzykByLRxt25rMuOWUuC40n4CAPY+ZCJiMwohBa+c0uEY+Da1BLGPtOk2vMj1G3mdDTvtFGnB+pyUDsY9EFgYACIwGqYFa93lggpUu2H4gQabgj7GZYidMuO5TQdGgSxav/VDQPqmOQx6CULY1+shIRJneRdvOZvSL0Mo29rPXDAA</key><key rid="1167751442">MwohBQPZYqWGvWXfA3+Oomjw+G97yTEsU9kQKyo2thMMmjVpED8YACIwgzs+2AluxuMcxAdHTLI9+QuAyBEJkXPJdkcmSC1v/XaC8NHCxhZpuPQOoL5TmW4MLKArsoMkivc=</key><key rid="1236368212">MwohBToim5s8NMbZA4f/Sx+bkGDMUcBY3bahj8yPLzTTTNI9EAcYASIwkkpvKN3Iu897+XbDP9zYZ7g2ht5RwYFU9DFvV/B7pvsklm2uED7UiDHmmSnlIX0+bQV3jW8AMmM=</key><iv>TmZ7gfH4fODQlrcs</iv></header><payload>Zk/ARg==</payload></encrypted><encryption xmlns="urn:xmpp:eme:0" namespace="eu.siacs.conversations.axolotl" name="OMEMO"></encryption><store xmlns="urn:xmpp:hints"></store></message>

(14:51:43) jabber: XML parser error for JabberStream 0x5605374fb400: Domain 3, code 100, level 1: xmlns: URI eu.siacs.conversations.axolotl is not absolute

(14:51:43) lurch: lurch_message_decrypt: failed to decrypt key (-1005)

Sender:

(14:49:20) xmlnode: XML parser error for xmlnode 04C99828: Domain 3, code 100, level 1: xmlns: URI eu.siacs.conversations.axolotl is not absolute

(14:49:20) jabber: Sending (ssl) (client2@******.***/W006T4): <message type='chat' id='purplebfbc0bfe' to='client1@******.***/Pidgin003'><active xmlns='http://jabber.org/protocol/chatstates'/><encrypted xmlns='eu.siacs.conversations.axolotl'><header sid='194243931'><key rid='1967527969'>Mwg3EiEFb85KOe9K3JjIMsFxjwT/2OJZ18SjgwWLhMfHChiJuEAaIQUKChImKdsZ4E7kzykByLRxt25rMuOWUuC40n4CAPY+ZCJjMwohBWqxPh9Nss1WVZ8Z4a/siQeMBt6qUEbZBE6ZqyT65K0xEIkBGAAiMKLimXfLW0LTWdROKII6VwbSDGciQcRvj6X4tdc+MWe6owiu7hgBwFe16tyNHyy4zCpJNRSyQfOQKNvaz1wwAA==</key><key rid='743671112'>MwglEiEFAF9uBhFD1PbeEYyXnHeqbaoafPOkYePKgBmWubLgZS4aIQUKChImKdsZ4E7kzykByLRxt25rMuOWUuC40n4CAPY+ZCJiMwohBa+c0uEY+Da1BLGPtOk2vMj1G3mdDTvtFGnB+pyUDsY9EFgYACIwGqYFa93lggpUu2H4gQabgj7GZYidMuO5TQdGgSxav/VDQPqmOQx6CULY1+shIRJneRdvOZvSL0Mo29rPXDAA</key><key rid='1167751442'>MwohBQPZYqWGvWXfA3+Oomjw+G97yTEsU9kQKyo2thMMmjVpED8YACIwgzs+2AluxuMcxAdHTLI9+QuAyBEJkXPJdkcmSC1v/XaC8NHCxhZpuPQOoL5TmW4MLKArsoMkivc=</key><key rid='1236368212'>MwohBToim5s8NMbZA4f/Sx+bkGDMUcBY3bahj8yPLzTTTNI9EAcYASIwkkpvKN3Iu897+XbDP9zYZ7g2ht5RwYFU9DFvV/B7pvsklm2uED7UiDHmmSnlIX0+bQV3jW8AMmM=</key><iv>TmZ7gfH4fODQlrcs</iv></header><payload>Zk/ARg==</payload></encrypted><encryption xmlns='urn:xmpp:eme:0' namespace='eu.siacs.conversations.axolotl' name='OMEMO'/><store xmlns='urn:xmpp:hints'/></message>

@gkdr
Copy link
Owner

gkdr commented Jun 14, 2024

That error code seems pretty bad, it's deep from inside libsignal.
However, there should be more specific output still. Can you open the plugin window (ctrl + u), find lurch, click on "Configure Plugin", and make sure that the box is checked with the log level set to debug?

@ZenithElevate
Copy link
Author

ZenithElevate commented Jun 14, 2024

Receive:

(15:22:03) jabber: Recv (ssl)(1371): <message type="chat" id="purpled00e9250" to="client1@******.***/Pidgin003" from="client2@******.***/63885139-57b3-4361-a7c5-068d8aeb42c7"><active xmlns="http://jabber.org/protocol/chatstates"></active><encrypted xmlns="eu.siacs.conversations.axolotl"><header sid="194243931"><key rid="1967527969">Mwg3EiEFb85KOe9K3JjIMsFxjwT/2OJZ18SjgwWLhMfHChiJuEAaIQUKChImKdsZ4E7kzykByLRxt25rMuOWUuC40n4CAPY+ZCJjMwohBWqxPh9Nss1WVZ8Z4a/siQeMBt6qUEbZBE6ZqyT65K0xEIoBGAAiMO4kuhKKJfG6aeW/zjIzzcgxZFp7VWe98zgTX0IxRMkN6+HiMIJc2nQOmpfIeC+P4tRbKApFPWy7KNvaz1wwAA==</key><key rid="743671112">MwglEiEFAF9uBhFD1PbeEYyXnHeqbaoafPOkYePKgBmWubLgZS4aIQUKChImKdsZ4E7kzykByLRxt25rMuOWUuC40n4CAPY+ZCJiMwohBa+c0uEY+Da1BLGPtOk2vMj1G3mdDTvtFGnB+pyUDsY9EFkYACIwFZi9Dksyo3TImlIuFxhKE9zmNtnDoiBeND4lBJPIMo2FGfWTnMhe7FMaSTZalTBqZuLy/Ko5aAwo29rPXDAA</key><key rid="1167751442">MwohBQPZYqWGvWXfA3+Oomjw+G97yTEsU9kQKyo2thMMmjVpEEAYACIwmSA8NeSkEcLOSyfXwt1Bswis1uEtVV0sY3cLOwVlY+L9sk05r82LgPnL2xWIefVtCy/1nbBOG4I=</key><key rid="1236368212">MwohBToim5s8NMbZA4f/Sx+bkGDMUcBY3bahj8yPLzTTTNI9EAgYASIwAWjsV35u8UhbDthk9wddhcxKuWCMjnp1drTnhOaMtBnA7cfvXaJmTrrP33rcKF/rHbSC5prJd3U=</key><iv>ZfKJGG22SaUtxAM7</iv></header><payload>k/oiFA==</payload></encrypted><encryption xmlns="urn:xmpp:eme:0" namespace="eu.siacs.conversations.axolotl" name="OMEMO"></encryption><store xmlns="urn:xmpp:hints"></store></message>
(15:22:03) jabber: XML parser error for JabberStream 0x56053771a9a0: Domain 3, code 100, level 1: xmlns: URI eu.siacs.conversations.axolotl is not absolute
(15:22:03) lurch: [AXC INFO] axc_init: initializing axolotl client
(15:22:03) lurch: [AXC DEBUG] axc_init: created and set axolotl context
(15:22:03) lurch: [AXC DEBUG] axc_init: set axolotl crypto provider
(15:22:03) lurch: [AXC DEBUG] axc_init: created store context
(15:22:03) lurch: [AXC DEBUG] axc_init: set store context
(15:22:03) lurch: [AXC INFO] axc_init: done initializing axc
(15:22:03) lurch: [AXC ERROR] axc_pre_key_message_process: not a pre key msg
(15:22:03) lurch: [AXC NOTICE] Bad MAC
(15:22:03) lurch: [AXC WARNING] Message mac not verified
(15:22:03) lurch: [AXC WARNING] No valid sessions
(15:22:03) lurch: [AXC ERROR] axc_message_decrypt_from_serialized: failed to decrypt cipher message
(15:22:03) lurch: lurch_message_decrypt: failed to decrypt key (-1005)
(15:22:03) jabber: Recv (ssl)(223): <message type="chat" id="purpled00e9251" to="client1@******.***/Pidgin003" from="client2@******.***/63885139-57b3-4361-a7c5-068d8aeb42c7"><active xmlns="http://jabber.org/protocol/chatstates"></active></message>
(15:22:03) lurch: [AXC INFO] axc_init: initializing axolotl client
(15:22:03) lurch: [AXC DEBUG] axc_init: created and set axolotl context
(15:22:03) lurch: [AXC DEBUG] axc_init: set axolotl crypto provider
(15:22:03) lurch: [AXC DEBUG] axc_init: created store context
(15:22:03) lurch: [AXC DEBUG] axc_init: set store context
(15:22:03) lurch: [AXC INFO] axc_init: done initializing axc

Send:

(15:21:55) jabber: Sending (ssl) (client2@******.***/63885139-57b3-4361-a7c5-068d8aeb42c7): <message type='chat' id='purpled00e9254' to='client1@******.***/Pidgin003'><composing xmlns='http://jabber.org/protocol/chatstates'/></message>
(15:21:55) jabber: Sending (ssl) (client2@******.***/63885139-57b3-4361-a7c5-068d8aeb42c7): <r xmlns='urn:xmpp:sm:3'/>
(15:21:55) jabber: Recv (ssl)(34): <a xmlns='urn:xmpp:sm:3' h='48' />
(15:21:55) XEP-0198: Acknowledged 48 out of 48 outbound stanzas
(15:21:57) lurch: [AXC INFO] axc_init: initializing axolotl client
(15:21:57) lurch: [AXC DEBUG] axc_init: created and set axolotl context
(15:21:57) lurch: [AXC DEBUG] axc_init: set axolotl crypto provider
(15:21:57) lurch: [AXC DEBUG] axc_init: created store context
(15:21:57) lurch: [AXC DEBUG] axc_init: set store context
(15:21:57) lurch: [AXC INFO] axc_init: done initializing axc
(15:21:57) lurch: retrieved devicelist for client1@******.***:
<publish node="eu.siacs.conversations.axolotl.devicelist"><item><list
xmlns="eu.siacs.conversations.axolotl"><device id="743671112" /><device
id="1167751442" /><device id="1236368212" /></list></item></publish>

(15:21:57) lurch: retrieved own devicelist:
<publish node="eu.siacs.conversations.axolotl.devicelist"><item><list
xmlns="eu.siacs.conversations.axolotl"><device id="194243931" /><device
id="1967527969" /></list></item></publish>

(15:21:57) lurch: lurch_msg_encrypt_for_addrs: trying to encrypt key for 4 devices
(15:21:57) lurch: lurch_key_encrypt: encrypting key for client1@******.***:1236368212
(15:21:57) lurch: lurch_key_encrypt: encrypting key for client1@******.***:1167751442
(15:21:57) lurch: lurch_key_encrypt: encrypting key for client1@******.***:743671112
(15:21:57) lurch: lurch_key_encrypt: encrypting key for client2@******.***:1967527969
(15:21:57) xmlnode: XML parser error for xmlnode 073D3480: Domain 3, code 100, level 1: xmlns: URI eu.siacs.conversations.axolotl is not absolute
(15:21:57) jabber: Sending (ssl) (client2@******.***/63885139-57b3-4361-a7c5-068d8aeb42c7): <message type='chat' id='purpled00e9255' to='client1@******.***/Pidgin003'><active xmlns='http://jabber.org/protocol/chatstates'/><encrypted xmlns='eu.siacs.conversations.axolotl'><header sid='194243931'><key rid='1967527969'>Mwg3EiEFb85KOe9K3JjIMsFxjwT/2OJZ18SjgwWLhMfHChiJuEAaIQUKChImKdsZ4E7kzykByLRxt25rMuOWUuC40n4CAPY+ZCJjMwohBWqxPh9Nss1WVZ8Z4a/siQeMBt6qUEbZBE6ZqyT65K0xEIsBGAAiMO4JUO3mlcP27MohlAX01M3vzCfduZYA8uUf3fZD3OV/1dvB7P9GNFfadkYTBWRxSJC262uUmoLwKNvaz1wwAA==</key><key rid='743671112'>MwglEiEFAF9uBhFD1PbeEYyXnHeqbaoafPOkYePKgBmWubLgZS4aIQUKChImKdsZ4E7kzykByLRxt25rMuOWUuC40n4CAPY+ZCJiMwohBa+c0uEY+Da1BLGPtOk2vMj1G3mdDTvtFGnB+pyUDsY9EFoYACIwypReErBEym5uScKJB8jyN+9QFUE98nBvm++H9ZxvDKpCO0sCNz7wzrWAdU6qWCMsToH9JOCpmp8o29rPXDAA</key><key rid='1167751442'>MwohBQPZYqWGvWXfA3+Oomjw+G97yTEsU9kQKyo2thMMmjVpEEEYACIwQufbBFbdQejAPcxj1xMuoJ7vcA5MM2EBJdB1B9iCKc0dzSkl/a+gI5MXSyenV3wxHS4If2KUpXE=</key><key rid='1236368212'>MwohBToim5s8NMbZA4f/Sx+bkGDMUcBY3bahj8yPLzTTTNI9EAkYASIwYKGr6jNHqGRAg3JpFOAWfolc7g+FsUnqrciVlP7bcM/9gEW5yVPvfveDCVRYplg/FUZP2gwLsjs=</key><iv>ZsR8U5swo9Kyw1cw</iv></header><payload>xvi4Mw==</payload></encrypted><encryption xmlns='urn:xmpp:eme:0' namespace='eu.siacs.conversations.axolotl' name='OMEMO'/><store xmlns='urn:xmpp:hints'/></message>
(15:21:57) jabber: Sending (ssl) (client2@******.***/63885139-57b3-4361-a7c5-068d8aeb42c7): <r xmlns='urn:xmpp:sm:3'/>
(15:21:57) sound: Playing C:\Program Files (x86)\Pidgin\sounds\naviIn.wav
(15:21:57) jabber: Sending (ssl) (client2@******.***/63885139-57b3-4361-a7c5-068d8aeb42c7): <message type='chat' id='purpled00e9256' to='client1@******.***/Pidgin003'><active xmlns='http://jabber.org/protocol/chatstates'/></message>
(15:21:57) jabber: Sending (ssl) (client2@******.***/63885139-57b3-4361-a7c5-068d8aeb42c7): <r xmlns='urn:xmpp:sm:3'/>
(15:21:57) jabber: Recv (ssl)(34): <a xmlns='urn:xmpp:sm:3' h='49' />
(15:21:57) XEP-0198: Acknowledged 49 out of 50 outbound stanzas
(15:21:57) jabber: Recv (ssl)(34): <a xmlns='urn:xmpp:sm:3' h='50' />
(15:21:57) XEP-0198: Acknowledged 50 out of 50 outbound stanzas

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants