Symfony: Logging a request's origin IP

The Symfony framework provides an incredible amount of debug information in its application log file. In its development environment, Symfony will write a whole host of information into the app/logs/dev.log file on every request. Using the default logging setup, a line from this log looks something like this:

1[2015-03-15 20:41:29] request.INFO: Matched route "homepage" (parameters: "_controller": "AppBundle\Controller\DefaultController::indexAction", "_route": "homepage") [] {}

We have the time the line was generated, the log level, the log message itself, and space for some 'extra' info. What we don't have is the IP address of the client making the request, and this is something that is really useful to include in your application logs.

At first, it might seem that Monolog provides a built-in solution for this through its WebProcessor which, 'adds the current request URI, request method and client IP to a log record'. Sounds like exactly what we need!

Setting up the WebProcessor

Using the built-in Monolog processors with Symfony is relatively straightforward. We just need to create a service for the processor, and tag it with the monolog.processor tag.

To do this, add something like the below to the services section of your app/config/services.yml file:

1services:
2  monolog.processor.web:
3    class: Monolog\Processor\WebProcessor
4    tags:
5      - { name: monolog.processor }

If we now repeat our request from earlier, we'll see a line like this in our dev.log:

1[2015-03-15 20:58:04] request.INFO: Matched route "homepage" (parameters: "_controller": "AppBundle\Controller\DefaultController::indexAction", "_route": "homepage") [] {"url":"/app/example","ip":"10.0.2.2","http_method":"GET","server":"localhost","referrer":null}

We now have a set of extra info about the request, including the IP address! Yay! But it's all just bunged onto the end of the line in the extra array, and we don't really want the rest of this information! Boo!

Lets integrate the IP a little better into the log line.

Adding a log formatter

To include items from the log record's extra array in the main section of our log lines, we need to configure a Formatter and then apply it to our log handler.

First, add this formatter configuration - again in app/config/services.yaml - it can go directly under the service config we already added for the processor:

1monolog.formatter.standard:
2  class: Monolog\Formatter\LineFormatter
3  arguments:
4    format: "%%datetime%% | %%extra.ip%% | %%channel%%.%%level_name%%: %%message%% %%context%%\n"

The format line here defines what we want our log lines to include; we've added the extra.ip field (and we could just as well have added any of the other keys from the extra list: url, ip, http_method, server or referrer) and also added a | separator between fields, for easier log parsing with awk or similar.

Now, we need to tell our log handler to use the new formatter. To do this, find the monolog section in app/config/config_dev.yml (and config_prod.yml, if you like) and add the last line shown below.

1monolog:
2  handlers:
3    main:
4      type: stream
5      path: "%kernel.logs_dir%/%kernel.environment%.log"
6      level: debug
7      formatter: monolog.formatter.standard

With these two changes in place, our log lines now look like this:

12015-03-15 21:08:38 | 10.0.2.2 | request.INFO: Matched route "homepage" (parameters: "_controller": "AppBundle\Controller\DefaultController::indexAction", "_route": "homepage") []

This is starting to look pretty good! We have the IP address included as part of the log line proper, and we've dumped the extraneous information we had earlier.

There's just one problem: our Symfony app is behind a reverse proxy (think CloudFlare or similar) and the proxy's IP address is 10.0.2.2. We're not logging the client's IP, we're logging our proxy's IP! Needless to say, this is less than ideal.

Getting the real client IP address

Thankfully our reverse proxy is well-behaved, and adds the IP address of the client who really made the request to our app to the X-Forwarded-For HTTP header. We're just going to need to write a log record processor of our own to extract this information from the request and add it to our log records.

This should probably look something like the class shown here (obviously the namespace and such will need adjusting to suit your project):

1<?php
2// src/AppBundle/Log/ClientIpProcessor
3namespace AppBundle\Log;
4
5use Symfony\Component\HttpFoundation\RequestStack;
6
7class ClientIpProcessor
8{
9    private $requestStack;
10    private $cachedClientIp = null;
11
12    public function __construct(RequestStack $requestStack)
13    {
14        $this->requestStack = $requestStack;
15    }
16
17    public function __invoke(array $record)
18    {
19        // request_ip will hold our proxy server's IP
20        $record['extra']['request_ip'] = isset($_SERVER['REMOTE_ADDR'])
21            ? $_SERVER['REMOTE_ADDR']
22            : 'unavailable';
23        // client_ip will hold the request's actual origin address
24        $record['extra']['client_ip'] = $this->cachedClientIp
25            ? $this->cachedClientIp
26            : 'unavailable';
27
28        // Return if we already know client's IP
29        if ($record['extra']['client_ip'] !== 'unavailable') {
30            return $record;
31        }
32
33        // Ensure we have a request (maybe we're in a console command)
34        if (! $request = $this->requestStack->getCurrentRequest()) {
35            return $record;
36        }
37
38        // If we do, get the client's IP, and cache it for later.
39        $this->cachedClientIp = $request->getClientIp();
40        $record['extra']['client_ip'] = $this->cachedClientIp;
41
42        return $record;
43    }
44}

And with the class in place, we should create a service for it, so Symfony knows to use it as a Monolog processor. The config below should replace our earlier monolog.processor.web service in app/config/services.yml:

1monolog.processor.client_ip:
2    class: AppBundle\Log\ClientIpProcessor
3    arguments: [ @request_stack ]
4    tags:
5        - { name: monolog.processor }

And since our processor uses new extra array fields to hold the proxy server and client IP addresses, we need to update our log formatter config to look like this:

1monolog.formatter.standard:
2  class: Monolog\Formatter\LineFormatter
3  arguments:
4    format: "%%datetime%% | %%extra.request_ip%% | %%extra.client_ip%% | %%channel%%.%%level_name%%: %%message%% %%context%%\n"

If we haven't already, we also need to tell Symfony to trust our reverse proxy. This is done in the framework section of app/config/config.yml:

1framework:
2  # Set your proxy's IP address(es) here
3  trusted_proxies: 10.0.2.2

Phew! With all of the above in place, lets make another request to our app:

12015-03-15 21:33:57 | 10.0.2.2 | 5.10.144.10 | request.INFO: Matched route "homepage" (parameters: "_controller": "AppBundle\Controller\DefaultController::indexAction", "_route": "homepage") []

We now have everything we want - we've got the proxy's IP address (10.0.2.2) and the IP address of the client who sent the original request (5.10.144.10).

This post has really only scratched the surface of what is possible with the combination of Symfony and Monolog, but I hope it provides some inspiration for the kinds of possibilities they offer.