You should really be using monolog.

If you’ve ever had any problem with a program in your career (hardly ever happens), you’ve checked a log file to help discern “What the !@#$ is happening?”. As PHP professionals we know we should be logging to make systems easier to monitor and debug both for ourselves and anyone else who may inherit them. However, the difficulty of creating poignant, searchable, interpretable logs is often overlooked when accomplishing a new task. So being the professionals we are, we set up a log file, have our application spew to it in a few choice locations, pat ourselves on the back for a job well done, and never look at the log file again.

6 months later something breaks, and we’re no closer to answering the question — “What the !@#$ is happening?”

Monolog is a composer installable package which provides an extensible framework for delivering logs to wherever you would like them, as well as increasing their utility. While it is possible to make that unorganized log file you’re about to make using monolog, it’s much less likely that you will because the framework provides you with the tools, the rules, and the flexibility to do much more.

You should really be using monolog and here’s why.

PSR-3

The php-fig (Framework Interop Group) exists to solve common PHP programming problems. The PSR-3 spec defines a common interface and some helper classes for use by logging libraries. The MonologLogger class is an instance of the PSR-3 LoggerInterface and complies fully with this standard. Yay standards, let’s play nice!

PSR-3 defines eight log levels for defining the priority and intent behind your logs. At a quick glance you can scan for high priority events to get a feel for the health of your system. Using log analyzer tools you can organize, filter, search and visualize your logs based on these event levels in order to quantify and measure system health.

  1. Debug – Detailed debug information. This level is generally for minutia. Often this information is useful during development or bug hunting.

  2. Info – Interesting events. High frequency logs of events which you want to track, possibly store, but are reflective of normal operation of common system tasks. Example: user updates.

  3. Notice – Normal but significant events. These events are excellent for getting a view of the behavior of your system. It’s useful to use notices to mark the kick off, and completion of tasks. Example: Database migration completed OR user unsubscribe from newsletter.

  4. Warning – Exceptional occurrences that are not errors. Anything that interrupts normal operation but isn’t necessarily incorrect. Things in this category can range from use of a deprecated API methods to mindful ignorance of a task which is usually performed but doesn’t break anything when not performed. Example: Disk space is over 80% utilized.

  5. Error – Runtime errors that do not require immediate action but should typically be logged and monitored. These are errors you anticipated and planned to catch. Example: Missing configuration file.

  6. Critical – Critical conditions. This is something your system can recover from, but may necessitate human intervention. These are events you would like to investigate promptly when they arise. Example: Application component unavailable.

  7. Alert – Action must be taken immediately. Major components of the system are broken or completely unavailable. Example: Database unavailable / Web Server down.

  8. Emergency – System is unusable. This is reserved for your applications equivalent of the apocalypse. Something might literally be on fire.

Channel – Broad identification for a log.

When making a Logger you provide a text string which will accompany all logs made by that instance. If you have built a program which does migration for your blog database, you may give it a channel of “blog-migration.” This will help you sort and search your logs by that channel when the time comes.

$logger = new MonologLogger("blog-migration");

Context – Dig into the details.

The logger methods take a message argument to describe the event, as well as an array of “context” data to describe the circumstances of the event. Above all else, the use of context should be to increase log clarity. For example, when you’re logging about saving a user, put the user’s data into context so you know which user the log pertains to.

In general, make your messages broad, and your contexts specific.

Instead of:

$user = new User("username");
$db->put($user);
$logger->info('User ' . $user->username . ' saved.');

Tend toward:

$user = new User("username");
$db->put($user);

$context = get_object_vars($user);
$logger->info("User saved.", $context);

Keeping specifics out of your messages leaves you with consistent homogenous messages you can use when searching. You may want to know how many users are saved in a day, so you do a search for all messages in the last day equal to “User saved.” Now, if you’re interested in seeing a “User saved.” log pertaining to a specific user you can still do that by adding context["username"] === 'bob' to the search conditions.

Using contexts is an easy way to increase the expressiveness of your logs, do it.

Records – Structure of a log.

Records are an associative array which act as the data currency of monolog. In a record you find all the pertinent information which define a log — the level, the message, the context, etc. Here is the basic skeleton of a monolog record:

$record = array(
    'message' => string,
    'context' => array
    'level' => integer,
    'level_name' => string,
    'channel' => string,
    'datetime' => float (unix microtime)
    'extra' => array
);

Handlers – Log here, there, and everywhere.

