Unable to send messages from threaded handlers over TCP on Windows

[alcarney]

#501 seems to have found an interesting bug.

When a server

• Is running on Windows
• Is connected to a client over TCP
• And tries to send a message from a background thread it fails

The following logs are taken from tests/e2e/test_threaded_handler.py (reordered slightly to help tell the story better)

test_countdown_threaded

The server receives the count.down.thread command from the client

DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Received bytearray(b'Content-Length: 146\r\nContent-Type: application/vscode-jsonrpc; charset=utf-8\r\n\r\n{"id": "2a098fb1-85be-4a10-97fb-b7507614a470", "params": {"command": "count.down.thread"}, "method": "workspace/executeCommand", "jsonrpc": "2.0"}')
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Request message received.

The server starts its countdown

DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'ThreadPoolExecutor-0_0' ... 10")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'ThreadPoolExecutor-0_0' ... 10"}, "method": "window/showMessage", "jsonrpc": "2.0"}

Interestingly, the client appears to receive the first notification!

DEBUG    pygls.client:client.py:136 Content length: 143
DEBUG    pygls.protocol.json_rpc:json_rpc.py:365 Notification message received.

But then the server immediately raises a RuntimeError.

Note

We only get this traceback when running the tests with asyncio debug mode enabled.

Without debug mode, there are no obvious errors at all in the log.

DEBUG    root:conftest.py:199 [server]: ERROR:asyncio:GetQueuedCompletionStatus() returned an unexpected event
DEBUG    root:conftest.py:199 [server]: status: 'err=0 transferred=223 key=0x0 address=0x26c3a0697e0'
DEBUG    root:conftest.py:199 [server]: ERROR:pygls.protocol.json_rpc:Error sending data
DEBUG    root:conftest.py:199 [server]: Traceback (most recent call last):
DEBUG    root:conftest.py:199 [server]:   File "D:\a\pygls\pygls\pygls\protocol\json_rpc.py", line 399, in _send_data
DEBUG    root:conftest.py:199 [server]:     self.transport.write(header + body.encode(self.CHARSET))
DEBUG    root:conftest.py:199 [server]:   File "C:\hostedtoolcache\windows\Python\3.10.11\x64\lib\asyncio\proactor_events.py", line 365, in write
DEBUG    root:conftest.py:199 [server]:     self._loop_writing(data=bytes(data))
DEBUG    root:conftest.py:199 [server]:   File "C:\hostedtoolcache\windows\Python\3.10.11\x64\lib\asyncio\proactor_events.py", line 408, in _loop_writing
DEBUG    root:conftest.py:199 [server]:     self._write_fut.add_done_callback(self._loop_writing)
DEBUG    root:conftest.py:199 [server]:   File "C:\hostedtoolcache\windows\Python\3.10.11\x64\lib\asyncio\base_events.py", line 755, in call_soon
DEBUG    root:conftest.py:199 [server]:     self._check_thread()
DEBUG    root:conftest.py:199 [server]:   File "C:\hostedtoolcache\windows\Python\3.10.11\x64\lib\asyncio\base_events.py", line 792, in _check_thread
DEBUG    root:conftest.py:199 [server]:     raise RuntimeError(
DEBUG    root:conftest.py:199 [server]: RuntimeError: Non-thread-safe operation invoked on an event loop other than the current one

But the server still attempts to communicate with the client

DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Error: 1>, message='Error in server: Non-thread-safe operation invoked on an event loop other than the current one')
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 1, "message": "Error in server: Non-thread-safe operation invoked on an event loop other than the current one"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Received bytearray(b'Content-Length: 243\r\nContent-Type: application/vscode-jsonrpc; charset=utf-8\r\n\r\n{"id": "289c8fbc-d1b4-4602-8170-bb77e61143cd", "params": {"textDocument": {"uri": "file:///d:/a/pygls/pygls/examples/servers/workspace/code.txt"}, "position": {"line": 0, "character": 1}}, "method": "textDocument/completion", "jsonrpc": "2.0"}')
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Request message received.
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"id": "289c8fbc-d1b4-4602-8170-bb77e61143cd", "jsonrpc": "2.0", "result": {"isIncomplete": false, "items": [{"label": "one"}, {"label": "two"}, {"label": "three"}, {"label": "four"}, {"label": "five"}]}}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'ThreadPoolExecutor-0_0' ... 9")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'ThreadPoolExecutor-0_0' ... 9"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'ThreadPoolExecutor-0_0' ... 8")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'ThreadPoolExecutor-0_0' ... 8"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'ThreadPoolExecutor-0_0' ... 7")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'ThreadPoolExecutor-0_0' ... 7"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'ThreadPoolExecutor-0_0' ... 6")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'ThreadPoolExecutor-0_0' ... 6"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'ThreadPoolExecutor-0_0' ... 5")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'ThreadPoolExecutor-0_0' ... 5"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'ThreadPoolExecutor-0_0' ... 4")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'ThreadPoolExecutor-0_0' ... 4"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'ThreadPoolExecutor-0_0' ... 3")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'ThreadPoolExecutor-0_0' ... 3"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'ThreadPoolExecutor-0_0' ... 2")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'ThreadPoolExecutor-0_0' ... 2"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'ThreadPoolExecutor-0_0' ... 1")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'ThreadPoolExecutor-0_0' ... 1"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"id": "2a098fb1-85be-4a10-97fb-b7507614a470", "jsonrpc": "2.0", "result": null}

