php5: Newlines showing as "\n" in Apache error log

[simon@…]

When PHP5 writes to the error log it is treating newlines as literal characters. For example:

[Thu Jan 01 15:21:14 2009] [error] [client 127.0.0.1] Array\n(\n [0] => Array\n (\n [file] => /Users/simon/Projects/WordPress/site/wordpress/wp-admin/admin.php\n [line] => 64\n [function] => wp_redirect\n [args] => Array\n (\n [0] => tools.php?page=picks_tables\n )\n\n )\n\n [1] => Array\n (\n [file] => /Users/simon/Projects/WordPress/site/wordpress/wp-admin/edit.php\n [line] => 10\n [args] => Array\n (\n [0] => /Users/simon/Projects/WordPress/site/wordpress/wp-admin/admin.php\n )\n\n [function] => require_once\n )\n\n)\n, referer: http://wp.test.site/wordpress/wp-admin/tools.php?page=picks_tables

Note the "\n" characters where you would expect a line break.

[mf2k (Frank Schima)]

Assigning to maintainers.

[ryandesign (Ryan Carsten Schmidt)]

I don't see this on my system; I do see actual line breaks in the log. Can you provide the php code you are using which produces this output in the error log?

[simon@…]

Replying to ryandesign@…:

Can you provide the php code you are using which produces this output in the error log?

Happens with any error_log function calls. For example (just tested) this code:

<?php

$my_array = array( 'blue', 'red', 'orange', 'apple' );

error_log( print_r( $my_array, true ) );

?>

Produces this in the Apache error log for that VirtualHost:

 Sunday, 4 January 2009 11:08:50 Europe/London 
[Sun Jan 04 11:09:20 2009] [error] [client 127.0.0.1] Array\n(\n    [0] => blue\n    [1] => red\n    [2] => orange\n    [3] => apple\n)\n

I'm viewing the log with Console, screengrab: ​http://skitch.com/simonwheatley/byrb6/wp.test.site-error-log

[simon@…]

Is there anything else I can provide which would help diagnose this error? It would be much easier to see the line breaks!

I have seen this occuring on multiple machines, all installed by me so I support that could be the point of failure :)

[ryandesign (Ryan Carsten Schmidt)]

Sorry, I misunderstood the problem before. The title of the ticket said "PHP error logs" and the summary says "the error log" so I assumed you meant the PHP error log, the one you set with the error_log directive in the php.ini. After running your code from above, I see this in my PHP error log:

[28-Jan-2009 16:46:04] Array
(
    [0] => blue
    [1] => red
    [2] => orange
    [3] => apple
)

However, I now see that you said "Apache error log" later, which is of course a different thing. If I remove the error_log directive from my php.ini and restart Apache and run your code again, then in my Apache error log, I see:

[Wed Jan 28 16:47:30 2009] [error] [client ::1] Array\n(\n    [0] => blue\n    [1] => red\n    [2] => orange\n    [3] => apple\n)\n

This is probably not a bug and is in fact intentional. There are web server log analyzers out there which undoubtedly assume that each line of the log is a request; if PHP were to be allowed to insert newlines into the log, such analyzers wouldn't be able to work properly. So I'm going to close this ticket as "invalid" (which is our issue tracker's way of saying "not a bug"). If you need further information on this, someone in a PHP support channel would probably be better able to help you than I.

[simon@…]

Replying to ryandesign@…:

Thank you for your reply. Unfortunately it has highlighted that the problem is not where I thought it was. My PHP config does specify an error_log location, but the errors are still written to the Apache log regardless.

To illustrate, when I run this code:

$my_array = array( 'blue', 'red', 'orange', 'apple' );

error_log( print_r( $my_array, true ) );

error_log( ini_get( 'error_log' ) );

I see the following in my Apache log:

[Wed Jan 28 23:03:47 2009] [error] [client 192.168.0.1] Array\n(\n    [0] => blue\n    [1] => red\n    [2] => orange\n    [3] => apple\n)\n
[Wed Jan 28 23:03:47 2009] [error] [client 192.168.0.1] /Users/simon/Library/Logs/php.log

Note the second error line, which claims the error logging is set to a different location. Unfortunately there is no logging happening at this location (although something was appended to the correct file last November, so something somewhere at sometime was using the php.log file).

I'll attach a PDF of the output of phpinfo() on the same page, which shows the php.ini file should be being read from /opt/local/etc/php.ini. I'll also attach that php.ini for good measure, I have error_log set as /Users/simon/Library/Logs/php.log, but there is no output in that file since November 2008. (Running phpinfo() on PHP on the commandline gives the same output, as far as the loaded php.ini and the error_log location goes.)

I've reopened the ticket, I hope that's OK, please let me know if you'd rather I started a new one, with a more accurate description.

[simon@…]

php.ini

[simon@…]

Output of phpinfo()

[ryandesign (Ryan Carsten Schmidt)]

PHP seems to either write to the error_log if one is set and it can write to it, otherwise it writes to the Apache error log. I can't find a way to make it write to both. So since it's writing to the Apache error log even though you're telling it to write elsewhere, it must be unable to write to the logfile you've given it. Check that the php.log has www as the owner and group, that it is writable, and that all the intermediate directories are at least executable by the www user. This is not usually the case -- on my systems, /Users/*/Library has 0700 permissions, meaning only the owner is allowed to look inside. If you want everyone including php/apache to be able to look inside, it will need 0755 permissions. Same goes for the Logs directory inside.

[simon@…]

Thank you for your very prompt reply.

The permissions were as you expected, however... I've chmod'd /Users/simon/Library/Logs/php.log to 777, here's the relevant line from the output of ls -Al on that dir:

-rwxrwxrwx    1 root   staff    1463 27 Nov 15:38 php.log

I restarted Apache. I then browsed to my test script again, but the log is still outputting to the Apache error log. The Apache error log permissions are set as follows:

-rw-r--r--  1 root  staff  42946942 28 Jan 23:34 wp.test.site-error_log

[ryandesign (Ryan Carsten Schmidt)]

Did you also chmod /Users/simon/Library and /Users/simon/Library/Logs?

[simon@…]

Thank you. I've just tried this

SW-MBP:site simon$ sudo chmod 766 ~/Library/
SW-MBP:site simon$ sudo chmod 766 ~/Library/Logs/

Relevant lines from ls -Al:

drwxrw-rw-   31 simon  staff   1054    28 Jan 13:12 Logs
drwxrw-rw-+  52 simon  staff   1768    1 Jan 19:21 Library

Browsed to the test script again, still seeing the output in my Apache logs. :(

[ryandesign (Ryan Carsten Schmidt)]

You don't need the write bit set on the directories but you do need the execute bit set (for directories this is the "search" bit). Try chmod 755 on both directories.

[simon@…]

Hooray! That works. Thank you so so much.

Would you mind sending me your email address? I've tried to send a token of appreciation and it's bouncing off the ryandesign@… address... you can contact me here: ​http://www.simonwheatley.co.uk/contact/

Thanks again!

[(none)]

Milestone Port Bugs deleted