Context Navigation

Some Thoughts on Logging

A logging configuration consists of the following components:

loggers
appenders
layouts

I will collectively refer to these components as a log generator.

You can define per context and per environment log generators. Log generators are roughly based on the Java log pattern with a few key differences which I will outline below.

Logger

Each logger configuration specifies at a minimum a name. The name is used to refer to this particular logger from within the code. Additionally you may specify a class for the logger and as well as a level. The level is some boolean combination of const elements from the AgaviLogger interface (e.g. AgaviLogger::DEBUG, AgaviLogger::WARN, etc).

Note that the severity level is tied to the logger and not the the appender, as is the Java convention.

Also unlike Java, when you refer to a logger you use the name of the logger not the name of the class with which you are logging. For instance, in Java you would do something like the following:

  private final static Logger logger = LogFactory.getLog(getclass());
  // some other code
  logger.info("Some message");

This gives you the ability to both filter messages created by a specific producer as well as filter those messages by severity.

In Agavi you would do something like the following:

  $message = new AgaviLoggerMessage("Some Message", AgaviLogger::INFO);
  $this->getContext()->getLoggerManager()->getLogger()->log($message);

or the shorthand

   $this->getContext()->getLoggerManager()->log("Some Message");

Note that you lose the calling class and have no ability to filter messages. By using the AgaviCommonsLogger? you can simply do the following:

  $this->getContext()->getLoggerManager()->getLogger(get_class())->info("Some Message");

Note that by replacing the default logger manager you can introduce two additional patterns for logging:

  $this->getContext()->getLoggerManager()->getLogger(get_class())->warning("Some message"[,$optional_exception]);

which now gives you semantics similar to those in Java. Additionally you can, using the AgaviCommonsLogger?, do the following:

  $this->Logger = $this->getContext()->getLoggerManager()->getLogger(get_class());
  // some other code
  $this->Logger->info("Some message");

Appender

An appender is responsible for writing a log message. The logger takes an message and passes it to the write method of an AgaviLoggerAppender?. The Appender then passes the message optionally to its Layout (which formats it) and appends the message. Unlike in Java where the appender handles messages of a particular severity level, in Agavi the level of the logger determines which appenders to write to. In terms of configuration, an appenders section has one or more appender children each of which take a required name as well as an optional class and layout. Any parameters of the child appender is applied to that appender. Note that the majority of the appenders supplied with the Agavi distribution are unsuitable for a high-traffic environment. Included appenders are:

File
RotatingFile
Stderr
Stdout

I hope to introduce the following appenders shortly:

AsyncAppender
SmtpAppender
SyslogAppender

In particular the AsyncAppender will be useful for tying into a queue for processing.

Layout

A layout is responsible for formatting a message, ideally before it is appended. An AgaviLoggerLayout must implement a format method which accepts an AgaviLoggerMessage and must return a string. There are only two Layout's in Agavi:

Timestamp
Passthru

The Passthru layout simply calls the __toString method of the AgaviLoggerMessage. The Timestamp layout also prepends a timestamp. Other information that would be essential in most distributed or busy environments include:

A trace token (for following a transaction across systems)
The class that generated the notice (along with line number, etc if an exception was generated)

Working Example

Below is a working example.

<?xml version="1.0" encoding="UTF-8"?>
<configurations xmlns="http://agavi.org/agavi/1.0/config">

  <!-- Configuration for non-production environments -->
    <configuration>
      <loggers default="every_msg">
        <!-- logs every messages -->
        <logger name="every_msg" class="AgaviLogger" level="AgaviLogger::ALL">
          <appenders>
            <appender>AllLogAppender</appender>
          </appenders>
        </logger>
      </loggers>
      <appenders>
        <appender name="AllLogAppender" class="AgaviFileLoggerAppender" layout="TimestampLayout">
          <parameters>
            <parameter name="file">/tmp/logs/allMessages.log</parameter>
          </parameters>
        </appender>
      </appenders>
      <layouts>
        <layout name="TimestampLayout" class="AgaviTimestampLoggerLayout" />
      </layouts>
    </configuration>
</configurations>

In this example we have specified that the default logger (e.g. when no logger is specified when calling getLoggerManager()->getLog()) should be a logger named "every_msg". We have defined only a single logger. The logger implementation being used is based on the AgaviLogger class and this logger will catch messages with any severity. Note that if you wanted to grab, for instance, everything except for debug messages the level would read: AgaviLogger::ALL ^ AgaviLogger::DEBUG.

