Outgoing messages doubled

[barefootcoder]

This just started happening today. When I send a message in Slack (either chat or personal), it's always displayed in the upper pane of the conversation (i.e., in with the incoming messages). Today, however, it appears up there twice. I verified with my coworkers that they're not seeing the messages twice, so it's not actually double sending ... just double displaying. And only for outgoing messages.

The last undoubled message I sent today was at 01:37:29 PM PDT and the first doubled one was at 01:49:17 PM PDT, so I have a fairly narrow window of when it started. I did not restart Pidgin between those two times; I did however restart Pidgin since then to see if that would fix it (it did not). I also verified that it doesn't happen for other protocols.

Any ideas on what I could look at to get more info? workarounds? anything else?

[dylex]

I tested just now on two different slacks with channels and IMs and don't see this (in finch 2.13.0). If you want to get a debug log of just sending a message that could help.

[barefootcoder]

Okay, this is as short a window as I could manage. Hopefully it's not too much useless stuff.

Pidgin Debug Log : Wed 15 Aug 2018 04:42:18 PM PDT
(16:42:03) pidgin-libnotify: Conversation Updated (UNSEEN)
(16:42:03) pidgin-libnotify: REMOVING ATTENTION FOR (chat:prpl-slack:x%40slack.com:tech) (0)
(16:42:04) slack: RTM: {"id":115,"type":"message","channel":"CXXXXXXX","text":"<@UUUUU|jcal>: not sure ... maybe we need @steve to jump in here at this point."}
(16:42:04) pidgin-libnotify: Conversation Updated (OTHER)
(16:42:04) pidgin-libnotify: Conversation Updated (UNSEEN)
(16:42:04) pidgin-libnotify: REMOVING ATTENTION FOR (chat:prpl-slack:x%40slack.com:tech) (0)
(16:42:05) websocket: message 81 len 227
(16:42:05) slack: RTM 1: {"type":"message","user":"UUUUUUUU","text":"<@UXXXXXX|jcal>: not sure ... maybe we need @steve to jump in here at this point.","team":"TXXXXX","channel":"CX","event_ts":"1534376525.000100","ts":"1534376525.000100"}
(16:42:05) pidgin-libnotify: Chat (barefootcoder) (@jcal: not sure ... maybe we need @steve to jump in here at this point.)
(16:42:05) websocket: message 81 len 144
(16:42:05) slack: RTM 1: {"ok":true,"reply_to":115,"ts":"1534376525.000100","text":"<@UXXX|jcal>: not sure ... maybe we need @steve to jump in here at this point."}
(16:42:05) pidgin-libnotify: Chat (barefootcoder) (@jcal: not sure ... maybe we need @steve to jump in here at this point.)
(16:42:05) slack: api call: https://slack.com/api/channels.mark?token=xoxp-&channel=C
(16:42:05) util: requesting to fetch a URL
(16:42:05) dnsquery: Performing DNS lookup for slack.com
(16:42:05) dns: DNS child 4585 no longer exists
(16:42:05) dns: Created new DNS child 4609, there are now 1 children.
(16:42:05) dns: Successfully sent DNS request to child 4609
(16:42:05) dns: Got response for 'slack.com'
(16:42:05) dnsquery: IP resolved for slack.com
(16:42:05) proxy: Attempting connection to 52.85.81.4
(16:42:05) proxy: Connecting to slack.com:443 with no proxy
(16:42:05) proxy: Connection in progress
(16:42:05) proxy: Connecting to slack.com:443.
(16:42:05) proxy: Connected to slack.com:443.
(16:42:05) nss: SSL version 3.3 using 128-bit AES-GCM with 128-bit AEAD MAC
Server Auth: 2048-bit RSA, Key Exchange: 256-bit ECDHE, Compression: NULL
Cipher Suite Name: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
(16:42:05) nss: subject=CN=slack.com,O="Slack Technologies, Inc.",L=San Francisco,ST=CA,C=US issuer=CN=DigiCert SHA2 Secure Server CA,O=DigiCert Inc,C=US
(16:42:05) nss: subject=CN=DigiCert SHA2 Secure Server CA,O=DigiCert Inc,C=US issuer=CN=DigiCert Global Root CA,OU=www.digicert.com,O=DigiCert Inc,C=US
(16:42:05) nss: partial certificate chain
(16:42:05) certificate/x509/tls_cached: Starting verify for slack.com
(16:42:05) certificate/x509/tls_cached: Checking for cached cert...
(16:42:05) certificate/x509/tls_cached: ...Found cached cert
(16:42:05) nss/x509: Loading certificate from /home/buddy/.purple/certificates/x509/tls_peers/slack.com
(16:42:05) certificate/x509/tls_cached: Peer cert matched cached
(16:42:05) nss/x509: Exporting certificate to /home/buddy/.purple/certificates/x509/tls_peers/slack.com
(16:42:05) util: Writing file /home/buddy/.purple/certificates/x509/tls_peers/slack.com
(16:42:05) nss: Trusting CN=slack.com,O="Slack Technologies, Inc.",L=San Francisco,ST=CA,C=US
(16:42:05) certificate: Successfully verified certificate for slack.com
(16:42:05) util: request constructed
(16:42:05) util: Response headers: 'HTTP/1.1 200 OK
Content-Type: application/json; charset=utf-8
Transfer-Encoding: chunked
Connection: close
Date: Wed, 15 Aug 2018 23:42:05 GMT
Server: Apache
Expires: Mon, 26 Jul 1997 05:00:00 GMT
X-Content-Type-Options: nosniff
Strict-Transport-Security: max-age=31536000; includeSubDomains; preload
Referrer-Policy: no-referrer
Cache-Control: private, no-cache, no-store, must-revalidate
X-OAuth-Scopes: identify,read,post,client,apps
Vary: Accept-Encoding
Pragma: no-cache
X-Accepted-OAuth-Scopes: channels:write,post
X-XSS-Protection: 0
X-Slack-Req-Id: 8b207a9b-fee4-4742-ba17-45fb5a81f5aa
X-Slack-Backend: h
Access-Control-Allow-Origin: *
X-Via: haproxy-www-nfrs
X-Cache: Miss from cloudfront
Via: 1.1 0e55a2120901dc62d004b10018942726.cloudfront.net (CloudFront)
X-Amz-Cf-Id: zUnw0r8l9WJa9Le8JHFcyvFM8TUmWMWOE_QreZDKe3Q4T2PyAb-9uQ==

