I’m a big believer that log files should be easy for machines to read and ingest. Structured logging opens up the door for using tools like the ELK stack or Splunk to aggregate, search, monitor, and alert on application activity.
The most common format for structured logging seems to be JSON. There are, of course, a lot of logging libraries for PHP, but I’ve been using log4php forever and don’t have any plans to switch. Like most logging libraries, log4php logs straight up strings.
There is no built in appender for JSON log formatting, though. The good news is that it’s easy to get properly formatted JSON logs using the standard LoggerAppenderDailyFile.
Here’s what I did.
First, I updated my log4php.config.xml file to write a JSON structure for the LoggerLayoutPattern. My updated appender looks like this. (For reference, all of log4php’s conversion parameters can be found here)
<appender name="jsonAppender" class="LoggerAppenderDailyFile">
<layout class="LoggerLayoutPattern">
<param name="conversionPattern" value="{"timestamp":"%d", "level":"%p", "ip":"%server{REMOTE_ADDR}", "details":%m}%n"/>
</layout>
<param name="file" value="/tmp/application_json_%s.log"/>
<param name="append" value="true"/>
</appender>Let’s break the conversion pattern down.
We open it with a bracket { and close it with another bracket followed by a newline }%n
This is just the basic JSON data structure.
Next we add a timestamp. This is where it gets a little funky. We have to encode the quotes because the config file is XML. %d the parameter is the standard ISO8601 datetime format.
"timestamp":"%d"This is equivalent to a JSON object that looks like {“timestamp”:”%d”}
The rest is pretty much the same.
{"timestamp":"%d", "level":"%p", "ip":"%server{REMOTE_ADDR}", "details":%m}%nThis creates a JSON object that looks like this
{“timestamp”:”%d”, “level”:”%p”, “ip”:”%server{REMOTE_ADDR}”, “details”:%m}%n
Next we need to make sure that the log information is written as JSON instead of plain text. I have a standard static Log class that I use for all logging.
class Log
{
/**
* @var Log
*/
protected static $_instance;
/**
* @var Logger
*/
protected $logger;
protected function __construct()
{
Logger::configure("log4php.config.xml");
$this->logger = Logger::getLogger('default');
}
/**
* @return Log
*/
private static function &GetInstance()
{
if (is_null(self::$_instance)) {
self::$_instance = new Log();
}
return self::$_instance;
}
/**
* @param string $message
* @param array $args
* @return LogMessage
*/
private static function EnrichLog($message, $args)
{
$logMessage = new LogMessage($message, $args);
$debug = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS);
if (is_array($debug)) {
$debugInfo = $debug[1];
}
else {
$debugInfo = array('file' => null, 'line' => null);
}
$logMessage->userId = $_SESSION['userId'];
$logMessage->file = $debugInfo['file'];
$logMessage->line = $debugInfo['line'];
return $logMessage;
}
/**
* @param string $message
* @param array $args
*/
public static function Debug($message, $args = array())
{
if (!self::GetInstance()->logger->isDebugEnabled()) {
return;
}
try {
$log = json_encode(self::EnrichLog($message, $args));
self::GetInstance()->logger->debug($log);
} catch (Exception $ex) {
echo $ex;
}
}
/**
* @param string $message
* @param array $args
*/
public static function Info($message, $args = array())
{
if (!self::GetInstance()->logger->isInfoEnabled()) {
return;
}
try {
$log = json_encode(self::EnrichLog($message, $args));
self::GetInstance()->logger->info($log);
} catch (Exception $ex) {
echo $ex;
}
}
/**
* @param string $message
* @param array $args
*/
public static function Warn($message, $args = array())
{
if (!self::GetInstance()->logger->isWarnEnabled()) {
return;
}
try {
$log = json_encode(self::EnrichLog($message, $args));
self::GetInstance()->logger->warn($log);
} catch (Exception $ex) {
echo $ex;
}
}
/**
* @param string $message
* @param array $args
* @param Exception|null $exception
*/
public static function Error($message, $args = array(), $exception = null)
{
if (!self::GetInstance()->logger->isErrorEnabled()) {
return;
}
try {
$logMessage = self::EnrichLog($message, $args);
$logMessage->exception = $exception;
$log = json_encode($logMessage);
self::GetInstance()->logger->error($log);
} catch (Exception $ex) {
echo $ex;
}
}
/**
* @param string $message
* @param array $args
* @param Exception|null $exception
*/
public static function Fatal($message, $args = array(), $exception = null)
{
if (!self::GetInstance()->logger->isFatalEnabled()) {
return;
}
try {
$logMessage = self::EnrichLog($message, $args);
$logMessage->exception = $exception;
$log = json_encode($logMessage);
self::GetInstance()->logger->fatal($log, $args);
} catch (Exception $ex) {
echo $ex;
}
}
public static function SetInstance($logger)
{
self::$_instance = $logger;
}
}
class LogMessage
{
/**
* @var string
*/
public $message;
/**
* @var int|null
*/
public $userId;
/**
* @var string|null
*/
public $file;
/**
* @var string|null
*/
public $line;
/**
* @var array|null
*/
public $args;
/**
* @var Exception|null
*/
public $exception;
public function __construct($message, $args = null)
{
$this->message = $message;
$this->args = $args;
}
}Using this is pretty simple, we just need to make sure we pass in any variables we want in a format that converts to JSON easily. I use an array because it’s readable and lightweight.
Log::Debug('This is a log message', ['param1' => 'value1', 'param2' => 123]);Would end up writing a log message that looks like this
{"timestamp":"2020-09-18T10:17:16-04:00", "details":"{"message":"This is a log message","userId":1,"file":"/var/www/app/test-logger.php","line":71,"args":{"param1":"value1", "param2": 123},"exception":null}", "level": "DEBUG"}This log can easily be parsed and searched using ElasticSearch now. This makes it trivial to find specific log events and look at trends.
To take it a step further, I could create a correlationId that is stored in the session at the beginning of a web request and added to every log entry. Now I can connect all the log events for every request.
