Wazo websocket expiration token issue

Description

In this log we see the token has been updated but websocketd seems doesn’t take it in consideration and close the websocket because authentication is expired.
My expiration token is set to 120 secs, not sure it’s related.

2024-02-22 23:41:23,166 [973436] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=1, data=b'{"op": "event", "code": 0, "data": {"tenant_uuid": "3535890a-3a43-497d-b770-6b0659c6e1aa", "session_uuid": "ad7f751c-3cc8-4b13-b86c-6feaa920e05e", "name": "auth_session_created", "user_uuid:a1a43d40-8b94-4d06-b7cb-5aad8bfd6501": true, "required_access": "event.auth_session_created", "required_acl": "events.auth.sessions.ad7f751c-3cc8-4b13-b86c-6feaa920e05e.created", "origin_uuid": "b8872216-f0d9-4080-bb05-3f4fd6b63fde", "timestamp": "2024-02-22T23:41:23.163459", "data": {"uuid": "ad7f751c-3cc8-4b13-b86c-6feaa920e05e", "tenant_uuid": "3535890a-3a43-497d-b770-6b0659c6e1aa", "user_uuid": "a1a43d40-8b94-4d06-b7cb-5aad8bfd6501", "mobile": false}}}', rsv1=False, rsv2=False, rsv3=False)
2024-02-22 23:41:23,201 [973436] (DEBUG) (websockets.protocol): server - event = data_received(<59 bytes>)
2024-02-22 23:41:23,201 [973436] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=1, data=b'{"op":"token","data":{"token":"6ff58dbc-59f1-4e77-b80e-7bac7d1a1605"}}', rsv1=False, rsv2=False, rsv3=False)
2024-02-22 23:41:23,201 [973436] (DEBUG) (wazo_websocketd.auth): getting token from wazo-auth
2024-02-22 23:41:23,209 [973436] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=1, data=b'{"op": "token", "code": 0, "data": null}', rsv1=False, rsv2=False, rsv3=False)
2024-02-22 23:42:02,269 [973436] (DEBUG) (wazo_websocketd.auth): dynamic auth check: testing token validity
2024-02-22 23:42:02,269 [973436] (DEBUG) (wazo_websocketd.auth): getting token from wazo-auth
2024-02-22 23:42:02,282 [973436] (INFO) (wazo_websocketd.session): closing websocket connection: authentication expired@

Zendesk Ticket IDs

None

Activity

Show:

Pascal Cadotte

February 23, 2024 at 4:23 PM

(edited)

