account disabled on every re-connect

[pulecp]

I have to manually re-enable my mattermost account always when I am re-connected to the Internet. Pidgins shows this reason "Invalid or expired Gitlab cookie".

[pulecp]

output in "Debug Window"

(08:59:33) http: Timeout reached for request 0x55f3eb39d360
(08:59:33) http: Request 0x55f3eb39d360 performed without success.
(08:59:33) mattermost: Got response: 
(08:59:33) connection: Connection error on 0x55f3e9493690 (reason: 2 description: Invalid or expired Gitlab cookie)

[EionRobb]

Can you get a bit more of a debug log? It would be good to know which request is timing out.

It looks more like a connection error than an authentication error though, so we're probably using the wrong error message which is causing the account to be disabled, rather than disconnected

[pulecp]

(22:28:02) prefs: /pidgin/blist/list_visible changed, scheduling save.
(22:28:04) network: Got StateChange from NetworkManager: 50.
(22:28:04) prefs: /pidgin/blist/list_visible changed, scheduling save.
(22:28:08) network: Got StateChange from NetworkManager: 10.
(22:28:14) util: Writing file prefs.xml to directory /home/user/.purple
(22:28:14) util: Writing file /home/user/.purple/prefs.xml
(22:28:14) network: Got StateChange from NetworkManager: 50.
(22:28:15) network: Got NameOwnerChanged signal, service = 'org.freedesktop.NetworkManager', old_owner = ':1.93617', new_owner = ''
(22:28:15) network: NetworkManager has gone away.
(22:28:15) network: Got NameOwnerChanged signal, service = 'org.freedesktop.NetworkManager', old_owner = '', new_owner = ':1.94391'
(22:28:15) network: NetworkManager has started.
(22:28:15) network: Got StateChange from NetworkManager: 50.
(22:28:19) network: Got StateChange from NetworkManager: 40.
(22:28:20) network: Got StateChange from NetworkManager: 50.
(22:28:20) network: Got StateChange from NetworkManager: 60.
(22:28:20) network: Got StateChange from NetworkManager: 70.
(22:28:21) prefs: /pidgin/blist/list_visible changed, scheduling save.
(22:28:24) prefs: /pidgin/blist/list_visible changed, scheduling save.
(22:28:27) util: Writing file prefs.xml to directory /home/user/.purple
(22:28:27) util: Writing file /home/user/.purple/prefs.xml
(22:28:28) g_log: purple_connection_get_state: assertion 'gc != NULL' failed
(22:28:30) GLib: g_source_remove: assertion 'tag > 0' failed
(22:28:30) gtkconv: setting active conversation on toolbar 0x55f3e82c4490
(22:28:32) mattermost: Fetching url https://mattermost.example.com/api/v4/channels/members/me/view
(22:28:32) mattermost: With postdata {"channel_id":"eqfxsj38fpybpgej8yqb9c9fmw","prev_channel_id":null}
(22:28:32) http: Performing new request 0x55f3eb1f2b40 to mattermost.example.com.
(22:28:32) dnsquery: Performing DNS lookup for mattermost.example.com
(22:28:32) dns: Wait for DNS child 10339 failed: No child processes
(22:28:32) dns: Wait for DNS child 10336 failed: No child processes
(22:28:32) dns: Wait for DNS child 10329 failed: No child processes
(22:28:32) dns: Wait for DNS child 10335 failed: No child processes
(22:28:32) dns: Created new DNS child 10646, there are now 1 children.
(22:28:32) dns: Successfully sent DNS request to child 10646
(22:28:32) dns: Got response for 'mattermost.example.com'
(22:28:32) dnsquery: IP resolved for mattermost.example.com
(22:28:32) proxy: Attempting connection to 1.2.3.4
(22:28:32) proxy: Connecting to mattermost.example.com:443 with no proxy
(22:28:32) proxy: Connection in progress
(22:28:32) proxy: Connecting to mattermost.example.com:443.
(22:28:32) proxy: Connected to mattermost.example.com:443.
(22:28:32) nss: SSL version 3.3 using 256-bit AES with 160-bit SHA1 MAC
Server Auth: 2048-bit RSA, Key Exchange: 256-bit ECDHE, Compression: NULL
Cipher Suite Name: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA
(22:28:32) nss: subject=CN=mattermost.example.com issuer=CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US
(22:28:32) nss: subject=CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US issuer=CN=DST Root CA X3,O=Digital Signature Trust Co.
(22:28:32) nss: subject=CN=DST Root CA X3,O=Digital Signature Trust Co. issuer=CN=DST Root CA X3,O=Digital Signature Trust Co.
(22:28:32) certificate/x509/tls_cached: Starting verify for mattermost.example.com
(22:28:32) certificate/x509/tls_cached: Checking for cached cert...
(22:28:32) certificate/x509/tls_cached: ...Found cached cert
(22:28:32) nss/x509: Loading certificate from /home/user/.purple/certificates/x509/tls_peers/mattermost.example.com
(22:28:32) certificate/x509/tls_cached: Peer cert matched cached
(22:28:32) nss/x509: Exporting certificate to /home/user/.purple/certificates/x509/tls_peers/mattermost.example.com
(22:28:32) util: Writing file /home/user/.purple/certificates/x509/tls_peers/mattermost.example.com
(22:28:32) nss: Trusting CN=mattermost.example.com
(22:28:32) certificate: Successfully verified certificate for mattermost.example.com
(22:28:32) mattermost: got frame data: {"event":"channel_viewed","data":{"channel_id":"eqfxsj38fpybpgej8yqb9c9fmw"},"broadcast":{"omit_users":null,"user_id":"zdme86jmgjg8dcz6e59a3fcg7c","channel_id":"","team_id":""},"seq":1}
(22:28:32) http: Request 0x55f3eb1f2b40 performed successfully.
(22:28:32) mattermost: Got response: {"status":"OK","last_viewed_at_times":{"eqfxsj38fpybpgej8yqb9c9fmw":1542144143463}}
(22:28:33) mattermost: Fetching url https://mattermost.example.com/api/v4/posts
(22:28:33) mattermost: With postdata {"pending_post_id":"00009804A7E5FFFF","channel_id":"eqfxsj38fpybpgej8yqb9c9fmw","message":"test","user_id":"zdme86jmgjg8dcz6e59a3fcg7c","create_at":0}
(22:28:33) http: Performing new request 0x55f3eb029910 to mattermost.example.com.
(22:28:33) GLib: Source ID 1492820 was not found when attempting to remove it
(22:28:33) dnsquery: Performing DNS lookup for mattermost.example.com
(22:28:33) dns: Successfully sent DNS request to child 10646
(22:28:33) dns: Got response for 'mattermost.example.com'
(22:28:33) dnsquery: IP resolved for mattermost.example.com
(22:28:33) proxy: Attempting connection to 1.2.3.4
(22:28:33) proxy: Connecting to mattermost.example.com:443 with no proxy
(22:28:33) proxy: Connection in progress
(22:28:33) proxy: Connecting to mattermost.example.com:443.
(22:28:33) proxy: Connected to mattermost.example.com:443.
(22:28:33) nss: SSL version 3.3 using 256-bit AES with 160-bit SHA1 MAC
Server Auth: 2048-bit RSA, Key Exchange: 256-bit ECDHE, Compression: NULL
Cipher Suite Name: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA
(22:28:33) nss: subject=CN=mattermost.example.com issuer=CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US
(22:28:33) nss: partial certificate chain
(22:28:33) certificate/x509/tls_cached: Starting verify for mattermost.example.com
(22:28:33) certificate/x509/tls_cached: Checking for cached cert...
(22:28:33) certificate/x509/tls_cached: ...Found cached cert
(22:28:33) nss/x509: Loading certificate from /home/user/.purple/certificates/x509/tls_peers/mattermost.example.com
(22:28:33) certificate/x509/tls_cached: Peer cert matched cached
(22:28:33) nss/x509: Exporting certificate to /home/user/.purple/certificates/x509/tls_peers/mattermost.example.com
(22:28:33) util: Writing file /home/user/.purple/certificates/x509/tls_peers/mattermost.example.com
(22:28:33) nss: Trusting CN=mattermost.example.com
(22:28:33) certificate: Successfully verified certificate for mattermost.example.com
(22:28:33) mattermost: got frame data: {"event":"posted","data":{"channel_display_name":"DailyOps","channel_name":"dailyops","channel_type":"O","post":"{\"id\":\"ff367ompopyyimiawjr4syassh\",\"create_at\":1542144513821,\"update_at\":1542144513821,\"edit_at\":0,\"delete_at\":0,\"is_pinned\":false,\"user_id\":\"zdme86jmgjg8dcz6e59a3fcg7c\",\"channel_id\":\"eqfxsj38fpybpgej8yqb9c9fmw\",\"root_id\":\"\",\"parent_id\":\"\",\"original_id\":\"\",\"message\":\"test\",\"type\":\"\",\"props\":{},\"hashtags\":\"\",\"pending_post_id\":\"00009804A7E5FFFF\"}","sender_name":"user","team_id":"e1wsztto7pnn9d3t6r63if4gxw"},"broadcast":{"omit_users":null,"user_id":"","channel_id":"eqfxsj38fpybpgej8yqb9c9fmw","team_id":""},"seq":2}
(22:28:33) http: Request 0x55f3eb029910 performed successfully.
(22:28:33) mattermost: Got response: {"id":"ff367ompopyyimiawjr4syassh","create_at":1542144513821,"update_at":1542144513821,"edit_at":0,"delete_at":0,"is_pinned":false,"user_id":"zdme86jmgjg8dcz6e59a3fcg7c","channel_id":"eqfxsj38fpybpgej8yqb9c9fmw","root_id":"","parent_id":"","original_id":"","message":"test","type":"","props":{},"hashtags":"","pending_post_id":"00009804A7E5FFFF"}
(22:28:33) mattermost: got frame data: {"event":"channel_viewed","data":{"channel_id":"eqfxsj38fpybpgej8yqb9c9fmw"},"broadcast":{"omit_users":null,"user_id":"zdme86jmgjg8dcz6e59a3fcg7c","channel_id":"","team_id":""},"seq":3}
(22:28:34) mattermost: Fetching url https://mattermost.example.com/api/v4/channels/members/me/view
(22:28:34) mattermost: With postdata {"channel_id":"eqfxsj38fpybpgej8yqb9c9fmw","prev_channel_id":"eqfxsj38fpybpgej8yqb9c9fmw"}
(22:28:34) http: Performing new request 0x55f3e98a7eb0 to mattermost.example.com.
(22:28:34) dnsquery: Performing DNS lookup for mattermost.example.com
(22:28:34) dns: Successfully sent DNS request to child 10646
(22:28:34) dns: Got response for 'mattermost.example.com'
(22:28:34) dnsquery: IP resolved for mattermost.example.com
(22:28:34) proxy: Attempting connection to 147.135.138.82
(22:28:34) proxy: Connecting to mattermost.example.com:443 with no proxy
(22:28:34) proxy: Connection in progress
(22:28:34) proxy: Connecting to mattermost.example.com:443.
(22:28:34) proxy: Connected to mattermost.example.com:443.
(22:28:34) nss: SSL version 3.3 using 256-bit AES with 160-bit SHA1 MAC
Server Auth: 2048-bit RSA, Key Exchange: 256-bit ECDHE, Compression: NULL
Cipher Suite Name: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA
(22:28:34) nss: subject=CN=mattermost.example.com issuer=CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US
(22:28:34) nss: partial certificate chain
(22:28:34) certificate/x509/tls_cached: Starting verify for mattermost.example.com
(22:28:34) certificate/x509/tls_cached: Checking for cached cert...
(22:28:34) certificate/x509/tls_cached: ...Found cached cert
(22:28:34) nss/x509: Loading certificate from /home/user/.purple/certificates/x509/tls_peers/mattermost.example.com
(22:28:34) certificate/x509/tls_cached: Peer cert matched cached
(22:28:34) nss/x509: Exporting certificate to /home/user/.purple/certificates/x509/tls_peers/mattermost.example.com
(22:28:34) util: Writing file /home/user/.purple/certificates/x509/tls_peers/mattermost.example.com
(22:28:34) nss: Trusting CN=mattermost.example.com
(22:28:34) certificate: Successfully verified certificate for mattermost.example.com
(22:28:34) mattermost: got frame data: {"event":"channel_viewed","data":{"channel_id":"eqfxsj38fpybpgej8yqb9c9fmw"},"broadcast":{"omit_users":null,"user_id":"zdme86jmgjg8dcz6e59a3fcg7c","channel_id":"","team_id":""},"seq":4}
(22:28:34) http: Request 0x55f3e98a7eb0 performed successfully.
(22:28:34) mattermost: Got response: {"status":"OK","last_viewed_at_times":{"eqfxsj38fpybpgej8yqb9c9fmw":1542144513821}}
(22:28:38) util: Writing file blist.xml to directory /home/user/.purple
(22:28:38) util: Writing file /home/user/.purple/blist.xml
(22:28:49) network: Got StateChange from NetworkManager: 40.
(22:28:49) account: Disconnecting account user|mattermost.example.com (0x55f3e8015a10)
(22:28:49) connection: Disconnecting connection 0x55f3e8f490b0
(22:28:49) GLib: Source ID 1492997 was not found when attempting to remove it
(22:28:49) mattermost: Fetching url https://mattermost.example.com/api/v4/users/me/status
(22:28:49) mattermost: With postdata {"status":"online"}
(22:28:49) http: Performing new request 0x55f3ea2b4590 to mattermost.example.com.
(22:28:49) http: Request 0x55f3ea2b4590 performed without success.
(22:28:49) mattermost: Got response: 
(22:28:49) connection: Destroying connection 0x55f3e8f490b0
(22:28:50) g_log: purple_connection_get_state: assertion 'gc != NULL' failed
(22:28:52) network: Got StateChange from NetworkManager: 70.
(22:28:52) autorecon: do_signon called
(22:28:52) autorecon: calling purple_account_connect
(22:28:52) account: Connecting to account user|mattermost.example.com.
(22:28:52) connection: Connecting. gc = 0x55f3e9192970
(22:28:52) mattermost: Fetching url https://mattermost.example.com/api/v4/users/me
(22:28:52) http: Performing new request 0x55f3eb029910 to mattermost.example.com.
(22:28:52) signals: Signal data for chat-conversation-typing not found!
(22:28:52) autorecon: done calling purple_account_connect
(22:28:52) dnsquery: Performing DNS lookup for mattermost.example.com
(22:28:52) dns: Successfully sent DNS request to child 10646
(22:28:52) GLib: ../glib/glib/giounix.c:410Error while getting flags for FD: Bad file descriptor (9)
(22:28:55) util: Writing file blist.xml to directory /home/user/.purple
(22:28:55) util: Writing file /home/user/.purple/blist.xml
(22:28:55) util: Writing file accounts.xml to directory /home/user/.purple
(22:28:55) util: Writing file /home/user/.purple/accounts.xml
(22:29:20) prefs: /pidgin/blist/list_visible changed, scheduling save.
(22:29:23) http: Timeout reached for request 0x55f3eb029910
(22:29:23) http: Request 0x55f3eb029910 performed without success.
(22:29:23) mattermost: Got response: 
(22:29:23) connection: Connection error on 0x55f3e9192970 (reason: 2 description: Invalid or expired Gitlab cookie)
(22:29:23) account: Disconnecting account user|mattermost.example.com (0x55f3e8015a10)
(22:29:23) connection: Disconnecting connection 0x55f3e9192970
(22:29:23) mattermost: Fetching url https://mattermost.example.com/api/v4/users/me/status
(22:29:23) mattermost: With postdata {"status":"online"}
(22:29:23) http: Performing new request 0x55f3ea2b4590 to mattermost.example.com.
(22:29:23) GLib: g_source_remove: assertion 'tag > 0' failed
(22:29:23) GLib: g_source_remove: assertion 'tag > 0' failed
(22:29:23) http: Request 0x55f3ea2b4590 performed without success.
(22:29:23) mattermost: Got response: 
(22:29:23) GLib: g_regex_unref: assertion 'regex != NULL' failed
(22:29:23) GLib: g_regex_unref: assertion 'regex != NULL' failed
(22:29:23) connection: Destroying connection 0x55f3e9192970
(22:29:26) util: Writing file prefs.xml to directory /home/user/.purple
(22:29:26) util: Writing file /home/user/.purple/prefs.xml
(22:29:28) util: Writing file accounts.xml to directory /home/user/.purple
(22:29:28) util: Writing file /home/user/.purple/accounts.xml
(22:30:30) prefs: /pidgin/blist/list_visible changed, scheduling save.
(22:30:30) prefs: /pidgin/blist/list_visible changed, scheduling save.
(22:30:31) prefs: /pidgin/blist/list_visible changed, scheduling save.
(22:30:34) g_log: purple_connection_get_state: assertion 'gc != NULL' failed

