A High-Performance Logger with PHP

Recently, at Leaseweb, another successful Hackathon came to an end. There was a lot of fun, a lot of coding, a lot of coffee and a lot of cool ideas that arose during these 2 days. In this blog post we want to share one of these ideas that made us proud and that was really fun to work on.

1. The motivation

As Leaseweb, we strive to know our customers better so that we can actively empower them. For that, we need to start logging events that have value for the business. So basically we want to implement a simple technical service (let’s call it a ‘Logging Service’) that accepts any kind of event with some rich data (in other words a payload), and then logs it, without interfering with the execution of the client.

Our Logging service would, on each request, return an ”OK” so that the client can continue with its own execution but still keep on logging events asynchronously.

2. Our tech stack and our tech choice for POC

Typically at Leaseweb, we have a pretty standardized technology stack that revolves around PHP+Apache or PHP+Nginx. If a server or an application is built using this kind of stack, we are bound to typical synchronous execution. This client sends a request to our application (in this case our Logging Service) and the client needs to wait until our application sends back a response after it finishes all the tasks. This is not an ideal scenario. We need a service that runs asynchronously, a service that receives the request, says ”OK” so that the client can continue with his execution, and then does its job.

In the market, there are several tools that would enable us to do this such as languages and tools like NodeJs, Golang or even some message queuing services that could be wired into our PHP stack. But as we are PHP enthusiasts at Leaseweb, we want to use our language of choice without adding dependencies. That is how we discovered ReactPHP (no relation to the front-end framework React). ReactPHP is a pure PHP library that allows the developer to do some cool reactive programming in PHP by running the code on an endless event loop :).

3. Implementation of the POC

With some ReactPHP libraries, we can handle HTTP requests in PHP itself. We no longer need a web server that handles the requests and creates PHP processes for us. We can just create a pure PHP process that handles everything for us and if we want to fully use the hardware power from our machine, we can create several PHP processes and put them behind a load balancer.

After choosing our technology we started playing around and implementing our idea. In order to make sure that asynchronous PHP would solve the majority of our concerns, we started benchmarking.

First we needed to script something to benchmark. Therefore we implemented 3 different scenarios:

  1. The all-time-favorite: An endpoint that prints Hello World.
  2. An API endpoint that calls a 3rd party API that takes 2 seconds to reply and proxies its response.
  3. An API-endpoint that accepts a payload with POST and logs it via HTTP to Elasticsearch (This is what we really want).

We implemented these 3 scenarios in two different stacks:

  • Stack A
    Traditional PHP+FPM+Nginx
  • Stack X
    4 PHP processes running on a loop with ReactPHP behind an Nginx load-balancer. The reason why we chose 4 processes was solely because this number looks good :). There are some theories in which suggestions are made regarding the number of processes that should run on a machine when using this approach. We will not go into further detail on this in this article. Note that in both Stack A and Stack X we used the exact same specs for the hardware server. On both, we had a CPU with 8 cores.

Then we ran some stress tests with Locust:

3.1 1st Benchmark – Hello world!

For the first benchmark, we just wanted to see how the implementation of the Scenario 1 would behave in both of our stacks.

Hello World with Stack X
Figure 1: Hello World with Stack X
Hello World with Stack A
Figure 2: Hello World with Stack A

We can see that both of the stacks perform very similar. The reason for this is that the computation needed to print a ”Hello World!” is minimal, therefore both of our stacks can answer a high amount of requests in a reliable way.

