websockets: Unexpected ConnectionClosed in keepalive ping task

Using websockets 7.0 on Python 3.7, this can occur semi-frequently:

Unexpected exception in keepalive ping task
Traceback (most recent call last):
  File "C:\Program Files\Python37\lib\site-packages\websockets\protocol.py", line 989, in keepalive_ping
	ping_waiter, self.ping_timeout, loop=self.loop
  File "C:\Program Files\Python37\lib\asyncio\tasks.py", line 416, in wait_for
	return fut.result()
websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason

This sometimes is followed by:

Error in data transfer
Traceback (most recent call last):
  File "C:\Program Files\Python37\lib\site-packages\websockets\protocol.py", line 674, in transfer_data
	message = yield from self.read_message()
  File "C:\Program Files\Python37\lib\site-packages\websockets\protocol.py", line 742, in read_message
	frame = yield from self.read_data_frame(max_size=self.max_size)
  File "C:\Program Files\Python37\lib\site-packages\websockets\protocol.py", line 846, in read_data_frame
	pong_waiter.set_result(None)
asyncio.base_futures.InvalidStateError: invalid state

The first error seems to contradict the documentation in keepalive_ping: https://github.com/aaugustin/websockets/blob/8fc78fee48d52bb3c690e925bad0825613319296/src/websockets/protocol.py#L967 I believe this is because pending keepalive pings are now aborted with ConnectionClosed in 7.0 (#467).

I think the latter error is because the ping is marked done with set_exception in abort_keepalive_pings where ConnectionClosed is raised: https://github.com/aaugustin/websockets/blob/8fc78fee48d52bb3c690e925bad0825613319296/src/websockets/protocol.py#L1148 and https://github.com/aaugustin/websockets/blob/8fc78fee48d52bb3c690e925bad0825613319296/src/websockets/protocol.py#L840 attempts to set the result to None, raising an error when the Future is already done.

About this issue

Original URL
State: closed
Created 5 years ago
Reactions: 7
Comments: 19 (6 by maintainers)

Commits related to this issue

downgrade websockets to avoid a bug https://github.com/aaugustin/websockets/issues/551 — committed to TankerHQ/sdk-js by deleted user 5 years ago
Handle ConnectionClosed exception in keepalive_ping. Fix #551. Thanks @Harmon758 for diagnosing the root cause and proposing a fix. — committed to python-websockets/websockets by aaugustin 5 years ago
Handle ConnectionClosed exception in keepalive_ping. Fix #551. Thanks @Harmon758 for reporting this bug and identifying the root cause. — committed to python-websockets/websockets by aaugustin 5 years ago
Handle aborted pings when receiving a pong. Fix #551. Thanks @Harmon758 for reporting this bug and identifying the root cause. — committed to python-websockets/websockets by aaugustin 5 years ago
Handle aborted pings when receiving a pong. Fix #551. Thanks @Harmon758 for reporting this bug and identifying the root cause. — committed to python-websockets/websockets by aaugustin 5 years ago
Handle ConnectionClosed exception in keepalive_ping. Fix #551. Thanks @Harmon758 for reporting this bug and identifying the root cause. — committed to python-websockets/websockets by aaugustin 5 years ago
Handle aborted pings when receiving a pong. Fix #551. Thanks @Harmon758 for reporting this bug and identifying the root cause. — committed to python-websockets/websockets by aaugustin 5 years ago
Encourage users to remove workarounds. Refs #551. — committed to python-websockets/websockets by aaugustin 5 years ago

Most upvoted comments

I have this issue as well and had to downgrade to version 6.0 to work around it.

fenhl on Jan 12, 2019

Very similar errors on 7.0 with python 3.7.2 on Linux

04/08/2019 18:09:34.090 WARNING websockets.protocol None Unexpected exception in keepalive ping task
Traceback (most recent call last):
  File "/home/xyz/lib64/python3.7/site-packages/websockets/protocol.py", line 984, in keepalive_ping
    ping_waiter = yield from self.ping()
  File "/home/xyz/lib64/python3.7/site-packages/websockets/protocol.py", line 583, in ping
    yield from self.ensure_open()
  File "/home/xyz/lib64/python3.7/site-packages/websockets/protocol.py", line 658, in ensure_open
    ) from self.transfer_data_exc
websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1011 (unexpected error), no reason

I got a bunch of these all at the same time on different connections when the ISP at the other end flaked out.

Typically in such situations I see:

WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason

which I expect, but I’d not seen the Tracebacks before.

rhiller on Apr 28, 2019

Indeed, websockets doesn’t handle well the situation where a ping is aborted because the connection was lost.

As noted by @Harmon758 in this bug report, this could manifest in two places:

When websockets aborts a ping that the keepalive task is waiting on;
When websockets processes a pong that matches an aborted ping.

The two commits in PR #627 address these two issues.

aaugustin on Jun 22, 2019

I have this issue as well and had to downgrade to version 6.0 to work around it.

@fenhl downgrade is not necessary, since with version 7.0 passing ping_interval=None to the Client or Server disables ping. but then you will not recognize a broken connection, so you have to care about ping/pong too

oliver-zehentleitner on Apr 28, 2019

I have this issue as well and had to downgrade to version 6.0 to work around it.

@fenhl downgrade is not necessary, since with version 7.0 passing ping_interval=None to the Client or Server disables ping.

WojciechMigda on Apr 6, 2019