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

[docteurklein]

@schmunk42 indeed that would be a problem as the exit status code is lost. A correct CMD statement would be:

CMD ["sh", "-o", "pipefail", "-c", "php-fpm -D | tail -f $LOG_STREAM"]

[tianon]

Given that this is an issue with PHP-FPM itself (and not something we can easily fix in the image), I'm going to close. I would recommend that folks interested in this topic (and whether it ever reaches a conclusion) follow and/or contribute to the upstream issue: https://bugs.php.net/bug.php?id=71880 👍 ❤️

[ghost]

follow and/or contribute to the upstream issue: https://bugs.php.net/bug.php?id=71880

Thanks for the link. How do I "follow" or "subscribe" to issues on bugs.php.net? On other bugtrackers, I would expect to be able to register an account and then have some "subscribe" or "CC" field appear. But in order to login to bugs.php.net, I apparently need an @php.net account / email address, which I don't have.

[tianon]

I'm not sure if there's a way to officially subscribe without a php.net address -- I simply meant that folks should look there for updates.

I believe the RSS feeds are the only way for non-php.net holders to subscribe: https://bugs.php.net/rss/bug.php?id=71880&format=rss2

[tianon]

Oh, and of course as I send that, I find a "subscribe" form on https://bugs.php.net/bug.php?id=71880&edit=3 (enter your email, solve a simple math problem, click subscribe)

[mikehaertl]

In case someone missed it, it should also be mentioned that you can also upvote the issue on that page https://bugs.php.net/bug.php?id=71880

[devurandom]

I find a "subscribe" form on https://bugs.php.net/bug.php?id=71880&edit=3 (enter your email, solve a simple math problem, click subscribe)

Thanks! That was about the only place, where I did not look.

[hopeseekr]

You are amazing, @Maks3w !!

[elonmir]

@Maks3w If you got a container with tty and want to enter it, that is not possible if you have tail as a command. In our case that even broke our CI...

[ghdna]

I'm getting pull access denied for image-with-php-fpm-and-previous-workaround, repository does not exist or may require 'docker login'
Is the image still valid or has that moved?

[tomfotherby]

php 7.3 is released (changelog) - it looks very promising with regards to logging improvements when running in docker:

New options have been added to customize the FPM logging:

• log_limit - This global option can be used for setting the log limit for the logged line which allows to log messages longer than 1024 characters without wrapping. It also fixes various wrapping issues.
• log_buffering - This global option allows an experimental logging without extra buffering.
• decorate_workers_output - This pool option allows to disable the output decoration for workers output when catch_workers_output is enabled.

I didn't get to try 7.3 yet, does it fix this Github issue and make our lives easier?

[vladkolotvin]

Just add this to php.ini to disable prefixes and truncating.

[php]
error_log = /proc/1/fd/2

[pengu-fr]

I confirm : using php-7.3 with decorate_workers_output = no does fix this issue.

[AnatolyRugalev]

I suppose we could enable it by default for 7.3 release, right?

[tianon]

I suppose we could enable it by default for 7.3 release, right?

Just to thread the needle, see #725 which did exactly that. 👍

[addozhang]

@mpyw with this command CMD ["sh", "-c", "exec 3<>/tmp/stderr; cat <&3 >&2 & exec php-fpm >/tmp/stderr 2>&1"], the process will run in background. After appending -F to php-fpm, it can run in foreground.

[addozhang]

@mpyw with this command CMD ["sh", "-c", "exec 3<>/tmp/stderr; cat <&3 >&2 & exec php-fpm >/tmp/stderr 2>&1"], the process will run in background. After appending -F to php-fpm, it runs in foreground.

[addozhang]

@mpyw It 's confused it can not run in foreground in my case without -F opt.

Currently, our team use 7.2.x.

[mpyw]

@addozhang My (deleted) comment was completely wrong, sorry. It seemed to be implicitly depending on the daemonization option in configuration file.

[mpyw]

Updated and deleted some comments

[emmm-dee]

@Maks3w Great workaround, however I seem to have issues on managing the container state. If php-fpm crashes, the container will remain running since the tail process continues to run. Any ideas how to kill the container from the inside if either php-fpm master or tail processes end?

[schmunk42]

@emmm-dee See #207 (comment)

[luispabon]

The problem with above's solutions is that if you run anything other than exec /path/to/binary as docker CMD, docker will run them under sh, which swallows up any signals sent to the process. This means SIGQUIT etc never make it to php-fpm and shutting down containers require docker kill instead of docker stop.

[luispabon]

For someone stumbling upon this ticket, php 7.3 have a new directive to remove all the extraneous text from log output:

; Place in a conf file at /etc/php/7.4/fpm/pool.d/ or equivalent on your system
[www]
decorate_workers_output = no

[mpyw]

For PHP 7.3:

[www]
decorate_workers_output = no

For PHP 7.2:
#207 (comment)

[romeritoCL]

Yeah, 👍 to fix this once and for all, your PHP-FPM has to be >7.3 cause they added a fix and some configuration to prevent this to happen. And then add this lines:

on php.ini or any overrides you have

log_errors_max_len = 8192

on the fpm configuration pool overrides.conf

[global]

; this prevents a bigger json to be splitted into multiple lines
log_limit = 8192

[www]

; this will void the warning messages on the log output
decorate_workers_output = no

Finally I can see my logs in Datadog as they should be :)