Feature Proposal: Modernize the Log API, and add LogDispatchContrib to core

Motivation

The logger currently combines together fields in order to add information without changing the layout of the logfile. File format ends up determined partly by the caller of the log() function, and fields are positional in the passed array.

Also, log records are a fixed layout. This feature would support a token based format for file based loggers, and permit database based loggers to map tokens to database columns.

There are some severe issues with the current default logger:

• PlainFile logger on busy systems is unable to rotate the logs, resulting in system crashes or corrupt logs.
• There is no file locking, so log records can be lost.
• There is no way to easily add information to the logs

Also the current logger supports only a single implementation. For ex, it would not be easy to log to Files for debug and error logs, but DBI for events. LogDispatchContrib allows pluggable, parallel logging, directing each class of log to one or more output destinations.

Description and Documentation

Change the Log API

Change the log() api to support hash based parameter passing, specifically for the "event" (level info). But maintain compatibility if called with an array.

ObjectMethod log( {
level => $level,
user => $user,
action => $action,
agent => $agent,
topic => $webtopic,
remoteaddr => $ip } )

If the logger is called with the level and an array of "arbitrary fields", operate in compatibility mode:

• $level - level of the event - one of debug, info, warning, error, critical, alert, emergency.
• @fields - an arbitrary list of fields to output to the log.

These fields are recoverable when the log is enumerated using the eachEventSince method.

Logging API structure.

Reviewing Foswiki core, there appears to be several approaches to logging:

• Foswiki.pm provides a logEvent() function that adds Agent, Remote Address, and user to the logged message. Used 29 places in the core.
• Foswiki::Func::writeEvent() provides a similar function which calls logEvent(). Used in only one place in core.
• Foswiki::Func::writeWarning() calls the logger->log() function directly. Does not appear to be used in core
• Foswiki::Func::writeDebug() also calls logger->log() directly. Also does not appear to be used in core.
• Most core uses call logger->log() directly for both debug and warning messages.

Reviewing Extension in svn,

• Foswiki::Func::write* calls are mostly used, though there are a small number of direct calls to logger->log()

New architecture

• Deprecate the positional parameter list style calls to Logger for the "event" (level info) events.
• Continue to support the positional parameter calls for debug and error logs
  • Add methods compatible with Log4J. Logger->warn(), for example.
• Move the automatic fill-in of Agent, Remote Address, User into the Logger, so that the fields can be used on any level of log message.
• Publish the Logger API as the standard API, so that it can be called directly.

Reviewing the Development/PluginsApiPolicies, the Logger API is not listed as being protected by our deprecation policy, and is subject to change without warning.

Deprecation Statement

The Logger API is not subject to our deprecation policy, however some backwards compatibility will be maintained. User written loggers would need to be updated to the new API.

• Deprecate calls to logger using positional parameters. The loggers will still function if called in that style.
• Deprecate Foswiki::writeEvent
• Core will be changed to call logger->log() for all logging using the hash style calls..
• Extensions should continue to use Foswiki::Func for all logging requests.

Add LogDispatchContrib to core

The LogDispatchContrib uses the CPAN Log::Dispatch module to support logging to a variety of outputs. The extension is in SVN, and still under development, but at this point it supports:

• Logging events to an arbitrary number of files
• "Filtering" messages, for ex. sending authentication messages to a separate auth log
• Logging to Files, Syslog, STDERR, and Rolling "Stamped Files"
• One of the File loggers is thread safe, supporting file locking
• Future support for Jabber, Email, DBI and Windows Event loggers
• LogDispatch would change the flat file format from a separate field-per-parameter, to a single concatenated message for the non-info events.

The logging "eachEventSince" is configurable as well. For example, processing a DBI logger for events, but the File logger for debug or error messages.

Examples

Impact

WhatDoesItAffect:

%WHATDOESITAFFECT%

edit

Implementation

-- Contributors: GeorgeClark - 26 Sep 2012

Discussion

For compatibility, I've added $logger->{acceptssHash}, so it's easy for core to decide how to build the log record. For example:

if ( $logger->{supportsHash} ) {
    $logger->log( level => $level, ...);
}
else {
    Build the compatibility array and use the old call....
}

