Most modern web applications aren't giant monoliths any more. While monoliths are useful for keeping ancient developers (who normally refer to themselves as "gurus") employed, they can be painful to simply maintain, let alone adding new features in any timeframe smaller than an archaeological period.

As such, developers have taken to breaking their code apart into smaller, more manageable, testable, reusable, and interesting chunks. While you may be not creating a full microservices platform, you quite often see a central platform with some minor services associated with it.

The downsides of this are instead of having only one application to worry about with one logging system and no concerns about internal requests, you now to need to be passing information between your services using a client, and hoping you're getting back valid responses within a timely manner.

Guzzle, the PHP HTTP client, is pretty awesome at helping with this. It makes communication between your application and APIs easy to implement. There are times though, just maybe the odd one or two, where Guzzle doesn't do everything you ever need it to out of the box. I know, this seems like an overly harsh statement but it's true.

What Guzzle has, apart from a massive user base, is a nice, simple-ish, middleware solution that allows you to add a chain of methods both before your request and after the response.

This blog's going to look at how we can use this middleware layer to add extra logging around these requests and responses, and then how we can utilise our new app_debug.php to output these to the frontend.

Log all the things

To begin with then, we're going to create a simple, concrete class based on PSR3's LoggerInterface and our own interface that will allow us to retrieve logs after we've stored them.

namespace Dittto\RequestLoggerBundle\Logger;
use Psr\Log\LoggerInterface;

interface RetrievableLogsInterface extends LoggerInterface {
    public function getLogs():array;
}

namespace Dittto\RequestLoggerBundle\Logger;
use Psr\Log\AbstractLogger;

class RequestLogger extends AbstractLogger implements RetrievableLogsInterface {
    private $logs = [];

    public const LOGGED_LEVEL = 'level';
    public const LOGGED_MESSAGE = 'message';
    public const LOGGED_CONTEXT = 'context';

    public function log($level, $message, array $context = array()) {
        $this->logs[] = [
            self::LOGGED_LEVEL => $level,
            self::LOGGED_MESSAGE => $message,
            self::LOGGED_CONTEXT => $context
        ];
    }

    public function getLogs():array {
        return $this->logs;
    }
}

With the PSR-provided AbstractLogger, you can get away with just defining the log() method. We use ourlog() method to just store any requests together with their message and context.

Guzzled logs

Now we have a store for our logged messages, let's start adding messages to it. To do this, we're going to use Guzzle's awesome middleware layer. The code's a bit weird for it as it's an anonymous function containing an anonymous function which returns a promise which contains another 2 anonymous functions.

Once you wrap your head around that though, it's quite powerful. The middleware code allows you to run some code before making a request, altering it as we require, and the run some other code based on whether the response was valid or not. Here's our code for this:

namespace Dittto\RequestLoggerBundle\GuzzleMiddleware;
use GuzzleHttp\Exception\TransferException;
use GuzzleHttp\Promise\RejectedPromise;
use Psr\Http\Message\{
    RequestInterface, ResponseInterface
};
use Psr\Log\LoggerInterface;

class LoggerMiddleware {
    public function onRequest(LoggerInterface $logger) {
        return function (callable $handler) use ($logger) {
            return function (RequestInterface $request, array $options) use ($handler, $logger) {
                $startTime = microtime(true);
                $logger->debug('Request started', [
                    LoggedVars::URI => (string) $request->getUri(),
                    LoggedVars::CURRENT_TIME => $startTime,
                ]);

                return $handler($request, $options)->then(
                    function (ResponseInterface $response) use ($request, $logger, $startTime) {
                        $endTime = microtime(true);
                        $logger->notice('Request success', [
                            LoggedVars::URI => (string) $request->getUri(),
                            LoggedVars::CURRENT_TIME => $endTime,
                            LoggedVars::STATUS_CODE => $response->getStatusCode(),
                            LoggedVars::TIME_TAKEN => $endTime - $startTime,
                        ]);

                        return $response;
                    },
                    function (TransferException $e) use ($request, $logger, $startTime) {
                        $endTime = microtime(true);
                        $logger->error('Request failed', [
                            LoggedVars::URI => (string) $request->getUri(),
                            LoggedVars::CURRENT_TIME => $endTime,
                            LoggedVars::STATUS_CODE => $e->getCode(),
                            LoggedVars::STATUS_MESSAGE => $e->getMessage(),
                            LoggedVars::TIME_TAKEN => $endTime - $startTime,
                        ]);

                        return new RejectedPromise($e);
                    }
                );
            };
        };
    }
}

