[Request] Docker-friendly logging

[bkuhl]

Docker expects all logs to be sent to stdout and stderr and Laravel doesn't seem to have the ability to separate logs in such a way, but requires all logs go to either rather than the ability to split them up. It'd be great if we were able to send error logs to stderr and the rest of the logs to stdout.

[guiwoda]

You can, but not directly through Laravel's Log facade. You need to add two handlers to Monolog:

$monolog = Log::getMonolog();

// Always add the stderr output for errors over WARNING level.
$monolog->pushHandler(
    new \Monolog\Handler\StreamHandler('php://stderr', \Monolog\Logger::WARNING)
);

// Conditionally add stdout debug.
if (config('app.debug')) {
    $monolog->pushHandler(
        new \Monolog\Handler\StreamHandler('php://stdout', \Monolog\Logger::DEBUG)
    );
}

Something along those lines!

EDIT: I understand that the stdout Handler will also get errors. I'm looking up ways to configure a max level in Monolog, but this would be a minor problem, as stdout should only be done in a debug setup.

[bbjay]

didn't know where to put the sample above...
combining the code above with the advice given in this answer worked for me:
http://stackoverflow.com/questions/32552450/laravel-how-to-log-info-to-separate-file

In bootstrap/app.php:

$app->configureMonologUsing(function($monolog) {
    // Always add the stderr output for errors over WARNING level.
    $monolog->pushHandler(
        new \Monolog\Handler\StreamHandler('php://stderr', \Monolog\Logger::WARNING)
    );
});

[andersonn-roberto]

Tank you a lot @bbjay and @guiwoda !
I was spending a lot of time trying to figure out what was wrong with my app, the error only said that Laravel can't create a singleLog.
After inserting your code on bootstrap/app.php the truly error showed up.

Thanks!

[gnumoksha]

For Lumen 5.4.*:

bootstrap/app.php

[...]

$app->configureMonologUsing(function ($monolog) {
    $monolog->pushHandler(new \Monolog\Handler\StreamHandler('php://stderr', \Monolog\Logger::WARNING));

    return $monolog;
});

return $app;

[Yo1L]

A solution with no code, only configuration for Laravel and Apache.
I’ve just set up Monolog to log in errorlog and Apache redirects ErrorLog in stdout.

.env

APP_LOG=errorlog

apache2 site conf

  ErrorLog /dev/stderr
  TransferLog /dev/stdout

I think you could do the same with nginx.

[lifeofguenter]

thanks @YoannLeViavant - this also works very well with docker/php-fpm

[taylorotwell]

New logging should be able to handle this.

[taylorotwell]

I've added an example to the default logging configuration file of how to do this.

[nasikshafeek]

@taylorotwell Is there any handlers for us to route logs to STDOUT? (I can see StreamHandler is for STDERR messages)

[mfn]

@kisanme The streamhandler is for streams, it does not matter where to.

You can use 'driver' => 'custom' and use 'via' => SetupYourLogger::class to set it up in any way, e.g. create a StreamHandler for stdout, etc.

Also see https://laravel.com/docs/5.6/logging#creating-channels-via-factories .

[nasikshafeek]

Figured that out @mfn
I've edited what @taylorotwell 's configuration looks like for STDERR to STDOUT. It looks like the following, without need of creating a factory class:

       # In config/logging.php

       'stdout' => [
           'driver'  => 'monolog',
           'handler' => StreamHandler::class,
           'with'    => [
               'stream' => 'php://stdout',
           ],
       ],

[SecondeJK]

Surely this should be included out the box?

[whereisaaron]

In recent versions (5.6+) the default config/logging.php appears to include a stderr config, so you can just inject a LOG_CHANNEL=stderr environment variable into the container.

        'stderr' => [
            'driver' => 'monolog',
            'handler' => StreamHandler::class,
            'with' => [
                'stream' => 'php://stderr',
            ],
        ],

[shaunthegeek]

if you are using docker CMD:

exec apache2-foreground

apache log had been outputed to stdout, you only need to change laravel config:

LOG_CHANNEL=errorlog

[samuraiseoul]

In regards to log levels, and using @kisanme 's solution above, do not do

'channel_name' => [
    'driver' => 'monolog',
    'handler' => StreamHandler::class,
        'with' => [
            'stream' => 'php://stdout'
        ],
        'level' => 'debug' //minimal log level
]

instead you must do

'channel_name' => [
    'driver' => 'monolog',
    'handler' => StreamHandler::class,
        'with' => [ //These are what get passed into the handler's constructor
            'stream' => 'php://stdout',
            'level' => 'debug' //minimal log level
        ]
]

