Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Unable to send messages from threaded handlers over TCP on Windows #502

Open
alcarney opened this issue Oct 8, 2024 · 1 comment
Open

Unable to send messages from threaded handlers over TCP on Windows #502

alcarney opened this issue Oct 8, 2024 · 1 comment
Labels
bug Something isn't working windows Issues only found on Windows

Comments

@alcarney
Copy link
Collaborator

alcarney commented Oct 8, 2024 •
edited
Loading

#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?? 🤔)

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 alcarney added the bug Something isn't working label Oct 8, 2024
alcarney added a commit to alcarney/pygls that referenced this issue Oct 8, 2024
@alcarney
test: skip test on Windows for now
be62b54 
see openlawlibrary#502
@alcarney alcarney added the windows Issues only found on Windows label Oct 8, 2024
alcarney added a commit to alcarney/pygls that referenced this issue Oct 8, 2024
@alcarney
test: skip test on Windows for now
428f457 
see openlawlibrary#502
@alcarney alcarney mentioned this issue Oct 8, 2024
Merged
6 tasks
alcarney added a commit that referenced this issue Oct 9, 2024
@alcarney
test: skip test on Windows for now
ff8bea2 
see #502
@alcarney
Copy link
Collaborator Author

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'.

@alcarney alcarney mentioned this issue Oct 13, 2024
Merged
6 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working windows Issues only found on Windows
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@alcarney