Logs to stdout get prefixed with warning in php-fpm image

[mikehaertl]

I try to run a [Yii based PHP application][1] in a Docker container using the php-fpm image. As usual for docker containers I write all log messages to stdout / stderr with some code like this:

$fp = @fopen('php://stdout','w');
fwrite($fp, $message);
fclose($fp);

Unfortunately PHP-FPM now prefixes all my log messages with ugly warnings:

[21-Mar-2016 14:10:02] WARNING: [pool www] child 12 said into stdout: "2016-03-21 14:10:02 [x.x.x.x][-][-][trace][yii\base\Application::bootstrap] Bootstrap with yii\debug\Module::bootstrap()"
[21-Mar-2016 14:10:02] WARNING: [pool www] child 12 said into stdout: "2016-03-21 14:10:02 [x.x.x.x][-][-][info][yii\web\Session::open] Session started"
...

Can we prevent this somehow or is there a better way to log app output?

[yosifkit]

That should be configurable by putting a config file in /usr/local/etc/php-fpm.d/. I think access.format under a [www] heading?

[mikehaertl]

@yosifkit Not sure what you mean by access.format. Any pointers?

[mikehaertl]

@yosifkit Ok found it in the example pool config. Weird that this is not really documented anywhere else - at least Google didn't find it.

But I don't think that this solves the issue. Please note that PHP-FPM adds the prefix WARNING: [pool www] child 12 said into stdout: to my log messages. It also splits up the message on line breaks. So if you had a single message spanning several lines, you'll end up with several log entries.

[yosifkit]

I found it on https://serverfault.com/questions/574880/nginx-php-fpm-error-logging, though not sure we can get rid of the fpm extra warning parts. Looking at how Heroku "fixed" it gives me little hope. There is also a post I found in a google group.

I saw your stackoverflow post, but I think the excessive logging might be in php-fpm code itself. 😞

[mikehaertl]

I've created a bug report at php.net: https://bugs.php.net/bug.php?id=71880

[phillydogg28]

@mikehaertl any progress on this issue? It is ugly seeing WARNING: [pool www] child 12 said into stdout: on every log line.

[mikehaertl]

@phillydogg28 Unfortunately not. The PHP issue mentioned above has not really got much attention as it seems. It would probably help if you cast a vote there.

[Maks3w]

A workaround is to add the following lines on your Dockerfile

FROM php:7.1-fpm

# Workaround https://bugs.php.net/bug.php?id=71880
ENV LOG_STREAM="/tmp/stdout"
RUN mkfifo $LOG_STREAM && chmod 777 $LOG_STREAM
CMD ["/bin/sh", "-c", "php-fpm -D | tail -f $LOG_STREAM"]

Then on your PHP code you have a getenv('LOG_STREAM') for to retrieve the value and configure your logger.

Finally there are some scenarios does not require this workaround like workers

#docker-compose.yml
version: "2"

services:
  MyWorker:
    command: php bin/worker.php
    image: image-with-php-fpm-and-previous-workaround
    environment:
      LOG_STREAM: php://stdout

[Maks3w]

Notice PHP-FPM does not only add a prefix, it also truncate the length of the message which end in a loss of information.

Workarounds based on sed or any other kind of messages process won't prevent the truncate of the message. You should opt for workarounds like I posted above which avoid send the output to php-fpm.

[mikehaertl]

@Maks3w Thanks, at least that's a solution for those who can't wait that this finally gets fixed in PHP. Though I'd prefer something where I don't have to change the CMD. If we do this, it's always a risk to upgrade to a newer PHP image, because you always have to check first, whether the entrypoint in CMD there has changed.

[schmunk42]

How does tail exit, when fpm has an error, will it also exit with an error code?

[schmunk42]

Related:

• Fix #73886: Handle access log & error log on Docker php/php-src#2310
• Logs (access.log, error.log) to stdErr #358

[sandrokeil]

See also this php/php-src/pull/1076