Logging guidelines

Koha has it's own logging facility Koha::Logger, which is powered by log4perl.

These are the best practices for implementing logging on new and existing subroutines and scripts in Koha:

Use structured logging

Human readable logs are helpful, but structured logs add value, especially as an application’s logs become more complex or as request throughput increases. Structured logging provides a well-defined format for your log entries so you can more easily parse, query, and process them for analytics.

JSON is the de facto standard for structured logging, and as such we should encode data in json when possible where each line consists of a single level of densely packed key/value pairs. This format is human readable and fairly easy to parse, if needed.

Consider these unstructured log entries:

2019-06-20T17:21:00.002899+00:00 app[email-wrkr.1]: DEBUG: Fetching mailing list 14777
2019-06-20T17:22:00.000098+00:00 app[email-wrkr.1]: DEBUG: User 3654 opted out

Changing these entries to use structured JSON results in:

2019-06-20T17:21:00.002899+00:00 app[email-wrkr.1]: DEBUG: Fetching mailing list: {"listid":14777}
2019-06-20T17:22:00.000098+00:00 app[email-wrkr.1]: DEBUG: User opted out: {"userid":3654}

The consistent format of these log messages makes it straightforward for your chosen log drain to parse them, extract the JSON metadata, and make it available for searching and filtering.

Log Levels

Log levels available:

FATAL – Identifies extremely serious error events that are likely to cause the application to abort. Typically, this leads to catastrophic failures.
ERROR – Identifies error events that may still let the software run, but with restricted capabilities in the impacted routes.
WARN – Describes events that are less destructive than errors. They usually do not result in any reduction of the application's functionality or its full failure. They are, however, red signs that must be investigated.
INFO – In the application behavior, it denotes the major event banners and informational messages.
DEBUG – Denotes particular and detailed data, which is mostly used for debugging. These logs assist us in debugging the code.
TRACE – To provide the greatest information on a specific event/context, it denotes the most low-level information, such as stack traces of code. These logs allow us to examine variable values as well as complete error stacks.

Best Practices

• use is_LEVEL if the logged output will be more complex then interpolated strings ( for example, converting data to JSON ).

 * EXAMPLE: $log->debug(to_json($data)) if $log->is_debug;

Logging stack traces

• All subroutines should log a stack trace at level TRACE using logcluck

Example

sub MySubroutine {
    my ( $patron, $item ) = @_;
    my $log = Koha::Logger->get;
    $log->logcluck("Called C4::Circulation::MySubroutine") if $log->is_trace; #logcluck is warn level so trace will catch it, maybe we should make our own helper method to set the level to trace
}

Logging subroutine inputs and outputs

• All input to a subroutine should be logged at level DEBUG
• All return values should be logged at level DEBUG

Example

sub MySubroutine {
    my ( $patron, $item ) = @_;
    my $log = Koha::Logger->get;
    $log->logcluck("Called C4::Circulation::MySubroutine") if $log->is_trace;
    $log->debug("C4::Circulation::MySubroutine paramters: " . JSON->new->space_before(0)->indent(0)->pretty(0)->encode({ patron => $patron->unblessed, $item->unblessed }) if $log->is_debug;
    ## We should make a helper method for the "start" and "end" of subs to simplify this code
    ...
    $log->debug("C4::Circulation::MySubroutine return: " . JSON->new->space_before(0)->indent(0)->pretty(0)->encode({ data1 => $data1, data2 => data2  }) if $log->is_debug;     
    return ( $data1, $data2 );
}

If the subroutine returns a single value ( such as a hash or list ) that value can be the sole parameter to encode:

    $log->debug("C4::Circulation::MySubroutine return: " . JSON->new->space_before(0)->indent(0)->pretty(0)->encode($data) if $log->is_debug;     
    return $data;

Logging important events

Important data/events inside a subroutine should be logged at level INFO

Example

   my $maxissueqty_rule = Koha::CirculationRules->get_effective_rule(
       {
           categorycode => $cat_borrower,
           itemtype     => $type,
           branchcode   => $branch,
           rule_name    => 'maxissueqty',
       }
   );
   $log->info("Using maxissueqty rule: . JSON->new->space_before(0)->indent(0)->pretty(0)->encode($maxissueqty_rule);

Logging Errors

Errors should be considered any failure that is not fatal. A good rule of thumb is, if we return from a routine prematurely, that is probably a good place to log an error.

Example

sub MarkIssueReturned {
   my ( $borrowernumber, $itemnumber, $returndate, $privacy, $params ) = @_;

   # Retrieve the issue
   my $issue = Koha::Checkouts->find( { itemnumber => $itemnumber } ) or return;

   return unless $issue->borrowernumber == $borrowernumber; # If the item is checked out to another patron we do not return it

could be transformed to

sub MarkIssueReturned {
   my ( $borrowernumber, $itemnumber, $returndate, $privacy, $params ) = @_;

   # Retrieve the issue
   my $issue = Koha::Checkouts->find( { itemnumber => $itemnumber } )
     or $log->error("Checkout for item not found: {itemnumber: $itemnumber}" and return;

   unless ( $issue->borrowernumber == $borrowernumber ) { # If the item is checked out to another patron we do not return it
       $log->error( "Checkout patron does not match incoming patron: { issue_borrowernumber: ${\($issue->borrowernumber)}, parameter_borrowernumber: $borrowernumber }");
       return;
   }

Logging Fatal Events

If an event would trigger the script to exit prematurely, log a fatal even.

Example

$patron = $issue->patron
 or die "Data inconsistency: barcode $barcode (itemnumber:$itemnumber) claims to be issued to non-existent borrowernumber '" . $issue->borrowernumber . "'\n"
 . Dumper($issue->unblessed) . "\n";

could be transformed to

$patron = $issue->patron or $logger->logdie("Data inconsistency, barcode claims to be issued to non-existent borrowernumber: " .
  JSON->new->space_before(0)->indent(0)->pretty(0)->encode($issue);

TODO Helper Methods

It seems clear from the examples above that we could use some helper methods:

• A helper method for use at the beginning of each subroutine to output the stack trace and/or the parameters if debug
• A wrapper for JSON->new->space_before(0)->indent(0)->pretty(0)->encode
• Perhaps even give each sub two parameters: message and data. Data would automatically be encoded using the above

References and sources

https://devcenter.heroku.com/articles/writing-best-practices-for-application-logs https://www.atatus.com/blog/9-best-practice-for-application-logging-that-you-must-know/ https://reflectoring.io/logging-levels/ https://www.section.io/engineering-education/how-to-choose-levels-of-logging/