Logmatic.io Blog

You’re doing PHP logging wrong:

Spice up your PHP logs

I was last week at the French PHP Tour event, proudly organized by the corresponding country’s PHP users association. It was an enjoyable two days in which I met many interesting PHP players, among which Paweł Jędrzejewski from Sylius, an e-commerce alternative to Magento very much on the rise… Though I had many engaging and interesting conversations, I was overall quite surprised by the fact that so many developers only use PHP logs for finding errors on their apps and websites.

As an evangelist, I obviously tried to spread the good word (and I swear, I’ll convert you too 😀 ): logs in general and PHP logs in particular are NOT JUST ABOUT ERRORS. You could do so much more, so easily and so quickly with your logs. So please, use your logs, everywhere.

I. What logging means for a PHP app

Because logs can cover such a vast range of technological stacks, let me clarify from the start that I will focus in this post on backend PHP logs and the core of an app, rather than front logging (browsers, mobile devices, etc…), even though PHP mainly serves websites, APIs and web applications.

Let’s get started…

Contrary to popular beliefs, PHP logs in an app can be used for 3 major purposes:

  1. Troubleshooting: what errors occurred? What unexpected behaviour or scenario was encountered by users?
  2. Performance: what are response times and latencies, whether they come from controllers, databases, or templating engines?
  3. Usage: what are the number of pages and API calls, logins, emails sent, or session duration…?

These 3 purposes form a mini Maslow pyramid, where the first step needs to be covered before addressing the next one:

maslow for devs

1) Troubleshooting: tracking PHP errors

I remember the first website I built, there were many errors on top of the page. So when I started coding in PHP as a self-taught developer, I was careful to switch off all warnings and errors in the server configuration. My first developments were of poor quality and my users rapidly faced issues (well, in fact whole black pages as I switched all traces off).

That’s how I learned that you need to know each type of error occurring on your project, and that the first option to which I had turned to – disabling them – was clearly a mistake.

Some errors are more impactful than others. For instance, a simple 404 – file not found – should not be too worrisome and does not require immediate action… except if this same error occured once for 100 users in the last hour. Then an important link is broken and needs to be fixed quickly. The same goes for databases errors, such as tables or columns missing after an upgrade, or timeouts caused by high traffic.

If you don’t track errors properly on your app, you are not aware of what’s happening and cannot take the right decisions. This is even more true if you’re working on an e-commerce website. Errors could have an immediate and serious impact on revenue if your users cannot use your website properly.

But let’s get back to some code, and put the following one in the right place. I recommend you to configure your server and application with the following setup:

// Reports all errors
error_reporting(E_ALL);
// Do not display errors for the end-users (security issue)
ini_set('display_errors','Off');
// Set a logging file
ini_set('error_log','my_file.log');

All errors, warnings and notices will thus be reported to a file: my_file.log. You can also use syslog() instead of a file if you’d rather use the syslog service of your host (or the Event Log in the case of Windows server).

This configuration will track all PHP errors, but not exceptions. Exceptions are a user’s feature allowing them to send out notices when something unexpected or wrong happens. PHP provides a global exception handler that can be overridden and allows you to define your own behavior. So get back to the app and update the code with the following snippet:

// Reports all errors
error_reporting(E_ALL);
// Do not display errors for the end-users (security issue)
ini_set('display_errors','Off');
// Set a logging file
ini_set('error_log','my_file.log');


// Override the default error handler behavior
set_exception_handler(function($exception) {
   error_log($exception);
   error_page("Something went wrong!");
});

batman

Now you are ready to find out what’s going wrong with your website.

2) Monitoring: tracking performance & response time with PHP logs

Once you’ve mastered finding errors on your website, you need to understand where the overall performance of your application stands, which parts are not working as expected, or simply too slow. If you have a MVC pattern (model-view-controller) inspired architecture, measuring response time for each layer is important to prioritize your upcoming developments and make users happy 🙂 .

PHP logs and traces coming from monitoring are not errors. They are just events. So, in order to track and distinguish them from errors, you have to define and use a second level of “information”. The usual recommendation is to log these types of events as debug.

Tracking performance and response times do not require complex tools. You can use the simple `microtime` function at the beginning. Here is a simple class that can be used again anywhere to track response time:

class ExecutionTime
{
     private $startTime;
     private $endTime;


     public function start(){
         $this->startTime = microtime(true);
     }
     public function end(){
         $this->endTime =  microtime(true);
     }
     public function diff(){
         return $this->endTime - $this->startTime;
     }
 }
 
// Usage
$mark = new ExecutionTime();
$mark->start(); 


// hack, code something


$mark->end(); 
logger.debug("Controller ‘home’ loaded in " . $mark->diff() . "ms";

solve rubiks cube

With that code, you are now able to simply track and record response times for each module. If you want to track response times for complex workflow involving multiple requests, controllers, views, consider the global session to store timers.

3) Understanding Usage: tracking events with PHP logs

The last stage of our mini-Maslow pyramid is usage metrics. Now that you should not be considering PHP logging as mere “errors reporting”, thinking bigger and envisioning logging as part of an event-driven architecture is possible.

Remember, your PHP logs are part of your app. They are streams of interesting and actionable events that will be consumed by both machines and humans.