'
(16:42:05) slack: api response: {"ok":true}
(16:42:05) websocket: message 81 len 231
(16:42:05) slack: RTM 1: {"type":"channel_marked","channel":"C","ts":"1534376518.000100","unread_count":1,"unread_count_display":1,"num_mentions":0,"num_mentions_display":0,"mention_count":0,"mention_count_display":0,"event_ts":"1534376525.000100"}
(16:42:05) slack: Unhandled RTM type channel_marked
(16:42:06) pidgin-libnotify: Conversation Updated (UNSEEN)
(16:42:06) pidgin-libnotify: REMOVING ATTENTION FOR (chat:prpl-slack:x%40slack.com:tech) (0)
(16:42:11) slack: api call: https://slack.com/api/channels.mark?token=xoxp-&ts=1534376525.000100&channel=C
(16:42:11) util: requesting to fetch a URL
(16:42:11) dnsquery: Performing DNS lookup for slack.com
(16:42:11) dns: Successfully sent DNS request to child 4609
(16:42:11) dns: Got response for 'slack.com'
(16:42:11) dnsquery: IP resolved for slack.com
(16:42:11) proxy: Attempting connection to 52.85.81.4
(16:42:11) proxy: Connecting to slack.com:443 with no proxy
(16:42:11) proxy: Connection in progress
(16:42:11) proxy: Connecting to slack.com:443.
(16:42:11) proxy: Connected to slack.com:443.
(16:42:12) nss: SSL version 3.3 using 128-bit AES-GCM with 128-bit AEAD MAC
Server Auth: 2048-bit RSA, Key Exchange: 256-bit ECDHE, Compression: NULL
Cipher Suite Name: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
(16:42:12) nss: subject=CN=slack.com,O="Slack Technologies, Inc.",L=San Francisco,ST=CA,C=US issuer=CN=DigiCert SHA2 Secure Server CA,O=DigiCert Inc,C=US
(16:42:12) nss: subject=CN=DigiCert SHA2 Secure Server CA,O=DigiCert Inc,C=US issuer=CN=DigiCert Global Root CA,OU=www.digicert.com,O=DigiCert Inc,C=US
(16:42:12) nss: partial certificate chain
(16:42:12) certificate/x509/tls_cached: Starting verify for slack.com
(16:42:12) certificate/x509/tls_cached: Checking for cached cert...
(16:42:12) certificate/x509/tls_cached: ...Found cached cert
(16:42:12) nss/x509: Loading certificate from /home/buddy/.purple/certificates/x509/tls_peers/slack.com
(16:42:12) certificate/x509/tls_cached: Peer cert matched cached
(16:42:12) nss/x509: Exporting certificate to /home/buddy/.purple/certificates/x509/tls_peers/slack.com
(16:42:12) util: Writing file /home/buddy/.purple/certificates/x509/tls_peers/slack.com
(16:42:12) nss: Trusting CN=slack.com,O="Slack Technologies, Inc.",L=San Francisco,ST=CA,C=US
(16:42:12) certificate: Successfully verified certificate for slack.com
(16:42:12) util: request constructed
(16:42:12) util: Response headers: 'HTTP/1.1 200 OK
Content-Type: application/json; charset=utf-8
Transfer-Encoding: chunked
Connection: close
Date: Wed, 15 Aug 2018 23:42:12 GMT
Server: Apache
Expires: Mon, 26 Jul 1997 05:00:00 GMT
X-Content-Type-Options: nosniff
Strict-Transport-Security: max-age=31536000; includeSubDomains; preload
Referrer-Policy: no-referrer
Cache-Control: private, no-cache, no-store, must-revalidate
X-OAuth-Scopes: identify,read,post,client,apps
Vary: Accept-Encoding
Pragma: no-cache
X-Accepted-OAuth-Scopes: channels:write,post
X-XSS-Protection: 0
X-Slack-Req-Id: f4ee03de-b46b-493b-812d-15a595acc1b8
X-Slack-Backend: h
Access-Control-Allow-Origin: *
X-Via: haproxy-www-wwh4
X-Cache: Miss from cloudfront
Via: 1.1 c5a973adb2cf2730cc2e8d8b45a9cbbe.cloudfront.net (CloudFront)
X-Amz-Cf-Id: cWpJrZXZe1BOejVVE5M_cp4i256NxI-NYA8jTDZqSCZSRQd8yc_9lQ==

