0

I am running CentOS 7 with Nginx/PHP-FPM. To debug a couple of slow Wordpress and CodeIgniter requests I activated PHP-FPMs slow log feature in www-pool.conf:

slowlog = /var/log/php-fpm/www-slow.log
request_slowlog_timeout = 4s

The slow requests are getting logged but the meaningful stack trace are not printed to www-slow.log. The file is being generated but empty and the default error.log is showing entries like this:

[12-Nov-2017 16:50:26] WARNING: [pool www] child 21497, script '/usr/share/nginx/www/wordpress/index.php' (request: "GET /index.php") executing too slow (4.161874 sec), logging
[12-Nov-2017 16:50:26] ERROR: failed to ptrace(ATTACH) child 21491: Operation not permitted (1)
[12-Nov-2017 16:50:26] WARNING: [pool www] child 21491, script '/usr/share/nginx/www/wordpress/index.php' (request: "GET /index.php") executing too slow (4.590854 sec), logging
[12-Nov-2017 16:50:26] ERROR: failed to ptrace(ATTACH) child 21490: Operation not permitted (1)
[12-Nov-2017 16:50:26] WARNING: [pool www] child 21490, script '/usr/share/nginx/www/wordpress/index.php' (request: "GET /index.php") executing too slow (4.620915 sec), logging
[12-Nov-2017 18:03:52] ERROR: failed to ptrace(ATTACH) child 21523: Operation not permitted (1)
[12-Nov-2017 18:03:52] WARNING: [pool www] child 21523, script '/usr/share/nginx/www/wordpress/wp-admin/index.php' (request: "GET /wp-admin/index.php") executing too slow (4.366918 sec), logging

The log files/folder are owned by php-fpm user under which php-fpm is running.

Any ideas?

Petter H
  • 3,443
  • 1
  • 16
  • 19
travisbotello
  • 23
  • 1
  • 7

1 Answers1

4

This is being caused by SELinux, which blocks the web server (and PHP, which runs under the web server's context) from attaching to processes to trace their execution.

This was reported to Red Hat some time ago, but they declined to do anything about it.

You can check your /var/log/audit/audit.log and you'll find this denial logged in an AVC similar to:

type=AVC msg=audit(05/21/2015 21:37:21.028:14259) : avc: denied { sys_ptrace } for pid=1385 comm=php-fpm capability=sys_ptrace scontext=system_u:system_r:httpd_t:s0 tcontext=system_u:system_r:httpd_t:s0 tclass=capability

To resolve the problem for your own server, you can create a local SELinux policy module with audit2allow. Feed the AVC to audit2allow by standard input, something like this:

$ audit2allow -M php_ptrace

type=AVC msg=audit(05/21/2015 21:37:21.028:14259) : avc: denied { sys_ptrace } for pid=1385 comm=php-fpm capability=sys_ptrace scontext=system_u:system_r:httpd_t:s0 tcontext=system_u:system_r:httpd_t:s0 tclass=capability

You run the command and then paste in the AVC log entry into the terminal and press Ctrl-D. You'll get a generated policy and instructions:

******************** IMPORTANT ***********************
To make this policy package active, execute:

semodule -i php_ptrace.pp

So, run that command, and you're done.

Michael Hampton
  • 244,070
  • 43
  • 506
  • 972
  • Created and applied the rule. Now error.log is printing the following messages: `[12-Nov-2017 20:07:19] ERROR: failed to ptrace(ATTACH) child 21493: Permission denied (13) [12-Nov-2017 20:07:19] WARNING: [pool www] child 21493, script '/usr/share/nginx/www/wp/index.php' (request: "GET /index.php") executing too slow (4.807994 sec), logging`. From `Operation not permitted (1)` to `Permission denied (13)` – travisbotello Nov 12 '17 at 19:09
  • Okay, just fed `$ audit2allow -M php_ptrace` with new audit.log msg again. It is working. Thanks!!! – travisbotello Nov 12 '17 at 19:19
  • This answer was very helpful, and allowed tracing some slow loading requests on our server. If you find that `ptrace` is still being denied by SELinux after creating the policy using `audit2allow` and installing using `semodule -i php_ptrace.dd`, you may also need to enable the SELinux module after installing it, if it doesn't become enabled automatically using `semodule -e php_ptrace` (the `-e` flag is short for `--enable`) and it seems for this second command that the `.pp` extension is not needed or recognized. Hope this helps, as it seemed to be the missing step for me on RHEL8. – bluebinary Jan 26 '22 at 07:43