Laravel 5.6 and logging you can configure

Configuring logging in 5.5 meant a service provider that reached into the Monolog instance and reconfigured it, which every project did slightly differently and none of it was visible from any config file. 5.6 makes logging a config file like everything else, and the feature that makes the change worth the upgrade is stacks.

The symptom

// app/Providers/AppServiceProvider.php — where logging lived
public function boot()
{
    $monolog = Log::getMonolog();
    $monolog->popHandler();          // undo what the framework did

    $handler = new RotatingFileHandler(storage_path('logs/app.log'), 14);
    $handler->setFormatter(new JsonFormatter());
    $monolog->pushHandler($handler);
}

Nothing about that is discoverable. Somebody asking where the logs go has to know to look in a service provider, and the environment conditional means the answer is different in production in a way no config file records. The popHandler call is the tell — it exists to undo what the framework already did.

Why it happens

Logging was configured by a single log key in app.php with four possible values — single, daily, syslog, errorlog — and no way to express anything else. Every requirement beyond those four was a provider, because there was nowhere else to put it.

The requirements that pushed people there are ordinary: JSON to a file for the log shipper, human-readable to stderr in development, a webhook for anything critical, and a separate channel for audit events that must not be mixed with debug noise. All four at once is normal, and none of them fit in one string.

The fix

Channels, and a stack that fans out

// config/logging.php
return [
    'default' => env('LOG_CHANNEL', 'stack'),

    'channels' => [
        'stack' => [
            'driver'            => 'stack',
            'channels'          => ['json', 'stderr'],
            'ignore_exceptions' => false,
        ],

        'json' => [
            'driver'    => 'daily',
            'path'      => storage_path('logs/app.json'),
            'formatter' => MonologFormatterJsonFormatter::class,
            'days'      => 14, 'level' => 'info',
        ],

        'stderr' => [
            'driver'  => 'monolog',
            'handler' => MonologHandlerStreamHandler::class,
            'with'    => ['stream' => 'php://stderr'],
        ],
        'audit' => [ 'driver' => 'daily', 'days' => 365,
                     'path' => storage_path('logs/audit.log') ],
    ],
];

A stack sends every record to each of its channels, and each channel applies its own level and formatter — so the same event is JSON in a file the shipper reads and plain text on stderr for whoever is watching the container. That is the arrangement the service provider was building by hand, expressed declaratively.

The audit channel demonstrates the other reason to want this: writing to a specific channel rather than the default keeps a low-volume, long-retention stream out of the noise.

Log::channel('audit')->info('permission.granted', [
    'actor'   => $actor->id,
    'subject' => $user->id,
    'role'    => $role->name,
]);

// or a stack assembled at the call site, without config
Log::stack(['json', 'slack'])->critical('payment.gateway_down');

Structured context that survives the trip to an index

The formatter is only half of structured logging. The other half is at the call site, and it is the half that changes how people write log lines.

// unparseable without a regex per message
Log::error("Payment failed for order 91204: declined (code 51)");

// a constant message, everything variable in context
Log::error('payment.failed', [
    'order_id' => $order->id, 'reason' => 'card_declined',
    'gateway_code' => 51, 'amount_cents' => $order->totalCents(),
]);

The message becoming a constant is the change developers resist, because the line reads worse to a human tailing a file. It reads enormously better to anything that aggregates: “how many payments failed this week, grouped by reason” becomes a query rather than a research project.

Context that attaches itself

Adding a correlation id to every log line by passing it into every call is not something anybody will keep doing. A Monolog processor attaches it once.

// on the channel:  'tap' => [AppLoggingAddRequestContext::class]

final class AddRequestContext
{
    public function __invoke($logger)
    {
        $logger->pushProcessor(function (array $record) {
            $record['extra']['correlation_id'] = request()->attributes->get('cid');
            $record['extra']['user_id'] = optional(auth()->user())->id;

            return $record;
        });

        return $logger;
    }
}

The tap array is the escape hatch for anything the config format cannot express, and it receives the fully constructed logger — so it is the right place for processors, custom formatters and handler-specific settings. It keeps the customisation in a named class next to the channel that uses it rather than in a provider that applies to everything.

Single-server scheduling, and the cron that ran three times

The other 5.6 addition worth adopting immediately has nothing to do with logging and everything to do with a class of bug that produces duplicate invoices.

$schedule->command('invoices:generate')
    ->dailyAt('02:00')
    ->onOneServer()
    ->withoutOverlapping();

// needs a SHARED cache driver. the file driver is per-machine,
// provides no protection, and reports no error.

Three application servers each running the same crontab means every scheduled task runs three times, which is invisible for a task that recomputes something and expensive for one that sends email. The lock is a cache key claimed by whichever server reaches it first, and the requirement that the cache be shared is stated in one line of the documentation and is the thing that goes wrong.

withoutOverlapping() solves a different problem — a run that takes longer than its interval — and both are frequently wanted. Neither has any effect on a task invoked manually, which is worth knowing before debugging why a lock did not apply.

Verifying it worked

>>> Log::info('check', ['a' => 1]);

$ tail -1 storage/logs/app-2018-02-14.json | jq -c .
{"message":"check","context":{"a":1},"level_name":"INFO",
 "extra":{"correlation_id":"3f9a...","user_id":null}}

$ docker-compose logs --tail=1 php
[2018-02-14 11:04:22] local.INFO: check {"a":1}

$ php artisan config:cache && php artisan tinker
>>> Log::channel('audit')->info('still works after caching');

The same event appearing in both destinations in both formats is the assertion the stack exists to make. Running it again after config:cache is the check that catches the classic mistake — a channel whose configuration calls env() outside the config file works uncached and returns null once compiled.

The other verification worth doing once is that a handler failing does not take the request with it. Pointing the Slack channel at an unreachable URL and confirming the page still renders tells you whether ignore_exceptions is set the way you think, and the answer matters more than it seems — a logging failure that becomes an outage is a bad trade.

What this costs

A config file that can silently send nothing anywhere is the honest risk. A channel with a level of error when the application logs at info, a path that is not writable, a stack referencing a channel that was renamed — all of them produce no error and no log lines, which is indistinguishable from an application that is not logging. A test asserting that a written line lands where it should is worth the ten minutes.

The migration from a provider is also not automatic, and the temptation is to leave the provider in place alongside the new config, which produces duplicate handlers and every line written twice. Deleting the old provider in the same commit as adding the config file is the only version of this that stays comprehensible, even though it makes the change larger than it needs to be.