[judgej]

This is all great for how the logs are sent to the logging channel, i.e. which stream. In our projects we are taking it a little further. We have:

• Where the logs go: stderr/stdout.
• How the logs are formatted: JSON, making it really easy to parse, especially the multiline log entries with the likes of stack dumps in them.
• What else gets added to the logs: additional Laravel-specific metadata that helps filter the logs from multiple Laravel and Lumen instances.

The formatting uses the standard monolog JSON formatter. That gives us a ready-made data structure that we assume (hope!) will follow some well-known conventions that other systems use. If there are better structures that more easily map to teh ELK stack, then this can be tweaked, along with the processors.

The finally the additional metadata is provided by a number of processors, added to the logging object through taps. We are collecting a number of standard and custom taps together here, and applying them to a lot of containerised Laravel and Lumen applications:

https://github.com/consilience/laravel-extended-logging

We will refine those processors over time, but hopefully it is of some interest or use to others in the meantime. It's still in alpha today (no releases) so take it or leave, but I fully intend to extend it further.

[kareemashraf]

$app->configureMonologUsing(function ($monolog) {
$monolog->pushHandler(new \Monolog\Handler\StreamHandler('php://stderr', \Monolog\Logger::WARNING));

return $monolog;

});

i get Call to undefined method Laravel\Lumen\Application::configureMonologUsing()

[judgej]

@kareemashraf that issue is long-standing, see https://laracasts.com/discuss/channels/lumen/configure-monolog-handler-for-lumen for some tips. I would suggest you find a workaround rather than extending the application. A stream handler to stderr can be set up entirely in config/logging.php.

[Harrisonbro]

The stderr-based logging works nicely for a Docker container running PHP as the primary process (e.g., php-fpm) but it doesn't quite fit the use-case for Laravel's scheduled commands for two reasons:

1. The idiomatic way to run the scheduler is by calling php artisan schedule:run >> /dev/null 2>&1 which means the output is discarded and will not be sent to the Docker logging driven (meaning you won't see anything in docker logs). Even if you omit the >> /dev/null 2>&1 part the only I can see to do this is by having a cronjob run on the Docker host server and call docker exec my-container php artisan schedule:run which will just pipe the output back to the cron job rather than sending them to the Docker logging driver — see this explanation of why docker exec doesn't pipe logs to the dockedr logs).
2. Even if there was a good way to pipe the output of php artisan schedule:run to docker logs, the only thing we see from the schedule:run command is things like Running scheduled command: ('/usr/local/bin/php' 'artisan' invoke:property-access-control-event-stream-processor > '/dev/null' 2>&1) which implies that the commands Laravel is actually running from the scheduler also discard the stdout

Point 2 seems to be the most problematic. The sending of scheduled commands' output to /dev/null seems to be baked into the way the Laravel scheduler works so if one configures Laravel to send logs to stderr as you suggested, @taylorotwell, I think that means the output from scheduled commands will be lost because the scheduler sends those commands' output to /dev/null.

It did occur to me that one could run the scheduler in its own container with the primary command being schedule:work but I think that will still only send the output of the scheduler itself to docker logs, not the output of the scheduled commands themselves.

Can anyone suggest a way to get scheduled commands' output into docker logs?

(PS. I'm aware of the task output option ->appendOutputTo($filePath) but as far as I can see that only allows us to output to a file which isn't docker-friendly. We need to get logs into the Docker logging driver, especially in Kubernetes environments.)

[mfn]

but as far as I can see that only allows us to output to a file which isn't docker-friendly

I've seen crazy things in docker containers, like processed being redirected to write to /proc/1/fd/2. What than happens is that this is the output of the docker container, actually. HTH

[captnCC]

@Harrisonbro To get the real output of the commands run in the schedule use:
/usr/local/bin/php /var/www/html/artisan schedule:run > /dev/null 2>/proc/1/fd/2

A beauty error remains: because of the missing "log processor", the output is completely naked. Would be nice to have the option to pipe the command output through the frameworks logging layer. This way the output could be formatted like the regular logs.

[mpurdon]

I've gotten around this limitation by not using commands in my scheduled tasks but Jobs instead:

$schedule->job(new TokenDailyRotation)
    ->timezone('America/Los_Angeles')
    ->at('03:00');

Which does not have the restriction of writing to /dev/null so log messages like this show up just fine (we configured logging write to stdout and then push them up to cloudwatch):

Log::error('could not update token due to error:' . $e->getMessage(), [
    'thing' => $thing->name ?? 'unknown',
    'job' => get_class(),
]);

