Symfony and Monolog, how use Processor in your project: a practical example

We often have to use different micro-services who write in many log files. Use utilities like Kibana is a good thing, but in order to take full advantage of its features we have to try to standardize and normalize the logs.
The company where I work having introduced Kibana recently, he asked me to implement a proper strategy to log all the micro-services.

First we defined the basic rules of the logs.

General logging rules of team

 

Mandatory Fields

  • Date + Hours : 2017-02-09 10:24:00
  • Log Level : TRACE DEBUG INFO WARN ERROR FATAL
  • Customer Id
  • Site or ProductLine
  • Message

If log is ERROR mandatory fields are also:

  • File
  • Class
  • Method
  • Line


Describing the exact point of the code that has launched the exception.

When logging

  • Start and End of service call
  • External call
  • Exceptions
  • Key points of the application

 

Where logging

  • 1 file for service
  • 1 error file for service

Technology

Monolog


Monolog sends your logs to files, sockets, inboxes, databases and various web services. See the complete list of handlers below. Special handlers allow you to build advanced logging strategies.
This library implements the PSR-3 interface that you can type-hint against in your own libraries to keep a maximum of interoperability. You can also use it in your applications to make sure you can always use another compatible logger at a later time. As of 1.11.0 Monolog public APIs will also accept PSR-3 log levels. Internally Monolog still uses its own level scheme since it predates PSR-3. Reference:https://github.com/Seldaek/monolog

Working with Symfony and Monolog

Symfony comes with native Monlog library that allows you to create logs that can be stored in a variety of different places.
The logger service has different methods for different logging levels/priorities. You can configure the logger to do different things based on the level of a message (e.g. send an email when an error occurs).
The logger has a stack of handlers, and each can be used to write the log entries to different locations (e.g. files, database, Slack, etc).

For a proper and complete vision of Monolog in Symfony, refer to the official documentation: http://symfony.com/doc/current/logging.htmlhttp://symfony.com/doc/current/logging/processors.html http://symfony.com/doc/current/reference/configuration/monolog.html

 

Usage example

We use as example one of many micro-services that my company use: “serviceactivator” web service.
What it does the micro-service does not matter. What interests us is how it write logs.

1) Configuration of monolog

#app/config.yml

monolog:
    handlers:
        main:
            type:   stream
            path:   "%kernel.logs_dir%/%kernel.environment%.log"
            channels: ['!serviceactivator']
        serviceactivator:
            type: stream
            path: '%kernel.logs_dir%/%kernel.environment%.serviceactivator.log'
            channels: [serviceactivator]
            formatter: monolog.formatter.service_activator


2) Base Logger: the parent logger class

<?php

namespace Meetic\LogBundle\Logging;

use Meetic\LogBundle\Logging\Processor\IntrospectionProcessor;
use Monolog\Logger;

/**
 * BaseLogger provide methods in order to write log using monolog.
 *
 * @package Meetic\LogBundle\Logging
 */
class BaseLogger
{
    protected $logger;
    protected $disabled;
    protected $processor;
 
    public function __construct(Logger $logger, $disabled = false)
    {
        $this->logger = $logger;
        $this->disabled = $disabled;
        $this->processor = new IntrospectionProcessor();
    }

    /**
     * Generic log method to transform message in string if
     * it's an object or an array
     *
     * @param string $level Log level
     * @param mixed $message Message (can be string, array, or object)
     * @param array $context Context
     */
    protected function log($level, $message, $context)
    {
        if (is_array($message) || is_object($message)) {
            $message = json_encode($message);
        }

        if (is_object($context)) {
            $context = json_decode(json_encode($context), true);
        }

        $this->logger->addRecord($level, (string)$message, (array)$context);
    }

    /**
     * Write error log
     *
     * @param string $message the message to write in log file
     *
     * @return void
     */
    public function logError($message, $context = [])
    {
        $this->logger->pushProcessor($this->processor);
        $this->log(Logger::ERROR, $message, $context);
    }

    /**
     * Write warning log
     *
     * @param string $message the message to write in log file
     *
     * @return void
     */
    public function logWarning($message, $context = [])
    {
        $this->log(Logger::WARNING, $message, $context);
    }

