Nginx Amplify failed to report PHP-FPM stats after some minutes

Question

VPS:DigitalOcean Amplify:v0.43 Nginx:v1.13.0 PHP-FPM:v7.0.19 OS: CentOS7

I´m trying to enable php-fpm-metrics in Nginx-Amplify reporting tool. It works for a few minutes, then get errors in /var/log/amplify-agent/agent.log after service restart

agent.conf (relevant parts):

[credentials]
api_key = ******************
hostname =
uuid = *******************
imagename =

[nginx]
user = nginx
stub_status = /nginx_status

[extensions]   
phpfpm = True  

agent.log (ERROR):

2017-05-30 21:30:48,374 [21034] supervisor running /usr/sbin/nginx -t -c /etc/nginx/nginx.conf
2017-05-30 21:31:18,079 [21034] supervisor failed to find php-fpm bin path, last attempt: "ls -la /proc/24400/exe" failed due to AmplifySubprocessError
2017-05-30 20:37:18,394 [9929] supervisor run failed
 Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/amplify/agent/managers/abstract.py", line 135, in _run
self._start_objects()
  File "/usr/lib/python2.7/site-packages/amplify/agent/managers/abstract.py", line 123, in _start_objects
child_obj.start()
File "/usr/lib/python2.7/site-packages/amplify/agent/objects/abstract.py", line 149, in start
context.log.debug('starting object "%s" %s' % (self.type, self.definition_hash))
File "/usr/lib/python2.7/site-packages/amplify/agent/objects/abstract.py", line 84, in definition_hash
definition_string = str(map(lambda x: u'%s:%s' % (x, self.definition[x]), sorted(self.definition.keys())))
File "/usr/lib/python2.7/site-packages/amplify/ext/abstract/object.py", line 47, in definition
return {'type': self.type, 'local_id': self.local_id, 'root_uuid': self.root_uuid}
File "/usr/lib/python2.7/site-packages/amplify/agent/objects/abstract.py", line 115, in local_id
self._local_id = hashlib.sha256('_'.join(self.local_id_args)).hexdigest()
TypeError: sequence item 0: expected string, list found

PHP-FPM /etc/php-fpm.d/www.conf (relevant parts):

[www]
user = nginx
group = nginx

listen = /var/run/php-fpm/php-fpm.sock
listen.backlog = 16383
listen.allowed_clients = 127.0.0.1

pm = dynamic
pm.max_children = 25
pm.start_servers = 10
pm.min_spare_servers = 5
pm.max_spare_servers = 10
pm.max_requests = 500

pm.status_path = /php_status

Nginx.conf (relevant parts):

user nginx nginx;

As noticed in the docs, this works:

$ SCRIPT_NAME=/php_status SCRIPT_FILENAME=/php_status QUERY_STRING= REQUEST_METHOD=GET cgi-fcgi -bind -connect /var/run/php-fpm/php-fpm.sock

Result:

X-Powered-By: PHP/7.0.19
Expires: Thu, 01 Jan 1970 00:00:00 GMT
Cache-Control: no-cache, no-store, must-revalidate, max-age=0
Content-type: text/plain;charset=UTF-8

pool:                 www
process manager:      dynamic
start time:           29/May/2017:15:40:29 +0200
start since:          107193
accepted conn:        806252
listen queue:         0
max listen queue:     0
listen queue len:     0
idle processes:       10
active processes:     14
total processes:      24
max active processes: 25
max children reached: 1840
slow requests:        330

I guess the problem is, a restarting process and a "changing" pid after some time:

supervisor failed to find php-fpm bin path, last attempt: "ls -la /proc/24400/exe" failed due to AmplifySubprocessError

Not sure but maybe pm.max_requests = 500 is reponible for that.

Answer 1

Thanks for the report!

There are two issues that are affecting your system here. The first is that we are unable to find the bin_path for your phpfpm via ls:

supervisor failed to find php-fpm bin path, last attempt: "ls -la /proc/24400/exe" failed due to AmplifySubprocessError

This means that the user our agent is running as does not have permissions to access the proc filesystem for your phpfpm master process or any of it's child pools. This information is purely meta-related and should not affect the running of agent or it's collection of phpfpm metrics from the its status page. The information we collect is your bin_path and then we run --version on it to gather version information about your phpfpm in order to display in in your inventory.

That said, we are releasing a new agent 0.44 at the end of this week (Fri Jun 16, 2017) or early next week (Mon Jun 19, 2017) that has a number of improvements to this work flow and may benefit you.

The second issue that affects your system is more serious and can affect your agent runtime:

17-05-30 21:31:18,079 [21034] supervisor failed to find php-fpm bin path, last attempt: "ls -la /proc/24400/exe" failed due to AmplifySubprocessError
2017-05-30 20:37:18,394 [9929] supervisor run failed
 Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/amplify/agent/managers/abstract.py", line 135, in _run
self._start_objects()
  File "/usr/lib/python2.7/site-packages/amplify/agent/managers/abstract.py", line 123, in _start_objects
child_obj.start()
File "/usr/lib/python2.7/site-packages/amplify/agent/objects/abstract.py", line 149, in start
context.log.debug('starting object "%s" %s' % (self.type, self.definition_hash))
File "/usr/lib/python2.7/site-packages/amplify/agent/objects/abstract.py", line 84, in definition_hash
definition_string = str(map(lambda x: u'%s:%s' % (x, self.definition[x]), sorted(self.definition.keys())))
File "/usr/lib/python2.7/site-packages/amplify/ext/abstract/object.py", line 47, in definition
return {'type': self.type, 'local_id': self.local_id, 'root_uuid': self.root_uuid}
File "/usr/lib/python2.7/site-packages/amplify/agent/objects/abstract.py", line 115, in local_id
self._local_id = hashlib.sha256('_'.join(self.local_id_args)).hexdigest()
TypeError: sequence item 0: expected string, list found

I can't say for sure for your system, but other customers have reported this error when our agent discovers an orphaned phpfpm pool worker. For example the output of ps xao pid,ppid,command | grep 'php-fpm[:]' might be:

[
    '15923     1 php-fpm: master process (/etc/php-fpm.conf)',
    '20704 15923 php-fpm: pool www',
    '20925 15923 php-fpm: pool www',
    '21350 15923 php-fpm: pool www',
    '21385 15923 php-fpm: pool www',
    '21386 15923 php-fpm: pool www',
    '21575 15923 php-fpm: pool www',
    '21699 15923 php-fpm: pool www',
    '21734 15923 php-fpm: pool www',
    '21735 15923 php-fpm: pool www',
    '21781 15923 php-fpm: pool www',
    '21782 15923 php-fpm: pool www',
    '22287 15923 php-fpm: pool www',
    '22330 15923 php-fpm: pool www',
    '22331 15923 php-fpm: pool www',
    '22495 15923 php-fpm: pool www',
    '22654 21386 php-fpm: pool www',  # <---- Orphan?
    ''
]

We are still investigating what can lead to this, but for now we have made our agent more robust by handling this situation silently. This fix can be found in our agent version 0.44 which should be released shortly as detailed above.

If you are still interested, I would highly recommend you download and install agent 0.44 when it is released. If you still see issues on your system please don't hesitate to reach out to us through our customer support channels.

I would also suggest you consider checking your own system to see if you have any "orphaned" pool workers as it has the potential to be indicative of other issues. But again, our new agent will appropriately catch and handle this situation.

I hope this helps!

Grant (NGINX Amplify agent contributor)