But for some reason the client never recieves any of the messages and the test case hangs indefinitely

test_countdown_blocking

For comparison, here are the logs when executing the test_countdown_blocking test case. The server sends the messages and the client receives them as expected. (Although for some reason all at once? Perhaps just a quirk of the logging approach?? 🤔)

Details

DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Received bytearray(b'Content-Length: 148\r\nContent-Type: application/vscode-jsonrpc; charset=utf-8\r\n\r\n{"id": "33ec758f-66ee-45ec-b111-295cd21d0384", "params": {"command": "count.down.blocking"}, "method": "workspace/executeCommand", "jsonrpc": "2.0"}')
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Request message received.
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'MainThread' ... 10")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'MainThread' ... 10"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    pygls.client:client.py:136 Content length: 131
DEBUG    pygls.protocol.json_rpc:json_rpc.py:365 Notification message received.
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'MainThread' ... 9")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'MainThread' ... 9"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'MainThread' ... 8")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'MainThread' ... 8"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'MainThread' ... 7")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'MainThread' ... 7"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'MainThread' ... 6")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'MainThread' ... 6"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'MainThread' ... 5")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'MainThread' ... 5"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'MainThread' ... 4")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'MainThread' ... 4"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'MainThread' ... 3")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'MainThread' ... 3"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'MainThread' ... 2")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'MainThread' ... 2"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: DEBUG:pygls.protocol.json_rpc:Sending notification: 'window/showMessage' ShowMessageParams(type=<MessageType.Info: 3>, message="Counting down in thread 'MainThread' ... 1")
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"params": {"type": 3, "message": "Counting down in thread 'MainThread' ... 1"}, "method": "window/showMessage", "jsonrpc": "2.0"}
DEBUG    root:conftest.py:199 [server]: INFO:pygls.protocol.json_rpc:Sending data: {"id": "33ec758f-66ee-45ec-b111-295cd21d0384", "jsonrpc": "2.0", "result": null}
DEBUG    root:conftest.py:199 [server]: WARNING:asyncio:Executing <Handle _ProactorReadPipeTransport._loop_reading(<_OverlappedF...events.py:502>) created at C:\hostedtoolcache\windows\Python\3.10.11\x64\lib\asyncio\windows_events.py:92> took 10.047 seconds
DEBUG    pygls.client:client.py:136 Content length: 130
DEBUG    pygls.protocol.json_rpc:json_rpc.py:365 Notification message received.
DEBUG    pygls.client:client.py:136 Content length: 130
DEBUG    pygls.protocol.json_rpc:json_rpc.py:365 Notification message received.
DEBUG    pygls.client:client.py:136 Content length: 130
DEBUG    pygls.protocol.json_rpc:json_rpc.py:365 Notification message received.
DEBUG    pygls.client:client.py:136 Content length: 130
DEBUG    pygls.protocol.json_rpc:json_rpc.py:365 Notification message received.
DEBUG    pygls.client:client.py:136 Content length: 130
DEBUG    pygls.protocol.json_rpc:json_rpc.py:365 Notification message received.
DEBUG    pygls.client:client.py:136 Content length: 130
DEBUG    pygls.protocol.json_rpc:json_rpc.py:365 Notification message received.
DEBUG    pygls.client:client.py:136 Content length: 130
DEBUG    pygls.protocol.json_rpc:json_rpc.py:365 Notification message received.
DEBUG    pygls.client:client.py:136 Content length: 130
DEBUG    pygls.protocol.json_rpc:json_rpc.py:365 Notification message received.
DEBUG    pygls.client:client.py:136 Content length: 130
DEBUG    pygls.protocol.json_rpc:json_rpc.py:365 Notification message received.
DEBUG    pygls.client:client.py:136 Content length: 80
DEBUG    pygls.protocol.json_rpc:json_rpc.py:372 Response message received.

Questions

• Why does this only happen on Windows? Trying to write from the wrong thread feels like a fundamental error, so why aren't there any issues on Linux?
• Why does this only happen over TCP? Trying to write from the wrong thread feels like a fundamental error, so why aren't there any issues on stdio?
• Why does it work sometimes? (Not every windows build fails every time)

[alcarney]

This is also an issue for WebSockets.

Traceback (most recent call last):
  File "/var/home/alex/Projects/openlawlibrary/pygls/options/pygls/protocol/json_rpc.py", line 391, in _send_data
    self.transport.write(body)  # type: ignore
    ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/var/home/alex/Projects/openlawlibrary/pygls/options/pygls/server.py", line 142, in write
    asyncio.ensure_future(self._ws.send(data))
  File "/usr/lib64/python3.12/asyncio/tasks.py", line 693, in ensure_future
    loop = events.get_event_loop()
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.12/asyncio/events.py", line 702, in get_event_loop
    raise RuntimeError('There is no current event loop in thread %r.'
RuntimeError: There is no current event loop in thread 'ThreadPoolExecutor-0_0'.