We find it helpful to include the Job classname in the logs for filtering a bunch of logs that get spewed out at the same scheduled time each day. It also promotes thinking about chaining sub-tasks for looped items as further async jobs by dispatching from the root Job like this:

UpdateToken::dispatch(get_class($thing), $thing->id);

Also, I find it very useful to write tests for these kinds of things to make sure that you catch issues like DST changes and whatnot. I have a trait to find a job from the schedule

namespace Tests\Unit\Console\Scheduler;

use Illuminate\Console\Scheduling\CallbackEvent;
use Illuminate\Console\Scheduling\Event;

trait ScheduledJobEvents
{
    /**
     * Get the event matching the given command signature from the scheduler
     *
     * @param string $jobSignature
     * @return CallbackEvent|null
     */
    private function getJobEvent(string $jobSignature): CallbackEvent
    {
        $event = collect($this->schedule->events())->first(function (Event $event) use ($jobSignature) {
            return stripos($event->description , $jobSignature);
        });

        if (!$event) {
            $this->fail('Event for "' . $jobSignature . '" not found in ' . $this->schedule->events());
        }

        return $event;
    }
}

and another trait for event helpers:

namespace Tests\Unit\Console\Scheduler;

use Carbon\Carbon;
use Cron\CronExpression;
use Illuminate\Console\Scheduling\Event;
use Illuminate\Console\Scheduling\Schedule;
use Illuminate\Support\Facades\Log;

trait ScheduledEvents
{
    /**
     * @var Schedule|null
     */
    protected Schedule|null $schedule = null;

    /**
     * Asserts that the given event will execute on the given test date
     *
     * @param Event $event
     * @param Carbon $testDate
     */
    protected function assertWillRun(Event $event, Carbon $testDate, string $message = '')
    {
        if ($message == '') {
            $message = 'Task should run on ' . $testDate->toIso8601String();
        }

        $this->assertTrue($this->willEventRun($event, $testDate), $message);
    }

    /**
     * Check if the given event will run on the given test date
     *
     * @param Event $event
     * @param Carbon $testDate
     * @return bool
     */
    protected function willEventRun(Event $event, Carbon $testDate)
    {
        Carbon::setTestNow($testDate);

        // Run the when() & skip() filters
        $filtersPass = $event->filtersPass($this->app);
        Log::debug('checking the when() and skip() filters', ['result' => $filtersPass]);

        // Test that the Cron expression passes
        $datePasses = $this->isEventDue($event);
        Log::debug('checking the cron expression', ['result' => $datePasses]);

        return $filtersPass && $datePasses;
    }

    /**
     * Determine if the Cron expression passes.
     *
     * @param Event $event
     * @return bool
     */
    protected function isEventDue(Event $event): bool
    {
        $date = Carbon::now();

        if ($event->timezone) {
            $date->setTimezone($event->timezone);
        }

        $expression = new CronExpression($event->expression);

        return $expression->isDue($date->toDateTimeString());
    }

    /**
     * Asserts that the given event will NOT execute on the given test date
     *
     * @param Event $event
     * @param Carbon $testDate
     */
    protected function assertWillNotRun(Event $event, Carbon $testDate, string $message = '')
    {
        if ($message == '') {
            $message = 'Task should run not on ' . $testDate->toIso8601String();
        }

        $this->assertFalse($this->willEventRun($event, $testDate), $message);
    }
}

a common TestCase for scheduled events that handles schedule setup/teardown

namespace Tests\Unit\Console\Scheduler;

use Illuminate\Console\Scheduling\Schedule;
use Tests\TestCase;

class ScheduleTestCase extends TestCase
{
    use ScheduledEvents;

    /**
     * Make sure that the test is set up
     */
    public function setUp(): void
    {
        parent::setUp();

        if (!$this->schedule) {
            $this->refreshSchedule();
        }
    }

    /**
     * Refresh the schedule instance.
     *
     * @return void
     */
    protected function refreshSchedule()
    {
        $this->schedule = $this->app->make(Schedule::class);
    }

    /**
     * Make sure we clean up after the test
     */
    public function tearDown(): void
    {
        $this->schedule = null;

        parent::tearDown();
    }
}

and finally a test case that uses that stuff, note that I test other kinds of events as well which is why the ScheduledJobEvents trait is not part of the base test class

class TokenDailyRotationTest extends ScheduleTestCase
{
    use ScheduledJobEvents;

