Handling connection timeout cleanly when using Mojo::UserAgent to perform an HTTP request

[Jeremy Begg]

Hi,

We have a Mojolicious web application which in general works quite nicely.
Recently we had a need to add the capability to get some of the application data from a remote device.
The remote device might be offline or slow so I wrote a Controller action to use Mojo::UA in non-blocking mode.
It seems to work fine when the remote device is active, but it generates spurious error output when the remote device is offline.
For example,

[Wed Jan 10 18:36:31 2018] [debug] GET "/dashboard/hfdata/179"
[Wed Jan 10 18:36:31 2018] [debug] Routing to controller "Frontend::Controller::Dashboard" and action "hf_proxy"
[Wed Jan 10 18:36:31 2018] [debug] Initiating request for live data from http://(removed)
[Wed Jan 10 18:36:31 2018] [debug] Request for live data failed; url=http://(removed) code=500 msg=Connect timeout
Mojo::Reactor::Poll: Timer failed: Connection already closed at /usr/local/share/perl/5.22.1/Mojo/UserAgent.pm line 251.

All but the last line are output by my Controller action.
The last line is output by Mojolicious from its internals, writing directly to STDOUT (or STDERR, I suppose).

Here is my Controller action (invoked via a Mojolicious route), is it doing something wrong?
(I have obfuscated the remote device's URL in the example above and in the code below.)

package Frontend::Controller::Dashboard;

use Mojo::Base 'Mojolicious::Controller';

sub hf_proxy {

    my $self = shift;
    my $user = $self->stash->{user};
    my $did  = $self->param('did');

    my $device = $user->device_by_id($did);
    $self->stash(device => $device);

    if (!$device) {
        # Non-existent device ID, or not owned by this user
        $self->app->log->error("No device $did for $user");
        return $self->render(status => 404, json => { message => 'Invalid device ID for this user' } );
    }

    # Use the Mojolicious UA to query the myWatt board.  See the article
    # "Blocking vs non-blocking 101" on the Mojolicious WiKi for explanation.
    my $ip = $device->ip;
    my $dhash = $device->device_id_hash;
    my $url = "http://(removed)";
    $self->app->log->debug("Initiating request for live data from $url");
    $self->render_later;
    $self->ua->get($url => sub {
        my ($ua, $tx) = (@_);
        if (my $res = $tx->success) {
            $self->app->log->debug("Got live data: ".$res->body);
            $self->render(data => $res->body, format => 'json');
        }
        else {
            my $error = $tx->error;
            my $code = $error->{code} || 500;
            my $msg  = $error->{message} || 'Connection failed';
            $self->app->log->debug("Request for live data failed; url=$url code=$code msg=$msg");
            $self->render(status => $code, json => { message => $msg });
        }
    });

}

FYI, we are running on Ubuntu 16.4 LTS:

jeremy@devtest:~$ mojo version
CORE
  Perl        (v5.22.1, linux)
  Mojolicious (7.44, Doughnut)

OPTIONAL
  EV 4.0+                 (n/a)
  IO::Socket::Socks 0.64+ (n/a)
  IO::Socket::SSL 1.94+   (2.024)
  Net::DNS::Native 0.15+  (n/a)
  Role::Tiny 2.000001+    (2.000001)

Thanks,

Jeremy Begg

[Scott Wiersdorf]

Hi Jeremy,

It looks like the event loop timeout (MOJO_INACTIVITY_TIMEOUT) is triggering before your connection timeout. Try setting that environment value longer than the user agent timeouts (or set your user agent connect and request timeouts shorter) and see if the error in the logs goes away. Your "else" block should trigger with the timeout error in there.

I had a similar experience recently:

https://groups.google.com/forum/#!topic/mojolicious/y43kqu06sgg

Scott

[Jeremy Begg]

Hi Scott,

Thanks for the suggestion.

After playing with various timers and not making much progress I took another look at the request logic from the browser, through Mojo to the remote device, and found the problem.
It turns out that the request from the web browser which triggers my {{hf_proxy}} action has a timeout of 1s.
So by the time Mojo::UserAgent has done its thing the web client has closed the connection and the action's final {{$self->render(...)}} has nothing to send the response to.

Jeremy