Error while creating session for user access token

Troubleshooting
1

Running a Mattermost 7.2 server installation and we’re seeing loads of these messages in our mattermost.log:

{"timestamp":"2022-10-03 02:55:21.112 +02:00","level":"warn","msg":"Error while creating session for user access token","caller":"app/session.go:89","error":"createSessionForUserAccessToken: Invalid or missing token., resource: UserAccessToken id: token=eyJhbGciOiJSUzI1NiIsImtpZCI6IiJ9.eyJpc3MiOiJrdWJlc"}

{"timestamp":"2022-10-03 02:55:21.112 +02:00","level":"info","msg":"Invalid session","caller":"web/handlers.go:257","error":"GetSession: Invalid session token=eyJhbGciOiJSUzI1NiIsImtpZCI6IiJ9.eyJpc3MiOiJrdWJlc, err=, "}

How do we deal with this? What is it?

2

Hi David,

do you have integrations or webhooks running that are trying to connect to your server with wrong credentials? You could try to enable debug logging in your config.json to see where these requests are coming from, maybe that helps with narrowing down the source.

3

Turned on debug logging for a couple of seconds and got this:

{"timestamp":"2022-10-04 10:37:51.080 +02:00","level":"debug","msg":"Received HTTP request","caller":"web/handlers.go:156","method":"POST","url":"/api/v4/users/status/ids","request_id":"fizmqkz6p3d4xcw3ep5he7uafy","status_code":"200"}
{"timestamp":"2022-10-04 10:37:51.082 +02:00","level":"debug","msg":"Received HTTP request","caller":"web/handlers.go:156","method":"POST","url":"/api/v4/users/status/ids","request_id":"yjm9ki44ztryiybkpd6jq9ba3h","status_code":"200"}
{"timestamp":"2022-10-04 10:37:51.104 +02:00","level":"warn","msg":"Error while creating session for user access token","caller":"app/session.go:89","error":"createSessionForUserAccessToken: Invalid or missing token., resource: UserAccessToken id: token=eyJhbGciOiJSUzI1NiIsImtpZCI6IiJ9.eyJpc3MiOiJrdWJlc"}
{"timestamp":"2022-10-04 10:37:51.104 +02:00","level":"info","msg":"Invalid session","caller":"web/handlers.go:257","error":"GetSession: Invalid session token=eyJhbGciOiJSUzI1NiIsImtpZCI6IiJ9.eyJpc3MiOiJrdWJlc, err=, "}
{"timestamp":"2022-10-04 10:37:51.105 +02:00","level":"debug","msg":"Received HTTP request","caller":"web/handlers.go:156","method":"GET","url":"/","request_id":"aa3c4koej7gw3xgqfczy8wf4ce","status_code":"200"}
{"timestamp":"2022-10-04 10:37:51.151 +02:00","level":"debug","msg":"Received HTTP request","caller":"web/handlers.go:156","method":"POST","url":"/api/v4/users/status/ids","request_id":"epesw8oy6trh8rsaw57y37w8my","status_code":"200"}
{"timestamp":"2022-10-04 10:37:51.201 +02:00","level":"debug","msg":"Received HTTP request","caller":"web/handlers.go:156","method":"POST","url":"/api/v4/users/status/ids","request_id":"tqfs9epm7iy9pnozx1ojwx968o","status_code":"200"}
{"timestamp":"2022-10-04 10:37:51.203 +02:00","level":"debug","msg":"Received HTTP request","caller":"web/handlers.go:156","method":"POST","url":"/api/v4/users/status/ids","request_id":"coj1n3si1j895x1e474p3m3g8a","status_code":"200"}
{"timestamp":"2022-10-04 10:37:51.241 +02:00","level":"debug","msg":"Websocket request","caller":"wsapi/websocket_handler.go:25","action":"user_update_active_status"}
{"timestamp":"2022-10-04 10:37:51.241 +02:00","level":"debug","msg":"Websocket request","caller":"wsapi/websocket_handler.go:25","action":"user_update_active_status"}
{"timestamp":"2022-10-04 10:37:51.276 +02:00","level":"debug","msg":"Received HTTP request","caller":"web/handlers.go:156","method":"GET","url":"/api/v4/users/me/teams/uu1rsfswmibnpm7q87oex1t1fy/channels","request_id":"xag1y8f1rj8cpk8spkpfhhhsew","status_code":"304"}
{"timestamp":"2022-10-04 10:37:51.277 +02:00","level":"debug","msg":"Received HTTP request","caller":"web/handlers.go:156","method":"GET","url":"/api/v4/channels/hdnqhfb6g7ytpmb6rp1guwb89c/posts","request_id":"99cfthxf4jfrxjifneots9fa9r","status_code":"200"}
{"timestamp":"2022-10-04 10:37:51.278 +02:00","level":"debug","msg":"Received HTTP request","caller":"web/handlers.go:156","method":"GET","url":"/api/v4/plugins/webapp","request_id":"1gwunbnj9j8mbyqcpaasc4hw5w","status_code":"200"}
{"timestamp":"2022-10-04 10:37:51.279 +02:00","level":"debug","msg":"Received HTTP request","caller":"web/handlers.go:156","method":"GET","url":"/api/v4/users/me/teams/unread","request_id":"n57uqncdmifn7rifu9887qkpjy","status_code":"200"}
{"timestamp":"2022-10-04 10:37:51.279 +02:00","level":"debug","msg":"Received HTTP request","caller":"web/handlers.go:156","method":"GET","url":"/api/v4/users/me/teams/uu1rsfswmibnpm7q87oex1t1fy/channels/members","request_id":"mscz5nos73nemb71q943f1136h","status_code":"200"}
{"timestamp":"2022-10-04 10:37:51.294 +02:00","level":"debug","msg":"Received HTTP request","caller":"web/handlers.go:156","method":"POST","url":"/api/v4/users/status/ids","request_id":"cewdfw3t8jgxjkukwsabmzzceo","status_code":"200"}
{"timestamp":"2022-10-04 10:37:51.294 +02:00","level":"debug","msg":"Received HTTP request","caller":"web/handlers.go:156","method":"POST","url":"/api/v4/users/status/ids","request_id":"rb6mooopgpr6ze3w4pro5e1mna","status_code":"200"}
{"timestamp":"2022-10-04 10:37:51.322 +02:00","level":"debug","msg":"Incoming webhook received","caller":"web/webhook.go:54","webhook_id":"ae983zda4pfc8bjq46n1koom8a","request_id":"oznp71fkejgoucws4w4qfwi4io","payload":"{\"text\":\"\",\"username\":\"Alertmanager\",\"icon_url\":\"\",\"channel\":\"#caas4\",\"props\":{\"attachments\":[{\"id\":0,\"fallback\":\"[FIRING:3] AlertmanagerFailedToSendAlerts alertmanager-main (alertmanager-proxy web slack alertmanager-main openshift-monitoring openshift-monitoring/k8s warning) | https://alertmanager-main-openshift-monitoring.infra.caas4.lm.se/#/alerts?receiver=Mattermost\",\"color\":\"danger\",\"pretext\":\"\",\"author_name\":\"\",\"author_link\":\"\",\"author_icon\":\"\",\"title\":\"[FIRING:3] AlertmanagerFailedToSendAlerts alertmanager-main (alertmanager-proxy web slack alertmanager-main openshift-monitoring openshift-monitoring/k8s warning)\",\"title_link\":\"https://alertmanager-main-openshift-monitoring.infra.caas4.lm.se/#/alerts?receiver=Mattermost\",\"text\":\"\",\"fields\":null,\"image_url\":\"\",\"thumb_url\":\"\",\"footer\":\"\",\"footer_icon\":\"\",\"ts\":null}],\"webhook_display_name\":\"caas4 alerts\"},\"attachments\":[{\"id\":0,\"fallback\":\"[FIRING:3] AlertmanagerFailedToSendAlerts alertmanager-main (alertmanager-proxy web slack alertmanager-main openshift-monitoring openshift-monitoring/k8s warning) | https://alertmanager-main-openshift-monitoring.infra.caas4.lm.se/#/alerts?receiver=Mattermost\",\"color\":\"danger\",\"pretext\":\"\",\"author_name\":\"\",\"author_link\":\"\",\"author_icon\":\"\",\"title\":\"[FIRING:3] AlertmanagerFailedToSendAlerts alertmanager-main (alertmanager-proxy web slack alertmanager-main openshift-monitoring openshift-monitoring/k8s warning)\",\"title_link\":\"https://alertmanager-main-openshift-monitoring.infra.caas4.lm.se/#/alerts?receiver=Mattermost\",\"text\":\"\",\"fields\":null,\"image_url\":\"\",\"thumb_url\":\"\",\"footer\":\"\",\"footer_icon\":\"\",\"ts\":null}],\"type\":\"\",\"icon_emoji\":\"\"}"}
{"timestamp":"2022-10-04 10:37:51.322 +02:00","level":"debug","msg":"Inappropriate channel permissions.","caller":"web/context.go:113","path":"/hooks/ae983zda4pfc8bjq46n1koom8a","request_id":"oznp71fkejgoucws4w4qfwi4io","ip_addr":"10.172.0.31","user_id":"","method":"POST","err_where":"HandleIncomingWebhook","http_code":403,"err_details":""}
{"timestamp":"2022-10-04 10:37:51.322 +02:00","level":"debug","msg":"Received HTTP request","caller":"web/handlers.go:156","method":"POST","url":"/hooks/ae983zda4pfc8bjq46n1koom8a","request_id":"oznp71fkejgoucws4w4qfwi4io","status_code":"403"}