    /**
     * Ensure that it's 3AM that we are scheduled for
     */
    public function testScheduleIsMorning() {
        $event = $this->getJobEvent('TokenDailyRotation');

        $testDate = Carbon::now('America/Los_Angeles')
            ->startOfDay()
            ->addHours(15); // 3 PM

        $this->assertWillNotRun($event, $testDate);
    }
}

Good luck

[captnCC]

Some updates on the way I managed around this problem.
First a few words on the setup:

Each task or role is run in a separate container: web, schedule, queue.
With each of this roles Laravel is executed in a complete different manner.

• The web container runs nginx and php-fpm as primary process
• The schedule container runs cron in foreground mode as primary process
• The queue container runs php artisan queue:work as primary

Each of this variants needs some adjustments to get consistent logging from all of them.

One key point is the monolog-docker-handler that allows to write the logs directly to /proc/1/fd/1 instead of using the php log stream.
This handles logs for all containers great and allows to use one LogFormatter for all logs.

The tricky part is to get the queue and schedule/command output to the log.
My solution is to extend the commands and override the line method. In this method I redirect the written messages to the Log driver. In addition I remove some of the formatting like timestamps etc. as they will be added by the LogFormatter.
Note that the line methods needs to be overridden by all commands that run as schedule too.

Unfortunately I haven't found a good way to detect if the command is run as schedule and therefor should log or use the default output. My workaround this far is to detect if the command runs inside the schedule container, so commands that are executed in the web container will output as usual to the console.
Ideally artisan would have a global flag, that would force the output to the logs. This way it would be possible to force all commands that are run programatically, either as scheduled commands or in the container startup, to log the output and commands that are run manually, to write to the console. This provide a much more consistent log, as all outputs of the container are formatted and contain timestamps etc.

To the implementation. At this point the code is part of our proprietary Docker Support Package, as it is highly tailored to our setup. But I plan a more general variant of this to be published in the future. So take this as an inspiration.

The trait used on all custom commands and the ScheduleRunCommand to redirect the logs:

<?php


namespace byteit\DockerSupport\Console;

use byteit\DockerSupport\Facades\Docker;
use Illuminate\Console\Concerns\InteractsWithIO;
use Illuminate\Support\Facades\Log;


trait LogsOutput
{

    use InteractsWithIO;

    /**
     * Write a string as standard output.
     *
     * @param  string  $string
     * @param  string|null  $style
     * @param  int|string|null  $verbosity
     *
     * @return void
     */
    public function line(
      $string,
      $style = null,
      $verbosity = null
    ) {
        // If run as schedule in container, redirect the output to the logger
        if (Docker::isSchedule()) {
            $style = $style ?: 'info';
            $message = method_exists($this, 'getName') ? sprintf('[%s] %s', $this->getName(), $string) : $string;
            Log::log($style, $message);
        } else {
            parent::line($string, $style, $verbosity);
        }
    }

}

The \Illuminate\Queue\Console\WorkCommand class:

<?php


namespace  byteit\DockerSupport\Console\Command;


use byteit\DockerSupport\Facades\Docker;
use Illuminate\Contracts\Queue\Job;
use Illuminate\Support\Facades\Log;

class WorkCommand extends \Illuminate\Queue\Console\WorkCommand
{
    protected function writeStatus(Job $job, $status, $type)
    {
        if(Docker::isQueue()){
            $type = in_array($type, ['info', 'error', 'debug'], true) ? $type : 'info';

            Log::log($type, sprintf(
              "[%s] %s %s",
              $job->getJobId(),
              str_pad("{$status}:", 11), $job->resolveName()
            ));
        }
        else{
            parent::writeStatus($job, $status, $type);
        }
    }
}

In your ServiceProvider's register method extend the two commands:

class ServiceProvider
{

   //...

    /**
     * Register any application services.
     *
     * @return void
     */
    public function register(): void
    {

        $this->app->extend('command.queue.work', function ($command, $app) {
            return new WorkCommand($app['queue.worker'], $app['cache.store']);
        });
        $this->app->extend(ScheduleRunCommand::class, function () {
            return new \byteit\DockerSupport\Console\Command\ScheduleRunCommand();
        });
    }

}

[Namoshek]

@captnCC Thank you, this was very helpful indeed! Just two things to note for future readers:

• Overriding the command with $this->app->extends(...) didn't work for me (I'm running the latest Laravel version), but the following did:

  $app->bind(WorkCommand::class, function ($app) {
      return new WorkCommand($app['queue.worker'], $app['cache.store']);
  });

• If Horizon is used for queue workers, then of course one should extend \Laravel\Horizon\Console\WorkCommand and not \Illuminate\Queue\Console\WorkCommand.