Php: 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. :disappointed:

[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:

• https://github.com/php/php-src/pull/2310
• https://github.com/docker-library/php/issues/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 :+1: :heart:

[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?

[tianon]

That was an example placeholder name; you need to build the image yourself.

[ghdna]

Does anyone have a full example following @Maks3w workaround? I'm using symfony->monolog->docker-compose flow and my fpm logs are truncated at 1024 characters. I updated my dockerfile but I'm not sure where to plug in getenv('LOG_STREAM')

[abcdmitry]

You can replace an entrypoint script with following:

#!/usr/bin/env bash
set -e

PIPE=/tmp/stdout

if ! [ -p $PIPE ]; then
    mkfifo $PIPE
    chmod 666 $PIPE
fi

tail -f $PIPE &

if [ "${1#-}" != "$1" ]; then
    set -- php-fpm "$@"
fi

exec "$@"

This way php-fpm remains a PID 1 process, thus accepting signals, but anything sent to /tmp/stdout will be printed to container logs.
Also it doesn't separate output of various workers, any child can write to /tmp/stdout

[AnatolyRugalev]

@abcdmitry Thanks! This workaround works fine for me.

[YorickH]

@abcdmitry For some reason (my guess would be because of upstream changes) your proposed solution is no longer working. The pipefile is filled correctly with the logs but docker isn't adding them to stdout. Any idea?

[mpyw]

@YorickH Currently I'm using

FROM php:7.2-fpm-alpine
RUN mkfifo -m 666 /tmp/stdout
CMD ["sh", "-c", "exec 3<>/tmp/stdout; cat <&3 >&2 & exec php-fpm -F >/tmp/stdout 2>&1"]

Note that your outputs in php-fpm containers should directly write to /tmp/stdout. Please confirm your logger settings.

[YorickH]

@mpyw Currently our app is writing logs with the monolog StreamHandler: $handler = new StreamHandler('/tmp/stdout');
I just tried your solution and still having the same issue, weird since yours and previous @abcdmitry his solution was confirmed working.

[mpyw]

@YorickH I'm using Monolog in Laravel 5.6, too. Confirmed working fine. (Note that I'm using /tmp/stderr instead of /tmp/stdout)

.env

LOG_CHANNEL=stderr
LOG_USE_JSONL=true

config/logging.php

<?php

return [

    /*
    |--------------------------------------------------------------------------
    | Default Log Channel
    |--------------------------------------------------------------------------
    |
    | This option defines the default log channel that gets used when writing
    | messages to the logs. The name specified in this option should match
    | one of the channels defined in the "channels" configuration array.
    |
    */

    'default' => env('LOG_CHANNEL', 'stderr'),

    /*
    |--------------------------------------------------------------------------
    | Log Channels
    |--------------------------------------------------------------------------
    |
    | Here you may configure the log channels for your application. Out of
    | the box, Laravel uses the Monolog PHP logging library. This gives
    | you a variety of powerful log handlers / formatters to utilize.
    |
    | Available Drivers: "single", "daily", "slack", "syslog",
    |                    "errorlog", "custom", "stack"
    |
    */

    'channels' => [

        'stderr' => [
            'driver' => 'stack',
            'channels' => env('LOG_USE_JSONL') ? ['stderr_jsonl'] : ['stderr_simple'],
        ],

        'stderr_simple' => [
            'driver' => 'single',
            'path' => '/tmp/stderr',
            'level' => 'debug',
        ],

        'stderr_jsonl' => [
            'driver' => 'monolog',
            'handler' => \Monolog\Handler\StreamHandler::class,
            'handler_with' => [
                'stream' => '/tmp/stderr',
                'level' => \Monolog\Logger::DEBUG,
            ],
            'formatter' => \Monolog\Formatter\JsonFormatter::class,
        ],

    ],

];

docker.conf

[global]
error_log = /tmp/stderr

[www]
access.log = /dev/null
clear_env = no
catch_workers_output = no

php.ini

[php]
log_errors = On
error_log = /tmp/stderr

Dockerfile

FROM php:7.2-fpm-alpine

COPY docker.conf /usr/local/etc/php-fpm.d/docker.conf
COPY php.ini /usr/local/etc/php

RUN mkfifo -m 666 /tmp/stderr

CMD ["sh", "-c", "exec 3<>/tmp/stderr; cat <&3 >&2 & exec php-fpm -F >/tmp/stderr 2>&1"]

• All captured exception messages are directly written to /tmp/stderr as JSONL by Monolog.
• All uncatchable error messages are written to /tmp/stderr via error_log directive.
• All php-fpm status messages are also written to /tmp/stderr.
• All data written to /tmp/stderr pipe can be correctly read thanks to the intermediate file descriptor 3 despite none of writer exists when we start reading.
• All data from file descriptor 3 are not buffered because they are emitted via stderr (file descriptor 2).

[mikehaertl]

I just noticed a very weird behavior: I use the fifo approach described above and thus have RUN mkfifo -m 666 /tmp/my-logs in my Dockerfile. I have started 2 containers from this image and found, that messages written to the fifo of any of the two containers both appear in the log output of one of them. The other never receives any messages written to any fifo file.

So it seems as both containers somehow share the same fifo file, even if they "live" in different containers. I assume that this has to do with the fifo file being baked into the image. Maybe it's safer to create a "fresh" fifo in the entry script. I'll have to verify this first, thought.

[YorickH]

@mpyw Thanks for the great explanation! I managed to get it working as expected.

[AdrianAntunez]

@mikehaertl have you further investigated the weird behavior you were facing? I have used the workaround proposed by @mpyw and it is working like a charm. Both php-fpm containers are writing into its own log and I have tested that both of them has contents and are different from each other so I can't understand why is that happening to you. Are you sharing /tmp volume? If that's the case, I think that the behaviour should be similar to the one you're facing...

[mikehaertl]

@AdrianAntunez No, I have not figured out, what's wrong here. I have several hosts where more than one instance of the same image is running. It only happened at one host so far. I could not reproduce it elsewhere either.

I know too little about the inner connections between a fifo in the filesystem and the kernel but what looks suspicious is that the inode number of the fifo file in both containers is the same (ls -i /tmp). But then again this is also the case on some other servers I have. There the logging works fine.

[yosifkit]

@mikehaertl Anything special about the host this happened on (ie a different docker storage driver)? I tried to replicate the behavior on my system that uses overlay and couldn't get two containers to talk through a fifo generated in a Dockerfile. While I did see that the inode was the same across containers, they had a different Device in stat.

```console
$ docker build -t fifo-test - < FROM debian:stretch-slim
RUN mkfifo -m 666 /tmp/stderr
EOF
$ docker run -it --rm fifo-test
root@d32799095309:/# stat /tmp/stderr
File: stderr
Size: 0 Blocks: 0 IO Block: 4096 fifo
Device: 4dh/77d Inode: 28086072 Links: 1
Access: (0666/prw-rw-rw-) Uid: ( 0/ root) Gid: ( 0/ root)
Access: 2018-10-05 16:51:11.000000000 +0000
Modify: 2018-10-05 16:51:11.000000000 +0000
Change: 2018-10-05 16:51:11.567778137 +0000
Birth: -
root@d32799095309:/# pipe=/tmp/stderr
root@d32799095309:/tmp# while true; do if read line <$pipe; then if [[ "$line" == 'quit' ]]; then break; fi; echo $line; fi; done

$ docker run -it --rm fifo-test
root@1f07e26aa240:/# stat /tmp/stderr
File: /tmp/stderr
Size: 0 Blocks: 0 IO Block: 4096 fifo
Device: 89h/137d Inode: 28086072 Links: 1
Access: (0666/prw-rw-rw-) Uid: ( 0/ root) Gid: ( 0/ root)
Access: 2018-10-05 16:51:11.000000000 +0000
Modify: 2018-10-05 16:51:11.000000000 +0000
Change: 2018-10-05 16:51:11.567778137 +0000
Birth: -
root@1f07e26aa240:/# echo "Hello from $$" >/tmp/stderr

this would just hang even though I have a loop in the other container reading the fifo

````

[mikehaertl]

@yosifkit The host is a virtual server hosted at DomainFactory here in Germany ("JiffyBox Cloudlevel1"). It's running Ubuntu 16.04.3 LTS with a kernel customized by DF (4.4.110-x86_64-jb1). I have other boxes there with the same kernel which don't have this problem.

I've checked with stat and the two files indeed have the same Device. Should I open another issue for this? I can't provide a procedure to reproduce, though. If I can do anything else to debug this further, let me know.

$ docker exec bac0d5d7 stat /tmp/yii-stdout
  File: /tmp/yii-stdout
  Size: 0               Blocks: 0          IO Block: 4096   fifo
Device: ca00h/51712d    Inode: 662004      Links: 1
Access: (0666/prw-rw-rw-)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2018-05-10 08:31:06.000000000
Modify: 2018-10-08 06:41:50.000000000
Change: 2018-10-08 06:41:50.000000000

$ docker exec cccb974 stat /tmp/yii-stdout
  File: /tmp/yii-stdout
  Size: 0               Blocks: 0          IO Block: 4096   fifo
Device: ca00h/51712d    Inode: 662004      Links: 1
Access: (0666/prw-rw-rw-)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2018-05-10 08:31:06.000000000
Modify: 2018-10-08 06:41:50.000000000
Change: 2018-10-08 06:41:50.000000000

UPDATE: Forgot to mention: No special storage drivers. It's using the defaults. Some versions:

$ docker version
Client:
 Version:      17.09.1-ce
 API version:  1.32
 Go version:   go1.8.3
 Git commit:   19e2cf6
 Built:        Thu Dec  7 22:24:23 2017
 OS/Arch:      linux/amd64

Server:
 Version:      17.09.1-ce
 API version:  1.32 (minimum version 1.12)
 Go version:   go1.8.3
 Git commit:   19e2cf6
 Built:        Thu Dec  7 22:23:00 2017
 OS/Arch:      linux/amd64
 Experimental: false

$ docker-compose version
docker-compose version 1.17.0, build ac53b73
docker-py version: 2.5.1
CPython version: 2.7.13
OpenSSL version: OpenSSL 1.0.1t  3 May 2016

[tianon]

This isn't an issue with PHP or FPM, so I'd recommend checking with the
Docker community at large (forums, slack, stack overflow, etc) -- there
might even be an issue for it filed already. 👍

[mikehaertl]

Not sure what I did wrong here: I followed the suggestions from this issue and run into a problem. Probably some side effect that someone else might also face. I even asked, if I should create another issue for this. Reaction is that I'm downvoted and basically told "go away, this is not right the place for you".

[tianon]

@mikehaertl I'm sorry you feel you've been pushed away -- my point is simply that this is not an issue with the php image, nor is it something _we_ could fix; it honestly sounds like a fundamental issue with Docker or with the Linux kernel, so there's really nothing at all we can do within https://github.com/docker-library/php even if there's a good reproducer, which is why we're suggesting you try a broader general Docker audience

Now that I'm at a computer, looking at https://github.com/moby/moby (which is an appropriate place to file Docker-related issues), I think https://github.com/moby/moby/issues/14221 is the closest I can find (they discuss doing something that sounds remarkably similar to what you're seeing but we can't reproduce reliably).

[mikehaertl]

@tianon Thanks and sorry for reading to much into your comment.

The issue you mentioned is also not really related, though. I don't pipe anything. I just have 2 containers with a fifo file each. The fifos get connected internally to the same device by the kernel which they shouldn't. I'll check for a better match or open a new issue.

To the downvoters (@AdrianAntunez @phy25):

Thing is, that this issue (prefixed warnings) still persists. It will be fixed in PHP 7.3 which is going to be released yet. Those googling for a workaround will end up here. So the workaround described here should be without flaws. But it seems not to be rock solid and have problems in some edge cases as my case shows.

I wonder what will you do if you follow the recommendation here and suddenly face the same issue? Where will you look for a solution? :confused:

[AdrianAntunez]

Hi @mikehaertl I didn't downvote you, I just was trying to express my confusion to that issue as it works for me and I can't see anything different apart from the SO versions along with the kernel...

Despite of the workaround proposed here works for me, I don't know if that should be stable enough to release it in a production environment with thousands of requests and a huge workload...

I hope that issue gets fixed in PHP 7.3 but in my particular case that's not an option as I'm limited to PHP 7.0 (AWS only provides a php module for its memcached version up to PHP 7.0 version... :( )

[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?

[cruelbob]

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 https://github.com/docker-library/php/pull/725 which did exactly that. :+1:

[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 https://github.com/docker-library/php/issues/207#issuecomment-334481208

[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:
https://github.com/docker-library/php/issues/207#issuecomment-424203803

[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 :)