Logging to stderr doesn't print anything

[Radiergummi]

• Octane Version: 1.0.4
• Laravel Version: 8.46.0
• PHP Version: 8.0.5
• Server & Version: ~Swoole~ / RoadRunner 2.2.1
• Database Driver & Version: -

Description:

When configuring the logging stack to write to stderr like the following:

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

...any logged messages will not be printed if the app is started using php artisan octane:start. The roadrunner request log still prints properly, though.

For context, our application runs in a Docker stack where it's quintessential to have all log messages printed to standard output.

Steps To Reproduce:

1. Create a new Laravel project:

   composer create-project laravel/laravel ./

2. Add the octane dependency:

   composer require laravel/octane

3. Install octane:

   php artisan octane:install

   Make sure to select 0 for roadrunner and confirm all prompts.

4. Update the logging stack configuration to write to stderr instead of single:

   'channels' => [
       'stack' => [
           'driver' => 'stack',
   -       'channels' => ['single'],
   +       'channels' => ['stderr'],
           'ignore_exceptions' => false,
       ],

5. Update the index route handler to log a message using the Log facade:

   Route::get('/', function () {
   +   \Illuminate\Support\Facades\Log::error('test');
       return view('welcome');
   });

6. Start octane:

   php artisan octane:start

7. Open http://localhost:8000 in the browser, monitor the log: No test message is logged.
8. For comparison, execute php artisan serve: A test message is logged

[Radiergummi]

Reproduction repository: Radiergummi/repro-laravel-octane-320.

[Radiergummi]

If logging to stderr requires additional steps, the documentation should include instructions that detail them. Especially for Docker-based application stacks, stderr logging is best practice and should work out of the box with Laravel.

[Namoshek]

This is because Roadrunner and Swoole spawn separate processes, which have their own process id. In containers, only the output of pid 1 is visible. In this case, pid 1 will be the php artisan octane:start process, which does not forward stdout/stderr of child processes.

As a dirty workaround (and I'm not sure there is an actual solution to this problem other than similar workarounds), you can create a symlink to /proc/1/fd/1 (for stdout) or /proc/1/fd/2 (for stderr) when building your image (you will need root permissions to create the symlink, so this cannot and should not be done in the entrypoint). You can then use the single driver to log to this symlink:

RUN ln -s /proc/1/fd/2 /app/storage/stderr.log

'channels' => [
    'stack' => [
        'driver' => 'stack',
        'channels' => ['single'],
        'ignore_exceptions' => false,
    ],

    'single' => [
        'driver' => 'single',
        'path' => storage_path('stderr.log'),
        'level' => env('LOG_LEVEL', 'debug'),
    ]
]

[Radiergummi]

@Namoshek AFAICT the octane code definitely takes care of forwarding child process output (without digging into the source too much, but it invokes getIncrementalOutput() of the symfony process component in several places, and configures RR to write to stdout, too).
RR on the other hand is definitely capable of picking up stderr output.

Also, this is reproducible outside of Docker, running octane on the CLI directly.

[Namoshek]

@Radiergummi You are right, my bad.

The issue seems that there is no logic which deals with server logger messages here: https://github.com/laravel/octane/blob/722b7567e2817b3f5e4a4ae7b49290f53968a114/src/Commands/StartRoadRunnerCommand.php#L163-L185

Adding

if ($debug['logger'] === 'server') {
    return $this->info($debug['msg']);
}

after line 184 adds the logging to the output. As I'm totally unfamiliar with RoadRunner, this is just a very quick debugging result and probably not the best thing to do... no idea. Feel free to explore and make a PR though.

Swapping stdout in the following with stderr may help in finding a solution as it will uncover some incremental output of RR. https://github.com/laravel/octane/blob/722b7567e2817b3f5e4a4ae7b49290f53968a114/src/Commands/StartRoadRunnerCommand.php#L89

[driesvints]

Hey @Radiergummi. Would appreciate a PR for the above if you could send that in. Also to the docs if you're willing. Thanks!

[Radiergummi]

@driesvints I'll see what I can come up with ✌️

[Radiergummi]

@driesvints thinking this through, I'll need some implementation advice before going ahead.

For context on the issue itself, as Roadrunner uses stdout as its response transmission channel, it files all stderr output as application logs, with a level of INFO. This does not match any condition in the getIncrementalOutput line handler callback, and is discarded. So we can get application logs into the output by simply adding the following:

Str::of($server->getIncrementalOutput())
   ->explode("\n")
   ->filter()
   ->each(function ($output) {
       // ...

+      if ($debug['level'] === 'info' && $debug['logger'] === 'server') {
+          $this->info($debug['msg']);
+      }
   });

This has a few downsides, however:

• It prints noise messages: Unfortunately, RR sends additional, non-app logs under the same channel ("INFO scan command"). There's not really a good way to prevent this other than blacklisting them.
• It hard-codes INFO as the log level: As we don't know which formatter the user has configured for the stderr logger, we can't simply parse the application-generated log line to extract the actual log level, and thus are forced to use INFO.
• It relies on an implementation detail: This is of lesser concern, but (ab)using the logger field of the Roadrunner output for something it probably isn't intended for seems brittle to me.

The first two points could be solved by adding special handling to Laravel itself: If it is running within Octane, log lines could be prefixed by some unique identifier, independently of the configured line formatter. That would allow checking for a substring match on the info lines received and only printing those.
Another option might be for Roadrunner itself to label application output differently, or adding a meta field to the log JSON.

Alternatively, we could simply add the three lines above and call it a day.

Any thoughts?

[driesvints]

Hey @Radiergummi, I can't provide this advice myself so I suggest you make a PR with the above info so Taylor or someone else can review it in debt 👍