Monolog handlers allow your logs to be output to multiple destinations. Perhaps you want logs output to the console so you can see them while you’re using a command line tool, but you also want to store them in a .log file, email them to yourself, and store everything in a third party log analysis tool. You can do that with monolog by simply pushing additional handlers. Monolog is shipped with A TON of built in handlers. One of the most common is StreamHandler which logs to an open stream such as php://stdout or a file. There are also built in email handlers for common email libraries, and even some common log storage services like Loggly.

$stdOutHandler = new StreamHandler('php://stdout');
$logFileHandler = new StreamHandler('/path/to/my/logfile.log');

$logglyFormatter = new LogglyFormatter();
$logglyHandler = new LogglyHandler("my-loggly-api-token");
$logglyHandler->setFormatter($logglyFormatter);

$logger = new Logger("blog-migration");
$logger->pushHandler($stdOutHandler);
$logger->pushHandler($logFileHandler);
$logger->pushHandler($logglyHandler);

The loggly handler takes data in a specific format, which is why it has a formatter. Something we haven’t covered, but we will.

At this point you know enough to go start injecting the logger into your classes. You could leave now if you’re saturated with new knowledge and just want to get to it. The next few sections are here if you want to do something custom with Monolog, are just curious, or if you want to provide variability in your setup.

Formatters – Have it your way.

Formatters are exactly what they sound like, they’re for controlling the format of a log record. Monolog supplies several built in formatters, JsonFormatter, HtmlFormatter, ElasticaFormatter, and LogglyFormatter are all examples of formatters provided by the library. These classes implement the FormatterInterface which provides format(array $record) and formatBatch(array $records) methods for altering records.

The JsonFormatter::format() method for instance is quite a simple example which conveys the general idea.

public function format(array $record)
{
    return json_encode($record) . ($this->appendNewline ? "n" : '');
}

It receives a record, and returns its json encoded value.

Processors – Do something, do more.

We learned above that contexts are a good way to store extra data in a log record. Processors are an alternative way to store “extra” data in a log record. Processors are PHP callables with an __invoke magic method that takes the record as it’s first argument, alters the extra key of the record, and returns it when it’s done processing. A processor allows you to do something, to run some addtional code at log time and stick the results into the record.

Processors can be pushed onto the Logger instance itself to process all records, or to individual handlers to process only the records sent to that handler. The logger and handlers then execute all the processors while they’re building log records.

Monolog being pretty awesome, has of course provided several built in processors which make excellent examples of what you can do with a processor. The ProcessIdProcessor for instance adds the current PHP process id to the record.

class ProcessIdProcessor
{
    /**
     * @param  array $record
     * @return array
     */
    public function __invoke(array $record)
    {
        $record['extra']['process_id'] = getmypid();

        return $record;
    }
}

Verbosity Levels – Take only what you want.

public function __construct($level = Logger::DEBUG, $bubble = true);

Above is the signature of monolog’s AbstractHandler base class. This means that all handlers built from that base class (most, if not all of them) take a $level argument which sets the minimum log level for that handler. This is really useful, because as you start using your logs more often you will quickly discover that most of the time you do not care about every single minute detail, and it is nice to turn down the volume. At Cascade Energy we have a file import process which ingests data into our system, we’ve set the LogglyHandler in that system to a level of Logger::NOTICE, because with anymore verbosity than that it becomes difficult to get a feel for what is happening. Unless you are a masochist you probably don’t want an email every time a user is saved, you might want to set the level to Logger::CRITICAL so you only get emails when you log a critical, alert, or emergency.

Thanks for reading

The goal here was to give a quick synopsis of some of the things monolog can help you do to organize and solidify the way you log in PHP applications, I hope if you were confused about monolog you have a clearer picture, and if you were on the fence about using monolog, I hope I’ve pushed you over. I’m using this framework often, so feel free to ask me questions on twitter @nackjicholsonn. If I can, I will answer them.

composer require monolog, you should really be using it.

Advertisements

One thought on “You should really be using monolog.

  1. That helped, thank you.
    I remain confused about how to use this puppy.
    In production I want notices only. When developing I want everything.
    Yet I do not want to have debug on all the time.

    I keep mentally falling back to pseudo-coding:
    if (verbose) then log.addDebug(…)

    Or should the level argument for the handler be variable?
    level = verbose ? Logger::WARNING : Logger::WARNING;
    log.pushHandler(new someHandler(‘arg’, level));

    Or are they both right?

    -paralyzed with indecision

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