However, I've also added code to Logger.pm., that will convert the new style call back to the old version, making this mostly unnecessary.

And in the logger->log() method: If passed the level and array, attempt to parse it apart into the hash, otherwise just use the passed hash, and fill in any missing pieces. (ie. all log records should include the remote IP address if available.)

Also, I plan to "push down" the field completion into the $logger->log() method, so any call to the logger gets a complete record, rather than just calls to logEvent. Core uses Foswiki::logEvent() only for logging to the events.log. Errors, Warnings, etc. are all done with direct calls to the $logger->log() method.

-- GeorgeClark - 26 Sep 2012

excellent. I'll wait for your impl before i push the listeners into this API too (though clearly I'll need to work out how to make that usage a nop when its not used.

-- SvenDowideit - 28 Sep 2012

Working on implementing it initially in LogDispatchContrib. Interface documentation:

Compatibility interface:

 $this->logger->log( 'info', $user, $action, $webTopic, $message, $remoteAddr );
 $this->logger->log( 'warning', $mess );
 $this->logger->log( 'debug', $mess );

Native interface:

 $this->logger->log( { level      => 'info',
                       user       => $user,
                       action     => $action,
                       webTopic   => $webTopic,
                       extra      => $message or \@arrayref,
                       agent      => $agent,
                       remoteAddr => $remoteAddr } );

 $this->logger->log( $level, fields, to, be, logged )

Fields recorded for info messages are generally fixed. Any levels other than info can be called with an array of additional fields to log. They are joined together and are substituted into the $fields token.

Arbitrary fields tokens can be passed in the hash, and added to the template.

Log4perl compatible calls

Carrying the suggestion below from DavidKramer forward, add the following methods for compatibility with Log4perl.

$logger->trace()
$logger->debug()
$logger->info()
$logger->warn()
$logger->error()
$logger->fatal()

Log record layout

This will eventually be configurable:

"info"level (events) log template

'| $timestamp $level | $user | $action | $webTopic | $message $agent | $remoteAddr |'

"debug and warning log template

'| $timestamp $level | $caller $fields';

LogDispatch makes a change here. The Compatibility and PlainFile loggers will write out each passed parameter as a separate field. For example: log->( 'error', 'message | text', 'and', 'more') would be written as separate vertical bar delimited fields, while protecting embedded vertical bars.

| 2012-10-02T07:30:28Z error | message &vbar; text | and | more |

LogDispatch would join the multiple fields into a single field in the log message.

| 2012-10-02T07:30:28Z error | message &vbar; text and more |

-- GeorgeClark - 29 Sep 2012

There is some conflicting or at least unclear information in our documentation.

• PluginsApiPolicies - Says that Foswiki::Meta, Foswiki::Func and EmptyPlugin are subject to deprecation considerations. We guaranty support for 2 releases after deprecation announced.
• PublishedAPI - lists a lot of additional APIs including Foswiki::Logger, but says nothing about deprecation.

My latest implementation ( see https://github.com/gac410/foswiki/commits/logger ) has the following API implications:

• Code that calls the logger API will be protected. The loggers will all understand both the old (list-based) and new (hash-based) calling conventions.
• Core will be changed to the new hash-based calling convention
• User written loggers must be changed to handle the new calling conventions.

-- GeorgeClark - 02 Oct 2012

OK, maybe this is a silly concept, but... One of the most popular, and imitated, loggers out there in open source is log4j. It's already been ported to Perl. http://search.cpan.org/~mschilli/Log-Log4perl-1.38/lib/Log/Log4perl.pm Why reinvent an existing excellent wheel with a proven design? You get cascading formatting, logging to multiple places (DB, email, file, syslog,...) with the same or different formats, for free, and even logging to multiple places at the same time. It's already debugged code.

Even if you don't use Log4perl, I think you could benefit from studying log4j's modular/layered approach, where the thing that decides whether the message should be logged is different from the thing that formats the log entry (and they can be cascaded), which is different from the thing that actually publishes the log message, however it's supposed to do that.

-- DavidKramer - 02 Oct 2012

We are actually doing that.

Previous to this effort, Sven reviewed loggers and settled on using CPAN:Log::Dispatch which has a similar modular approach to Log4perl, and for some of it's output classes (think appenders), uses Log4J conventions. (Actually reviewing the documentation, they seem to treat the appenders somewhat interchangeably, each recommending the other's.) So Log::Dispatch is debugged code, supports many of your described features, and is being used. Part of this proposal is to make Log::Dispatch a core logger in 1.2.