2024-02-22 23:39:23,113 [852540] (INFO) (wazo-auth): request: POST https://XXXX.wazo.community/api/auth/0.1/token {'Host': 'XXXX.wazo.community', 'X-Script-Name': '/api/auth', 'X-Forwarded-Proto': 'https', 'Connection': 'close', 'X-Real-Ip': '192.168.32.251', 'X-Frame-Options': 'SAMEORIGIN', 'Accept': '*/*', 'User-Agent': 'node-fetch/1.0 (+https://git
hub.com/bitinn/node-fetch)', 'Accept-Encoding': 'gzip,deflate', 'Content-Type': 'application/json', 'Content-Length': '124'} with data {"backend": "wazo_user", "expiration": "120", "refresh_token": "<hidden>", "cl
ient_id": "wazo-nodered"}
2024-02-22 23:39:23,193 [852540] (INFO) (wazo_auth.plugins.http.tokens.http): Successful login: application got token XXXXXXXX-XXXX-XXXX-XXXX-XXXXc6096b10 from X.X.X.X using agent "node-fetch/1.0 (+https://github.com/bitinn/node-fetch)"
2024-02-22 23:39:23,196 [852540] (INFO) (wazo-auth): response to X.X.X.X in 0.08s: POST https://XXXX.wazo.community/api/auth/0.1/token 200
2024-02-22 23:41:23,133 [852540] (INFO) (wazo-auth): request: POST https://XXXX.wazo.community/api/auth/0.1/token {'Host': 'XXXX.wazo.community', 'X-Script-Name': '/api/auth', 'X-Forwarded-Proto': 'https', 'Connection': 'close', 'X-Frame-Options': 'SAMEORIGIN', 'Accept': '*/*', 'User-Agent': 'node-fetch/1.0 (+https://github.com/bitinn/node-fetch)', 'Accept-Encoding': 'gzip,deflate', 'Content-Type': 'application/json', 'Content-Length': '124'} with data {"backend": "wazo_user", "expiration": "120", "refresh_token": "<hidden>", "client_id": "wazo-nodered"}
2024-02-22 23:41:23,165 [852540] (INFO) (wazo_auth.plugins.http.tokens.http): Successful login: application got token XXXXXXXX-XXXX-XXXX-XXXX-XXXX7d1a1605 from X.X.X.X using agent "node-fetch/1.0 (+https://github.com/bitinn/node-fetch)"
2024-02-22 23:41:23,167 [852540] (INFO) (wazo-auth): response to X.X.X.X in 0.03s: POST https://XXXX.wazo.community/api/auth/0.1/token 200
2024-02-22 23:41:23,203 [852540] (INFO) (wazo-auth): request: GET http://localhost:9497/0.1/token/6ff58dbc-59f1-4e77-b80e-7bac7d1a1605?scope=websocketd {'Host': 'localhost:9497', 'Accept-Encoding': 'identity', 'Connection': 'close', 'User-Agent': 'wazo-websocketd', 'Accept': 'application/json', 'Authorization': 'Basic <hidden>'}
2024-02-22 23:41:23,206 [852540] (INFO) (wazo-auth): response to X.X.X.X in 0.00s: GET http://localhost:9497/0.1/token/6ff58dbc-59f1-4e77-b80e-7bac7d1a1605?scope=websocketd 200
2024-02-22 23:41:23,255 [852540] (INFO) (wazo-auth): request: GET https://XXXX.wazo.community/api/auth/0.1/token/6ff58dbc-59f1-4e77-b80e-7bac7d1a1605 {'Host': 'XXXX.wazo.community', 'X-Script-Name': '/api/auth', 'X-Forwarded-Proto': 'https', 'Connection': 'close', 'X-Frame-Options': 'SAMEORIGIN', 'X-Auth-Token': 'XXXXXXXX-XXXX-XXXX-XXXX-XXXX7d1a1605', 'Accept': '*/*', 'User-Agent': 'node-fetch/1.0 (+https://github.com/bitinn/node-fetch)', 'Accept-Encoding': 'gzip,deflate', 'Content-Type': 'application/json'}
2024-02-22 23:41:23,258 [852540] (INFO) (wazo-auth): response to X.X.X.X in 0.00s: GET https://XXXX.wazo.community/api/auth/0.1/token/6ff58dbc-59f1-4e77-b80e-7bac7d1a1605 200
2024-02-22 23:42:02,271 [852540] (INFO) (wazo-auth): request: GET http://localhost:9497/0.1/token/99f3a61c-0d7b-4e6f-bb36-2d36c6096b10?scope=websocketd {'Host': 'localhost:9497', 'Accept-Encoding': 'identity', 'Connection': 'close', 'User-Agent': 'wazo-websocketd', 'Accept': 'application/json', 'Authorization': 'Basic <hidden>'}
2024-02-22 23:42:02,274 [852540] (INFO) (wazo-auth): response to X.X.X.X in 0.00s: GET http://localhost:9497/0.1/token/99f3a61c-0d7b-4e6f-bb36-2d36c6096b10?scope=websocketd 404

I mixed the 2 logs below

