Log output on stdout/stderr garbled by artisan serve

[Radiergummi]

Laravel Version

10.30.1

PHP Version

8.2.7

Database Driver & Version

Not applicable

Description

When using php artisan serve and configuring the logger to write to STDOUT or STDERR (which is pretty common in containerised environments), all application output is split by the character sequence ] (probably expecting a specifically formatted message) and limited to the second segment. This happens in ServeCommand.php on line 290.

Unfortunately, this breaks while reporting even builtin errors such as BindingResolutionExceptions, which have the message "Target [$concrete] is not instantiable.", containing the culprit sequence.
And if you start printing debug output to the console, this happens even more often, leading to confusing and only partially printed output.

This breaks several assumptions about framework configuration:

1. As per the documentation, Laravel supports Monolog stream output and processors
2. The default project includes configuration for stderr out of the box
3. JSON logging is quite common and implies heavy usage of the stop sequence
4. Neither the docs, nor the comments on the configuration options, nor the help output of the serve command indicate any potential problems when using this sequence

It is really annoying to be unable to log output on the command line in local development. The only real alternative would be using php-fpm or similar (with nginx in front of it), or Octane; both of them making the stack considerably more complex than necessary.

I think it's reasonable to expect pretty server output not to interfere with user log output. To solve this issue, the serve command should not make assumptions about the formatting of process output. I have no clue what the idea of that particular explode call was, but at minimum it should probably limit the number of split operations to two:

explode("[foo] [bar] baz", 2) === [ "[foo", "[bar] bar" ]

But ideally, the output should be printed verbatim. If that sequence does something special with the default settings, maybe use a better (unique) suffix, or check log settings -- but don't break my output.

This is related to #44781.

Steps To Reproduce

1. Configure Laravel to use the stderr channel in config/logging.php:

   -  'default' => env('LOG_CHANNEL', 'stack'),
   +  'default' => env('LOG_CHANNEL', 'stderr'),

2. Log something containing ] or cause a binding exception on purpose:

   Log::error('[Test] This is a test error log entry');

3. Start a development server using php artisan serve, trigger the code containing 2. and observe the log output:

   2023-11-06 14:07:53 ................................................... ~ 0s
   
   WARN  local.ERROR: [Test.  
   
   2023-11-06 14:07:56 ................................................... ~ 1s
   

   (Aside - it's also annoying how each line will be wrapped with blank lines, especially for reading stack traces)

[driesvints]

Thanks @Radiergummi. Would appreciate any help with figuring this out. Maybe @nunomaduro has some ideas as well.

[github-actions]

Thank you for reporting this issue!

As Laravel is an open source project, we rely on the community to help us diagnose and fix issues as it is not possible to research and fix every issue reported to us via GitHub.

If possible, please make a pull request fixing the issue you have described, along with corresponding tests. All pull requests are promptly reviewed by the Laravel team.

Thank you!

[Radiergummi]

@nunomaduro it would be super helpful to know why log messages are being split there, is that intended for something emitted by the PHP HTTP server itself?

If that isn't resolvable, maybe we could include a Monolog processor in the default config/logging.php that will prefix all log output with a known string, such as \0log\0 or something; the serve command could remove that prefix and print the line verbatim. That's not perfect (old-school debugging à la #44781 wouldn't work still), but would probably catch the majority of use cases.

[Radiergummi]

So I found something of a solution: https://gist.github.com/Radiergummi/beb80325543c5b8bcd611f7229d3608a

Essentially wrapping the log formatter used in the served application via env vars passed to the process, so users will still see their own log format. It's a bit rough, but works.

I'm aware this issue probably isn't high priority, but I'm happy to contribute a PR. Pretty sure we should try to come up with a better way of handling process output, however :)

[driesvints]

@Radiergummi you could always try to PR it to see what Taylor thinks 👍

[driesvints]

A PR was merged for this, thanks.