I'm not sure we had strong preference to Log::Log4Perl vs. Log::Dispatch, however when LogDispatchContrib was started, it was decided we needed it to work on Foswiki 1.1.x systems. Log4perl seemed to require more drastic changes, where as Log::Dispatch looked like it would plug into the existing logger API a bit easier. So LogDispatchContrib supports existing Foswiki systems, and will pass all the current unit tests. See Extensions/Testing.LogDispatchContrib

One note on Log::Log4Perl is that it is not yet thread safe, where as Log::Dispatch provides thread-safe and fork-safe loggers. That's definitely one of the things we need to address in the current Foswiki logger. Log4Perl also seems to need a separate config file, where as we need the configuration to be part of the current Foswiki configuration system.

But you make a good point, why not use the Log4Perl logger calling convention. Probably the one major different I can find is that Log4Perl (and Log::Dispatch as well) are natively a "message" logger. Multiple fields are simply concatenated into a message. Foswiki's logger is an "Event Logger", which will write out events for later replay, and provides an eachEventSince API. The simplest example is the MailerContrib email notifications. Events require multiple discrete fields. such as the Web.Topic being updated, Whether the change was minor, etc. We want to expand on that concept to allow event "Listeners" which can react to "store" events, for example, to mirror store actions into an external cloud storage, or database search accelerator, and also allow additional discrete fields to be added to logged events.

Foswiki trunk started down a parallel path of adding a new store event listener concept, but that's been deprecated before reaching release, as it was decided that the current event logger could perform a similar function without the duplication.

I think you influence some really important conclusions though: Other than the event logging which has specific Foswiki requirements

• Error, warning, debug, etc. should continue to be a simple concatenation of fields, keeping the API as close as possible to the Log4J API.
• We could add shims to Foswiki::Logger, so that calls like Logger->error() and Logger->warning() could be made using the Log4J calling convention
• We could probably even shim the Logger->info() call, by ensuring that the Logger class adds the required fixed fields: User, Agent, webTopic, action ...

-- GeorgeClark - 02 Oct 2012

yes, I did review the 4 main CPAN logger options, and only Log::Dispatch is flexible enough for the non-string logging needs we have for the eventing system. As George points out, Log4Perl is less capable - its a string logger, where Foswiki's Data-Wiki orientation calls for enabling structured data logging.

(ok, yes, this was discussed on irc for quite a while, and I never did put it down in writing)

-- SvenDowideit - 03 Oct 2012

And as I implement the Log4Perl equivalent function calls (shims), Log4Perl supports 5 levels: error, debug, warn, info, fatal, Log::Dispatch supports 8 levels which align nicely with syslog levels: debug, info, notice, warning, error, critical, alert, emergency I'm going to follow the Log::Dispatch conventions.

-- GeorgeClark - 03 Oct 2012

Thanks for your detailed response, George. One thing is clear is that Foswiki is trying to use a logging system as a messaging system, which is normally a totally different thing. One is fire and forget, and one is store and forward or subscribe and publish. Ideologically and functionally they are very different. Us Java heads would use JMS for the latter.

In log4j, the logging methods can take an Object, and the appenders are free to do whatever they want with that Object. I haven't found evidence either way with respect to Log4Perl or Log::Dispatch, but since Perl variables change type as easily as David Bowie, I'm guessing their log methods can to (ie the message attribute can be an object, or associative array), you can probably do the same, and the outputter can do with the object what it wants.

Or, use XML, which is also commonly used to searialize/martial objects.

But I wouldn't. I would use a separate messaging/pub-sub system. I know I'm coming late to the game so it might not be practical to make that big a change.

-- DavidKramer - 03 Oct 2012

I also looked for a general pub-sub messaging system on CPAN, and on reading the code, Log::Dispatch was the simplest one out there that did a large portion of what we want.

