search

loafoe / hubot-matteruser

Hubot adapter for Mattermost using Web API and Websockets
MIT License
193 stars 81 forks source link

Err403 on websocket URLs triggering reconnections? #66

Open xurizaemon opened 6 years ago

xurizaemon commented 6 years ago

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

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 commented 6 years ago

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 commented 5 years ago

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

uhlhosting commented 5 years ago 
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 commented 5 years ago

@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 commented 5 years ago

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

joemcl commented 4 years ago

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

Marthym commented 3 years ago

Hello

I think the problem come from mattermost-client https://github.com/loafoe/mattermost-client/issues/134

Fixed in latest versions with https://github.com/loafoe/mattermost-client/pull/135