We'll take this line by line (ish). The first couple of anonymous function calls just setup the request code. We then store a debug message in our logs regarding the HTTP request.

The handler is a promise which will either resolve successfully if the response is valid, or fail with an exception if the response is invalid.

For each of these possibilities, we calculate the time take between the start and the end and store that and any other related information about the request.

To make use of this middleware, we'll need to update the services we use:

services:
    dittto.request_logger:
        class: Dittto\RequestLoggerBundle\Logger\RequestLogger

    http_client:
        class: GuzzleHttp\Client
        arguments:
          - handler: '@http_client.handlerstack'
            connect_timeout: 5
            timeout: 5

    http_client.handlerstack:
        class: GuzzleHttp\HandlerStack
        factory: [ 'GuzzleHttp\HandlerStack', 'create' ]
        calls:
          - [ 'push', [ '@dittto.request_logger.middleware.request' ] ]

    dittto.request_logger.middleware:
        class: Dittto\RequestLoggerBundle\GuzzleMiddleware\LoggerMiddleware
        arguments: [ ]

    dittto.request_logger.middleware.request:
        class: Closure
        factory: [ '@dittto.request_logger.middleware', 'onRequest' ]
        arguments: [ '@dittto.request_logger' ]

You can see above that we first register our request logger object, then we define our Guzzle client and link the request logger middleware into it. If you already have a Guzzle client defined, just take the bits you need from above.

That's all it takes, if you want to manually call getLogs(). We want to build on the app_debug.php work, though, and have our logs automatically added to our JSON output.

Auto-debugger 

Now we have our RequestLogger being filled with logs, let's automatically output them. The following code relies on having Symfony's debug value set to `true` and the page response being both a 200 status code, and the page header being a valid JSON type:

namespace Dittto\RequestLoggerBundle\Listener;
use Dittto\RequestLoggerBundle\Logger\RetrievableLogsInterface;
use Symfony\Component\HttpKernel\Event\FilterResponseEvent;

class JSONDebugListener {
    private $logger;
    private $isDebug;
    private $validStatusCodes;

    private const CONTENT_TYPE_HEADER = 'content-type';
    private const CONTENT_TYPE_FOR_JSON = 'application/json';
    private const DEFAULT_VALID_STATUS_CODES = [200];
    private const OUTPUT_OBJECT_NAME = 'debug';

    public function __construct(RetrievableLogsInterface $logger, bool $isDebug = false, array $validStatusCodes = self::DEFAULT_VALID_STATUS_CODES) {
        $this->logger = $logger;
        $this->isDebug = $isDebug;
        $this->validStatusCodes = $validStatusCodes;
    }

    public function onKernelResponse(FilterResponseEvent $event):void {
        if (!$this->isDebug) {
            return;
        }

        $response = $event->getResponse();
        if ($response->headers->get(self::CONTENT_TYPE_HEADER) !== self::CONTENT_TYPE_FOR_JSON || !in_array($response->getStatusCode(), $this->validStatusCodes)) {
            return;
        }

        $content = $response->getContent();
        $data = json_decode($content, true);
        if ($data === null) {
            return;
        }

        $data[self::OUTPUT_OBJECT_NAME] = $this->logger->getLogs();

        $response->setContent(json_encode($data));
        $event->setResponse($response);
    }
}

services:
    dittto.request_logger.debug_listener:
        class: Dittto\RequestLoggerBundle\Listener\JSONDebugListener
        arguments: [ '@dittto.request_logger.alias', '%kernel.debug%' ]
        tags:
            - { name: kernel.event_listener, event: kernel.response, method: 'onKernelResponse' }

This code is entirely called by the service, above, and will append a JSON object called debug to the end of a valid JSON output.

There are some optimisations that could be made here, but it does what is required of it, and it has proven very useful when trying to debug issues on non-dev environments.

The output looks like:

{
    "test": "1",
    "debug": [
        {
            "level": "debug",
            "message": "Request started",
            "context": {
                "uri": "https://test-uri",
                "current_timestamp": 1499726224.188476
            }
        },
        {
            "level": "notice",
            "message": "Request success",
            "context": {
                "uri": "https://test-uri",
                "current_timestamp": 1499726225.925579,
                "status_code": 200,
                "time_taken_in_s": 1.73710298538208
            }
        }
    ]
}

The bundle

To make this easier to work with, I've bundled the code and placed it at github.com/dittto/symfony-request-logger. This bundle also contains an extra helper to allow you to also push the Guzzle middleware logs to monolog.