A note about String::Flogger and logging in dzil

Dist::Zilla uses Log::Dispatchouli for logging, which in turn uses String::Flogger to format arguments into the final string that gets logged.

String::Flogger is a convenient formatter. Depending on what arguments it gets, it does different things. First, if passed a simple string then it is returned as-is, so you can just do this:

$self->log("A simple message");

If you pass several strings (arguments), each string (argument) will be flogged individually and joined with space, e.g.:

$self->log("A message", "another message"); # final string is: "A message another message"

Second, if you pass an array reference, it will be formatted using (currently) sprintf(), e.g.:

$self->log(["A %s message", "sprintf-formatted"]); # "A sprintf-formatted message"

Note that in some other logging frameworks, like Log::Any, there is a separate set of methods to explicitly request sprintf-style formatting, so no extra pair of brackets is needed, e.g.:

$log->debugf("A %s message", "sprintf-formatted");

Third, if passed a coderef, String::Flogger calls the code. This can be useful if you want to do more complex formatting and/or defer relatively expensive calculation, e.g.:

$self->log(sub { "Current system load: ".sysload() });

So far so good.

But wait, there’s an extra level of convenience and design choice. In the array reference (sprintf-style) variant, if the sprintf arguments are references, they will be formatted using some rules:

1) scalar references or reference references will be formatted using “ref(VALUE)”, so \1 will become:

ref(1)

2) the rest will be passed to JSON encoder (currently JSON::MaybeXS) and then enclosed using “{{” and “}}”, e.g.:

$self->log(["Let there be some data: %s", [undef, "a"]]); # 'Let there be some data: {{[null,"a"]}}'

The choice of JSON indicates (also confirmed here) that RJBS envisions the log to also be processed with external tools outside the Perl ecosystem. A valid use case, but with some drawbacks that some Perl data structures cannot be viewed more accurately, which you also sometimes want when you are debugging some complex Perl data in your application.

Objects (blessed references) will be dumped as just “obj(ADDRESS)”.

Also, the extra convenience is that in the arrayref/sprintf-style variant, if the arguments are coderefs, they will also be called, e.g.:

$self->log(["Current system load: %s", sub { sysload() }];

This is a potential gotcha if you, like me, are used to the other logging frameworks. If you want a behaviour more like Log::Any:

$log->debugf("Data that might be anything including coderef: %s", $data);

In Log::Dispatchouli you should dump the data first using something else, e.g.:

$self->log(["Data that might be anything including coderef: %s", Data::Dmp::dmp($data)]);

or perhaps:

$self->log(["Data that might be anything including coderef: %s", sub { require Data::Dmp; Data::Dmp::dmp($data) }]);
Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s