We're updating the issue view to help you get more done. 

Refresh token for websocket doesn't seems works correctly

Description

Hello,

I make some test with a token who have an expiration in 180 secs. We see the client send the refresh token, but the server close after few secondes the connection because the token is expired.

2020-01-14 14:51:52,629 [4440] (DEBUG) (websockets.protocol): server - state = CONNECTING
2020-01-14 14:51:52,631 [4440] (DEBUG) (websockets.protocol): server - event = connection_made(<asyncio.sslproto._SSLProtocolTransport object at 0x7f5f5372fb70>)
2020-01-14 14:51:52,632 [4440] (DEBUG) (websockets.protocol): server - state = OPEN
2020-01-14 14:51:52,633 [4440] (INFO) (wazo_websocketd.session): websocket connection accepted from "xxx.xxx.xxx.xxx, 192.168.32.251"
2020-01-14 14:51:52,633 [4440] (DEBUG) (wazo_websocketd.auth): getting token from wazo-auth
2020-01-14 14:51:52,671 [4440] (DEBUG) (wazo_websocketd.bus): connecting to bus
2020-01-14 14:51:52,690 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=1, data=b'{"op": "init", "code": 0, "data": {"version": 2}}', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:51:52,750 [4440] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=1, data=b'{"op":"subscribe","data":{"event_name":"*"}}', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:51:52,750 [4440] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=1, data=b'{"op":"start"}', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:51:52,750 [4440] (DEBUG) (wazo_websocketd.session): subscribing to event "*"
2020-01-14 14:51:52,751 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=1, data=b'{"op": "subscribe", "code": 0, "data": null}', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:51:52,751 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=1, data=b'{"op": "start", "code": 0, "data": null}', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:52:12,673 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=9, data=b'\x99\x19\x86\xbc', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:52:12,696 [4440] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=10, data=b'\x99\x19\x86\xbc', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:52:12,696 [4440] (DEBUG) (websockets.protocol): server - received solicited pong: 991986bc
2020-01-14 14:52:32,710 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=9, data=b'\x1cY\xd6\xc9', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:52:32,792 [4440] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=10, data=b'\x1cY\xd6\xc9', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:52:32,792 [4440] (DEBUG) (websockets.protocol): server - received solicited pong: 1c59d6c9
2020-01-14 14:52:52,711 [4440] (DEBUG) (wazo_websocketd.session): sending websocket ping
2020-01-14 14:52:52,712 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=9, data=b'Q\x1b\xfe\xc6', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:52:52,712 [4440] (DEBUG) (wazo_websocketd.auth): static auth check: testing token validity
2020-01-14 14:52:52,712 [4440] (DEBUG) (wazo_websocketd.auth): checking token validity from wazo-auth
2020-01-14 14:52:52,770 [4440] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=10, data=b'Q\x1b\xfe\xc6', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:52:52,771 [4440] (DEBUG) (websockets.protocol): server - received solicited pong: 511bfec6
2020-01-14 14:52:52,793 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=9, data=b'\xd2\xc3\x1d\xad', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:52:52,821 [4440] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=10, data=b'\xd2\xc3\x1d\xad', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:52:52,822 [4440] (DEBUG) (websockets.protocol): server - received solicited pong: d2c31dad
2020-01-14 14:53:12,835 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=9, data=b':3B\xbe', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:53:12,937 [4440] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=10, data=b':3B\xbe', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:53:12,937 [4440] (DEBUG) (websockets.protocol): server - received solicited pong: 3a3342be
2020-01-14 14:53:32,955 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=9, data=b'D\x862\xa0', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:53:32,985 [4440] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=10, data=b'D\x862\xa0', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:53:32,986 [4440] (DEBUG) (websockets.protocol): server - received solicited pong: 448632a0
2020-01-14 14:53:52,731 [4440] (DEBUG) (wazo_websocketd.session): sending websocket ping
2020-01-14 14:53:52,732 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=9, data=b'\x12xr\xe4', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:53:52,736 [4440] (DEBUG) (wazo_websocketd.auth): static auth check: testing token validity
2020-01-14 14:53:52,737 [4440] (DEBUG) (wazo_websocketd.auth): checking token validity from wazo-auth
2020-01-14 14:53:52,750 [4440] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=10, data=b'\x12xr\xe4', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:53:52,750 [4440] (DEBUG) (websockets.protocol): server - received solicited pong: 127872e4
2020-01-14 14:53:52,988 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=9, data=b'q@\xb4T', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:53:53,079 [4440] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=10, data=b'q@\xb4T', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:53:53,080 [4440] (DEBUG) (websockets.protocol): server - received solicited pong: 7140b454
2020-01-14 14:54:07,809 [4440] (DEBUG) (wazo_websocketd.bus): bus message received
2020-01-14 14:54:07,809 [4440] (DEBUG) (wazo_websocketd.bus): dispatching event "auth_session_expire_soon" with ACL "events.auth.users.12214e4f-1272-43cd-a42d-31a3998ff722.sessions.ce3b1011-dd9f-4bea-b67d-a4d7120b4fa9.expire_soon"
2020-01-14 14:54:07,811 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=1, data=b'{"op": "event", "code": 0, "data": {"name": "auth_session_expire_soon", "origin_uuid": "624ac6e8-00df-4ad9-a5e8-8f50d6058632", "required_acl": "events.auth.users.12214e4f-1272-43cd-a42d-31a3998ff722.sessions.ce3b1011-dd9f-4bea-b67d-a4d7120b4fa9.expire_soon", "data": {"uuid": "ce3b1011-dd9f-4bea-b67d-a4d7120b4fa9", "tenant_uuid": "72dac8f6-df2f-401b-b213-58d2b66da1ac", "user_uuid": "12214e4f-1272-43cd-a42d-31a3998ff722"}}}', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:54:07,814 [4440] (DEBUG) (wazo_websocketd.bus): bus message received
2020-01-14 14:54:07,814 [4440] (DEBUG) (wazo_websocketd.bus): dispatching event "auth_session_expire_soon" with ACL "events.auth.users.12214e4f-1272-43cd-a42d-31a3998ff722.sessions.1612815e-b3bf-42ca-9f6a-798d63572c96.expire_soon"
2020-01-14 14:54:07,815 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=1, data=b'{"op": "event", "code": 0, "data": {"name": "auth_session_expire_soon", "origin_uuid": "624ac6e8-00df-4ad9-a5e8-8f50d6058632", "required_acl": "events.auth.users.12214e4f-1272-43cd-a42d-31a3998ff722.sessions.1612815e-b3bf-42ca-9f6a-798d63572c96.expire_soon", "data": {"uuid": "1612815e-b3bf-42ca-9f6a-798d63572c96", "tenant_uuid": "72dac8f6-df2f-401b-b213-58d2b66da1ac", "user_uuid": "12214e4f-1272-43cd-a42d-31a3998ff722"}}}', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:54:07,816 [4440] (DEBUG) (wazo_websocketd.bus): bus message received
2020-01-14 14:54:07,816 [4440] (DEBUG) (wazo_websocketd.bus): dispatching event "auth_session_expire_soon" with ACL "events.auth.users.12214e4f-1272-43cd-a42d-31a3998ff722.sessions.f74d5eaa-e1dc-4ba9-acfb-50db26d40e37.expire_soon"
2020-01-14 14:54:07,817 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=1, data=b'{"op": "event", "code": 0, "data": {"name": "auth_session_expire_soon", "origin_uuid": "624ac6e8-00df-4ad9-a5e8-8f50d6058632", "required_acl": "events.auth.users.12214e4f-1272-43cd-a42d-31a3998ff722.sessions.f74d5eaa-e1dc-4ba9-acfb-50db26d40e37.expire_soon", "data": {"uuid": "f74d5eaa-e1dc-4ba9-acfb-50db26d40e37", "tenant_uuid": "72dac8f6-df2f-401b-b213-58d2b66da1ac", "user_uuid": "12214e4f-1272-43cd-a42d-31a3998ff722"}}}', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:54:07,818 [4440] (DEBUG) (wazo_websocketd.bus): bus message received
2020-01-14 14:54:07,818 [4440] (DEBUG) (wazo_websocketd.bus): dispatching event "auth_session_expire_soon" with ACL "events.auth.users.12214e4f-1272-43cd-a42d-31a3998ff722.sessions.ca358509-cc5e-4b71-9443-4180b1427815.expire_soon"
2020-01-14 14:54:07,818 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=1, data=b'{"op": "event", "code": 0, "data": {"name": "auth_session_expire_soon", "origin_uuid": "624ac6e8-00df-4ad9-a5e8-8f50d6058632", "required_acl": "events.auth.users.12214e4f-1272-43cd-a42d-31a3998ff722.sessions.ca358509-cc5e-4b71-9443-4180b1427815.expire_soon", "data": {"uuid": "ca358509-cc5e-4b71-9443-4180b1427815", "tenant_uuid": "72dac8f6-df2f-401b-b213-58d2b66da1ac", "user_uuid": "12214e4f-1272-43cd-a42d-31a3998ff722"}}}', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:54:08,292 [4440] (DEBUG) (wazo_websocketd.bus): bus message received
2020-01-14 14:54:08,292 [4440] (DEBUG) (wazo_websocketd.bus): dispatching event "auth_session_created" with ACL "events.auth.sessions.3b41cb57-1046-409c-ba12-b80118c54c3a.created"
2020-01-14 14:54:08,292 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=1, data=b'{"op": "event", "code": 0, "data": {"name": "auth_session_created", "origin_uuid": "624ac6e8-00df-4ad9-a5e8-8f50d6058632", "required_acl": "events.auth.sessions.3b41cb57-1046-409c-ba12-b80118c54c3a.created", "data": {"uuid": "3b41cb57-1046-409c-ba12-b80118c54c3a", "tenant_uuid": "72dac8f6-df2f-401b-b213-58d2b66da1ac", "user_uuid": "12214e4f-1272-43cd-a42d-31a3998ff722", "mobile": false}}}', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:54:08,349 [4440] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=1, data=b'{"op":"token","data":{"token":"09906d1b-9c54-4447-86d0-6adb0ecdcc62"}}', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:54:08,350 [4440] (DEBUG) (wazo_websocketd.auth): getting token from wazo-auth
2020-01-14 14:54:08,372 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=1, data=b'{"op": "token", "code": 0, "data": null}', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:54:13,085 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=9, data=b'\xc68\xe2\x7f', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:54:13,151 [4440] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=10, data=b'\xc68\xe2\x7f', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:54:13,151 [4440] (DEBUG) (websockets.protocol): server - received solicited pong: c638e27f
2020-01-14 14:54:33,172 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=9, data=b'u\xc7\xab\x19', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:54:33,220 [4440] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=10, data=b'u\xc7\xab\x19', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:54:33,220 [4440] (DEBUG) (websockets.protocol): server - received solicited pong: 75c7ab19
2020-01-14 14:54:52,752 [4440] (DEBUG) (wazo_websocketd.session): sending websocket ping
2020-01-14 14:54:52,752 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=9, data=b'\r\xd3\xd4\xf9', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:54:52,764 [4440] (DEBUG) (wazo_websocketd.auth): static auth check: testing token validity
2020-01-14 14:54:52,764 [4440] (DEBUG) (wazo_websocketd.auth): checking token validity from wazo-auth
2020-01-14 14:54:52,777 [4440] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=10, data=b'\r\xd3\xd4\xf9', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:54:52,777 [4440] (DEBUG) (websockets.protocol): server - received solicited pong: 0dd3d4f9
2020-01-14 14:54:52,789 [4440] (INFO) (wazo_websocketd.session): closing websocket connection: authentication expired
2020-01-14 14:54:52,790 [4440] (DEBUG) (websockets.protocol): server - state = CLOSING
2020-01-14 14:54:52,790 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=8, data=b'\x0f\xa3authentication expired', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:54:52,816 [4440] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=8, data=b'\x0f\xa3authentication expired', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:54:52,817 [4440] (DEBUG) (websockets.protocol): server x closing TCP connection
2020-01-14 14:54:52,817 [4440] (DEBUG) (websockets.protocol): server - event = connection_lost(None)
2020-01-14 14:54:52,817 [4440] (DEBUG) (websockets.protocol): server - state = CLOSED
2020-01-14 14:54:52,818 [4440] (DEBUG) (websockets.protocol): server x code = 4003, reason = authentication expired
2020-01-14 14:54:52,818 [4440] (INFO) (wazo_websocketd.session): websocket session terminated xxx.xxx.xxx.xxx, 192.168.32.251
2020-01-14 14:54:56,149 [4440] (DEBUG) (websockets.protocol): server - state = CONNECTING
2020-01-14 14:54:56,151 [4440] (DEBUG) (websockets.protocol): server - event = connection_made(<asyncio.sslproto._SSLProtocolTransport object at 0x7f5f516a2dd8>)
2020-01-14 14:54:56,152 [4440] (DEBUG) (websockets.protocol): server - state = OPEN
2020-01-14 14:54:56,153 [4440] (INFO) (wazo_websocketd.session): websocket connection accepted from "xxx.xxx.xxx.xxx, 192.168.32.251"
2020-01-14 14:54:56,153 [4440] (DEBUG) (wazo_websocketd.auth): getting token from wazo-auth
2020-01-14 14:54:56,176 [4440] (INFO) (wazo_websocketd.session): closing websocket connection: authentication failed: 404 Client Error: NOT FOUND for url: https://localhost:9497/0.1/token/c2912228-d123-4541-8b62-319e1e177197?scope=websocketd
2020-01-14 14:54:56,176 [4440] (DEBUG) (websockets.protocol): server - state = CLOSING
2020-01-14 14:54:56,176 [4440] (DEBUG) (websockets.protocol): server > Frame(fin=True, opcode=8, data=b'\x0f\xa2authentication failed', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:54:56,200 [4440] (DEBUG) (websockets.protocol): server < Frame(fin=True, opcode=8, data=b'\x0f\xa2authentication failed', rsv1=False, rsv2=False, rsv3=False)
2020-01-14 14:54:56,200 [4440] (DEBUG) (websockets.protocol): server x closing TCP connection
2020-01-14 14:54:56,201 [4440] (DEBUG) (websockets.protocol): server - event = connection_lost(None)
2020-01-14 14:54:56,201 [4440] (DEBUG) (websockets.protocol): server - state = CLOSED
2020-01-14 14:54:56,201 [4440] (DEBUG) (websockets.protocol): server x code = 4002, reason = authentication failed
2020-01-14 14:54:56,202 [4440] (INFO) (wazo_websocketd.session): websocket session terminated xxx.xxx.xxx.xxx, 192.168.32.251

Environment

None

Activity

Show:
Mathias Wolff
January 31, 2020, 1:37 PM

could you have a look at this bug ?

Assignee

Mehdi Abaakouk

Reporter

Sylvain Boily

Labels

Approvers

None

Pair

None

Sprint

None

Fix versions

Priority

High
Configure