'
(16:42:12) slack: api response: {"ok":true}
(16:42:12) websocket: message 81 len 231
(16:42:12) slack: RTM 1: {"type":"channel_marked","channel":"C","ts":"1534376525.000100","unread_count":0,"unread_count_display":0,"num_mentions":0,"num_mentions_display":0,"mention_count":0,"mention_count_display":0,"event_ts":"1534376532.000100"}
(16:42:12) slack: Unhandled RTM type channel_marked
(16:42:18) prefs: /pidgin/filelocations/last_save_folder changed, scheduling save.

[dylex]

The strange part is the line (16:42:05) slack: RTM 1: {"type":"message", ... which is your own sent message coming back as if it's a new message. I don't think I've seen that before and can't make it happen. I notice it has a team set on it, which I don't usually see either. Is this one of those shared channels with multiple connected teams? I presume pidgin-libnotify can't change anything.

I don't see anything explicitly on the slack api docs about this (one way or another) or recent changes. The only even possibly relevant thing is about shared channel RTM:

deliveries are duplicated in shared channels when installed on multiple joined workspaces due to the multiple socket connections.

But this doesn't seem quite right.

(BTW, I edited your message to remove identifying information and auth tokens.)

[tykeal]

Just started happening to me as well. It's happening on channels as well as DMs. AFAIK our team doesn't have any shared team channels, and I know for a fact that the primary channels I'm in (and seeing this on) are not shared team channels as they're for our internal IT discussions.

[dylex]

Hm. Given that the message comes before the send response, I think I have an idea how to fix this for channels, since we can check the timestamp against the last received message before calling serv_got_chat_in (still leaves a small race condition if there's an intervening message but probably okay). But this trick won't work for IMs because libpurple displays them itself, so it's too late... I'll add this for channels anyway to see if it works.

Maybe this is a change still propagating and will eventually happen on my slacks too so I can test better.

[barefootcoder]

I notice it has a team set on it, which I don't usually see either. Is this one of those shared channels with multiple connected teams? I presume pidgin-libnotify can't change anything.

No, we have a fairly small team and we're all on one instance. I did happen to send you a message sent on a team channel, but (as tykeal confirmed, and thank goodness I'm not the only one seeing this) it happens on personal messages as well. I'd be happy to send you another debug log with one of those if that's helpful.

(BTW, I edited your message to remove identifying information and auth tokens.)

Thanks much. I did glance quickly at the wall of text there to see if anything password-y jumped out at me, but I didn't see anything, and then I thought, I'm sure Pidgin wouldn't put sensitive stuff like that in a debug log. :-D Probably should have thought that through a bit more. ;->

(If you can tell me what to look for and expunge, I'll make sure any future debug logs are sanitized before posting. Also, should I maybe put such things in a gist vs a big text dump in the issue?)

[pacak]

Same problem btw, let me know if you need any info.

[ordex]

FYI, ed82bbe did not help :(

[fredcooke]

I've got it, too, and in PMs and in proper channels, just the same, but only when sent from pidgin. Not when sent using the web UI and just logged in pidgin. Hope that helps.

[fredcooke]

@dylex I checked my own tiny 4 person channel and it happens there, as well as the other bigger/older ones, so I sent you an invite, feel free to create a token and test there in the #random channel. Just don't link here, please :-)

[xavier-re]

@dylex same problem here, ed82bbe did not help for personnal (1 to 1) messages. messages sent to channels are fine, not duplicated. messages sent to mpdm-channels are fine too, not duplicated. (multi -DM)

[PresGas]

I just got it today and in direct chats, multi-chats as well as channels. Incoming messages are fine. Yesterday was fine outgoing. I did a fresh clone as a "nuke from orbit" option and still getting the issue.

[dylex]

This is now happening on one of my slacks as well, so I should be able to test and figure out something now.

[dylex]

Actually, ed82bbe does seem to fix the problem for me on channels only (not on IMs). Can others confirm this? (I'll keep working on IMs.)

[xavier-re]

I confirm ed82bbe does seem to fix the problem on channels only (not on IMs).

[dylex]

Great, thank you. I have a plan to fix IMs now as well -- coming in the next hour or so.

[dylex]

With ee0f2bd both IMs and channels work for me. Let me know if anyone still sees this issue after updating.

As written, there is a slight chance of still seeing duplicates on a really busy/laggy channel if another message is sent at the same time, depending how slack handles this. If anyone observes this, I have a possible tweak to fix it.

[xavier-re]

ee0f2bd fixed it for me too, my messages in IM or channels are not duplicated. thanks for the fast work !

[tykeal]

All working now for me too! Thanks @dylex !

[fredcooke]

Thanks Dylan, you're a star! :-)

[barefootcoder]

Also works for me. Thx for the quick turnaround, and especially thx for taking on this plugin and keeping it going in the first place. My team switching to Slack would have been a much more traumatic experience without this, so I just wanted to let you know how much you are appreciated. :thumbsup:

[dylex]

Based on some limited data, it seems like slack has changed the behavior again such that the original problem no longer happens. I've reverted the fix (for #80) so please let me know if anyone again sees the issue.