Debugging PHP web applications

In 2017, this topic seems a little dated and will probably not get me an opportunity to speak at a conference. While all of the elite programmers, cool kids, and CS grads are talking languages such as Go and Erlang – how to do tracing, performance testing, and the like – it seems very juvenile for me to write about PHP.

PHP is a language made specifically for the web. It is the first web language I learned after HTML 4/CSS. I learned it because it was easy. The syntax was easy, the variables – easy, running it – easy; however, when something broke, it was difficult as a beginner to troubleshoot. I would spend several hours looking at the code I just wrote only to find out I missed a semicolon or quote. This post is several things I wish I knew when I started with PHP.

White Pages

When coding in PHP, you will often find a blank white page with nothing printed on it. This means PHP was unable to complete the page construction due to an error in the code.

In the early days, PHP had error reporting on by default. Rather than being greeted with a white page on error, you would have the error code presented to you – making it very obvious where the issue is located. Due to novice SysAdmins/Devs who would leave error reporting on in production, PHP maintainers switched this default behavior to off.

I find it easier to debug code when the process goes like:

  1. Write code
  2. Load page in browser
  3. See error message
  4. Fix code
  5. Repeat

With current defaults, the workflow is as follows:

  1. Write code
  2. Load page in browser
  3. Open terminal
  4. Tail log file
  5. See error message
  6. Fix code
  7. Repeat

While it is only 2 steps more, consider the time wasted trying to find the correct path to the log file. Would it be in nginx’s error log file or would it be in the www fpm pool’s www-error.log?

Application deployment

It is 2017, if you have not tried nginx as your webserver, you are missing out. I have wrote an article on how to deploy a LEMP stack which you should read. Not only is nginx syntax easier to read, it is much easier to tune, and it forces you to use PHP-FPM which is currently the best way to run PHP applications. In the early days, PHP was run as a process of the apache web server. This made applications spawn a new apache worker to run simple PHP code.

If your application code and web server reside on the same server, make sure PHP is listening as a unix socket. Why should the flow of bits go through the network stack back to the same machine? This is inefficient.

Setting up PHP-FPM

On RHEL/Fedora/CentOS PHP-FPM settings are in /etc/php-fpm.d/<pool name>.conf To set up a unix socket, find the listen directive and change it to a file path – such as /var/run/php.sock. You will then have to alter the listen.user, listen.group, and listen.mode settings. These three settings determine which level of access your user will have to the PHP application socket. For instance if the listen.user is andrew, your web server will have to be running as andrew. The andrew user would also need access to the directory on your system with the application code (typically /var/www/html/<application name>/).

In the old days before git, many web developers ssh’ed into a box and edited the same code base. The same group would be applied to all users ssh’ing in and the application directory would have the group own the folder like the example below.

drwxrws---. 2 nginx webadmins 4096 Dec 22 07:38 /var/www/html

Users would then have to be the nginx user or a member of the webadmins group to access this folder – all other access was prohibited. Before cloud computing, many people shared the same server and groups would differentiate who had access to what.

The listen.group directive in the PHP-FPM pool is which group you want to be able to access the socket. The listen.mode determines which access the user, group, and other have to this socket. Permissions of 0444 would prevent anything being written to the PHP socket.

Know thy logs

Production machines should not be writing logs to disks that are local. Production machines should have a separate NIC that is connected to an internal network – over which logs should be sent. The separate NIC is there to ensure your logs are not interfering with web traffic. Below are the 4 logs of PHP applications.

nginx/apache access.log

The access log shows what people are trying to access on your server. Log formats can be adjusted, but I have found the default works quite well. The default format shows the originating IP, the HTTP status code, time accessed, the URI being accessed, and other useful information. The access log is not generally used in debugging, but it does give some great insights as to who is visiting your application.

nginx/apache error.log

The error log contains the errors your application presents to your web server. If your application produces a T_STRING php error, the line will show up here. This log is your friend. You must understand everything he says and fix it. 🙂

<php-fpm pool>-error.log

This log informs you about the stability of your process workers. If you restart them, it logs that action here. If there is something wrong with your compiled version of PHP, it will show up here.

