mattgrayisok

The default logging option for most web frameworks is to write to a file on the local filesystem. Craft is no exception. However when working with Docker, an application's filesystem might not be trivially accessible and worse, is often considered ephemeral 😟

Because of Docker containers' transient nature it's common to take a slightly different approach and send our application logs to stdout or stderr which Docker will monitor. There are then countless integrations which can send these log streams to log aggregators, 3rd party services or simply to the host machine's filesystem where they'll be safe.

As is always the case there are a few hoops to jump through to get this working nicely.

Prerequisites

I'm assuming you have a Craft 3 project running in a Docker container(s) with a similar setup to that described in my standard Craft development workflow.

Step 1: Send Logs To Stderr

Because Craft is using Yii under the hood we can use components built for Yii when we want to make changes to underlying functionality. For this particular job we want to swap the standard filesystem logging component for one which will send logs to stderr, an I/O stream. PHP is actually kind enough to make this available to us as a URL when we're using it within scripts: php://stderr.

In order to get this working we'll need the help of a custom component. The most popular + simple that's available to us is yii2-streamlog which is mature and seems to work for our purpose.

If you've been following my Craft Workflow series we can get that installed by starting our containers with docker-compose up and then running:

docker-compose exec --user www-data php composer require codemix/yii2-streamlog

This will download the component and stick it in vendor whilst also updating our mounted composer.json and composer.lock.

Once that's complete we can update our Craft config to swap out the default logging component with our alternative.

Update your src/config/app.php with the following component definition:

return [
    'modules' => [
        // ...
    ],
    'components' => [
        'log' => function() {
            return Craft::createObject([
                'class' => yii\log\Dispatcher::class,
                'targets' => [
                    [
                        'class' => codemix\streamlog\Target::class,
                        'url' => 'php://stderr',
                        'levels' => yii\log\Logger::LEVEL_ERROR,
                    ]
                ]
            ]);
        }
    ],
    //'bootstrap' => ['my-module'],
];

You can swap out the log level by changing levels as you prefer. The options and their meanings are listed here.

For the sake of testing you can set it to LEVEL_TRACE which will spit out loads of logs for every page request.

Save that and open your project in a browser, you should immediately see log messages filling up your terminal if you left docker running in the foreground. If you ran docker in the background using -d you'll need to run:

docker-compose logs php

to see them.

Step 2: Do Something With Your Logs

What you do with these logs next is up to you. I like to use a log aggregator where possible so setting up something like DataDog's Log Collector as an additional container would sort you out with only a few seconds work required.

Many other log aggregation services have bolt-on support for docker's logging mechanism too, however if you just want to keep things simple have a read of Docker's basic logging documentation to see what other options you have.

Step 3 (Optional): Clean Up Those Logs

***The following was written while PHP 7.3 was in release candidate status. All info is still accurate but you'll probably want to use the php:7.3-fpm base image instead of php:7.3-rc-fpm***

If we take a closer look at the logs which are being collected you'll see that a message is being prefixed to each line which is not coming from Craft.

WARNING: [pool www] child 107 said into stderr:

To understand where this is coming from you need to understand the relationship between some of the components of php-fpm. When php-fpm is executed is starts a master process which is responsible for managing many child worker processes.

The access and error log output for this master process are defined in the php-fpm daemon configuration files. By default you can find this inside your running container:

docker-compose exec php cat /usr/local/etc/php-fpm.d/docker.conf 

...

[global]
error_log = /proc/self/fd/2

[www]
; if we send this to /proc/self/fd/1, it never appears
access.log = /proc/self/fd/2

clear_env = no

; Ensure worker stdout and stderr are sent to the main error log.
catch_workers_output = yes

This default configuration instructs the php-fpm daemon to send all of its output to /proc/self/fd/2 which is the stream that Docker listens to in order to gather its container logs. All good.

When a request is passed to php-fpm from nginx, the actual processing of the request is performed by a worker, a separate process which the master spawns. When the worker process is spawned its stdout/stderr are set as buffers within the master process. This allows the master process to intercept any output from the workers, process it and send it wherever it has been configured to do so.

The problem we have is that for all version of php-fpm up to 7.2, the master process will:

• Truncate any lines to 1024 characters
• Add a prefix to the beginning to identify the worker process from which it originated.

The only (good) way to disable this behaviour is to use php-fpm 7.3 as our container base. It's still in Release Candidate state, but let's follow this through to its conclusion so that we can feel like we accomplished something great.

Update your docker-config/php/Dockerfile to change the base image, add an additional COPY command to the top and add libzip-dev to the list of packages to install using apt-get:

FROM php:7.3-rc-fpm

COPY ./docker-config/php/docker.conf /usr/local/etc/php-fpm.d/docker.conf

RUN apt-get update && apt-get install -y \
        libfreetype6-dev libjpeg62-turbo-dev \
        libmcrypt-dev libpng-dev libbz2-dev \
        libssl-dev autoconf \
        ca-certificates curl g++ libicu-dev \
        libmagickwand-dev mysql-client libzip-dev \

# Keep everything else

The newly copied docker.conf file adds some additional config for the php-fpm daemon to allow longer log lines and prevent the prefix being added.

Create the new file docker-config/php/docker.conf containing:

[global]
error_log = /proc/self/fd/2
log_limit = 16384

[www]
; if we send this to /proc/self/fd/1, it never appears
access.log = /dev/null

clear_env = no

; Ensure worker stdout and stderr are sent to the main error log.
catch_workers_output = yes
decorate_workers_output = no

I've also set the access.log to /dev/null in here as we don't really want to be logging all requests coming into our php container. If we do want an access log it would be much more sensible to do this from our nginx container.

Finally we'll need to rebuild our docker image to take these changes into account.

docker-compose build php

Once that has completed we can bring up the containers again. The php container will be recreated using the updated image and now our log lines will be much prettier.

Step 4 (Optional): Format Logs As JSON

Todo. Still trying to find a nice solution for this. Might require a new Yii logging component. Check back later.