Log4Perl didn't suite the uses I had in mind as well.

so David - exactly and really, Log::Dispatch is a bit mis-named for what it can do

-- SvenDowideit - 03 Oct 2012

Additional issues turned up by writing a log viewer:

1. eachEventSince() does not return consistent event data. For debug and warning, it needs to return the documented fields, with the missing information undef (or null strings). The action should be 'logtext', or something else identifiable in this case. In all cases, it needs to return something in all the documented fields, and the data returned needs to be identifiable and decodable by a general consumer. (Such as a log display utility
2. eachEventSince() only returns items at a single severity level. For debugging, we want items in (merged if necessary) chronological order from all (or a user-specifed filter) severity levels. The $level argument needs to accept an arrayref of levels required.
3. The returned events need to include a field for the event severity, as when multiple levels are requested, the level of the returned event is otherwise unknown.
4. The logger - with all its dependencies - must run in a lightweight/stand-alone environment such as configure. It can't inhale the full Foswiki engine.

-- TimotheLitt - 19 Jan 2013

Good point, If the logger now supports logging additional arbitrary fields, and provides no way to get them back out.

Foswiki::Func::eachEventSince is broken worse than I thought. For one, it claims to support a requested level, but is actually hard-coded to the 'info' level. I'm thinking we should deprecate Func::eachEventSince and allow the Logger->eachEventSince to be callable directly.

Revised documentation eachEventSince

• eachEventSince($time, $level) -> $iterator
• eachEventSince($time, \@levels, [qw/field list/] ) -> $iterator
• $time - a time in the past
• $level - single log level to return events for.
• \@levels - arrayRef of requested levels
• field list - optional list of fields requested from the log.

Get an iterator over the list of all the events at the requested level(s) between $time and now.

Events are returned in oldest-first order.

The field list has the following valid values

undefined

Legacy mode, Each event is returned as a reference to an array. The first element of this array is always the date of the event seconds since the epoch). Fields returned are: (timestamp, login, action, Web.Topic, Extras, IP )

• Note that because multiple "levels" can be collapsed into a single log file, legacy mode is not recommended for anything other than processing 'info' events.

defined but empty

Each event is returned as a reference to a hash.

Array

Each event returned as a reference to an array, containing the fields listed in the array as requested.

• A special field "level" should be included in the list to know what log level was logged.

-- GeorgeClark - 20 Jan 2013

Flipped back to UnderConstruction to address the eachEventSince API.

-- GeorgeClark - 20 Jan 2013

Since the log() now accepts a new hash based API call, I'm wondering if the new eachEventSince should actually be revised to accept a hash for the parameter list and use that as the indicator to return the new style hash results.

ObjectMethod eachEventSince( {
  level => \@levels,           #Accept scalar or array reference,  all levels if omitted.
  user => $user,                #filter by user if available in the record)
  action => $action,            #filter by action if available in the record)
  agent => $agent,              #filter by agent if available
  topic => $webtopic,           #filter by...
  remoteaddr => $ip,            #filter
  <random field = $value>       # Filter by any other log field in the hash.
  filter = $regex,              # Filter matching records across all fields.
  includeMissing => $boolean,   # Should records with missing fields be reported or omitted
  starttime => $time,
  endtime => $time,
  limit => $count
   } )

The includeMissing boolean would be used when a specific field filter is requested, but a requested level doesn't log that field. For example, requesting all log levels, but filtering by user, would actually omit all records from all levels except info. Because the current loggers don't log user for anything except info events. includeMissing would be set to return records that are missing that field from the log record.

-- GeorgeClark - 30 Jan 2013

Downsized a bit...

    eachEventSince( {startTime =>
    levels =>
    recordsMatching => 
})

-- GeorgeClark - 30 Jan 2013

I guess this has to become a rejected proposal - at least the LogDispatch part. LogDispatch requires Class::Load and a conflicting decision was made to remove Class::Load from the list of Foswiki dependencies.

-- GeorgeClark - 16 Apr 2014

The second part is rejected by implication, because it requires a module that has too many dependency problems. The first part is still fine, though.

-- CrawfordCurrie - 17 Apr 2014

Commenting is disabled while not logged in