[pulecp]

It looks more like a connection error than an authentication error though, so we're probably using the wrong error message which is causing the account to be disabled, rather than disconnected

It's not an authentication issue because when I re-enable the mattermost account, I'm always immediately connected.

[EionRobb]

It looks like every request to "/api/v4/users/me/status" is timing out. If you were to change your status in Pidgin from Online to Away and back again once you were connected to the account, does it disable the account?

[EionRobb]

Are there any logs on the server-side about that request timing out or causing errors on the server?

[pulecp]

I can confirm that the issue occurs always when I change my status from online to offline and back. This disable my mattermost account.

I can't see anything in logs on Mattermost server.

[pulecp]

I found this in the logs but it doesn't occur always when I the issue happen.

[2018/11/13 22:43:01 CET] [INFO] /api/v4/users/me/status:ServeHTTP code=401 rid=***hidden*** uid= ip=***hidden*** Invalid or expired session, please login again. [details: token=***hidden*** Appears to be a CSRF attempt]

[EionRobb]

That looks like Issue #91 Can you try the fix in https://github.com/EionRobb/purple-mattermost/issues/91#issuecomment-435701771 and see if that helps with your issue too?

[pulecp]

That looks like Issue #91 Can you try the fix in #91 (comment) and see if that helps with your issue too?

Nope, it didn't help. But i figured out that when I go offline, wait at least 15 seconds and then I go back online, the issue doesn't occur.