Add support for hooks

[mikkoi]

REASON:
I create logs in JSON. I want to log things like timestamp, file name and line number in every message. These change on every row. Context is very useful but to make it truly useful, there should be a way to generate it automatically. Using filter does not fill this need because filter() is not applied with structured logging. Structured logging is what I need to use when writing logs with JSON.

Hooks could fill this need. Besides, if we later decide to add more hooks, we can do it easily and in a compatible way.

EXPLANATION:
User can define a function to be called at a specific time. At the moment, there is only one hook: build_context. It is called right before passing the message and structured data to the Adapter.

The hook makes using the context easier.
Instead of defining the context every time when you call a logging function, e.g. $log->debugf(),
you can use the hook to define repeating information, like file name and line or timestamp.
Because the hooks support several hooked sub routines, you can add more context temporarily when you need it.

User can define the hooks either when useing Log::Any or at any point afterwards.
There can be several subroutines for each hook.
They are executed in the order the hooks are added.

Examples:

use Log::Any q($log), hooks => { build_context => [ \&build_context, ] };
#
push @{ $log->hooks->{'build_context'} }, \&build_more_context;

[preaction]

Thanks! This looks like a good thing to add! I definitely want the structured logging to have some better filtering/modifying options, and this also looks like it would reduce the need to create custom Proxy classes. Though, we have to be wary of performance hits in the proxy (#69).

I've just got some small suggestions/changes before we can merge this.

Additionally, things like timestamp and caller location could be provided by adapters. A custom adapter might be better for your specific situation: Your custom adapter would also be able to add the timestamp/caller info to Log::Any when it's being used by other CPAN modules. As it is, adding a hook to a proxy would only add the information to that specific proxy, not when another module gets its own proxy.

[preaction]

Do we need to require a hooks param, or can we keep the current behavior of having no hooks?

[mikkoi]

I followed the style of the other parameters adapter, category and context.
Besides that, this eliminates the need to check if the parameter exists every time.
Alternatively, of course, we could create $self->{hooks} in init().
But if hooks is a feature of Log::Any, then it would be supported in every Proxy, right?

[preaction]

I would move this into the hook callback itself and remove the $callback argument to the hook to minimize the amount of work Log::Any has to do if folks don't want to pull out the file/line values.

[mikkoi]

I agree, it creates overhead --- which is always bad. Please see below in my comment for more pondering about this.

[preaction]

To make this a bit faster and give the end-user some more options, could we pass in the current context instead of an empty hashref of items? Then the hook could modify the context (to, for example, scrub sensitive values). Something like:

# No copying needed, yet
my $context = $self->{context};
if ( my $hooks = $self->{hooks}{build_context} ) {
    # We have a build_context hook, so we need to copy context so it can be modified
    $context = { %{$context} };
    for my $hook ( @$hooks ) {
        $hook->( $realname, $self->{category}, $context );
    }
}

[mikkoi]

I thought about that. In fact, my first implementation did that: it allowed the hook to modify $self->{context} straight.
My thinking in doing it this way, is that now any additions that the hook makes in context:

1. overshadow the existing context in this logging statement, later when $data_from_parts, $data_from_context and $data_from_hooks are merged and mapped into $data.
2. are not permanent, i.e. the context remains the same between calls to trace() (or equivalent logging statement).
3. because %i is merged into %items, a later hook can build over the values that the earlier hook created.

Then the hook could modify the context (to, for example, scrub sensitive values).

That is a good point. Right now it is not possible. But wouldn't sensitive info rather be in the logging message?
Comes to mind, wouldn't it be Adapter's job to scrub them?

[mikkoi]

Your custom adapter would also be able to add the timestamp/caller info to Log::Any when it's being used by other CPAN modules. As it is, adding a hook to a proxy would only add the information to that specific proxy, not when another module gets its own proxy.

Yes, you are right. I see that now. The context is not (might not be) the right place for technical information. Adapter is. For example, I have been thinking about using epoch (gmtime) in logs to reduce the overhead, and then make the logviewer translate those values into (local) timestamps so the viewer can enjoy localised time and date, instead of being forced to convert the timestamps in his mind when reading.

Having the timestamps added in the Adapter, the user, not the designer, can decide when to use them.

But the caller() info is another matter, I think. The Adapter would need to know how many layers of stack to go back to. We already have the problem that using tracef() (or equivalent) adds another layer compared with trace(). That's why the code is accommodating to that:

    my $caller = (caller 0)[0] ne 'Log::Any::Proxy'
                && (caller 0)[3] eq 'Log::Any::Proxy::__ANON__'
            ? [ caller 0 ] : [ caller 1 ];

Running the caller in Adapter would mean that we can't change the internals of Log::Any any more.

Unless, we provide the stack level number to the hook instead of the whole caller info... [?]

[mikkoi]

I moved the caller() stuff to Log::Any::Adapter::Util.
Maybe it works better there...

[mikkoi]

Rebased to master, applied version 1.715.