Using Correlation IDs in API Calls

Over the years, the IT industry has moved from a single domain, monolithic architecture to a microservice architecture. In a microservice architecture, complex processes are split into smaller and simpler sub-processes. While this kind of architecture has many benefits, there are also some downsides – for example, if you send one request to a Leaseweb API, it ends up in multiple requests in other backend systems [FIGURE 1]. How do you keep track of requests and responses processed by multiple systems? This is where Correlation IDs come into play.

[FIGURE 1: Example request/response flow]

Using a Correlation ID

A Correlation ID is a unique, randomly generated identifier value that is added to every request and response. In a microservice architecture, the initial Correlation ID is passed to your sub-processes. If a sub-system also makes sub-requests, it will also pass the Correlation ID to those systems.

How you pass the Correlation ID to other systems depends on your architecture. At Leaseweb we are using REST APIs a lot, with HTTP headers to pass on the Correlation ID. As a rule, we assign a Correlation ID as soon as possible, and always use a Correlation ID if it is passed on. Our public API only accepts Correlation IDs from internally trusted clients. For any other client (such as an employee or customer API clients) a new Correlation ID is generated for the request.

Real Value of Correlation IDs

The real value of Correlation IDs is realized when you also log the Correlation IDs. Debugging or tracing requests becomes much easier, as you can search all of your logs for the same Correlation ID. Combined with central logging solutions (such as the ELK stack), searching logs becomes even easier and can be done by non-technical colleagues. Providing tools to your colleagues to troubleshoot issues allows them to have more responsibility and gives you more time to work on more technical projects.

We mainly use Correlation IDs at Leaseweb for debugging purposes. When an error occurs, we provide the Correlation ID to the client/customer. If users provide the Correlation ID when submitting a support ticket, we can visualize the entire process needed to fulfil the client’s initial intent. This has significantly improved the time it takes us to fix bugs.

[FIGURE 2: Example of one Correlation ID with multiple requests]

Debugging issues is a time-consuming process if Correlation IDs are not used. When your environment scales, you will need to find solutions to group transactions happening in your systems. By using a Correlation ID, you can easily group requests and events in your systems, allowing you to spend more time fixing the problem and less time trying to find it.

Practical examples on how to implement Correlation IDs

The following examples use Symfony, a popular web application framework. These concepts can also be applied to any other framework, such as Laravel, Django, Flask or Ruby on Rails.

If you are unfamiliar with the concept of Service Containers and Dependency Injection, we recommend reading the excellent Symfony documentation about it here: https://symfony.com/doc/current/service_container.html

Using Monolog to append Correlation IDs to your application logs