The real power of asynchronous code comes when we need to deal with Input/Output (I/O (reading from a DB, API, Filesystem, etc) because these operations are time-consuming (see [zhuk:2026:event-driven-with-php]). I/O is slow and CPU computation is fast. By going with an asynchronous approach, our program can execute other computations while waiting for I/O.

It is time to try this theory with the next benchmark:

3.2 2nd Benchmark – Response from a 3rd-party API

Following what we described in the previous section, the power of asynchronous code comes when we deal with input and output. So we were curious to find out how the APIs would behave if they need to call a 3rd party API that takes 2 seconds to respond and then it forwards its response.

Let’s run the tests:

Response from a 3rd-party API with Stack X
Figure 3: Response from a 3rd-party API with Stack X
Response from a 3rd-party API with Stack A
Figure 4: Response from a 3rd-party API with Stack A

With the benchmarks illustrated in figure 3 and 4, it’s encouraging to see we already have very interesting results. We ran a stress test where we gradually spawn 100 concurrent users that send a request per second, and we can easily see that the more the concurrent users grow, the less responsive Stack A becomes. Stack A is achieving an average response time of 40 seconds, while Stack X maintains an average response time of 2 seconds (which is the time that the 3rd-party API takes to respond).

With Stack A, each request made creates a process that will stay idle until the 3rd-party API responds. The implication is that, at some point in time, we will have hundreds of idle processes waiting for a reply. This will cause an immense overload on our machine’s resources.

Stack X performs exceedingly well. This is because the same processes that wait for the reply from the 3rd-party API will continue doing other work during their execution, for example, handling other HTTP requests and incoming responses from the 3rd-party API. With this, we can achieve much more efficiency in our stack.

After observing these results we wanted to push it a bit harder – we wanted to see whether we could break Stack A entirely. So we decided to run the same stress test for this scenario but this time with 1000 concurrent users.

Response from a 3rd-party API with Stack X with 1000 users
Figure 5: Response from a 3rd-party API with Stack X with 1000 users
Response from a 3rd-party API with Stack A with 1000 users
Figure 6: Response from a 3rd-party API with Stack A with 1000 users

We did it! We can see that at some point Stack A is unable to handle the requests anymore so it stops responding completely after reaching an average response time of 60 seconds. Stack X remains perfectly smooth with an average response time of 2 seconds :).

3.3 3rd Benchmark

It was indeed fun trying to see how the stacks behave with the previous scenarios but we want to see how it behaves in a real-world scenario. Next, we wanted our API to accept a JSON payload via an HTTP post and log it to an Elasticsearch cluster via HTTP to keep it simple (Scenario 3).

How the stacks work in a nutshell:

  • Stack X receives an HTTP Post request with the payload, sends a response to the client saying OK and then logs it to Elasticsearch (asynchronously).
  • Stack A receives an HTTP Post request with the payload, logs it to Elasticsearch and sends a response to the client saying OK.

Let’s bombard it with Locust again and why not with 1000 of concurrent connections right away:

Logging payloads with Stack X
Figure 7: Logging payloads with Stack X
Logging payloads with Stack A
Figure 8: Logging payloads with Stack A

We can see that we can achieve a pretty reliable and high-performance logger. And this only with pure PHP code!!

Because our intention was always to push the limits, we chose this benchmark with 1000 concurrent users being spawned gradually. Stack A at some point stops handling the requests, while the Stack X always keeps a pretty good response time, around 10ms.

4. What can we use it for now?

With this experiment, we pretty much built a central logging service!! Coming back to our main motivation, we can use this to log whatever we want, and we want to start logging meaningful domain events, from any application within our system with a simple non-blocking HTTP Request. For example, if we start logging meaningful events, we can get to know our customers better. If we log all of this into Elasticsearch we can also start making cool graphs from it. For example:

Graph with Business Events
Figure 9: Graph with Business Events

OR

Graph with End-user Actions
Figure 10: Graph with End-user Actions

Since this approach is so highly responsive, we can even start using it to log anything and maybe everything, where our logging exists in a central endpoint. System monitoring, near-real-time-analytics, domain events, trends, etc, etc. And all of this with pure PHP :).

5. Cons of the approach and future work

When using ReactPHP there are some important considerations, which in some scenarios can be seen as cons, that usually they are not applicable to projects that follow an architecture similar to Stack A.

  • ReactPHP uses reactive/event-driven programming which is a paradigm that might have a big learning curve.
  • Long-running PHP processes can lead to memory leak and in case of failures, they could affect all the current connections to the server
  • These processes need to be constantly carefully monitored in order to avoid and predict fatal failures.
  • The usage of blocking functions (functions that block the execution of the code) will massively affect the performance for all the connections to the server.

Also, some extra work on the ”Operational / Infra side” is needed to make sure that we continuously check on the process’ health and if something goes wrong, create new ones automatically. We also need to work on the way we deploy the code. We need to make sure that we restart a process sequentially when deploying new code so that our service can finish serving the requests that it has queued at that time.

6. Conclusion

Pushing the limits of our preferred technology is one of the most fun things to do. PHP is not a usual choice if there is the need for an high-performing application, but thanks to a lot of great work of the community around, solutions like ReactPHP starts to emerge. That opens a new path to discover new programming paradigms, it introduces different mind-sets on how to approach a problem and it challenges the knowledge we have regarding the technology.

Challenging what we already know, is one of the most interesting things that we can do because it takes us out of our comfort zone and helps us to become more mature. It is really fun and it makes us realise that we can never know everything.