Or at least, this is the theory. But if you want to track some usage/user metrics, and you feel lost, here are some inspiring examples:

  • Track all calls from endpoints, and report IP, datetime, sessions, urls and query params
  • Track all events related to security (login, logout, failed attempts, etc.)
  • Track all response times from assets and resources used within your front app
  • Track server metrics (cpu, disk usage, disk latencies, network and memory) to correlate user and server behavior, especially when your app is under a huge load pressure.

II. Getting the big picture on your servers

1) Structure your logs

At this point, you might be thinking that you already have all you need to build your dream-come true-360-degree-view-machine. But you’re actually still missing one thing: a practical way to retrieve and analyse what’s going on in your PHP logs and events.

Because you will be dealing with millions or billions of logs and events, keep some rules in mind for this activity to be as stress free as possible:

  • Write stateless events: each PHP log and every line must be stateless. In order to ensure this is true everywhere, add a few meta fields and some context. For instance, add the user email if you have it, session id, ip and whatever you feel like that could be helpful later on.
  • Get a human AND machine readable format: JSON is the obvious solution. Keep one attribute for the human (and call it message :D) and create one attribute per field for context and meta. It will be much more easier to search and filter the information later on. Do not use arrays, as they’re really painful to operate.
{
    // Logger level
    "level": "INFO",
    // Module
    "thread_name": "FsmaticDataCluster-akka.actor.default-dispatcher-4",


    // HTTP data
    "@version": 1,
    "http": {
      "method": "POST",
      "url": {
        "path": "/v1/input/xxxxxxxxxxxxxxxxxxxxxxxx",
        "host": "api.logmatic.io",
        "queryString": {
          "cluster": "coorp-clust-web-1",
          "apptype": "mooc",
          "brand": "_core",
          "platform": "production"
        }
      },
      "remoteIp": "54.198.197.176",
      "version": "HTTP/1.1",
      "statusCode": 200
    },


    // User id
    "user": "guillaume@logmtic.io",


    // Human readable message
    "message": "POST /api.logmatic.io/v1/input/Jxxxxxx?apptype=mooc&brand=_core&platform=production&cluster=coorp-clust-web-1"
}

And one last advice. You might need to propagate context to all layers of your service or application. In that case, using a global logger instance or some global variables (such as $_SESSION) could solve the problem.

2) The libraries to use for PHP log: the Homemade, Monolog, and Zend ways

Coding a logging class or module can be similar to … an academic exercise. Re-inventing the wheel is not necessary, especially when very good libraries such as Monolog or Zend_Log exist.

All logger libraries include many features, but check for the following capabilities that are the most important:

  • Different logging levels
  • Context attachment
  • Dynamically added meta attributes

My personal preference goes for Monolog which actually includes all of these capabilities, so don’t waste any more time and start using it 😀

Here is a simple example with Monolog to illustrate all the things we’ve seen before. First things first: add the dependency to your code. And if you don’t use composer … it’s a good occasion to start.

# Install it via composer
composer require "monolog/monolog"

In your PHP bootstrap file, create your first logger. Set Json as the default format and start logging with a context.

<?php

// load Monolog library
use Monolog\Logger;
use Monolog\Handler\StreamHandler;
use Monolog\Formatter\JsonFormatter.php
  
// create a log channel
$log = new Logger('channel_name');

// create a Json formatter
$formatter = new JsonFormatter();

// create a handler
$stream = new StreamHandler(__DIR__.'/application-json.log', Logger::DEBUG);
$stream->setFormatter($formatter);

// bind
$log->pushHandler($stream);


$logger->info('Adding a new user', array('username' => 'Seldaek'));

Attaching the same context every time could become very inefficient. To avoid it, you can create a preprocessor that will automatically attach context for you. See the following code to attach the username:

$log->pushProcessor(function ($record) {

    // record the current user from the $_SESSION
    $user = SessionHandler::getCurrentUser();
    $record['context']['user'] = array(
        'name' => $user->getName(),
        'username' => $user->getUsername(),
        'email' => $user->getEmail(),
    );

    // Add various tags
    $record['context']['tags'] = array('key' => 'value');

    // Add various generic context
    $record['extra']['key'] = 'value';

    return $record;
});

And here we are: you’re definitely ready to understand and improve what’s going on in your PHP app!

3) Gathering PHP logs into a single platform

Assuming that you have tuned up your PHP logs, set up a collector for server metrics and written slow databases queries for each website and application you are in charge of, you are now in possession of a dozen, even hundreds sources of logs.

Gathering all these PHP logs into a single log management tool is a necessity.

My experience tells me that one of the best agents to send your logs to a single place is Rsyslog (NxLog for Windows). The simple reason being that Rsyslog is using many kernel features to be extremely performant. Plus, Rsyslog has some native buffering mechanisms, and backoff retries in order to be sure that your logs, files and events are shipped to the right place.

4) Analyzing your PHP logs

Let’s finish by you giving me one chance to convince you to take a peek Logmatic.io.

frank house of cards

More seriously, having your logs in a proper log analytics platform – navigating them properly – will greatly help your day to day work. Many services are available. Obviously, I joined Logmatic.io because I believe that having real-time log data with super analytics is incredibly powerful. But it’s your choice to make!

Related Posts