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.

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; 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(); } 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 ); } public function logError( $message , $context = []) { $this ->logger->pushProcessor( $this ->processor); $this ->log(Logger::ERROR, $message , $context ); } public function logWarning( $message , $context = []) { $this ->log(Logger::WARNING, $message , $context ); } public function logNotice( $message , $context = []) { $this ->log(Logger::NOTICE, $message , $context ); } 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%%

"



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(); } ... ... 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\\Constraints ConstraintsAboidActifValidator ", " 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 { const SIMPLE_FORMAT = "[%datetime%] %channel%.%level_name%: %message% %context% %extra%

" ; const MEETIC_FORMAT = "[%datetime%] [%extra.customerId%] [%extra.productLine%]". "%channel%.%level_name%: %message% %context% %extra%

" ; protected $format ; protected $allowInlineLineBreaks ; protected $ignoreEmptyContextAndExtra ; protected $includeStacktraces ; public function __construct( $format = null, $dateFormat = null, $allowInlineLineBreaks = false, $ignoreEmptyContextAndExtra = false ) { $this ->allowInlineLineBreaks = $allowInlineLineBreaks ; $this ->ignoreEmptyContextAndExtra = $ignoreEmptyContextAndExtra ; parent::__construct( $dateFormat ); } ... ... ... public function format( array $record ) { $vars = parent::format( $record ); 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