We specified that the logger would use only one appender, the AllLogAppender. That is a basic file appender using a layout named TimestampLayout which is defined a bit later on. Note that each Appender has different parameters which they can take advantage of.

Recommendations

First, I think that the severity level should be specified on a per appender basis. This allows you to for instance log every single item to a logfile but only log FATAL or ERROR level messages to for instance an SmtpAppender. Yes, you could create multiple loggers to do this but that becomes verbose and time consuming. It also kind of breaks the separation of concerns by having to do something like:

  $this->getContext()->getLoggerManager()->getLog('smtp')->log('Serious Error');
  $this->getContext()->getLoggerManager()->getLog('file')->log('Mild issue');

What you really want is:

  $this->getContext()->getLoggerManager()->getLogger(get_class())->error("Serious Error"[,$optional_exception]);

You should simply be able to execute your logging statement and what messages and where those messages are logged should depend on the name of the log producer (the one passed in that specifies that class) and the severity of the messages, not the log implementation.

Doing this would require a few things.

Replace the log manager
- Implement one that allows you to specify an arbitrary logger name which simply becomes an attribute of the default logger
- Note that you can have a mix of named loggers as well as arbitrary names. A conflict could occur but is unlikely given Agavi naming conventions.
Replace the AgaviLogger? implementation
- One that allows you to specify the log level as the method name (error, warn, etc)
- One that accepts exceptions as an optional parameter to methods, like in apache commons
- One that respects an additional parameter of each appender, a level
- One that utilizes the level specified on a per appender basis (but uses the level specified at the top level as a default) to determine whether to write to the appender
Create a more sophisticated Layout or Message class
- Needs to handle different types (Exception, array, etc)
- Should be able to output in different formats (XML, JSON, etc)

Here is what a new sample configuration might look like:

<?xml version="1.0" encoding="UTF-8"?>
<configurations xmlns="http://agavi.org/agavi/1.0/config">

  <!-- Configuration for non-production environments -->
    <configuration>
      <loggers default="msg_logger">
        <!-- logs every messages -->
        <logger name="msg_logger" class="AgaviCommonsLogger" level="AgaviLogger::ALL">
          <appenders>
            <appender>AsyncLogAppender</appender>
            <appender>SmtpLogAppender</appender>
          </appenders>
        </logger>
      </loggers>
      <appenders>
        <appender name="AsyncLogAppender" class="AgaviAsyncLoggerAppender" layout="TimestampLayout">
          <parameters>
            <parameter name="queue_name">messages</parameter>
            <parameter name="level.root">AgaviLogger::INFO</parameter>
            <parameter name="level.SomeClass">AgaviLogger::ALL</parameter>
          </parameters>
        </appender>
        <appender name="SmtpLogAppender" class="AgaviSmtpLoggerAppender" layout="TimestampLayout">
          <parameters>
            <parameter name="email_to">foo@bar.com</parameter>
            <parameter name="level.root">AgaviLogger::FATAL</parameter>
            <parameter name="level.SomeProblemClass">AgaviLogger::ERROR</parameter>
          </parameters>
        </appender>
      </appenders>
      <layouts>
        <layout name="TimestampLayout" class="AgaviTimestampLoggerLayout" />
      </layouts>
    </configuration>
</configurations>

Note that hierarchical usage of levels. We have a top level specified (the minimum level for any appenders to be looked at for a message), a per appender level (specified by level.root), and an optional per class level. This allows you to easily update what gets logged where, on the fly, by modifying appenders instead of code.

Let's look at a sample use case, before and after. Previously if you wanted similar semantics you would need to create different loggers, not different appenders and use them as follows:

  $this->getContext()->getLoggerManager()->getLogger('async')->log(new AgaviLoggerMessage('My Message', AgaviLogger::INFO));

now let's say we're seeing something in production that we want to get mailed about. Up, we need to go and add a new logger to the logging.xml config as well as add a place in the code that does:

  $this->getContext()->getLoggerManager()->getLogger('async')->log(new AgaviLoggerMessage('My Message', AgaviLogger::INFO));
  $this->getContext()->getLoggerManager()->getLogger('smtp')->log(new AgaviLoggerMessage('My Message', AgaviLogger::ERROR));

With the new logger, you have one logging statement, say:

  $this->getContext()->getLoggerManager()->getLogger(get_class())->error('My Message'[,$optional_ex]);

and you can tweak where those messages get logged to both by class as well as severity, strictly within the appender, without touching any code.

Now, it's true that if you log using the loggerManager log method, it will send a log message to all loggers that have an appropriate level. However, you still don't have many of what I see as being the benefits of taking the above approach.

Download in other formats:

Plain Text