wslink icon indicating copy to clipboard operation
wslink copied to clipboard

Asynchronous RPC Methods Processed Sequentially, Blocking Concurrent Execution

Open joaomlap opened this issue 1 year ago • 3 comments

Describe the bug

When using asynchronous RPC methods in wslink, requests are processed sequentially, even though the RPC methods are defined as async. This blocks concurrent handling of WebSocket messages, preventing expected asynchronous behavior. As a result, multiple requests from different clients or tabs are handled one at a time instead of concurrently.

To Reproduce

Steps to reproduce the behavior:

  1. Define an async RPC method using wslink, such as:
from wslink.websocket import LinkProtocol
from wslink import register
import asyncio

class MyProtocol(LinkProtocol):
    @register("test.async.method")
    async def test_async_method(self):
        print("Received request")
        await asyncio.sleep(5)  # Simulate long-running task
        print("Completed request")
        return "Done"
  1. Open two clients (e.g., different browser tabs or clients) and call this RPC method simultaneously. Alternatively, use a single client (e.g., browser tab) to make two requests in rapid succession.
  2. Observe the logs or results — the second request does not start processing until the first one is completed.

Code

The issue is in the WslinkHandler class, where onMessage processes messages sequentially by awaiting the onCompleteMessage function:

async def onMessage(self, is_binary, msg, client_id):
    full_message = self.unchunkers[client_id].process_chunk(msg.data)
    if full_message is not None:
        await self.onCompleteMessage(full_message, client_id)  # Sequential processing

Expected behavior

I expect that asynchronous RPC methods would be handled concurrently. In other words:

Multiple clients should be able to invoke async RPCs at the same time, with each request starting execution without waiting for other requests to finish. The logs should show both "Received request" logs before either "Completed request" log, indicating concurrent execution.

Screenshots

N/A

Platform:

Device:

  • [x] Desktop
  • [ ] Mobile

OS:

  • [x] Windows
  • [x] MacOS
  • [x] Linux
  • [ ] Android
  • [ ] iOS

Browsers Affected:

  • [x] Chrome
  • [x] Firefox
  • [ ] Safari
  • [ ] IE (Version)

wslink version: 2.2.1

Proposed Fix

To enable concurrent message processing, modify the onMessage method to schedule the processing of messages as tasks rather than awaiting them sequentially. This change allows the event loop to handle multiple messages concurrently:

async def onMessage(self, is_binary, msg, client_id):
    if not is_binary:
        logger.critical("wslink is not expecting text message:\n> %s", msg.data)
        return

    full_message = self.unchunkers[client_id].process_chunk(msg.data)
    if full_message is not None:
        # Schedule the message processing as a task to enable concurrency
        asyncio.create_task(self.onCompleteMessage(full_message, client_id))

This change ensures that multiple asynchronous RPC calls can be processed concurrently without blocking the event loop.

joaomlap avatar Oct 22 '24 16:10 joaomlap

That behavior is expected. The main issue of triggering task here is that you could start having some out of order behavior. I know that is what you want for your application, but imposing it on the network layer could have some huge side effect.

That is why it is better to define them as task within your application. That is what we do with a trame decorator or controller helpers. But that way you stay in control of what you want to be sequential vs what you don't.

jourdain avatar Oct 22 '24 16:10 jourdain

Just out of curiosity would there be another way of letting the users define an async function and wslink handling multiple requests at the same time. Maybe not that change specifically but something similar?

joaomlap avatar Oct 23 '24 08:10 joaomlap

You can make your own decorator, there is nothing specific to trame in the one we did here.

jourdain avatar Oct 23 '24 16:10 jourdain