Where are the Logs?

TL;DR: When running WordPress inside a container based on the wordpress:php7.4-fpm-alpine image, docker logs will only show you the system logs. Your own log messages i.e., the messages you output in your application using the error_log function will appear in the WP_DEBUG_LOG file irrespective of what you set the error_log directive to in the /usr/local/etc/php/conf.d/error-logging.ini file [1]. This assuming you have WP_DEBUG enabled. If the WP_DEBUG is disabled then only the error_log directive will make a difference. If you want to log to a location other than WP_DEBUG_LOG specify the location explicitly in the error_log function using message type 3. Logging to /dev/stderr or /proc/self/fd/2 or /proc/1/fd/2 will not make the messages appear in docker logs [2]

My goal in this exercise was to be able to see my application logs when I run the docker logs command. As I learned this is not possible without some advanced hacks which I didn’t get into. The first lesson I learned is that when docker logs is called it only outputs the logs of the PID 1 process running inside the container. Further these logs are stored in the special file /proc/1/fd/2 which is a pipe

bash-5.0# ls -al /proc/1/fd/2
l-wx------    1 root     root            64 Mar 24 17:15 /proc/1/fd/2 -> pipe:[20292]

You can try echoing something into /proc/1/fd/2 and it will immediately appear in docker logs. Some posts say to log to /proc/self/fd/2 to make log messages appear in docker logs but it does not work. And logging to /proc/1/fd/2 from your application also does not work because of permissions related limitations.

Re: the location where messages are logged by default, I found two places where this location is defined in form of error_log directive. These two locations are:

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

Which of these two is relevant and matters ultimately? The directive in

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

is controlling where the PHP-FPM process and the www child processes it forks will output their messages. This directive is explained in php-fpm’s configuration file. By default the logs of child processes are discarded unless the catch_workers_output option is set to yes. One can see the www child processes in the output below:

bash-5.0# ps aux | grep php
    1 root      0:00 php-fpm: master process (/usr/local/etc/php-fpm.conf)
   72 www-data  0:00 php-fpm: pool www
   73 www-data  0:00 php-fpm: pool www

It is the child processes which run our application code inside the container. You can see the child process runs as www-data i.e., has privileges associated with www-data user. PHP-FPM exposes a log_level directive that can be tweaked to control the verbosity of PHP-FPM logs. By default it is set to notice. Try setting it to debug in /usr/local/etc/php-fpm.conf (or the /usr/local/etc/php-fpm.d/docker.conf file) and you will see the difference.

; Log level
; Possible Values: alert, error, warning, notice, debug
; Default Value: notice
;log_level = notice
;log_level = debug

Coming back, the directive that controls where application logs are output (by application logs I mean log messages that are output as result of calling PHP’s error_log function) is defined in

bash-5.0# cat /usr/local/etc/php/conf.d/error-logging.ini
error_reporting = E_ERROR | E_WARNING | E_PARSE | E_CORE_ERROR | E_CORE_WARNING | E_COMPILE_ERROR | E_COMPILE_WARNING | E_RECOVERABLE_ERROR
display_errors = Off
display_startup_errors = Off
log_errors = On
error_log = /dev/stderr
log_errors_max_len = 1024
ignore_repeated_errors = On
ignore_repeated_source = Off
html_errors = Off

The /dev/stderr is symlink to /proc/self/fd/2 which is a link to /dev/pts/0 which exists only while a terminal is attached to a container

bash-5.0# ls -al /dev/stderr
lrwxrwxrwx    1 root     root            15 Mar 24 17:15 /dev/stderr -> /proc/self/fd/2
bash-5.0# ls -al /proc/self/fd/2
lrwx------    1 root     root            64 Mar 24 18:23 /proc/self/fd/2 -> /dev/pts/0

When the container is detached from any terminal you will observe

WITSC02X6385JGH:~ sjain68$ docker exec wordpress ls -al /proc/self/fd/2
l-wx------    1 root     root            64 Mar 24 18:24 /proc/self/fd/2 -> pipe:[23169]

I think the pipe in above is only temporary. Anyway logging to /dev/stderr does not cause messages to appear in docker logs. And I have tried logging to /proc/1/fd/2 directly and it gives this error:

[23-Mar-2021 20:26:06 UTC] PHP Warning:  error_log(/proc/1/fd/2): failed to open stream: Permission denied in /var/www/html/wp-content/logging.php on line 11

The funny thing is that on another container I do see application logs in docker logs. On this container I observe:

$ docker exec -it wordpress ls -al /proc/self/fd/2
lrwx------    1 root     root            64 Mar 24 18:27 /proc/self/fd/2 -> /dev/pts/1

The confusion does not end here. I changed the log location in /usr/local/etc/php/conf.d/error-logging.ini and it did not make any difference. It turns out that when WP_DEBUG is enabled, WordPress overrides whatever log location you may have set in /usr/local/etc/php/conf.d/error-logging.ini with the log location given by WP_DEBUG_LOG. The code that does this can be found here.

This entry was posted in Software and tagged . Bookmark the permalink.

Leave a comment