We would like to thank and acknowledge everybody in the communities around the tools we used in this fun experiment 🙂

Some useful links:

by Joao Castro and Elrich Faul

Share

GoAccess is a top for Nginx or Apache

goaccess-dashboard

GoAccess is an open source real-time web log analyser and interactive viewer that runs in a terminal on Linux systems. The name suggest that is written in the Go language, but it actually is not (it is written in C).

Monitoring

Effectively it is like the “top” command, but instead of showing processes it is giving you insight in the traffic on your webserver. The tool provides all kinds of top lists useful for spotting irregularities. Great features include the listing of IP addresses by percentage of hits and showing the status codes of the served responses. Typically you would use this tool if your webserver is reporting high load or high bandwidth usage and you want to find out what is going on. The outcomes of the analysis with this tool can then be used to adjust your firewall or caching rules.

Installing

On my Ubuntu 15.04 I can install version 0.8.3 with:

sudo apt-get install goaccess

If you are on any Debian based Linux and you want to run the latest (0.9.2) version you can simply run:

wget http://tar.goaccess.io/goaccess-0.9.2.tar.gz
tar -xvzf goaccess-0.9.2.tar.gz
cd goaccess-0.9.2/
sudo apt-get install build-essential
sudo apt-get install libglib2.0-dev
sudo apt-get install libgeoip-dev
sudo apt-get install libncursesw5-dev
./configure --enable-geoip --enable-utf8
make
sudo make install

This will install the software in “/usr/local/bin/” and the manual in “/usr/local/man/”.

Running

Running the software is as easy as:

man goaccess
goaccess -f /var/log/apache2/access.log

The software will prompt you the log format. For me the “NCSA Combined Log Format” log format worked best. For nginx I just ran:

goaccess -f /var/log/nginx/access.log

It is really awesome, try it!

Share

Heka monolog decoder

This post is about how to use heka to give your symfony 2 application logs the care they deserve.

Application logs are very important for the quality of the product or service you are offering.

They help you find out what went wrong so you can explain and fix a bug that was reported recently. Or maybe to gather statistics to see how often a certain feature is used. For example how many bare metal reinstallation requests were issued last month and how many of those failed. Valuable information that you could use to decide what feature you are going to work on next.

At LeaseWeb we use quite a lot of php and Seldaek’s monolog is our logging library of choice. Recently we open sourced a heka decoder on github here. For you who do not know heka yet, check out their documentation.

Heka is an open source stream processing software system developed by Mozilla. Heka is a “Swiss Army Knife” type tool for data processing, useful for a wide variety of different tasks, such as …

Heka runs as a system daemon just like logstash or fluentd. Heka is written in go and comes with an easy to use plugin system based on lua. It has almost no dependencies and is lightweight. James Turnbull has written a nice article on how to get started with heka.

send symfony 2 application logs to elastic search

How better to explain with an example.

Lets say you have a symfony 2 application and you want the application logs to be sent to an Elastic Search platform.

On a debian based os you can download one of the heka debian packages from github.

    $ wget https://github.com/mozilla-services/heka/releases/download/v0.9.2/heka_0.9.2_i386.deb
    $ sudo dpkg -i heka_0.9.2_i386.deb

To configure heka you are required to edit the configuration file located at /etc/hekad.toml.

    $ vim /etc/hekad.toml

Take your time to read the excellent documentation on heka. There are many ways of using heka but we will use it as a forwarder:

  1. Define an input, where messages come from.
  2. Tell heka how it should decode the monolog log line into a heka message
  3. Tell heka how to encode the message so Elastic Search will understand it
  4. Define an output, where should the messages be sent to.

First we define the input:

    [Symfony2MonologFileInput]
    type = "LogstreamerInput"
    log_directory = "/var/www/app/logs"
    file_match = 'prod\.log'
    decoder = "Symfony2MonologDecoder"

Adjust `log_directory` and `file_match` according to your setup. As you can see we alread told heka to use the `Symfony2MonologDecoder` to we will define that one next:

    [Symfony2MonologDecoder]
    type = "SandboxDecoder"
    filename = "/etc/symfony2_decoder.lua"

Change the `filename` with the path where you placed the lua script on your system.

Now we have defined the input we can tell heka where to output messages to:

    [ESJsonEncoder]
    index = "%{Hostname}"
    es_index_from_timestamp = true
    type_name = "%{Type}"

    [ElasticSearchOutput]
    message_matcher = "TRUE"
    server = "http://192.168.100.1:9200"
    flush_interval = 5000
    flush_count = 10
    encoder = "ESJsonEncoder"

