search

gkdr / lurch

XEP-0384: OMEMO Encryption for libpurple.
GNU General Public License v3.0
289 stars 32 forks source link

Can't see messages sent from my account but from another device #52

Open axelsimon opened 7 years ago

axelsimon commented 7 years ago

Hi, I'm getting the following message:

I sent you an OMEMO encrypted message but your client doesn’t seem to support that. Find more information on https://conversations.im/omemo

when sending messages from my account from Conversations on my phone.

It looks like Conversations hasn't properly sent its keys to Pidgin/Lurch, or that Lurch hasn't properly received them. A /lurch show fp conv shows all my devices, including Conversations' OMEMO keys fingerprint:

The devices participating in this conversation and their fingerprints are as follows: This device's (axel@domain.net:1939924165) fingerprint: 5d256630 9975f6e6 5e0c64ee 032741cd da4eab9e 8748ca5a 0ed5de66 xxxxxxxx axel@domain.net:75786319's fingerprint: 78c01743 c8f1901a 476de76b 49e885df 010d6106 ae0f85f0 fb1bc50f xxxxxxxx

So Lurch knows of Conversations and has its fingerprint. Strange.

Any ideas?

Thanks

gkdr commented 7 years ago

Which version of Conversations are you using? As far as I know, it has not been sending those messages for a while now. (It is an additional <body> tag, but it was exchanged for an EME <encryption> tag.)

Can you copy the message's raw XML from the debug log (Tools -> Debug Window)? And additionally see if anything else goes wrong there? Maybe I broke some test cases and did not notice it.

axelsimon commented 7 years ago

Sorry for the slow reply. I think this was on my previous version of Conversations, so 1.18.2. I don't think I've seen it recently (on Conversations 1.18.3) but when/if I do I'll grab the raw stanzas from the debug window.

GigabyteProductions commented 7 years ago

