Open ZenithElevate opened 3 months ago
Another system now has the same problem.
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?
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.
Are you able to confirm whether it is the expected behavior that a few weeks since the activation lurch begins to send corrupted messages?
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.
Where does lurch keep its keys?
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.
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>
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?
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
Did the above debug info help shed light on the root cause of the error message? Do you need any more debug info?
This epidemic is slowly spreading across our users. We have more and more of those who are unable to send or receive messages. What is causing that? How is it that on a number of systems the software becomes rotten with time? If there is no chance of this being resolved or at leased looked after, we will have to discontinue the use of lurch. Any ideas? Any suggestions?
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:
This is what corresponds to that error in debug log:
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?