    /**
     * Write notice log
     *
     * @param string $message the message to write in log file
     *
     * @return void
     */
    public function logNotice($message, $context = [])
    {
        $this->log(Logger::NOTICE, $message, $context);
    }

    /**
     * Write info log
     *
     * @param string $message the message to write in log file
     *
     * @return void
     */
    public function logInfo($message, $context = [])
    {
        $this->log(Logger::INFO, $message, $context);
    }
}


3) The specific logger class

<?php

namespace Meetic\LogBundle\Logging;

class ServiceActivatorLogger extends BaseLogger
{

}

 

4) Configuration of services

services:
    serviceactivator_logger:
        class: Meetic\LogBundle\Logging\ServiceActivatorLogger
        arguments: ["@logger"]
        tags:
            - { name: monolog.logger, channel: serviceactivator }

    monolog.formatter.service_activator:
        class: Meetic\LogBundle\Logging\Formatter\MeeticLineFormatter
        arguments:
            - "[%%datetime%%] [%%extra.customerId%%] [%%extra.productLine%%] %%channel%%.
               %%level_name%%: %%message%% %%context%%\n"


5) Creation of Monolog Processor

Monolog allows you to process the record before logging it to add some extra data. A processor can be applied for the whole handler stack or only for a specific handler.
A processor is simply a callable receiving the record as its first argument. Processors are configured using the monolog.processor DIC tag. See the reference about it.

<?php

namespace Meetic\LogBundle\Logging\Processor;

class ServiceActivatorProcessor
{
    /**
     * @param  array $record
     * @return array
     */
    public function __invoke(array $record)
    {
        foreach ($record['context'] as $key => $val) {
            $record['extra'][$key] = $val;
        }
       return $record;
    }
}


This processor, for example, is responsible to place in extra all key/value pairs passed in the context.

6) Declare service Processor

monolog.processor.serviceactivator:
    class: Meetic\LogBundle\Logging\Processor\ServiceActivatorProcessor
    tags:
        - { name: monolog.processor, method: __invoke, handler: serviceactivator }

The method __invoke of Processor will be called every times that ServiceActivatorLogger write log.

7) Call log Example

$this->logger->logInfo(
    'Result of curl call',
    array(
        'codeResponse' => $this->httpReponseCode,
        'result' => $result,
        'customerId' => $this->customerId,
        'productLine' => $this->productLine
    )
);


Generated log:

[2017-03-13 11:50:58] [29341843] [DATING] serviceactivator.INFO: Result of curl call 
{"codeResponse":204,"result":"blablabla","customerId":"29341843","productLine":"DATING"}

 
8) Specific Processor for log error

We will use IntrospectionProcessor that will be called only if application want log a error:

namespace Meetic\LogBundle\Logging;
use Meetic\LogBundle\Logging\Processor\IntrospectionProcessor;
class BaseLogger {
    
protected $processor;

    public function __construct(Logger $logger, $disabled = false)
    {
        …
        $this->processor = new IntrospectionProcessor();
    }
   
  
    ...
    ...

    /**
    * Write error log
    *
    * @param string $message the message to write in log file
    *
    * @return void
    */
    public function logError($message, $context = [])
    {
        $this->logger->pushProcessor($this->processor);
        $this->log(Logger::ERROR, $message, $context);
    }
    ...
}

 

Generated log:

[2017-03-10 10:40:38] [61762462] [DATING]serviceactivator.ERROR: : user not active
{"file":"<path>/ConstraintsAboidActifValidator.php",
"line":19,
"class":"ServiceActivatorWSBundle\\Validator\\ConstraintsConstraintsAboidActifValidator",
"function":"validate"}

9) Separate file for error log

Nothing could be simpler with monolog:

serviceactivator_error:
    type: stream
    path: '%kernel.logs_dir%/%kernel.environment%.serviceactivator_error.log'
    channels: [serviceactivator_error]
    formatter: monolog.formatter.service_activator

 

10) Custom Formatter

So far everything is fine, but what happens if we have not ‘customerId’ or productLine in context array? We will have a log like this:

