possible to log a unique id per request/response?

[Scott Wiersdorf]

[Mojo 3.97--I can't upgrade past this atm]

Hello, does anyone know of a trivial way to log a unique or semi-unique such as scalar($self-req) identifier for a request? The problem I'm trying to solve is: how do I track individual complete requests (from when the request comes in until the response is generated) in the log with multiple requests coming in? I want to be able to identify a single request and follow it through the logs to completion, hence I want to tack on a unique id somewhere in the log entry itself.

My questions:

a) is this a sensible approach to add a unique id to the log?

b) if not, what would be a better way?

If yes to a), then what I want to see in my log is something like [rid: xxxxxxx]:

    [2013-06-14 15:12:04] [rid: 7fae9be89010] [debug] GET /bar (Mojolicious (Perl)).

    [2013-06-14 15:12:04] [rid: 7fae9be89010] [debug] Routing to controller "foo" and action "bar".

    [2013-06-14 15:12:04] [rid: 7fae9be89010] [debug] 200 OK (0.000960s, 1041.667/s).

I don't care if the ID is an integer, uuid, etc.

Here's what I've tried:

I add a helper to make the id and store it in the session/stash:

    $self->helper(

        request_id => sub { my $app = shift;

                            if( ! $app->session('rid') ) {

                                my ($rid) = scalar($app->req) =~ /0x([a-f0-9]+)/;

                                $app->session( rid => $rid,

                                               expires => time + 300 );

                            }

                            $app->session('rid'); });

(Note: I've tried this multiple ways, including manipulating the stash directly, etc.)

and in another plugin I have a monkey patch for the log to use the request id:

sub register {

    my ($c, $app, $config) = @_;

    monkey_patch "Mojo::Log",

      format => sub {

          my ($self, $level, @lines) = @_;

          my $request_id = $app->request_id;

          return '[' . strftime("%F %T", localtime($time)) . "] [rid: $request_id] [$level] " . join("\n", @lines) . "\n";

      };

}

but each time something is logged, I get different ids. Anyone know of a way to make the request id persist until the response is sent?

Thanks,

Scott

[Cornelius Bartke]

Hi Scott.

Here is one way to do it: Use the 'after_build_tx'-hook to register a
'progress' callback, which is about the earliest point in the
request's lifecycle to tap in. The callback will trigger "whenever
there is progress parsing the request" and receive the trnsaction's
request object as first argument. Just return from the callback until
parsing the request headers is finished. Then add your own request
header with a generated request ID and unsubscribe from the 'progress'
event to avoid triggering the callback for every body chunk for
performance reasons:

$app->hook(
after_build_tx => sub {
my $tx = shift;
$tx->req->on(progress => sub {
$_[0]->headers->is_finished or return;
$_[0]->headers->header('X-RID' => gen_req_id());
$_[0]->unsubscribe('progress');
});
});
);

You could then write a helper that first look into the stash for the
request ID and, if it doesn't find it there, extracts it from your
custom header, stashes it and then returns it. Caching it on the stash
may be more efficient but I don't have benchmarks to back that up.

-Cornelius

> --
> You received this message because you are subscribed to the Google Groups
> "Mojolicious" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to mojolicious...@googlegroups.com.
> To post to this group, send email to mojol...@googlegroups.com.
> Visit this group at http://groups.google.com/group/mojolicious.
> For more options, visit https://groups.google.com/groups/opt_out.
>
>

[sri]

> Hello, does anyone know of a trivial way to log a unique or semi-unique
> such as scalar($self-req) identifier for a request? The problem I'm trying
> to solve is: how do I track individual complete requests (from when the
> request comes in until the response is generated) in the log with multiple
> requests coming in?

Simple answer:
You can't, Mojolicious is async by design and there may be thousands
of concurrent requests active at any given time.

Complex answer:
If you limit your application (through the server) to handling only
one request at a time and don't use any real-time web features (not
that it would make much sense if you can't handle concurrent
requests), you could subclass Mojo::Log to customize the message
format and store a global unique id for every new request.

--
sebastian

[sri]

> ... and store a global unique id for every new request.

I've actually done something like that once for a hack that adds
action level keywords to Mojolicious::Lite, it just stores the current
controller instead of a unique id.

https://gist.github.com/kraih/4351674

Don't get me wrong, i do not recommend this, just pointing out that
it's possible.

--
sebastian

[Cornelius Bartke]

On Sat, Jun 15, 2013 at 1:55 AM, sri <kra...@googlemail.com> wrote:
>> Hello, does anyone know of a trivial way to log a unique or semi-unique
>> such as scalar($self-req) identifier for a request?
>

> Simple answer: You can't, Mojolicious is async by design [...]

Huh, did I miss something?

Assuming that (1) the unique request ID generator can keep up with the
rate of incoming requests and (2) still maintain uniqueness and that
(3) each incoming request can be tagged with a header as I suggested
earlier, why shouldn't that work? Granted, I was talking just about
http and not websocket messages (haven't used that part, yet), but how
is async processing preventing a per-request id?

-Cornelius

[Sebastian Riedel]

> Huh, did I miss something?

The logger is a property of the application and not associated with any one request, so your solution depends on all log messages going through a custom helper (where they get tagged with the id) and a request actually being active. It's another complex answer, sure you can do it, but there are serious tradeoffs.

--
Sebastian Riedel
http://twitter.com/kraih
http://mojolicio.us