Question about MOJO_INACTIVITY_TIMEOUT effects and Mojo::IOLoop::Stream

[Scott Wiersdorf]

I have a slow HTTP service I'm writing a proxy for. If I hit the service directly using curl, it looks like this:

$ time curl http://localhost:3333/?timer=10

{"message":"waited 10 seconds"}

real 0m10.018s

user 0m0.005s

sys 0m0.005s

I can hit it at 14s:

$ time curl http://localhost:3333/?timer=14

{"message":"waited 14 seconds"}

real 0m14.019s

user 0m0.005s

sys 0m0.005s

And at 16s:

$ time curl http://localhost:3333/?timer=16

{"message":"waited 16 seconds"}

real 0m16.018s

user 0m0.005s

sys 0m0.005s

I wrote a Mojolicious proxy for the slow service:

use Mojolicious::Lite;

get '/slow' => sub {

    my $c = shift;

    my $timer = $c->param('timer') // 10;

    $c->render_later;

    my $url = Mojo::URL->new('http://localhost:3333');

    $url->query(timer => $timer);

    app->log->debug("Invoking " . $url->to_string);

    $c->ua->inactivity_timeout(60)->connect_timeout(60)->request_timeout(60)->get($url, sub {

        my $tx = pop;

        $c->render(json => $tx->res->json);

    });

};

app->start;

You can see my various *_timeout() invocations on the user agent. If I hit the proxy, I get what I expect at 14s:

$ curl --include http://localhost:3000/slow?timer=14

HTTP/1.1 200 OK

Content-Length: 31

Server: Mojolicious (Perl)

Date: Tue, 05 Sep 2017 20:00:04 GMT

Content-Type: application/json;charset=UTF-8

{"message":"waited 14 seconds"}

But at 16s I get a timeout error:

$ curl --include http://localhost:3000/slow?timer=16

curl: (52) Empty reply from server

Indeed, the proxy's log shows the request and then a timeout 15s after the request:

[Tue Sep  5 14:00:45 2017] [debug] Invoking http://localhost:3333?timer=16

[Tue Sep  5 14:01:00 2017] [debug] Inactivity timeout

Mojo::Reactor::Poll: I/O watcher failed: Connection already closed at utils/slow-wrap line 15.

There's something magic about 15s.  I added the various timeouts on the user agent, so something else is timing out. I suspect it may be the default timeout in the Mojo::IOLoop::Stream constructor:

sub new { shift->SUPER::new(handle => shift, buffer => '', timeout => 15) }

If I start my proxy with MOJO_INACTIVITY_TIMOUT=60, then the proxy does not timeout:

$ curl --include http://localhost:3000/slow?timer=16

HTTP/1.1 200 OK

Content-Length: 31

Server: Mojolicious (Perl)

Content-Type: application/json;charset=UTF-8

Date: Tue, 05 Sep 2017 20:04:50 GMT

{"message":"waited 16 seconds"}

And the proxy logs are clean:

$ MOJO_INACTIVITY_TIMEOUT=60 ct utils/slow-wrap daemon

[Tue Sep  5 14:04:28 2017] [info] Listening at "http://*:3000"

Server available at http://127.0.0.1:3000

[Tue Sep  5 14:04:34 2017] [debug] GET "/slow"

[Tue Sep  5 14:04:34 2017] [debug] Routing to a callback

[Tue Sep  5 14:04:34 2017] [debug] Invoking http://localhost:3333?timer=16

[Tue Sep  5 14:04:50 2017] [debug] 200 OK (16.012817s, 0.062/s)

My question is: how can I determine what timeout is being triggered at 15s, and how can I change it on a per-request basis? I don't want to set that timeout for the entire proxy (I do want other slow calls to timeout)—just this particular controller. Is that possible? I've seen various email threads that recommend adding something like to the controller (before invoking the user-agent):

Mojo::IOLoop->stream($c->tx->connection)->timeout(60);

which seems to work in this situation, but I'm unsure this is the right approach. Is there a better mechanism for this? Will this hold up for many requests in the event loop at once?

Scott

[Scott Wiersdorf]

I should add that this is Mojolicious 7.43.

[Scott Wiersdorf]

And then I find the answer in the FAQ:

In Mojolicious applications you can also use the helper "inactivity_timeout" in Mojolicious::Plugin::DefaultHelpers to change it on demand for each connection individually. This timeout always applies, so you might have to tweak it for applications that take a long time to process a request.

Not sure how I missed that. As you were.

Scott

On Tuesday, September 5, 2017 at 2:21:31 PM UTC-6, Scott Wiersdorf wrote: