Err403 on websocket URLs triggering reconnections?

[xurizaemon]

We've been observing issues with Hubot getting locked out of our Mattermost server (see xurizaemon/bolts#25). What happens seems to be this:

• Hubot logs in as expected.
• Something triggers Hubot to reconnect (more on this below)
• Hubot starts reconnecting at intervals (even though it's connected)
• Mattermost detects the high number of authentication attempts and locks Hubot (MaximumLoginAttempts in MM config.json?)

Mattermost Version: 4.7.1 (4.7.3) (https://chat.civicrm.org) and 4.9.1-rc1 (https://oss.mattermost.com). I see the repeat logins occur when testing on oss.mattermost.com, but I haven't yet seen the lockout behaviour (guessing diff values of MaximumLoginAttempts on the servers).

I've managed to trace my way through and identify that after a successful login, I see an HTTP403 response when mattermost-client requests the websocket.

When using Mattermost via desktop browser I see this request, with the same URL, get an HTTP101 and upgrade to wss. The wss URL is wss://oss.mattermost.com:443/api/v4/websocket. After this I see

error Error: unexpected server response (403)

Here's where I hit the limits of my JS debugging and get speculative (I know, I know). I suspect this triggers mattermost-client to re-initialise the websocket connection and repeat login, which makes Mattermost increment its login counter and leads to the lockout.

My aim in reporting this is (1) to ensure it is on your radar if we're hitting a real issue in the MM adapter, and (2) to ask for guidance in debugging further. I'll update if I'm able to track it down any further!

[sunnythaper]

I am very much having this issue as well. Hope this screenshot of my error helps further. I get all the way into being logged and hubot recognizing chat members as typing but as soon as we hit a trigger, it goes into the reconnect loop as described by OP. This is the error it spits out just before going into the reconnect loop.

https://cl.ly/340J1S3x0k1h

[uhlhosting]

Having the same issue, unable yet o track it down.

[uhlhosting]

hubot@boo:~$ sudo systemctl status hubot.service
● hubot.service - Hubot
   Loaded: loaded (/lib/systemd/system/hubot.service; linked; vendor preset: enabled)
   Active: active (running) since Fri 2019-01-18 13:29:56 UTC; 33min ago
 Main PID: 300968 (node)
    Tasks: 11 (limit: 154550)
   Memory: 26.7M
   CGroup: /system.slice/hubot.service
           └─300968 node node_modules/.bin/coffee node_modules/.bin/hubot --name boo --adapter matteruser >> /home/hubot/hubot.log 2>&1

Jan 18 14:02:09 boo hubot[300968]: [Fri Jan 18 2019 14:02:09 GMT+0000 (Coordinated Universal Time)] INFO Attempting reconnect
Jan 18 14:02:09 boo hubot[300968]: [Fri Jan 18 2019 14:02:09 GMT+0000 (Coordinated Universal Time)] INFO Logging in with personal access token...
Jan 18 14:02:09 boo hubot[300968]: [Fri Jan 18 2019 14:02:09 GMT+0000 (Coordinated Universal Time)] INFO api url:http://172.18.111.30:8065/api/v4/users/me
Jan 18 14:02:09 boo hubot[300968]: [Fri Jan 18 2019 14:02:09 GMT+0000 (Coordinated Universal Time)] ERROR Login call failed
Jan 18 14:02:09 boo hubot[300968]: [Fri Jan 18 2019 14:02:09 GMT+0000 (Coordinated Universal Time)] INFO Reconnecting in 61000ms
Jan 18 14:03:10 boo hubot[300968]: [Fri Jan 18 2019 14:03:10 GMT+0000 (Coordinated Universal Time)] INFO Attempting reconnect
Jan 18 14:03:10 boo hubot[300968]: [Fri Jan 18 2019 14:03:10 GMT+0000 (Coordinated Universal Time)] INFO Logging in with personal access token...
Jan 18 14:03:10 boo hubot[300968]: [Fri Jan 18 2019 14:03:10 GMT+0000 (Coordinated Universal Time)] INFO api url:http://172.18.111.30:8065/api/v4/users/me
Jan 18 14:03:10 boo hubot[300968]: [Fri Jan 18 2019 14:03:10 GMT+0000 (Coordinated Universal Time)] ERROR Login call failed
Jan 18 14:03:10 boo hubot[300968]: [Fri Jan 18 2019 14:03:10 GMT+0000 (Coordinated Universal Time)] INFO Reconnecting in 62000ms

[xurizaemon]

@uhlhosting @sunnythaper are you able to confirm if you're still affected by this issue? What Mattermost / adapter versions are you running (today, a year later) if so?

[sunnythaper]

@xurizaemon TBH because of this issue I switched over to mmpy_bot a while back. Apologize for the delayed response.

[joemcl]

Hi @xurizaemon are we still seeing this at chat.civicrm.org ?

[Marthym]

Hello

I think the problem come from mattermost-client loafoe/mattermost-client#134

Fixed in latest versions with loafoe/mattermost-client#135