2024-02-22 23:39:23,113 [852540] (INFO) (wazo-auth): request: POST https://XXXX.wazo.community/api/auth/0.1/token {'Host': 'XXXX.wazo.community', 'X-Script-Name': '/api/auth', 'X-Forwarded-Proto': 'https', 'Connection': 'close', 'X-Real-Ip': '192.168.32.251', 'X-Frame-Options': 'SAMEORIGIN', 'Accept': '*/*', 'User-Agent': 'node-fetch/1.0 (+https://git
hub.com/bitinn/node-fetch)', 'Accept-Encoding': 'gzip,deflate', 'Content-Type': 'application/json', 'Content-Length': '124'} with data {"backend": "wazo_user", "expiration": "120", "refresh_token": "<hidden>", "cl
ient_id": "wazo-nodered"}
2024-02-22 23:39:23,193 [852540] (INFO) (wazo_auth.plugins.http.tokens.http): Successful login: application got token XXXXXXXX-XXXX-XXXX-XXXX-XXXXc6096b10 from X.X.X.X using agent "node-fetch/1.0 (+https://github.com/bitinn/node-fetch)"
2024-02-22 23:39:23,196 [852540] (INFO) (wazo-auth): response to X.X.X.X in 0.08s: POST https://XXXX.wazo.community/api/auth/0.1/token 200
2024-02-22 23:41:23,133 [852540] (INFO) (wazo-auth): request: POST https://XXXX.wazo.community/api/auth/0.1/token {'Host': 'XXXX.wazo.community', 'X-Script-Name': '/api/auth', 'X-Forwarded-Proto': 'https', 'Connection': 'close', 'X-Frame-Options': 'SAMEORIGIN', 'Accept': '*/*', 'User-Agent': 'node-fetch/1.0 (+https://github.com/bitinn/node-fetch)', 'Accept-Encoding': 'gzip,deflate', 'Content-Type': 'application/json', 'Content-Length': '124'} with data {"backend": "wazo_user", "expiration": "120", "refresh_token": "<hidden>", "client_id": "wazo-nodered"}
2024-02-22 23:41:23,165 [852540] (INFO) (wazo_auth.plugins.http.tokens.http): Successful login: application got token XXXXXXXX-XXXX-XXXX-XXXX-XXXX7d1a1605 from X.X.X.X using agent "node-fetch/1.0 (+https://github.com/bitinn/node-fetch)"
2024-02-22 23:41:23,166 [973436] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=1, data=b'{"op": "event", "code": 0, "data": {"tenant_uuid": "3535890a-3a43-497d-b770-6b0659c6e1aa", "session_uuid": "ad7f751c-3cc8-4b13-b86c-6feaa920e05e", "name": "auth_session_created", "user_uuid:a1a43d40-8b94-4d06-b7cb-5aad8bfd6501": true, "required_access": "event.auth_session_created", "required_acl": "events.auth.sessions.ad7f751c-3cc8-4b13-b86c-6feaa920e05e.created", "origin_uuid": "b8872216-f0d9-4080-bb05-3f4fd6b63fde", "timestamp": "2024-02-22T23:41:23.163459", "data": {"uuid": "ad7f751c-3cc8-4b13-b86c-6feaa920e05e", "tenant_uuid": "3535890a-3a43-497d-b770-6b0659c6e1aa", "user_uuid": "a1a43d40-8b94-4d06-b7cb-5aad8bfd6501", "mobile": false}}}', rsv1=False, rsv2=False, rsv3=False)
2024-02-22 23:41:23,167 [852540] (INFO) (wazo-auth): response to X.X.X.X in 0.03s: POST https://XXXX.wazo.community/api/auth/0.1/token 200
2024-02-22 23:41:23,201 [973436] (DEBUG) (websockets.protocol): server - event = data_received(<59 bytes>)
2024-02-22 23:41:23,201 [973436] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=1, data=b'{"op":"token","data":{"token":"6ff58dbc-59f1-4e77-b80e-7bac7d1a1605"}}', rsv1=False, rsv2=False, rsv3=False)
2024-02-22 23:41:23,201 [973436] (DEBUG) (wazo_websocketd.auth): getting token from wazo-auth
2024-02-22 23:41:23,203 [852540] (INFO) (wazo-auth): request: GET http://localhost:9497/0.1/token/6ff58dbc-59f1-4e77-b80e-7bac7d1a1605?scope=websocketd {'Host': 'localhost:9497', 'Accept-Encoding': 'identity', 'Connection': 'close', 'User-Agent': 'wazo-websocketd', 'Accept': 'application/json', 'Authorization': 'Basic <hidden>'}
2024-02-22 23:41:23,206 [852540] (INFO) (wazo-auth): response to X.X.X.X in 0.00s: GET http://localhost:9497/0.1/token/6ff58dbc-59f1-4e77-b80e-7bac7d1a1605?scope=websocketd 200
2024-02-22 23:41:23,209 [973436] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=1, data=b'{"op": "token", "code": 0, "data": null}', rsv1=False, rsv2=False, rsv3=False)
2024-02-22 23:41:23,255 [852540] (INFO) (wazo-auth): request: GET https://XXXX.wazo.community/api/auth/0.1/token/6ff58dbc-59f1-4e77-b80e-7bac7d1a1605 {'Host': 'XXXX.wazo.community', 'X-Script-Name': '/api/auth', 'X-Forwarded-Proto': 'https', 'Connection': 'close', 'X-Frame-Options': 'SAMEORIGIN', 'X-Auth-Token': 'XXXXXXXX-XXXX-XXXX-XXXX-XXXX7d1a1605', 'Accept': '*/*', 'User-Agent': 'node-fetch/1.0 (+https://github.com/bitinn/node-fetch)', 'Accept-Encoding': 'gzip,deflate', 'Content-Type': 'application/json'}
2024-02-22 23:41:23,258 [852540] (INFO) (wazo-auth): response to X.X.X.X in 0.00s: GET https://XXXX.wazo.community/api/auth/0.1/token/6ff58dbc-59f1-4e77-b80e-7bac7d1a1605 200
2024-02-22 23:42:02,269 [973436] (DEBUG) (wazo_websocketd.auth): dynamic auth check: testing token validity
2024-02-22 23:42:02,269 [973436] (DEBUG) (wazo_websocketd.auth): getting token from wazo-auth
2024-02-22 23:42:02,271 [852540] (INFO) (wazo-auth): request: GET http://localhost:9497/0.1/token/99f3a61c-0d7b-4e6f-bb36-2d36c6096b10?scope=websocketd {'Host': 'localhost:9497', 'Accept-Encoding': 'identity', 'Connection': 'close', 'User-Agent': 'wazo-websocketd', 'Accept': 'application/json', 'Authorization': 'Basic <hidden>'}
2024-02-22 23:42:02,274 [852540] (INFO) (wazo-auth): response to X.X.X.X in 0.00s: GET http://localhost:9497/0.1/token/99f3a61c-0d7b-4e6f-bb36-2d36c6096b10?scope=websocketd 404
2024-02-22 23:42:02,282 [973436] (INFO) (wazo_websocketd.session): closing websocket connection: authentication expired@

The auth error causing the closing websocket at the end is caused by a GET on the token created at 2024-02-22 23:39:23,113 that is already expired. The new one should have been tested instead

Sylvain Boily

February 22, 2024 at 11:52 PM

The problem here is we could lost events from the websocket, because the client need to be reconnected.

Resize issue view side panel

Done

Details

Priority

Medium

Assignee

Pascal Cadotte

Reporter

Sylvain Boily

Pair

Sébastien Duthil

Fix versions

24.04

Sprint

Add sprint

Story Points

Zendesk Support

Created February 22, 2024 at 11:47 PM

Updated March 13, 2024 at 3:41 PM

Resolved March 5, 2024 at 2:31 PM