[2017-03-13 11:09:14] [] [] serviceactivator_error.ERROR: Error parameters validator
{"error":"6176243423423423462: user not active","customerId":"6176243423423423462","productLine":"DATING"} {"file":"<path>/ConstraintsAboidActifValidator.php","line":19,
"class":"Meetic\\Payment\\ServiceActivatorWSBundle\\Validator\\Constraints
ConstraintsAboidActifValidator","function":"validate"}

You can see that brackets that should contain customerId and productLine are empty.
So, the last step, act to printing well logs are customize monolog formatter class. Specifically we will customize LineFormatter class.

<?php

namespace Meetic\LogBundle\Logging\Formatter;

use Monolog\Formatter\NormalizerFormatter;

class MeeticLineFormatter extends NormalizerFormatter
{
    //DEFAULT FORMAT
    const SIMPLE_FORMAT = "[%datetime%] %channel%.%level_name%: %message% %context% %extra%\n";
   
    //MEETIC FORMAT
    const MEETIC_FORMAT = "[%datetime%] [%extra.customerId%] [%extra.productLine%]".
                          "%channel%.%level_name%: %message% %context% %extra%\n";

    protected $format;
    protected $allowInlineLineBreaks;
    protected $ignoreEmptyContextAndExtra;
    protected $includeStacktraces;

    /**
     * @param string $format The format of the message
     * @param string $dateFormat The format of the timestamp: one supported by DateTime::format
     * @param bool $allowInlineLineBreaks Whether to allow inline line breaks in log entries
     * @param bool $ignoreEmptyContextAndExtra
     */

    public function __construct(

        $format = null,
        $dateFormat = null,
        $allowInlineLineBreaks = false,
        $ignoreEmptyContextAndExtra = false
    ) {
        $this->allowInlineLineBreaks = $allowInlineLineBreaks;
        $this->ignoreEmptyContextAndExtra = $ignoreEmptyContextAndExtra;
 
        parent::__construct($dateFormat);
    }

    ...
    ...
    ...

    /**
     * {@inheritdoc}
     */
    public function format(array $record)
    {
        $vars = parent::format($record);
        
        //If customerId and productLine are not defined we use default format.
        if (empty($record['extra']['customerId']) || empty($record['extra']['productLine'])) {
            $output = str_repeat('-', 120).PHP_EOL.static::SIMPLE_FORMAT;
        } else {
            $output = str_repeat('-', 120).PHP_EOL.static::MEETIC_FORMAT;
        }
        ...
        ...
        ...

        return $output;
    }
    ...
    ...
    ...
}

 

If customerId and productLine are empty the application use default format (SIMPLE_FORMAT) and we will have a log like this:

[2017-03-13 11:43:30] serviceactivator_error.ERROR: Error parameters validator
{"error":"DATINGa is not a valid ProductLine","customerId":"29341843","productLine":"DATINGa"} 
{"file":"<path>/ConstraintsProductLineAcceptedValidator.php","line":26,
"class":"ServiceActivatorWSBundle\\Validator\\Constraints\\ConstraintsProductLineAcceptedValidator","function":"validate"}

So now, the formatter service can change in this way:

monolog.formatter.service_activator:
  class: Meetic\LogBundle\Logging\Formatter\MeeticLineFormatter
  arguments: [null, null, true, true]

We can do this because we put the custom logic, act to handle format of log, inside custom format method of formatter class.

 

Evolutions

The next development could be use configuration files to tell to processor which fields include in extra field of record structure:

 

mandatory_logger_fields:
    serviceactivator:
        customerId: ~
        productLine: ~    

 

And pass it to service:

monolog.processor.serviceactivator:
    class: Meetic\LogBundle\Logging\Processor\ServiceActivatorProcessor
    arguments: ["@=container.getParameter('mandatory_logger_fields')['serviceactivator']]
    tags:
      - { name: monolog.processor, method: __invoke, handler: serviceactivator  }

 

 

References

 

10 thoughts on “Symfony and Monolog, how use Processor in your project: a practical example”

  8. When I implemented something like this its log the BaseLogger call… What do you think, if BaseLogger implements PSR-3 as well to make the class more reliable?

    Like

Leave a comment