Understanding Mojo::IOLoop::Stream events

[Bernhard Graf]

Hi,

I have a user-agent script that subscribes to events of Mojo::IOLoop::Stream:

https://gist.github.com/augensalat/caad97c62fb375dd4f4c

The read- and write-event subscribers are counting the number of transmitted bytes.

My expectation was to see one or more write events, followed by one or more read events, then a close event, and finally the request callback that shows the amout of transmitted data.
But when I run this script, the (last) read event happens after the close event and after the request callback.

Am I doing it wrong?

How can this be fixed?

Bernhard

[Bernhard Graf]

Meanwhile I found the reason - but not a solution:

I ran the script with MOJO_EVENTEMITTER_DEBUG=1:

graf@augensalat:~> MOJO_EVENTEMITTER_DEBUG=1 perl streamres.pl
-- Emit start in Mojo::UserAgent (1)
-- Emit connect in Mojo::IOLoop::Client (1)
-- Emit connection in Mojo::Transaction::HTTP (1)
-- Emit progress in Mojo::Message::Request (0)
-- Emit progress in Mojo::Message::Request (0)
-- Emit progress in Mojo::Message::Request (0)
-- Emit finish in Mojo::Message::Request (0)
-- Emit write in Mojo::IOLoop::Stream (1)
++ Stream write event - 130 bytes written.
-- Emit drain in Mojo::IOLoop::Stream (0)
-- Emit read in Mojo::IOLoop::Stream (2)
-- Emit body in Mojo::Content::Single (0)
-- Emit read in Mojo::Content::Single (1)
-- Emit progress in Mojo::Message::Response (0)
-- Emit finish in Mojo::Message::Response (0)
-- Emit finish in Mojo::Transaction::HTTP (0)
-- Emit close in Mojo::IOLoop::Stream (3)
++ Stream close event
++ DONE: 0 bytes read, 130 bytes written.
         Response content size is 1610 bytes.
++ Stream read event - 1610 bytes read.

There are two subscribers to the "read" event of Mojo::IOLoop::Stream - mine is probably the last.
DEBUG shows that the "read" event of Mojo::IOLoop::Stream is fired at the correct position, but still my subscribed callback is called at the very end! This is suprising, because the code in Mojo::EventEmitter::emit() shows that the subscribed callbacks are executed immediately after the debug output.

I added more debug code to Mojo::EventEmitter::emit():
https://gist.github.com/augensalat/6a1fe8647c3d009a2385
and now things start to become clear:

graf@augensalat:~> MOJO_EVENTEMITTER_DEBUG=1 perl -Imojolicious/lib streamres.pl
-- Emit start in Mojo::UserAgent (1)
xx call cb #0 start in Mojo::UserAgent
-- Emit connect in Mojo::IOLoop::Client (1)
xx call cb #0 connect in Mojo::IOLoop::Client
-- Emit connection in Mojo::Transaction::HTTP (1)
xx call cb #0 connection in Mojo::Transaction::HTTP
-- Emit progress in Mojo::Message::Request (0)
-- Emit progress in Mojo::Message::Request (0)
-- Emit progress in Mojo::Message::Request (0)
-- Emit finish in Mojo::Message::Request (0)
-- Emit write in Mojo::IOLoop::Stream (1)
xx call cb #0 write in Mojo::IOLoop::Stream
++ Stream write event - 130 bytes written.
-- Emit drain in Mojo::IOLoop::Stream (0)
-- Emit read in Mojo::IOLoop::Stream (2)
xx call cb #0 read in Mojo::IOLoop::Stream
-- Emit body in Mojo::Content::Single (0)
-- Emit read in Mojo::Content::Single (1)
xx call cb #0 read in Mojo::Content::Single
-- Emit progress in Mojo::Message::Response (0)
-- Emit finish in Mojo::Message::Response (0)
-- Emit finish in Mojo::Transaction::HTTP (0)
-- Emit close in Mojo::IOLoop::Stream (3)
xx call cb #0 close in Mojo::IOLoop::Stream
xx call cb #1 close in Mojo::IOLoop::Stream
xx call cb #2 close in Mojo::IOLoop::Stream
++ Stream close event
++ DONE: 0 bytes read, 130 bytes written.
         Response content size is 1610 bytes.
xx call cb #1 read in Mojo::IOLoop::Stream
++ Stream read event - 1610 bytes read.

The "read" event of Mojo::IOLoop::Stream runs the first callback (which is Mojo::UserAgent::_read) and this obviously triggers all the next actions until the second subscribed callback is called.
Looks like "Welcome to callback hell".

My questions are now:
1. Is this a bug, or works as desinged, or can't be fixed?
2. What should a subscriber to the "read" event of Mojo::IOLoop::Stream do to avoid this situation? I don't see an official way to subscribe to the beginning of an event subscription list, which might fix the problem.

Bernhard