When processing a HTTP request your application often logs some information – such as when an error occurred, or an important change made in your system that you want to keep track of. When using the Monolog logging library in PHP (https://seldaek.github.io/monolog/), you can use the concept of “Processors” (read more about that here on symfony.com).

One way to do this is by creating a Monolog Processor class:

<?php

namespace App\Monolog\Processor;

use Symfony\Component\HttpFoundation\RequestStack;

class CorrelationIdProcessor
{
    protected $requestStack;

    public function __construct(RequestStack $requestStack)
    { 

       $this->requestStack = $requestStack;

    }
 
    public function processRecord(array $record)
    {
        $request = $this->requestStack->getCurrentRequest();

        if (!$request) {
            return;
        }

        $correlationId = $request->headers->get(‘X-My-Correlation-ID');

        if (empty($correlationId)) {
             return;
        }

        // If we have a correlation id include it in every monolog line
        $record['extra']['correlation_id'] = $correlationId;
 
        return $record;
    }
}

Then register this class on the service container as a monolog processor in services.yml:

# app/config/services.yml

services:
  App\Monolog\Processor\CorrelationIdProcessor:
    arguments: ["@request_stack"]
    tags:
      - name: monolog.processor
        method: processRecord

Now, every time you log something in your application with Monolog:

$this->logger->info('shopping_cart_emptied', [‘cart_id’ => 123]);

You will see the Correlation ID of the HTTP Request in your log files:

$ grep ‘shopping_cart_emptied’ var/logs/prod.log

[2020-07-03 12:14:45] app.INFO: shopping_cart_emptied {“cart_id”: 123} {"correlation_id":"d135d5f1-3dd0-45fa-8f26-55d8d6a44876"}

You can utilize the same pattern to log the name of the user that is currently logged in, the remote IP address of the API client, or anything else that makes troubleshooting faster for you.

Using Guzzle to append Correlation IDs when making sub-requests

If your API makes API calls to other microservices (and you use Guzzle to do this) you can make use of Handlers and Middleware.

Some teams at Leaseweb depend on many downstream microservices, and can therefore have multiple guzzle clients as services on the service container. While each Guzzle client is configured with its own base URL and/or authentication, it is possible for all of the Guzzle clients to share the same HandlerStack.

First, create the middleware:

<?php

namespace App\Guzzle\Middleware;

use Symfony\Component\HttpFoundation\RequestStack;
use Psr\Http\Message\RequestInterface;

class CorrelationIdMiddleware
{
    protected $requestStack;
 
    public function __construct(RequestStack $requestStack)
    {
        $this->requestStack = $requestStack;
    }

    public function __invoke(callable $handler)
    {
        return function (RequestInterface $request, array $options = []) use ($handler) {
            $request = $this->requestStack->getCurrentRequest();

            if (!$request) {
                return $handler($request, $options);
            }

            $correlationId = $request->headers->get(‘X-My-Correlation-ID');

            if (empty($correlationId)) {
                 return $handler($request, $options);
            } 
 
            $request = $request->withHeader(‘X-My-Correlation-ID’, $correlationId);
 
            return $handler($request, $options);
        };
    }
}

Define this middleware as service on the service container and create a HandlerStack:

# app/config/services.yml

services:
  correlation_id_middleware:
    class: App\Guzzle\Middleware:
    arguments: ["@request_stack"]

  correlation_id_handler_stack:
    class: GuzzleHttp\HandlerStack
    factory: ['GuzzleHttp\HandlerStack', 'create']
    calls:
      - [push, ["@correlation_id_middleware", "correlation_id_forwarder"]]

With these two services defined, you can now configure all your Guzzle clients using the HandlerStack so that the Correlation ID of the current HTTP request is forwarded to downstream HTTP requests:

# app/config/services.yml

services:
  my_downstream_api:
    class:
    arguments:
      - base_uri: https://my-downstream-api.example.com
        handler: "@correlation_id_handler_stack”

Now every API call that you make to https://my-downstream-api.example.com will include the HTTP request header ‘X-My-Correlation-ID’ and have the same value as the Correlation ID of the current HTTP request. You can also apply the same Monolog and Guzzle tricks described here to the downstream API.

Expose Correlation IDs in error responses

The missing link between these processes is to now expose your Correlation IDs to your users so they can also log them or use them in support cases they report to your organization.

Symfony makes this easy using Event Listeners. You can define Event Listeners in Symfony to pre-process HTTP requests as well as to post-process HTTP Responses just before they are returned by Symfony to the API caller. In this example, we will create a HTTP Response listener and add the Correlation ID of the current HTTP request as a HTTP Header in the HTTP Response.

First, we create a service on the Service Container:

<?php
 
namespace App\Listener;
 
use Symfony\Component\HttpFoundation\RequestStack;
use Symfony\Component\HttpKernel\Event\FilterResponseEvent;

class CorrelationIdResponseListener
{
    protected $requestStack;
 
    public function __construct(RequestStack $requestStack)
    {
        $this->requestStack = $requestStack;
    }

    public function onKernelResponse(FilterResponseEvent $event)
    {
        $request = $this->requestStack->getCurrentRequest();

        if (!$request) {
            return;
        }

        $correlationId = $request->headers->get(‘X-My-Correlation-ID');

        if (empty($correlationId)) {
             return;
        }

        $event->getResponse()->headers->set(‘X-My-Correlation-ID’, $correlationId);
    }
}

Now configure it as a Symfony Event Listener:

# app/config/services.yml

services:
  correlation_id_response_listener:
    class: App\Listener\CorrelationIdResponseListener
    arguments: ["@request_stack"]
    tags:
      - { name: kernel.event_listener, event: kernel.response, method: onKernelResponse }

Every response that is generated by your Symfony application will now include a X-My-Correlation-ID HTTP response header with the same Correlation ID as the HTTP request.

The Value of Correlation IDs

Using Correlation IDs throughout your whole stack gives you more insight into all (sub)requests during a transaction. Using the right tools allows others to debug issues, giving your developers more time to work on new awesome features.

Implementing Correlation IDs isn’t hard to do, and can be achieved quickly depending on your software stack. At Leaseweb, the use of Correlation IDs has saved us hours of time while debugging issues on numerous occasions.

Technical Careers at Leaseweb

We are searching for the next generation of engineers and developers to help us build infrastructure to automate our global hosting services! If you are interested in finding out more, check out our Careers at Leaseweb.

Share

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