FPM: error_log entries all on same line

verne-wv commented 1 year ago

Description

The following code:

<?php
echo 'try err msg on line 1<p>';
error_log("err on line 1");
echo 'try err msg on line 2<p>';
error_log('err on line 2');
echo 'try err msg on line 3<p>';
error_log('err on line 3');
?>

Resulted in this output:

[Mon Mar 20 15:07:40.253904 2023] [proxy_fcgi:error] [pid 122391:tid 140026615572224] [client 129.71.34.33:53261] AH01071: Got error 'PHP message: err on line 1PHP message: err on line 2PHP message: err on line 3'

But I expected something similar to this instead:

[Mon Mar 20 13:25:38.221700 2023] [fcgid:warn] [pid 97183:tid 140026511869696] [client 129.71.34.33:57883] mod_fcgid: stderr: err on line 1
[Mon Mar 20 13:25:38.221753 2023] [fcgid:warn] [pid 97183:tid 140026511869696] [client 129.71.34.33:57883] mod_fcgid: stderr: err on line 2
[Mon Mar 20 13:25:38.221762 2023] [fcgid:warn] [pid 97183:tid 140026511869696] [client 129.71.34.33:57883] mod_fcgid: stderr: err on line 3

If I change back to FCGId I do get the above three individual log entries -- in fact my example above, as you can see, is from FCGId.

Either I am missing a setting in my PHP and/or FPM config (some flush or cache setting?) or FPM is the culprit here :-) If I send three different distinct error messages, each should be standalone and not concatenated together -- again FCGId logs things properly.

PHP Version

PHP 8.2.4

Operating System

No response

bukka commented 1 year ago

Are you sure that the used PHP version is 8.2.4? I fixed this in https://github.com/php/php-src/pull/10022 which went to 8.2.2. I just tested your script on the latest PHP 8.2 with Apache and getting:

 [Mon Apr 10 17:51:20.832324 2023] [proxy_fcgi:error] [pid 1269749:tid 139696038180608] [client 127.0.0.1:46064] AH01071: Got error 'PHP message: err on line 1; PHP message: err on line 2; PHP message: err on line 3'

It is still on single line but it is with ; separator which is expected because there is only a single error record so it is logical to have it on single line.

verne-wv commented 1 year ago

There are numerous complaints in various blogs over the last several years about having all the msgs on a single line, regardless of any separator character.

I am suggesting that FPM should process this the same as FCGI does it -- each msg as a separate logged item into syslog.

The general issue of having FCGI and FPM log things differently (that is, putting everything on one very long line) goes back to 7.3 or before -- my test system does not have anything older than 7.3 :-)

If its not possible, or is a function/design change, that should be clearly and plainly stated somewhere :-)

I feel if a php piece of code makes three different calls to error_log, each should be processed individually -- again FCGI does it that way. Am I missing a flag or setting for FPM to have the behavior I want?

donnorman commented 1 year ago

I hope this is appropriate to add here!

I have been trying to figure this one out for a couple of months after switching to use PHP-FPM instead of mod_php with Apache on Ubuntu.

A little background, I run two different environments:

One with AlmaLinux 8.x, Apache 2.4, and PHP 8.1, using the Remi repos for packages. In this environment, using mostly default configurations, PHP-FPM will log each entry to a new line for each HTTP request regardless of how many times error_log is used.
The other with Ubuntu 22 LTS, Apache 2.4, and PHP 8.1, not using any special repos for the packages. In this environment, using identical ini/pool configs as the other environment, PHP-FPM will log each error_log entry concatenated together in a single line for each HTTP request.

In my case, PHP-FPM 8.1 in Alma is behaving as I would like with the multiple lines, and I would really like to get it working the same in the Ubuntu environment. I'm not sure if it's something Remi does with the packages he releases that has PHP-FPM working like that. The Remi packages also leave out all the [proxy_fcgi:error] [pid 21157:tid 139847039448640] [client x.x.x.x:53291] AH01071: Got error 'PHP message: stuff out of the log files; which I would like to be able to configure in Ubuntu but can't find any documentation about that.

bukka commented 1 year ago

@verne-wv So I just want to first clarify that the mod_fcgid and mod_proxy_fcgi are both under Apache (technically mod_fcgid is not part of 2.4 codebase and does not seem to be maintained anymore) and php-fpm does not have any special handling for them in terms of logging. So it's all about how it works in Apache and has nothing to do with php-fpm. Nevertheless when I have time for this I will try to check what's done differently in each of those modules.

To address this in FPM we could maybe try to do fcgi_flush after logging the error message. But it needs to be done carefully as it might impact some clients potentially. It is something that I would prefer not to do in bug fixing release though. The fact is that the error messages have been always grouped in FPM in the single record so some apps might already rely on that behaviour and we should not probably change it in bug fixing release. So I will change this to feature request as this could be done only in minor version bump.

bukka commented 1 year ago

@donnorman This is most likely because the first case has configured error_log in php.ini and it is actually a PHP error log (not Apache). The SAPI log_message is called only if the PHP ini error log is not configure.

donnorman commented 1 year ago

@bukka Sorry for the delayed response! I double checked all the configs in both environments and they are identical in that:

php.ini: ;error_log = syslog

php_fpm.conf: catch_workers_output = yes php_flag[display_errors] = on php_admin_value[display_errors] = 'stderr' php_admin_value[error_log] = path_to_apache_log-error_log php_admin_flag[log_errors] = on

zaunere commented 1 year ago

May be related in that the SAPI logs (FPM/nginx) don't flush until the end of the request.

sqaxomonophonen commented 10 months ago

Trying to upgrade a PHP 7.x codebase to 8.x makes this problem really annoying, because:

It's normal to see a lot of new log output when migrating to a new PHP major version
Fatal errors — the ones you want to fix first when migrating — come at the end of log output

trondhuso commented 4 months ago

@bukka Just want you to know that thanks to your "fix" I have an error message (or notification) in the log that spans 20 lines and is probably 1000 characters long. Which makes it VERY problematic to debug and try to remove the notifications.

Quoting your answer:

Are you sure that the used PHP version is 8.2.4? I fixed this in https://github.com/php/php-src/pull/10022 which went to 8.2.2. I just tested your script on the latest PHP 8.2 with Apache and getting:

[Mon Apr 10 17:51:20.832324 2023] [proxy_fcgi:error] [pid 1269749:tid 139696038180608] [client 127.0.0.1:46064] AH01071: Got error 'PHP message: err on line 1; PHP message: err on line 2; PHP message: err on line 3' It is still on single line but it is with ; separator which is expected because there is only a single error record so it is logical to have it on single line.

I disagree it is logical to have it on single line.

Is there a way to configure my way out of this?

bukka commented 4 months ago

@trondhuso That's not becuase of the "fix". You would see that before as well or there was another issue even before. That separator was meant to just make is slighly more readable and not have PHP message: err on line 1PHP message: err on line 2PHP message: err on line 3.

As I mentioned in https://github.com/php/php-src/issues/10890#issuecomment-1510373112, there is a way how to sort this out potentially but it requires some effort and lots of testing and it's also a bit risky so this can happen only in minor version. I have got currently some other priorities and not that much time so unfortunately it won't happen in 8.4 unless someone else does the work.

php / php-src