python-websockets/websockets

Duplicate ping/pong ?

albaintor opened this issue · 2 comments

albaintor commented

``I have enabled loglevel debug in my integration (home assistant plugin that creates a websocket connection)
I have double checked that I have only one connection active

The loglevel reports duplicates ping/pong and also the other thing is that it occurs every 5 seconds instead of 20 seconds

2024-02-19 11:36:00.759 DEBUG (MainThread) [websockets.client] % sending keepalive ping
2024-02-19 11:36:00.764 DEBUG (MainThread) [websockets.client] % sending keepalive ping
2024-02-19 11:36:00.878 DEBUG (MainThread) [websockets.client] % received keepalive pong
2024-02-19 11:36:00.879 DEBUG (MainThread) [websockets.client] % received keepalive pong
2024-02-19 11:36:03.251 DEBUG (MainThread) [websockets.client] 7bea25df-0216-40ed-9da8-f26f5ba087fd % sending keepalive ping
2024-02-19 11:36:03.252 DEBUG (MainThread) [websockets.client] 7bea25df-0216-40ed-9da8-f26f5ba087fd > PING 29 0b 1d 85 [binary, 4 bytes]
2024-02-19 11:36:03.262 DEBUG (MainThread) [websockets.client] 7bea25df-0216-40ed-9da8-f26f5ba087fd < PONG 29 0b 1d 85 [binary, 4 bytes]
2024-02-19 11:36:03.262 DEBUG (MainThread) [websockets.client] 7bea25df-0216-40ed-9da8-f26f5ba087fd % received keepalive pong
2024-02-19 11:36:05.880 DEBUG (MainThread) [websockets.client] % sending keepalive ping
2024-02-19 11:36:05.882 DEBUG (MainThread) [websockets.client] % sending keepalive ping
2024-02-19 11:36:05.886 DEBUG (MainThread) [websockets.client] % received keepalive pong
2024-02-19 11:36:05.887 DEBUG (MainThread) [websockets.client] % received keepalive pong
2024-02-19 11:36:10.887 DEBUG (MainThread) [websockets.client] % sending keepalive ping
2024-02-19 11:36:10.889 DEBUG (MainThread) [websockets.client] % sending keepalive ping
2024-02-19 11:36:10.894 DEBUG (MainThread) [websockets.client] % received keepalive pong
2024-02-19 11:36:10.894 DEBUG (MainThread) [websockets.client] % received keepalive pong
2024-02-19 11:36:15.895 DEBUG (MainThread) [websockets.client] % sending keepalive ping
2024-02-19 11:36:15.897 DEBUG (MainThread) [websockets.client] % sending keepalive ping
2024-02-19 11:36:15.901 DEBUG (MainThread) [websockets.client] % received keepalive pong
2024-02-19 11:36:15.902 DEBUG (MainThread) [websockets.client] % received keepalive pong
2024-02-19 11:36:20.902 DEBUG (MainThread) [websockets.client] % sending keepalive ping
2024-02-19 11:36:20.904 DEBUG (MainThread) [websockets.client] % sending keepalive ping
2024-02-19 11:36:20.908 DEBUG (MainThread) [websockets.client] % received keepalive pong
2024-02-19 11:36:20.909 DEBUG (MainThread) [websockets.client] % received keepalive pong
2024-02-19 11:36:25.911 DEBUG (MainThread) [websockets.client] % sending keepalive ping
2024-02-19 11:36:25.912 DEBUG (MainThread) [websockets.client] % sending keepalive ping
2024-02-19 11:36:25.916 DEBUG (MainThread) [websockets.client] % received keepalive pong
2024-02-19 11:36:25.917 DEBUG (MainThread) [websockets.client] % received keepalive pong
2024-02-19 11:36:30.916 DEBUG (MainThread) [websockets.client] % sending keepalive ping
2024-02-19 11:36:30.918 DEBUG (MainThread) [websockets.client] % sending keepalive ping
2024-02-19 11:36:30.922 DEBUG (MainThread) [websockets.client] % received keepalive pong
2024-02-19 11:36:30.922 DEBUG (MainThread) [websockets.client] % received keepalive pong
2024-02-19 11:36:33.263 DEBUG (MainThread) [websockets.client] 7bea25df-0216-40ed-9da8-f26f5ba087fd % sending keepalive ping
2024-02-19 11:36:33.263 DEBUG (MainThread) [websockets.client] 7bea25df-0216-40ed-9da8-f26f5ba087fd > PING ac 18 6c ee [binary, 4 bytes]
2024-02-19 11:36:33.291 DEBUG (MainThread) [websockets.client] 7bea25df-0216-40ed-9da8-f26f5ba087fd < PONG ac 18 6c ee [binary, 4 bytes]
2024-02-19 11:36:33.291 DEBUG (MainThread) [websockets.client] 7bea25df-0216-40ed-9da8-f26f5ba087fd % received keepalive pong

Here is my code :

        async for websocket in websockets.connect(self.endpoint, extra_headers={"API-KEY": self.api_key},
                                                  logger=LoggerAdapter(logger, None)):
            try:
                _LOGGER.debug("websocket connection initialized")
                self.websocket = websocket
                await self.subscribe_events()
                while True:
                    async for message in websocket:
                        try:
                            receive_callback(message)
                        except Exception as ex:
                            _LOGGER.debug("exception in websocket receive callback", ex)
            except websockets.ConnectionClosed as error:
                _LOGGER.debug("websocket closed. Waiting before reconnecting...", error)
                try:
                    await self.close_websocket()
                except Exception:
                    pass
                await asyncio.sleep(WS_RECONNECTION_DELAY)
                continue

Thank you for your help

aaugustin commented

Logs for connection with id 7bea25df-0216-40ed-9da8-f26f5ba087fd show one ping and one pong every 20 seconds.

With the information you provided, I cannot tell where the other logs are coming from, but I suspect another component of Home Assistant also uses websockets, probably with ping_interval=5.

albaintor commented

Hi,

Thank you you're right this was another web socket instance