In the above example we assume that your Elastic Search server is running at 192.168.100.1.

And thats it.

A simple log line in app/logs/prod.log:

    [2015-06-03 22:08:02] app.INFO: Dit is een test {"bareMetalId":123,"os":"centos"} {"token":"556f5ea25f6af"}

Is now sent to Elastic Search. You should now be able to query your Elastic Search for log messages, assuming the hostname of your server running symfony 2 is myapi:

    $ curl http://192.168.100.1:9200/myapi/_search | python -mjson.tool
    {
        "_shards": {
            "failed": 0,
            "successful": 5,
            "total": 5
        },
        "hits": {
            "hits": [
                {
                    "_id": "ZIV7ryZrQRmXDiB6thY_yQ",
                    "_index": "myapi",
                    "_score": 1.0,
                    "_source": {
                        "EnvVersion": "",
                        "Hostname": "myapi",
                        "Logger": "Symfony2MonologFileInput",
                        "Payload": "Dit is een test",
                        "Pid": 0,
                        "Severity": 7,
                        "Timestamp": "2015-06-03T20:08:02.000Z",
                        "Type": "logfile",
                        "Uuid": "344e7cae-6ab7-4fb2-a770-d2cbad6653c3",
                        "channel": "app",
                        "levelname": "INFO",
                        "bareMetalId": 123,
                        "os": "centos",
                        "token": "556f5ea25f6af"
                    },
                    "_type": "logfile"
                },
        // ...
        }
    }

What is important to notice is that the keys token, bareMetalId and os in the monolog log line end up in Elastic Search as an indexable fields. From your php code you can add this extra information to your monolog messages by supplying an associative array as a second argument to the default monolog log functions:

    <?php

    $logger = $this->logger;
    $logger->info('The server was reinstalled', array('bareMetalId' => 123, 'os' => 'centos'));

Happy logging!

Share

CakePHP flash error message logging

When your CakePHP application cannot handle a submitted form it shows a flash error message (normally a red bar) and some fields in red (validation errors). By default, CakePHP log exceptions and fatal errors to “app/tmp/logs/error.log”. Unfortunately flash error messages and validation errors are not logged by default. This can be explained since the errors are actually handled and can thus be considered “user errors” and not “application errors”. But when a customer needs assistance, you actually need both types of error logs. Note that the Apache access log will also log these requests, but normally this does not provide enough information. In this post we will show how you can add flash error message logging to your CakePHP application.

First we will show that normal error logging is pretty useful. For example, when you call the PHP function “nltobr()” while this function is actually called “nl2br()” it will be logged as expected:

$ cat app/tmp/logs/error.log
2013-06-09 21:54:44 Error: [FatalErrorException] Call to undefined function nltobr()

For flash error message logging we have created a data structure and a CakePHP component that allows you to make a nice overview like this:

runtime_list

Figure 1: List with all pages served with flash error messages

And when you actually view the details of the flash error message you see the following screen:
runtime
Figure 2: Detail page for the table, showing a flash error message

You can clearly see that somebody was trying to edit user 1. The error message was not very descriptive, while the validation errors were pretty clear about the missing data (password).

Instructions

The data structure used is a MySQL database table that can be created by executing the following SQL:

CREATE TABLE `runtime_errors` (
 `id` int(11) NOT NULL AUTO_INCREMENT,
 `created` datetime NOT NULL,
 `ip_address` varchar(255) NOT NULL,
 `method` varchar(255) NOT NULL,
 `url` varchar(255) NOT NULL,
 `referer` varchar(255) NOT NULL,
 `redirect_url` varchar(255) NOT NULL,
 `data` text NOT NULL,
 `validation_errors` text NOT NULL,
 `flash_message` text NOT NULL,
 `user_id` int(11) DEFAULT NULL,
 PRIMARY KEY (`id`),
 KEY `user_id` (`user_id`),
 KEY `created` (`created`),
 CONSTRAINT `runtime_errors_ibfk_1` FOREIGN KEY (`user_id`) REFERENCES `users` (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

Now create the following model and save it to “app/Model/RuntimeError.php”:

<?php
App::uses('AppModel', 'Model/App');

class RuntimeError extends AppModel {
  public $displayField = 'url';
  public $belongsTo = array('User');
}

Add the following component code to “app/Controller/Component/ErrorLoggerComponent.php” to log the flash messages:

<?php
App::uses('Component','Controller');

class ErrorLoggerComponent extends Component
{
  public function beforeRedirect(&$controller, $url, $status, $exit) {
    $this->log($controller,$url);
    return parent::beforeRedirect($controller, $url, $status, $exit);
  }

  public function beforeRender(&$controller) {
    $this->log($controller);
    parent::beforeRender($controller);
  }

  public function log(&$controller,$redirectUrl=false) {
    $session = $controller->Session->read();
    $flash = isset($session['Message']['flash'])?$session['Message']['flash']:false;
    $success = isset($flash['params']['class'])?$flash['params']['class']=='success':false;
    if ($flash && $success==false) {
      $controller->User->RuntimeError->create();
      $data = array('RuntimeError'=>array());
      $data['RuntimeError']['method'] = $controller->request->method();
      $data['RuntimeError']['url'] = $controller->request->here;
      $data['RuntimeError']['referer'] = $controller->request->referer();
      $data['RuntimeError']['redirect_url'] = $redirectUrl?Router::url($redirectUrl):'';
      $data['RuntimeError']['data'] = Spyc::YAMLDump($controller->params->data,2,80);
      $data['RuntimeError']['validation_errors'] = Spyc::YAMLDump($this->getErrors(),2,80);
      $data['RuntimeError']['flash_message'] = Spyc::YAMLDump($flash,2,80);
      $data['RuntimeError']['user_id'] = $controller->Auth->user('id');
      $data['RuntimeError']['ip_address'] = $controller->request->clientIp(true);
      if (!$controller->User->RuntimeError->save($data)) {
        throw new InternalErrorException('Could not log action');
      }
    }
  }

  private function getErrors()
  { $validationErrors = array();
    $models = ClassRegistry::keys();
    foreach ($models as $currentModel) {
      $currentObject = ClassRegistry::getObject($currentModel);
      if (is_a($currentObject, 'Model')) {
        if ($currentObject->validationErrors) {
          $validationErrors[$currentObject->alias] =& $currentObject->validationErrors;
        }
      }
    }
    return $validationErrors;
  }
}

Note that you may want to fine-tune the business logic that decides which messages to log (only errors), because the above code will log all flash messages without exception. To load the above component you have to add the “ErrorLogger” to the “$components” array in “app/Controller/AppController.php”:

 public $components = array(
   ...
   'ErrorLogger'=>array()
 );

Dependencies

For writing YAML output from CakePHP we have added “Spyc” to composer.json, which makes our full composer.json file look like this:

{
  "minimum-stability": "dev",
  "config": {
    "vendor-dir": "vendors"
  },
  "repositories" : [
    {
      "type": "package",
      "package": {
        "name" : "cakephp/cakephp",
        "version" : "2.3.5",
        "source" : {
          "type" : "git",
          "url" : "git://github.com/cakephp/cakephp.git",
          "reference" : "2.3.5"
        },
        "bin" : ["lib/Cake/Console/cake"]
      }
    }
  ],
  "extra": {
    "installer-paths": {
      "app/Plugin/DebugKit": ["cakephp/debug_kit"]
    }
  },
  "require" : {
    "php": ">=5.2",
    "cakephp/cakephp" : "2.3.5",
    "cakephp/debug_kit": "2.2.*",
    "mustangostang/spyc": "0.5.*"
  }
}

To achieve the nice looking index and view pages from Figure 1 and 2 you will have to “bake” some views and controllers. Good luck!

Share

Turn off reverse DNS lookups for Apache access logging

If reverse DNS lookups are shown in your Apache access log, while you were expecting (and needing) IP addresses, this post may help.

htaccess ip address block
Figure 1: Example “.htaccess” file for blocking IP addresses

By default IP addresses are logged in the Apache access log “/var/log/apache2/access.log” unless you specify “HostnameLookups On” in “/etc/apache2/apache2.conf” (it is off by default). But if you are restricting access to specific content using an “.htaccess” file with an “allow from” or “deny from” construction this changes. If you have this in your “.htaccess” file IP addresses are logged:


deny from 14.23.32.41

But if you add a comment to the line like this reverse DNS lookups are logged:


deny from 14.23.32.41 # my home ip address

Cause and work-around

This is caused by “mod_authz_host” (which is enabled by default) that kicks in and converts the IP addresses to hostnames. The work-around is to put the comment on the previous line:


# my home ip address:
deny from 14.23.32.41

It also happens when you use a regular expression or a host name (which is more obvious). Plain IP addresses and CIDR notation do not trigger the conversion. Hopefully this post can save you some time.

Share