Bug#949974: Finish hangs after flush

classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

Bug#949974: Finish hangs after flush

Enrico Zini via nm
Package: python3-tornado
Version: 5.1.1-4
Severity: normal

Hello,

thank you for maintaining tornado in Debian.

Here's a simple variation of Tornado's hello example, supposing one
wants to take timing or log things after a flush:

- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
import tornado.ioloop
import tornado.web


class MainHandler(tornado.web.RequestHandler):
    async def get(self):
        print("START")
        self.write("Hello, world")
        await self.flush()
        print("DATA WRITTEN")
        await self.finish()
        print("REQUEST DONE")


def make_app():
    return tornado.web.Application([
        (r"/", MainHandler),
    ])


if __name__ == "__main__":
    app = make_app()
    app.listen(8888)
    tornado.ioloop.IOLoop.current().start()
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -

Running this code, curl localhost:8888, and the output on tornado is:

  START
  DATA WRITTEN

That is, finish() seems to hang forever if it has no more data to write.


Enrico


-- System Information:
Debian Release: 10.2
  APT prefers stable
  APT policy: (500, 'stable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 5.4.0-0.bpo.2-amd64 (SMP w/4 CPU cores)
Kernel taint flags: TAINT_WARN
Locale: LANG=en_IE.UTF-8, LC_CTYPE=en_IE.UTF-8 (charmap=UTF-8), LANGUAGE=en_IE:en (charmap=UTF-8)
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages python3-tornado depends on:
ii  ca-certificates  20190110
ii  libc6            2.28-10
ii  python3          3.7.3-1

python3-tornado recommends no packages.

Versions of packages python3-tornado suggests:
ii  python-tornado-doc  5.1.1-4
ii  python3-pycurl      7.43.0.2-0.1
ii  python3-twisted     18.9.0-3

-- no debconf information

Reply | Threaded
Open this post in threaded view
|

Bug#949974: More details

Enrico Zini
Hello,

I tracked the issue: in http1connection.py, the write method does:

    self._pending_write = self.stream.write(fchunk)
    self._pending_write.add_done_callback(self._on_write_complete)  

The Future[1] documentation says:

    Callbacks registered with add_done_callback() are always called via
    the event loop’s call_soon_threadsafe().

So although self._pending_write in that case is already in a 'done'
state, self._on_write_complete is only called the next time we'll
reenter the event loop.

Meanwhile, before returning to the event loop, the flow of the code
continues and RequestHandler.finish calls:

    self.request.connection.finish()

It detects correctly that there is still a pending write, and calls:

    future_add_done_callback(self._pending_write, self._finish_request)

However, future_add_done_callback does not schedule self._finish_request
for the next ioloop iteration like Future.add_done_callback does:

    # concurrent.py:
    def future_add_done_callback(future, callback):
        # …
        if future.done():
            callback(future)
        else:
            future.add_done_callback(callback)

Compare with:

    # In concurrent.py, class Future:
    def add_done_callback(self, fn):
        # …
        if self._done:
            from tornado.ioloop import IOLoop
            IOLoop.current().add_callback(fn, self)
        else:
            self._callbacks.append(fn)

So self._finish_request is called before self._on_write_complete,
_clear_callbacks() is called, which resets self._write_callbacks.

When control returns to the event loop, _on_write_complete is finally,
called, which finds self._write_future set to None, and won't trigger
the future that will permit RequestHandler.flush() to continue.

If there is still data to write, self._pending_write is not done when
future_add_done_callback is called, and RequestHandler.flush() won't get
stuck.


Enrico


[1] https://www.tornadoweb.org/en/stable/concurrent.html#tornado.concurrent.Future.add_done_callback

--
GPG key: 4096R/634F4BD1E7AD5568 2009-05-08 Enrico Zini <[hidden email]>

signature.asc (849 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Bug#949974: Upstream?

Julien PUYDT-2
In reply to this post by Enrico Zini via nm
Hi,

isn't it an upstream issue?

Cheers,

JP

Reply | Threaded
Open this post in threaded view
|

Bug#949974: More details

Enrico Zini
In reply to this post by Enrico Zini
On Mon, Jan 27, 2020 at 09:46:35PM +0100, Enrico Zini wrote:

> If there is still data to write, self._pending_write is not done when
> future_add_done_callback is called, and RequestHandler.flush() won't get
> stuck.

Keeping the write buffer nonempty is not sufficient: if it remains with
a few data, the problem is triggered anyway, as it will managed to get
written right away and set the _pending_write future to done() before
reaching the event loop, triggering the hang again.

Since this depends on whether there is enough pending data to write to
cause the buffer to block, it's hard to predict what is a reasonable
amount of data to leave in the pipeline as a workaround.

Meaning, I currently cannot find a way to await finish() in tornado 5.

It would be important for me to do so, as it's the only way I have to be
able to log an outcome of a request, figuring out for example if the
remote has closed the connection early.

 - - -

To answer Julien Puydt, this is fixed upstream in Tornado 6, which is
not in Debian yet.

I would call this by now a debian-specific bug, and I think it's useful
to document it here, rather than waste upstream's time with an issue
they have fixed in a version releases a year ago.


Enrico

--
GPG key: 4096R/634F4BD1E7AD5568 2009-05-08 Enrico Zini <[hidden email]>

signature.asc (849 bytes) Download Attachment