Not sure how to interpret this, the requests surrounding the “Invalid session token”-message seem to execute just fine?

The token it mentions: eyJhbGciOiJSUzI1NiIsImtpZCI6IiJ9.eyJpc3MiOiJrdWJlc, which part of this is the user id? I’ve tried searching for both eyJhbGciOiJSUzI1NiIsImtpZCI6IiJ9 and eyJpc3MiOiJrdWJlc but no user exists with those ids.

4

The format looks just wrong. The user access tokens are GUIDs, 26 characters in length, no dots usually.
Can you run the following SQL query on your system and check if there are strange looking tokens in the table?

SELECT token FROM sessions;

Don’t post the tokens here in cleartext, one could authenticate with them to your system, but look for the format.
Unfortunately, we still cannot see what client requested a session with this token. Do you have a reverse proxy in front of your Mattermost server? If so, do you have access logging turned on there and can find a logline with client IP for the request that causes this error message?
My best guess is that there’s a client which has an invalid session token.

5

Ran the query, couldn’t find any other tokens in the same format. We do have a BigIP in front of the server, not sure if access logging is turned on. I’ll investigate and get back to you.

6

Ok, so I contacted our NOC and got help with hunting down whoever/whatever was causing this. Turns out its some old, misconfigured application. Problem solved. Thanks for your time @agriesser!

7

Awesome, thanks for confirming and marking this issue as resolved. Glad to hear we could clear it up.