I was experiencing this issue with my build of Conversations 1.19.3 (unmodified source code). While testing this, I unintentionally found that switching to Unencrypted and back to OMEMO is necessary for the own fingerprint trust (though, Conversations was aware of the lurch client's key before message receipt was successful). Switching the account off and back on in Conversations didn't fix the issue. I did not test restarting Conversations entirely.

In case this is of any interest, this successful test that I expected to fail looked like this:

<message lang='en' type='chat' id='5e885da7-1c8e-4488-9117-8cbb801f49a0' from='gigabyteproductions@gigabyteproductions.net/phone' to='REDACTED@gigabyteproductions.net'>
    <encrypted xmlns='eu.siacs.conversations.axolotl'>
        <header sid='1615521877'>
            <key rid='1195612485'>MwohBSRQnkoxoIhOPKRs1QZDjkWw9H+bib6seYMtlLripn40EAsYACIwShqGIqF00xqlX9Gy4rH5oLd/WaBHMWnpCPOfPinY891UK9cYYrcbZpQxtu1Zttnnm4pEfzgd2M0=</key>
            <key rid='2070265000'>MwohBcliumM6jOgZWBlCfzV8u5Fiv2sZZutYgM4MTAYHnRUkEAAYACIw3ca3EL64soO4WVe9ajR76gslgZOWNFpjFkDAHdBRvmCgeBT2k3iAszRWjn6A0W/KDNK8E9hcfrc=</key>
            <key prekey='true' rid='1375750836'>MwgOEiEFk7FLs1lIhJqGB3xAlum1lw6a4dbjuH2apNiAkRQK7X0aIQW905hazd9EtqxbgIIQC8ohdpU1PlPXDSE6BY1D7L7aFyJiMwohBa2I3Bdpe3N/+rxRPq3NOiwyAE/eOjaWDajPdQmzAohVEAAYACIwlqiY/dGa4f2fVLc5fTH7d0Vfv4frZxAiFfnvLicLmxC9qLkV344VWRyn5j4eLzpdmfVTFxaSQi0o1dCrggYwAA==</key>
            <key rid='791767728'>MwohBR9nswkcil2BA3CJUjhwd6MjhBqxHCyUP7omJLkIhhxaEH4YACIwmNSkEKVPMG76ZT5TvZEun8OKl5jTJSf1gqTMdM+YI8DaQjgeNte4m75Ak7jIVURoicBcCYbrVmE=</key>
            <iv>3OFOAvcT7gWt1Bj+wcvQUg==</iv>
        </header>
        <payload>PxJxJlmI8nkT3KLMm4Ne0mrVLQfUOLcsIQ==</payload>
    </encrypted>
    <markable xmlns='urn:xmpp:chat-markers:0'/>
    <origin-id xmlns='urn:xmpp:sid:0' id='5e885da7-1c8e-4488-9117-8cbb801f49a0'/>
    <store xmlns='urn:xmpp:hints'/>
    <encryption xmlns='urn:xmpp:eme:0' name='OMEMO' namespace='eu.siacs.conversations.axolotl'/>
</message>

Where 1195612485 is the key ID of my lurch client. (The prekey has been confirmed to be the exchange with my contact's new device, not my own device.)

kugel- commented 6 years ago

I experience the same issue. I tried to temporarily switch to unencrypted but that didn't help. Conversations has the fingerprint of my desktop pidgin instance

gkdr commented 6 years ago

@kugel- If this still persists, can you copy the raw XMPP and the exact lurch error message from the debug log? How soon after you try to add a new device does this happen? Might be some (server-side) PEP issue.

gkdr commented 6 years ago

I suspect this might have been related to https://github.com/gkdr/carbons/issues/20 somehow. In any case, I have no idea how I can try reproducing it and the issue has been quiet for a while, so if this still happens to you just write here or open a new one.

GigabyteProductions commented 6 years ago

I have been experiencing this lately (actually after my "upgrade" to dev branch in testing #63, but without updating Conversations), and a friend/user complained about experiencing this after updating Conversations (but not upgrading lurch, as far as I understand).

However, I haven't bothered to collect any data, yet.

GigabyteProductions commented 6 years ago

I forgot to point out that I also haven't upgraded carbons since gkdr/carbons@35dd48de17003ba9d17e2b413bc6d762d506d0fc. I'll report back if experience the issue after upgrading.

GigabyteProductions commented 6 years ago

Fast result! As of 530c61474ba0b9e5542e2bf936f75988df93da15 and gkdr/carbons@153b45c425894d1990a2fb7237fdc0309023cacf, with two Pidgin devices logged in, I did not recieve my own messages on each Pidgin if it was sent from the other Pidgin. It did not reproduce after a restart of all clients.

GigabyteProductions commented 6 years ago

Just randomly reproduced again on this same run. Sadly, there is a lack of information to present.

Debug window (note the reception of the stanza is logged):

(19:44:27) jabber: Recv (ssl)(1538): <message to='gigabyteproductions@gigabyteproductions.net/125099263688313876492180' from='gigabyteproductions@gigabyteproductions.net' type='chat'><sent xmlns='urn:xmpp:carbons:2'><forwarded xmlns='urn:xmpp:forward:0'><message xml:lang='en' to='REDACTED@gigabyteproductions.net' from='gigabyteproductions@gigabyteproductions.net/4272579510463595521163282' type='chat' id='purple66cf418e' xmlns='jabber:client'><active xmlns='http://jabber.org/protocol/chatstates'/><encrypted xmlns='eu.siacs.conversations.axolotl'><header sid='1195612485'><key rid='967469621'>MwohBVCMEEIMVEw/qKMMM+Y5pVLzIVIYxMyWHssu/PqnMUYREAEYASIwdpZWqR8jaRhm5lDU86CKu1UzqSZc8RgkXWezGIcmgL/aW4NZepEB42t/d4eg9CE4cNLTsxeUixg=</key><key rid='1615521877'>MwohBVMpZBxvwzM07qcA/3rXoNcPdp3qdlNE4KzD2pIDGEQmEAEYASIwesEIVzYKbgwP37CdJKehCS3xqWOWhn9WSk6eBZ1f/TUWhCJYyf9IRpj25oQhZ0mWD1l5X5rm1gk=</key><key rid='1086045050'>MwohBQHhvPw+RoCtGoTA0ODwrjVmeAa1I/h5vkam6yCB2z4mEAEYACIwpjHsQScNYhOP8waDe0fFZvj3iuwfkvNG+TjC3MQstqxcebLi5vrgLea/UTtfT9rx4GSWxnhoO/A=</key><key rid='1375750836'>MwohBXXgyANHQs7SLbkVDHCYv9hBL5dIS23VK1U7wxwnuV8dEAIYACIwKga65lSUMrmpQoBXpllu4cyhOIJqxJrYXZ1Vgk+utoKMz328sGAfHEFL9y+nne/59IfqJxgpCiQ=</key><iv>+xjNU2W08Zk/Wstp2I0eRA==</iv></header><payload>wSyYucrm3I6VHoW8QgC/XzkwufooyYCo7p6SHVd7r4md684i2CoFlj2tv+ojWvQha5aiXq+YRSKsPhbDJg7Db2bci2mF2p7bxy2s2CaO2MqXZ4yVsNsG7aGWNg==</payload></encrypted><encryption xmlns='urn:xmpp:eme:0' namespace='eu.siacs.conversations.axolotl' name='OMEMO'/><store xmlns='urn:xmpp:hints'/></message></forwarded></sent></message>
(19:44:27) jabber: XML parser error for JabberStream 0x560b2d3ec510: Domain 3, code 100, level 1: xmlns: URI eu.siacs.conversations.axolotl is not absolute
(19:44:27) carbons: Received carbon copy of a sent message.
(19:44:27) carbons: Carbon copy of sent message does not contain a body - stripping and passing it through.
(19:44:27) carbons: Carbon copy of sent message contains a body, but also an additional encrypted element - stripping and passing it through.

Circumstances: two Pidgins (both Fedora's pidgin-2.12.0-3.fc27.x86_64, running 530c61474ba0b9e5542e2bf936f75988df93da15 and gkdr/carbons@153b45c425894d1990a2fb7237fdc0309023cacf) and a Conversations siacs/Conversations@35a4b848a5f664e24a5c9d5297cec1a686528be7 logged into my account. Messages sent from any other device is not received by either Pidgin (but Conversations always successfully receives it).

GigabyteProductions commented 6 years ago

Once it starts, I do not receive my own messages sent from another device to any of my contacts.

gkdr commented 6 years ago

Thanks for the report. There's so many moving parts that I thought maybe the issue resolved itself by now, but I guess I was wrong. I can't quite tell: did it get worse with the new carbons? Also I realized the carbons debug statements are pretty stupid, should have double-checked that while testing the functionality.

Okay, so when the issue was opened, you got the "you received an OMEMO message" text instead of the decrypted message, and now you simply get nothing, correct?

GigabyteProductions commented 6 years ago

My friend, who isn't up-to-date, gets Conversations's fallback text (remember #57 when testing this).

I am using the later commits mentioned, and I don't even see the fallback text for messages sent from Conversations.

gkdr commented 6 years ago

I could not reproduce this, but incidentally found another funny thing because I was testing the other bug you reported and still had the conversation with my own account open in another tab. Basically, in the manual handling of carbon-copied, encrypted messages sent from another own device, I accidentally told it to write the message to the sender's conversation, and not the recipient's. I assume it only worked sometimes because libpurple handles this intelligently, but when I had the conversation window with myself open, it would write all mesages to there, that's how I noticed.

The problem is that libpurple does not know what to do with incoming messages sent from the own account to someone else, and I can't handle this in carbons because of the encryption. However, I think I should just add another handler with a high priority in carbons (high means later handling in libpurple), which would handle all of this manual writing, so lurch can just pass the message on as usual.

I am not sure it will fix the problem described here, but I do think it's worth a try. Would you mind trying with 2ea47f4?

GigabyteProductions commented 6 years ago

I've updated my clients to 2ea47f488ba80910121f4f007f6c56400e856509. Due to the seemingly random nature of the bug, I think I'll have to follow up after more usage.

However, it seems to be working well, so far.

GigabyteProductions commented 6 years ago

It took a while but the issue reproduced on one of my Pidgin/lurch client after running for about 24 days with an uninterrupted connection to the server. Messages I send from another device are not displayed. In addition, messages sent from my contact won't decrypt and show fallback text.

Note: my client's device ID (1195612485) is not actually referenced in the non-decryptable messages. The client I'm using to send the messages, Conversations, also shows this device's fingerprint as greyed-out/inactive (Conversations usually does this when a device has been offline for a long period of time). Understanding this, I suspect lurch may not be maintaining that its key is valid. My Conversations client has been on for 10 days (but constantly disconnecting and reconnecting), and was sending decryptable messages within those 10 days. Fully restarting Conversations for the first time during this investigation reveals no improvement; it still does not reference the relevant device ID.

Note: There was a period of 2 days where no message was sent to or received by this particular contact.

Note: I suspect I would see a fallback body for my own messages if one was present...

I send message to contact:

(18:36:41) jabber: Recv (ssl)(1350): <message to='gigabyteproductions@gigabyteproductions.net/15734987375658530817179282' from='gigabyteproductions@gigabyteproductions.net' type='chat'><sent xmlns='urn:xmpp:carbons:2'><forwarded xmlns='urn:xmpp:forward:0'><message xml:lang='en' to='REDACTED@gigabyteproductions.net' from='gigabyteproductions@gigabyteproductions.net/phone' type='chat' id='0174edfe-6de3-4646-afde-09871149931c' xmlns='jabber:client'><encrypted xmlns='eu.siacs.conversations.axolotl'><header sid='1615521877'><key rid='967469621'>MwohBf7FH/yaZxXcvNd4l5XpcE2FN8grHmKnVMeNzmBKbh5DEAcYACIwZ3V9NYy8NDcrPEUae9toC4e0aeJYqMgN79DSSvnEo9AU016SLbkJVm8MF7H6BN72FELnsfwiV4g=</key><key rid='967696253'>MwohBQ/TBjhtp8BwFeDwG3qZX9pchkYNWVUE63/x8bRFi0huECwYACIw5ScK3PrDsU4R8NLqoqStm8iru4P/EefcUpLsX/mF2iCb98vQYPhj/qLzXvz0oDXaPYMxBLkIsqg=</key><key rid='1086045050'>MwohBT6ty17ERj7DPUCeCh+4qxtAr90xM9TlQ1kAW7jrDQtpEAYYACIwBCl90JQ7T/DtCAeXhfw7ArOTJrX2XLHu18Lg+qZmCUqyb8vh6smwVACmVzFmPbgCfU/TPglVaVw=</key><iv>EBcJRX4OBi9GsEig3lQn8g==</iv></header><payload>Tuz5OtKKU7PumdrT3KpqKJ6DV/g=</payload></encrypted><markable xmlns='urn:xmpp:chat-markers:0'/><origin-id xmlns='urn:xmpp:sid:0' id='0174edfe-6de3-4646-afde-09871149931c'/><store xmlns='urn:xmpp:hints'/><encryption xmlns='urn:xmpp:eme:0' name='OMEMO' namespace='eu.siacs.conversations.axolotl'/></message></forwarded></sent></message>
(18:36:41) jabber: XML parser error for JabberStream 0x555fc47e9810: Domain 3, code 100, level 1: xmlns: URI eu.siacs.conversations.axolotl is not absolute
(18:36:41) carbons: Received carbon copy of a sent message.
(18:36:41) carbons: Carbon copy of sent message does not contain a body - stripping and passing it through.
(18:36:41) carbons: Carbon copy of sent message contains a body, but also an additional encrypted element - stripping and passing it through.
(18:36:41) lurch: received omemo message that does not contain a key for this device, skipping

Receive message from contact:

(19:04:26) jabber: Recv (ssl)(1250): <message xml:lang='en' to='gigabyteproductions@gigabyteproductions.net/15734987375658530817179282' from='REDACTED@gigabyteproductions.net/Conversations.Dhog' type='chat' id='5d976d02-cd09-42c6-b00d-dc10e27d508b'><encrypted xmlns='eu.siacs.conversations.axolotl'><header sid='1086045050'><key rid='967469621'>MwohBcu1ri6+cDkaAgTiv59R2Zy7IANUrzqHdPVcNH0w1t4YEAEYACIwEER//6cuxuSQCEPGuGWjL/lScyDUCA4oJXM0f64d5DKdymyIhc4kZHKMbhp26bv6KOXvA1iHapU=</key><key rid='967696253'>MwohBebBQMgMjgslOHNO0i6FlMxR5klbs9kekLdjcES+o1EDEEAYMCIwL2ErD0U7dMQPGZVIveA5Frdob63ha5AC+3+owCnGA7gOPQsiW1BMhqkWd4+V5KBtTMGqZy+gnVg=</key><key rid='1615521877'>MwohBcSCXe4QKLpAOmZZkYPiE5H9MF5bhnK7HCainwHdCZNeEAAYAiIwLbdeSGgDbIheJK4cOpl9GGB3gk2eOHklr7iKig6SSrWYeuZRVwtWtDAhbsG/xNf8aWkelWW0lr8=</key><iv>tw3f2oIVh/W45vDnhQPo5Q==</iv></header><payload>k0A=</payload></encrypted><markable xmlns='urn:xmpp:chat-markers:0'/><origin-id xmlns='urn:xmpp:sid:0' id='5d976d02-cd09-42c6-b00d-dc10e27d508b'/><store xmlns='urn:xmpp:hints'/><encryption xmlns='urn:xmpp:eme:0' name='OMEMO' namespace='eu.siacs.conversations.axolotl'/><body>I sent you an OMEMO encrypted message but your client doesn\u2019t seem to support that. Find more information on https://conversations.im/omemo</body></message>
(19:04:26) jabber: XML parser error for JabberStream 0x555fc47e9810: Domain 3, code 100, level 1: xmlns: URI eu.siacs.conversations.axolotl is not absolute
(19:04:26) lurch: received omemo message that does not contain a key for this device, skipping
(19:04:26) jabber: Binding conversation to REDACTED@gigabyteproductions.net/Conversations.Dhog
gkdr commented 6 years ago

PEP nodes (like the one saving the devicelist) are not persistent and I am not sure if it's even properly defined how they should be handled by servers. For this reason, every time you connect to your account, this plugin does two things: 1) uploading the whole device bundle again, just in case 2) asking the server for the own devicelist so it can readd itself to it if necessary. It only does it at startup because usually you get "PEP updates", but not if there is no list at all because it was dropped.

So my suspicion is that the PEP node somehow got dropped, because it can happen. However, I also suspect that when your Conversations client reconnected, it should have caused a PEP update message with the device list. If you happen to still have the logs, I'm looking for messages like these: (22:09:53) lurch: lurch_devicelist_process: processing devicelist from b@localhost for b@localhost.

Otherwise, I don't really have a clue what to do except periodically sending the cached devicelist to the server, and a bundle too for good measure. You could check what's currently in the PEP note by sending the following through the XMPP console:

<iq type='get'
    to='b@localhost'
    id='whatever123'>
  <pubsub xmlns='http://jabber.org/protocol/pubsub'>
    <items node='eu.siacs.conversations.axolotl.devicelist'/>
  </pubsub>
</iq>
GigabyteProductions commented 6 years ago

Yep, the device ID is missing from the list.

So my suspicion is that the PEP node somehow got dropped, because it can happen.

OMEMO XEP mentions a potential race condition that can cause a device ID to get lost due to another device's simultaneous update. The mentioned mitigation to the race condition is to check for and re-add your own device ID upon receiving a PEP update. Perhaps doing this will mitigate the issue, regardless of race condition, here?

From: https://xmpp.org/extensions/xep-0384.html#usecases-announcing

This step presents the risk of introducing a race condition: Two devices might simultaneously try to announce themselves, unaware of the other's existence. The second device would overwrite the first one. To mitigate this, devices MUST check that their own device ID is contained in the list whenever they receive a PEP update from their own account. If they have been removed, they MUST reannounce themselves.

Back to you:

However, I also suspect that when your Conversations client reconnected, it should have caused a PEP update message with the device list.

I do not have the original logs, but some quick testing with disabling and re-enabling Internet access, the account, or killing and re-opening Conversations does not cause a device list update in the debug log or XMPP Console. If I had to guess why: I'm guessing Conversations isn't sending updates if it sees its own device ID from a query. In which case I think it's less likely that Conversations reconnecting every few seconds (wifi issue, Android sucks) is smashing other devices out of the list, but I suppose it might give some insight to investigate when else Conversations will send updates.

I still suspect at this point that one of the clients (Conversations, or another Pidgin/lurch on an also unreliable connection) is sending an update that excludes the device ID in question, which should be obvious to that device due to the PEP updates.

gkdr commented 6 years ago

Yep, the device ID is missing from the list.

But the devicelist is not empty? Could you tell me the output of /lurch show id list?

The mentioned mitigation to the race condition is to check for and re-add your own device ID upon receiving a PEP update. Perhaps doing this will mitigate the issue, regardless of race condition, here?

I did implement this, and just confirmed that it still works. Using /lurch remove id <deviceid> I removed my own ID, which led to the following log:

(09:45:17) jabber: Sending (ssl) (a@localhost/edc0b95e-f35f-408d-852b-77560a3c64b0): <iq type='set' id='purple8fef6881'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.devicelist'><item><list xmlns='eu.siacs.conversations.axolotl'/></item></publish></pubsub></iq>
(09:45:17) jabber: Recv (ssl)(394): <iq id='purple8fef6881' type='result' to='a@localhost/edc0b95e-f35f-408d-852b-77560a3c64b0'/><message type='headline' to='a@localhost/edc0b95e-f35f-408d-852b-77560a3c64b0' from='a@localhost'><event xmlns='http://jabber.org/protocol/pubsub#event'><items node='eu.siacs.conversations.axolotl.devicelist'><item id='1'><list xmlns='eu.siacs.conversations.axolotl'/></item></items></event></message>
(09:45:17) lurch: lurch_pep_own_devicelist_request_handler: comparing received devicelist with cached one
(09:45:17) lurch: lurch_pep_own_devicelist_request_handler: own id was missing, adding it
(09:45:17) lurch: lurch_pep_own_devicelist_request_handler: devicelist needs publishing...
(09:45:17) jabber: Sending (ssl) (a@localhost/edc0b95e-f35f-408d-852b-77560a3c64b0): <iq type='set' id='purple8fef6883'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.devicelist'><item><list xmlns='eu.siacs.conversations.axolotl'><device id='942218035'/></list></item></publish></pubsub></iq>
(09:45:17) lurch: lurch_pep_own_devicelist_request_handler: 
...done:
[...]
(09:45:17) lurch: lurch_bundle_publish_own: published own bundle for a@localhost
(09:45:17) lurch: lurch_devicelist_process: processing devicelist from a@localhost for a@localhost
(09:45:17) lurch: lurch_devicelist_process: cached devicelist is
<publish node="eu.siacs.conversations.axolotl.devicelist"><item><list
xmlns="eu.siacs.conversations.axolotl"><device id="942218035" /></list></item></publish>
(09:45:17) lurch: lurch_pep_own_devicelist_request_handler: comparing received devicelist with cached one
(09:45:17) lurch: lurch_pep_own_devicelist_request_handler: own id was already contained in received devicelist, doing nothing

The key element here is <event>, because this is what makes it a PEP "update". I assume that when a server drops a PEP node, you do not receive an update - it is just gone. To deal with this (and also first-time install), this plugin creates all necessary nodes at account connect. I'm not sure if there is anything I can do but doing that more often. However, I wonder why your other devices are on there.

GigabyteProductions commented 6 years ago

But the devicelist is not empty? Could you tell me the output of /lurch show id list?

The list from pubsub is not empty:

<iq lang='en' to='gigabyteproductions@gigabyteproductions.net/15734987375658530817179282' from='gigabyteproductions@gigabyteproductions.net' type='result' id='test1'>
    <pubsub xmlns='http://jabber.org/protocol/pubsub'>
        <items node='eu.siacs.conversations.axolotl.devicelist'>
            <item id='5F77A224A88B9'>
                <list xmlns='eu.siacs.conversations.axolotl'>
                    <device id='967469621'/>
                    <device id='1615521877'/>
                </list>
            </item>
        </items>
    </pubsub>
</iq>

But /lurch show id list on the affected device shows:

(05/31/2018 11:50:03 AM) This user (gigabyteproductions@gigabyteproductions.net) has the following devices:
1195612485 (this device)
967469621
1615521877

I did implement this, and just confirmed that it still works. Using /lurch remove id I removed my own ID

Interestingly, this does not cause my affected device to notice that it's still missing from the list!

Unloading and reloading the plugin (without restarting Pidgin) does re-add the ID to the list (confirmed with a console query). However, my other clients (another Pidgin/lurch, and Conversations) did not catch on to the new ID until some kind of reload (reload plugin in Pidgin, disable/re-enable account in Conversations).

From my past experience, it is known that my contacts must also reload their clients to get my "new" device ID, too.

I should have grabbed a log to confirm, but are you sure a PEP event is sent in the plugin initialization logic?

I assume that when a server drops a PEP node, you do not receive an update - it is just gone.

By "drop", do you mean a kind of automatic deletion, or failure to send/receive a specific update?

I have doubts that my server is deleting nodes, but I can investigate this if you disagree.

On the matter of failure to send/receive PEP updates: Since XMPP connections run over TCP, either the specific update makes it through to the other side in TCP's retransmissions, or the entire TCP session is reset and closed. If a TCP connection is closed, the client will re-connect and re-run all the initialization logic that ensures the device ID makes it into the list. So, if the server is sending updates to the affected client, the affected client must be receiving them, or it'll reconnect due to a networking issue.

In addition, the affected client is on the same broadcast domain as the server, and I don't expect there was a single disconnect since the time I connected (still trying to figure out when connection was last established besides through logs). I experience this issue only with this persistently-connected client. A contact of mine experiences the issue sometimes, and, for the most part, his affected client was also persistently connected.

Anyway, now that it is clear that the cause of the issue (in my case) is the device ID being removed from the list, I'll try to cause further reproduction of the issue and extract more logs. Hopefully it won't take another month to reproduce, but expect the delay...

gkdr commented 6 years ago

Interestingly, this does not cause my affected device to notice that it's still missing from the list!

Did you watch the traffic on the debug log? After setting the PEP node, every subscribed device (including the sender) should have received a PEP event. Your server might see that the list is the same and not send an update event though, however I'd guess it doesn't actually inspect the content.

Unloading and reloading the plugin (without restarting Pidgin) does re-add the ID to the list (confirmed with a console query). However, my other clients (another Pidgin/lurch, and Conversations) did not catch on to the new ID until some kind of reload (reload plugin in Pidgin, disable/re-enable account in Conversations).

This does sound to me like server's PEP handling is broken. As I said, a change in the node (which you confirmed happened by querying the node manually) should trigger a PEP event to all subscribed devices. Since it's 2 different clients who didn't get the change, I'd blame the server for not sending, to be honest.

From my past experience, it is known that my contacts must also reload their clients to get my "new" device ID, too.

Your contacts read the same devicelist node as your own clients (but they're not allowed to write them unless you specifically allow it).

I should have grabbed a log to confirm, but are you sure a PEP event is sent in the plugin initialization logic?

Not the plugin init logic, but a handler is registered on the "account connected" event which specifically requests the own devicelist node with the same query you manually entered in the XMPP console, and the response is handled by the same lurch_pep_own_devicelist_request_handler you see in the debug log I pasted above. It has to be set as a handler manually for that call because a response to a query is not a PEP event, which is also the reason nothing happens when you enter the query into the XMPP console. This is the code I suggested calling manually (as in not part of the protocol) more often, but I'd hate to introduce more state than necessary.

You should be able to watch all this in the debug log when reconnecting an account.

By "drop", do you mean a kind of automatic deletion, or failure to send/receive a specific update? I have doubts that my server is deleting nodes, but I can investigate this if you disagree.

As far as I know, PEP nodes are not persistent. They are definitely gone when a server restarts, for example. So I can imagine they can just "get lost" somehow, since it's not specified they shouldn't. Maybe you have some XEP installed which spams PEP updates and the server software just keeps the last 1000 or whatever. Maybe it has a debug log you could activate?

gkdr commented 5 years ago

Closing this old issue for age and inactivity. If you come across this problem again, please create a new one.

GigabyteProductions commented 5 years ago

Actually, I still run into this issue on a regular basis, but been too busy to isolate variables and properly investigate.

I'll open a new issue with more details when I investigate, if you'd really prefer that over adding to this issue.

gkdr commented 5 years ago

Sorry, I just saw that the last reply is by me and was done quite some time ago. Since you still run into the issue, I'll reopen this one (though I'm still not sure if the additional info from the lengthy thread might help or is just confusing). There are some PEP problems in other issues too, I really wonder what the cause is.