Refresh token for websocket doesn't seems works correctly

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