<php-fpm pool>-slow.log

The slow log is also your friend, but it has to be enabled and configured first. The slow log is set by enabling it in the PHP-FPM pool (slowlog = /path/to/$pool-slow.log) and configuring a threshold of when it should begin logging (request_slowlog_timeout = 0). Any PHP script that runs longer than the threshold will have the stack trace written to the slow log.

In one instance when the slow log was very useful, I was asked to investigate why the admin-ajax.php of a wordpress multisite was performing poorly. When I turned on the slow log, I saw the below output.

[19-Jan-2017 19:46:02] [pool www] pid 9705
script_filename = /var/www/html/wordpress/wp-admin/admin-ajax.php
[0x00007f1f7a5e1e88] curl_exec() /var/www/html/wordpress/wp-includes/Requests/Transport/cURL.php:162
[0x00007f1f7a5e14c8] request() /var/www/html/wordpress/wp-includes/class-requests.php:379
[0x00007f1f7a5e0dd0] request() /var/www/html/wordpress/wp-includes/class-http.php:366
[0x00007f1f7a5df2d0] request() /var/www/html/wordpress/wp-includes/class-http.php:593
[0x00007f1f7a5df120] get() /var/www/html/wordpress/wp-includes/http.php:170
[0x00007f1f7a5def98] wp_remote_get() /var/www/html/wordpress/wp-content/plugins/nginx-helper/purger.php:304
[0x00007f1f7a5dea90] _do_remote_get() /var/www/html/wordpress/wp-content/plugins/nginx-helper/purger.php:242
[0x00007f1f7a5de120] purgeUrl() /var/www/html/wordpress/wp-content/plugins/nginx-helper/purger.php:394
[0x00007ffd2e85c9e0] purgeImageOnEdit() unknown:0
[0x00007f1f7a5ddbd0] call_user_func_array() /var/www/html/wordpress/wp-includes/class-wp-hook.php:298
[0x00007f1f7a5dd420] apply_filters() /var/www/html/wordpress/wp-includes/class-wp-hook.php:323
[0x00007f1f7a5dd218] do_action() /var/www/html/wordpress/wp-includes/plugin.php:453
[0x00007f1f7a5dc798] do_action() /var/www/html/wordpress/wp-includes/post.php:3430
[0x00007f1f7a5d8ff8] wp_insert_post() /var/www/html/wordpress/wp-includes/post.php:4836
[0x00007f1f7a5d8d70] wp_insert_attachment() /var/www/html/wordpress/wp-includes/post.php:3576
[0x00007f1f7a5d8638] wp_update_post() /var/www/html/wordpress/wp-admin/includes/ajax-actions.php:2497
[0x00007ffd2e85d630] wp_ajax_save_attachment() unknown:0
[0x00007f1f7a5d79a8] call_user_func_array() /var/www/html/wordpress/wp-includes/class-wp-hook.php:298
[0x00007f1f7a5d71f8] apply_filters() /var/www/html/wordpress/wp-includes/class-wp-hook.php:323
[0x00007f1f7a5d6ff0] do_action() /var/www/html/wordpress/wp-includes/plugin.php:453

The slow log first showed the script filename of which met the threshold of taking too long to execute and then shows a stack trace of what PHP methods were called in order to get to this location. The more I work with wordpress, the more I understand the issues with wordpress are not from core, but stem from the plugins a user adds to their website. In this case the issue stemmed from the nginx-helper plugin. I had manually set the two multisite settings in the nginx configuration and no longer needed this helper plugin. Unknowingly, an infinite loop was happening. Once the plugin was disabled, the infinite loop ended, and the customer was happy with the results.

Final thoughts

I did not cover everything there is to debugging PHP applications. Most find it helpful to use syntax highlighting (something I was not aware of when I first started) as well as an IDE that has PHP linting, code completion, and other features built-in. You may also want to look into using pm = static and manually determining how many child workers FPM should have. Another option is to enable the /status page and configuring your monitoring application to poll that URL. All of these settings are found and set in the PHP pool’s config file.


    David

    This is really helpful! Thanks for posting.


Add to the conversation:

Your email address will not be published. Required fields are marked *