bug#67945: 30.0.50; Jsonrpc trouble dealing with nested synchronous requests

bug#67945: 30.0.50; Jsonrpc trouble dealing with nested synchronous requests

[João Távora]

[-- Attachment #1: Type: text/plain, Size: 3525 bytes --]

Hi,

I've come across a rather complicated bug in jsonrpc.el that affects a
certain class of JSON-RPC applications.  Eglot, on of the more important
`jsonrpc.el` clients (perhaps the most) is not affected, as far as I
can tell.

I already have a fix for this bug, but I am filing this report as a
reference for the commit message and to collect comments.

I was made aware of this bug by Daniel Pettersson, who is experimenting
with integrating JSONRPC in his DAP client, dape.el.  DAP's based
transport protocol isn't really JSON-RPC based but jsonrpc.el can be
accomodated to support it.

However the bug can be triggered with a sufficiently insidious and plain
JSON-RPC application.  The attached files jbug.el and jbug.py worked on
by Daniel and me demonstrate the problem.

* jbug.py is a JSON-RPC server that upon receiving the ":ping"" request
  immediately notifies the client with a ":hello"" notification.  Then
  it waits briefly 0.1 seconds before reponding to the ":ping" request
  with ":pong".

* jbug.el is a JSON-RPC client that sends a ":ping" request and waits
  for a response.  While waiting for that response, it receives the
  ":hello" notification and issues a synchronous second ":slow" request
  inside the notification handler.  Both requests are synchronous and
  performed with the Elisp function 'jsonrpc-request'

As the name implies, the server takes longer to answer the ":slow"
request (about 0.5 seconds)

Before the patch that I'm about to push, the response to the ":slow"
request is never seen by the client.  The notification handler, which
runs in a timer, simply exists non-locally.

The reasons for this are somewhat complicated, but now well understood.

Briefly, the synchronicity of 'jsonrpc-request' is achieved by having
'accept-process-output' wrapped in a try-catch block.  A continuation
handler running in a timer will eventually throw to the catch tag, so
the next form after 'jsonrpc-request' can be executed.  During the wait,
JSON-RPC notifications may come in and they often do, but in most
JSON-RPC applications (Eglot, at least), the notification handlers don't
issue what will become a nested 'jsonrpc-request'.  And even if they
were to do that, they would only run into this problem if that second
inner request ends at a later time than the first request.

In dape.el and in the jbug.el file attached, this can happen.  The
result will be that the outer catch tag of the first outer request is
"thrown to" when the response arrives, but that also unwinds the stack
of the second inner request, which leads to the application never seeing
the response that will appear only later.

In the fix I'm about to push, the solution is to record the nesting in
an Elisp structure and prevent throwing to the outer request when its
response arrives.  Rather, we record that desired continuation to run
only when the inner request has resolved fully.  The throwing will
happen only when we are back at the first outer requests's
'accept-process-output'.

This makes both responses be seen by the JSON-RPC application, albeit in
reverse order.  I think this isn't a problem in real life, because from
the jsonrpc.el programmer's perspective a blocking jsonrpc-request call
is only meant to preserve the order of execution of the forms in which
that call.  It's _not_ the relative order of multiple "concurrent"
'jsonrpc-request' calls, because this concurrency isn't really defined
in the single-threaded Elisp programming model.

I attach the two files jbug.el and jbug.py.

[-- Attachment #2: jbug.py --]
[-- Type: application/octet-stream, Size: 1463 bytes --]

#!/usr/bin/env python3
# jbug.py
import sys
import json
import asyncio
from jsonrpcserver import method, async_dispatch, Success, Error

@method
async def ping():
    send_json({"method": "hello", "params": {}})
    await asyncio.sleep(0.1)  # Simulate asynchronous work
    return Success("pong")

@method
async def slow(sender):
    await asyncio.sleep(0.5)
    return Success(f"Response within {sender}")

def send_json(data):
    data = dict(data)
    data["jsonrpc"] = "2.0"
    json_data = json.dumps(data)
    write_response(json_data)

def write_response(response_str):
    sys.stdout.write(f"Content-length: {len(response_str)}\r\n\r\n{response_str}")
    sys.stdout.flush()

async def handle_request(request_str):
    try:
        response_str = await async_dispatch(request_str)
        write_response(response_str)
    except Exception as e:
        error_response = Error(str(e))
        write_response(str(error_response))

def read_message():
    content_length = sys.stdin.readline().strip()
    sys.stdin.readline()
    message_length = int(content_length.split(":")[1].strip())
    message = sys.stdin.read(message_length)
    return message

async def main():
    loop = asyncio.get_event_loop()

    while True:
        try:
            message = await loop.run_in_executor(None, read_message)
            loop.create_task(handle_request(message))
        except EOFError:
            break

if __name__ == "__main__":
    asyncio.run(main())

[-- Attachment #3: jbug.el --]
[-- Type: application/octet-stream, Size: 2006 bytes --]

;;; jbug.el --- asd                           -*- lexical-binding: t; -*-
(require 'jsonrpc)

(defclass jbug-test-connection (jsonrpc-process-connection) ((things :initform nil)))

(cl-defmethod jbug-handle-notification (conn (m (eql hello)) _)
  (push (jsonrpc-request conn :slow (list :sender (symbol-name m) ))
        (slot-value conn 'things)))

(defvar jbug-test-client nil)


(defun jbug-events ()
  (interactive)
  (with-current-buffer
      (jsonrpc-events-buffer jbug-test-client)
    (let ((inhibit-read-only t))
      (erase-buffer))
    (display-buffer (current-buffer))))

(defun jbug ()
  (interactive)
  (when jbug-test-client
    (jsonrpc-shutdown jbug-test-client)
    (jbug-events))
  (setq jbug-test-client
        (make-instance 'jbug-test-connection
                       :name "test client"
                       :request-dispatcher 'ignore
                       :notification-dispatcher #'jbug-handle-notification
                       :process (lambda (_conn)
                                  (make-process
                                   :name "dummy server"
                                   :stderr (get-buffer-create
                                            (format "*test client stderr*"))
                                   :command '("python3" "jbug.py")
                                   :connection-type 'pipe
                                   :coding 'utf-8-emacs-unix
                                   :noquery t)))))

(progn
  (jbug)
  (jbug-events) ; for debugging
  (push (jsonrpc-request jbug-test-client :ping (make-hash-table))
        (slot-value jbug-test-client 'things))
  (save-excursion
    (insert (format "\n;; %S" (slot-value jbug-test-client 'things)))))
;; ("pong" "Response within hello")
;; ("pong" "Response within hello")

;; ("pong" "Response within secondEvent")
;; ("pong" "Response within secondEvent")
;; ("pong" "Response within secondEvent")
;; ("Response within secondEvent" "pong")
;; ("Response within secondEvent" "pong")

bug#67945: 30.0.50; Jsonrpc trouble dealing with nested synchronous requests

[João Távora]

On Wed, Dec 20, 2023 at 11:31 PM João Távora <joaotavora@gmail.com> wrote:
>
> Hi,
>
> I've come across a rather complicated bug in jsonrpc.el that affects a
> certain class of JSON-RPC applications.  Eglot, on of the more important
> `jsonrpc.el` clients (perhaps the most) is not affected, as far as I
> can tell.
>
> I already have a fix for this bug, but I am filing this report as a
> reference for the commit message and to collect comments.

I've now pushed the fix to jsonrpc.el and tagged version 1.0.21
of the jsonrpc package.

I'd like to push some tests using the `jbug.py` test server
attached earlier.  Is here a good place to store such helper scripts
in our test subtree?

João

bug#67945: 30.0.50; Jsonrpc trouble dealing with nested synchronous requests

[Eli Zaretskii]

> From: João Távora <joaotavora@gmail.com>
> Date: Thu, 21 Dec 2023 01:01:44 +0000
> 
> I'd like to push some tests using the `jbug.py` test server
> attached earlier.  Is here a good place to store such helper scripts
> in our test subtree?

In the FOO-resources subdirectory (where FOO is the name of the test)?

bug#67945: 30.0.50; Jsonrpc trouble dealing with nested synchronous requests

[João Távora]

On Thu, Dec 21, 2023 at 7:51 AM Eli Zaretskii <eliz@gnu.org> wrote:
>
> > From: João Távora <joaotavora@gmail.com>
> > Date: Thu, 21 Dec 2023 01:01:44 +0000
> >
> > I'd like to push some tests using the `jbug.py` test server
> > attached earlier.  Is here a good place to store such helper scripts
> > in our test subtree?
>
> In the FOO-resources subdirectory (where FOO is the name of the test)?

Yes, that was my idea too.  Thanks for confirming.

bug#67945: 30.0.50; Jsonrpc trouble dealing with nested synchronous requests

[Stefan Kangas]

João Távora <joaotavora@gmail.com> writes:

> On Wed, Dec 20, 2023 at 11:31 PM João Távora <joaotavora@gmail.com> wrote:
>>
>> Hi,
>>
>> I've come across a rather complicated bug in jsonrpc.el that affects a
>> certain class of JSON-RPC applications.  Eglot, on of the more important
>> `jsonrpc.el` clients (perhaps the most) is not affected, as far as I
>> can tell.
>>
>> I already have a fix for this bug, but I am filing this report as a
>> reference for the commit message and to collect comments.
>
> I've now pushed the fix to jsonrpc.el and tagged version 1.0.21
> of the jsonrpc package.
>
> I'd like to push some tests using the `jbug.py` test server
> attached earlier.  Is here a good place to store such helper scripts
> in our test subtree?
>
> João

Thanks, should this bug be closed or is there more to do here?

bug#67945: 30.0.50; Jsonrpc trouble dealing with nested synchronous requests

[João Távora]

On Fri, Feb 2, 2024 at 7:41 AM Stefan Kangas <stefankangas@gmail.com> wrote:
>
> João Távora <joaotavora@gmail.com> writes:
>
> > On Wed, Dec 20, 2023 at 11:31 PM João Távora <joaotavora@gmail.com> wrote:
> >>
> >> Hi,
> >>
> >> I've come across a rather complicated bug in jsonrpc.el that affects a
> >> certain class of JSON-RPC applications.  Eglot, on of the more important
> >> `jsonrpc.el` clients (perhaps the most) is not affected, as far as I
> >> can tell.
> >>
> >> I already have a fix for this bug, but I am filing this report as a
> >> reference for the commit message and to collect comments.
> >
> > I've now pushed the fix to jsonrpc.el and tagged version 1.0.21
> > of the jsonrpc package.
> >
> > I'd like to push some tests using the `jbug.py` test server
> > attached earlier.  Is here a good place to store such helper scripts
> > in our test subtree?
> >
> > João
>
> Thanks, should this bug be closed or is there more to do here?

This is fixed for the somewhat limited manual testing I did.

But!

* the automated tests are not in place.  They shouldn't be hard to
  add though, and Eli's suggestion to put jbug.py somewhere in a
  "resources" directory is perfectly acceptable.

* Daniel Pettersson, who is now using jsonrpc.el in his DAP extension,
  tried to do more even more advanced stuff with this jsonrpc.el
  version and hit an internal sanity assertion, i.e. most assuredly
  a bug.  I haven't yet reproduced it.

* I think Daniel Pettersson would make a fine jsonrpc.el maintainer :-)
  <triple wink>

João

bug#67945: 30.0.50; Jsonrpc trouble dealing with nested synchronous requests

[Daniel Pettersson]

> * I think Daniel Pettersson would make a fine jsonrpc.el maintainer :-)
>  <triple wink>

I might be able to take it on, I am not familiar with the mechanics of
maintaining an core package but I might be up for it.

Daniel