Isolate the problem and strace multiple PHP-FPM (FastCGI Process Manager for PHP) processes to identify the culprit.
Prerequisites
Install strace utility.
$ sudo apt install strace
Preliminary notes
I will use pgrep to get process IDs as this solution is good enough for this use case.
$ pgrep php-fpm | paste -s 11183 21844 21858 21881
Strace multiple processes
Execute strace to track the PHP-FPM process activity.
$ sudo strace -f $(pgrep php-fpm | paste -s | sed -e 's/\([0-9]\+\)/-p \1/g' -e 's/\t/ /g')
[...]
[pid 23645] openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 5
[pid 23645] fstat(5, {st_mode=S_IFREG|0644, st_size=129, ...}) = 0
[pid 23645] read(5, "127.0.1.1\tnextcloud\n127.0.0.1\tlo"..., 512) = 129
[pid 23645] read(5, "", 512) = 0
[pid 23645] close(5) = 0
[pid 23645] socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 5
[pid 23645] connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, 16) = 0
[...]
Execute strace and increase the size of the printed string as the default value is relatively low (32).
$ sudo strace -s 1024 -f $(pgrep php-fpm | paste -s | sed -e 's/\([0-9]\+\)/-p \1/g' -e 's/\t/ /g')
[...]
[pid 23660] openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 5
[pid 23660] fstat(5, {st_mode=S_IFREG|0644, st_size=129, ...}) = 0
[pid 23660] read(5, "127.0.1.1\tnextcloud\n127.0.0.1\tlocalhost\n::1\t\tlocalhost ip6-localhost ip6-loopback\nff02::1\t\tip6-allnodes\nff02::2\t\tip6-allrouters\n\n", 512) = 129
[pid 23660] read(5, "", 512) = 0
[pid 23660] close(5) = 0
[pid 23660] socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 5
[pid 23660] connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, 16) = 0
[...]
Store strace output
Store strace output to a single php-fpm.strace-log using the number of seconds since the epoch and microseconds as a timestamp.
$ sudo strace -o php-fpm.strace-log -ttt -f $(pgrep php-fpm | paste -s | sed -e 's/\([0-9]\+\)/-p \1/g' -e 's/\t/ /g')
$ cat php-fpm.strace-log | grep -A6 "/etc/hosts" -m 1
[...]
24087 1561766893.359335 openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 5
24087 1561766893.359373 fstat(5, {st_mode=S_IFREG|0644, st_size=129, ...}) = 0
24087 1561766893.359406 read(5, "127.0.1.1\tnextcloud\n127.0.0.1\tlo"..., 512) = 129
24087 1561766893.359455 read(5, "", 512) = 0
24087 1561766893.359486 close(5) = 0
24087 1561766893.359521 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 5
24087 1561766893.359555 connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, 16) = 0
[...]
Store strace output to a multiple php-fpm.strace-log.<strong>$PID</strong> files.
$ sudo strace -o php-fpm.strace-log -ttt -ff $(pgrep php-fpm | paste -s | sed -e 's/\([0-9]\+\)/-p \1/g' -e 's/\t/ /g')
$ ls php-fpm.strace-log.11183 php-fpm.strace-log.24087 php-fpm.strace-log.24708 php-fpm.strace-log.24710 php-fpm.strace-log.23660 php-fpm.strace-log.24343 php-fpm.strace-log.24709 php-fpm.strace-log.24711
$ grep -A6 "/etc/hosts" -m 1 php-fpm.strace-log.*
php-fpm.strace-log.23660:1561767209.074249 openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 5
php-fpm.strace-log.23660-1561767209.074326 fstat(5, {st_mode=S_IFREG|0644, st_size=129, ...}) = 0
php-fpm.strace-log.23660-1561767209.074388 read(5, "127.0.1.1\tnextcloud\n127.0.0.1\tlo"..., 512) = 129
php-fpm.strace-log.23660-1561767209.074460 read(5, "", 512) = 0
php-fpm.strace-log.23660-1561767209.074518 close(5) = 0
php-fpm.strace-log.23660-1561767209.074576 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 5
php-fpm.strace-log.23660-1561767209.074633 connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, 16) = 0
--
php-fpm.strace-log.24087:1561767208.579327 openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 5
php-fpm.strace-log.24087-1561767208.579419 fstat(5, {st_mode=S_IFREG|0644, st_size=129, ...}) = 0
php-fpm.strace-log.24087-1561767208.579493 read(5, "127.0.1.1\tnextcloud\n127.0.0.1\tlo"..., 512) = 129
php-fpm.strace-log.24087-1561767208.579582 read(5, "", 512) = 0
php-fpm.strace-log.24087-1561767208.579648 close(5) = 0
php-fpm.strace-log.24087-1561767208.579721 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 5
php-fpm.strace-log.24087-1561767208.579809 connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, 16) = 0
--
php-fpm.strace-log.24343:1561767208.433473 openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 5
php-fpm.strace-log.24343-1561767208.433528 fstat(5, {st_mode=S_IFREG|0644, st_size=129, ...}) = 0
php-fpm.strace-log.24343-1561767208.433577 read(5, "127.0.1.1\tnextcloud\n127.0.0.1\tlo"..., 512) = 129
php-fpm.strace-log.24343-1561767208.433639 read(5, "", 512) = 0
php-fpm.strace-log.24343-1561767208.433692 close(5) = 0
php-fpm.strace-log.24343-1561767208.433751 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 5
php-fpm.strace-log.24343-1561767208.433802 connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, 16) = 0
Merge multiple strace log files using strace-log-merge utility.
That is the main reason why I am using the number of seconds since the epoch and microseconds as a timestamp – to avoid sorting problems when the trace log exceed midnight. Check out the manual page for more information.
$ strace-log-merge php-fpm.strace-log | grep -A6 "/etc/hosts" -m 1
[...]
24343 1561767208.433473 openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 5
24343 1561767208.433528 fstat(5, {st_mode=S_IFREG|0644, st_size=129, ...}) = 0
24343 1561767208.433577 read(5, "127.0.1.1\tnextcloud\n127.0.0.1\tlo"..., 512) = 129
24343 1561767208.433639 read(5, "", 512) = 0
24343 1561767208.433692 close(5) = 0
24343 1561767208.433751 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 5
24343 1561767208.433802 connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, 16) = 0
[...]
Display strace output and copy it to the php-fpm.strace-log file.
$ sudo strace -f $(pgrep php-fpm | paste -s | sed -e 's/\([0-9]\+\)/-p \1/g' -e 's/\t/ /g') 2>&1 | tee php-fpm.strace-log
# ls -l php-fpm.strace-log -rw-r--r-- 1 root root 2454720 Jun 29 00:21 php-fpm.strace-log
Strace specific events
Execute strace to track network operations.
$ sudo strace -e trace=%network -f $(pgrep php-fpm | paste -s | sed -e 's/\([0-9]\+\)/-p \1/g' -e 's/\t/ /g')
[...]
[pid 24850] socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 10
[pid 24850] connect(10, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, 16) = 0
[pid 24850] sendmmsg(10, [{msg_hdr={msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\4\322\1\0\0\1\0\0\0\0\0\1\5redis\7example\3org\0\0\1\0\1\0\0)\4\260\0\0\0\0\0\0", iov_len=46}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CTRUNC|MSG_DONTWAIT|MSG_CONFIRM|MSG_WAITFORONE|MSG_BATCH|MSG_ZEROCOPY|MSG_FASTOPEN|MSG_CMSG_CLOEXEC|0x3980010}, msg_len=46}, {msg_hdr={msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="T\342\1\0\0\1\0\0\0\0\0\1\5redis\7example\3org\0\0\34\0\1\0\0)\4\260\0\0\0\0\0\0", iov_len=46}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_TRUNC|MSG_DONTWAIT|MSG_EOR|MSG_WAITALL|MSG_FIN|MSG_NOSIGNAL|MSG_MORE|MSG_BATCH|MSG_FASTOPEN|MSG_CMSG_CLOEXEC|0x13b20000}, msg_len=46}], 2, MSG_NOSIGNAL) = 2
[pid 24850] recvfrom(10, "\4\322\201\203\0\1\0\0\0\0\0\1\5redis\7example\3org\0\0\1\0\1\0\0)\377\326\0\0\0\0\0\0", 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, [28->16]) = 46
[pid 24850] recvfrom(10, "T\342\201\203\0\1\0\0\0\0\0\1\5redis\7example\3org\0\0\34\0\1\0\0)\377\326\0\0\0\0\0\0", 65536, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, [28->16]) = 46
[pid 24850] socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 10
[...]
Execute strace to follow a specific system call.
$ sudo strace -e trace=connect -f $(pgrep php-fpm | paste -s | sed -e 's/\([0-9]\+\)/-p \1/g' -e 's/\t/ /g')
[...]
[pid 25496] connect(10, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, 16) = 0
[pid 25496] connect(10, {sa_family=AF_INET, sin_port=htons(6379), sin_addr=inet_addr("192.0.2.21")}, 16) = -1 EINPROGRESS (Operation now in progress)
[...]
Execute strace to track file operations (e.g., open, stat, chmod, unlink, …).
$ sudo strace -e trace=%file -f $(pgrep php-fpm | paste -s | sed -e 's/\([0-9]\+\)/-p \1/g' -e 's/\t/ /g')
[...]
[pid 26289] access("/srv/nextcloud/apps/logreader/composer/autoload.php", F_OK) = -1 ENOENT (No such file or directory)
[pid 26289] access("/srv/nextcloud/apps/lookup_server_connector", F_OK) = 0
[pid 26289] access("/srv/nextcloud/apps/lookup_server_connector/appinfo/info.xml", F_OK) = 0
[...]
Execute strace to track file descriptor operations.
$ sudo strace -s 1024 -e trace=%desc -f $(pgrep php-fpm | paste -s | sed -e 's/\([0-9]\+\)/-p \1/g' -e 's/\t/ /g')
[...]
[pid 26407] write(4, "\1\6\0\1\3\207\1\0Expires: Thu, 19 Nov 1981 08:52:00 GMT\r\nPragma: no-cache\r\nX-Frame-Options: SAMEORIGIN\r\nCache-Control: no-cache, no-store, must-revalidate\r\nContent-Security-Policy: default-src 'none';base-uri 'none';manifest-src 'self'\r\nETag: 3835302d181d9abc25bca79c3704ea2d\r\nContent-Type: application/json; charset=utf-8\r\nContent-Length: 573\r\n\r\n{\"ocs\":{\"meta\":{\"status\":\"ok\",\"statuscode\":200,\"message\":\"OK\"},\"data\":[{\"notification_id\":8,\"app\":\"core\",\"user\":\"milosz\",\"datetime\":\"2019-05-17T13:46:32+00:00\",\"object_type\":\"repair\",\"object_id\":\"exposing_links\",\"subject\":\"Some of your link shares have been removed\",\"message\":\"Due to a security bug we had to remove some of your link shares. Please see the link for more information.\",\"link\":\"https:\\/\\/nextcloud.com\\/security\\/advisory\\/?id=NC-SA-2019-003\",\"subjectRich\":\"\",\"subjectRichParameters\":[],\"messageRich\":\"\",\"messageRichParameters\":[],\"icon\":\"\",\"actions\":[]}]}}\0\1\3\0\1\0\10\0\0\0\0\0\0\0ff\"", 928) = 928
[pid 26407] close(4)
[...]
Execute strace to follow process operations.
$ sudo strace -s 1024 -e trace=%process -f $(pgrep php-fpm | paste -s | sed -e 's/\([0-9]\+\)/-p \1/g' -e 's/\t/ /g')
[...]
[pid 26681] clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7ff8864bfed0) = 26684
strace: Process 26684 attached
[pid 26684] execve("/bin/sh", ["sh", "-c", "command -v libreoffice"], 0x5639dc581220 /* 7 vars */) = 0
[pid 26684] arch_prctl(ARCH_SET_FS, 0x7fc48e121540) = 0
[pid 26684] exit_group(127) = ?
[pid 26684] +++ exited with 127 +++
[...]
Execute strace and print paths associated with file descriptors.
$ sudo strace -s 1024 -y -f $(pgrep php-fpm | paste -s | sed -e 's/\([0-9]\+\)/-p \1/g' -e 's/\t/ /g')
[...]
[pid 27142] openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 5</etc/hosts>
[pid 27142] fstat(5</etc/hosts>, {st_mode=S_IFREG|0644, st_size=129, ...}) = 0
[pid 27142] read(5</etc/hosts>, "127.0.1.1\tnextcloud\n127.0.0.1\tlocalhost\n::1\t\tlocalhost ip6-localhost ip6-loopback\nff02::1\t\tip6-allnodes\nff02::2\t\tip6-allrouters\n\n", 512) = 129
[pid 27142] read(5</etc/hosts>, "", 512) = 0
[pid 27142] close(5</etc/hosts>) = 0
[pid 27142] socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 5<socket:[6841240]>
[pid 27142] connect(5<socket:[6841240]>, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, 16) = 0
[pid 27142] poll([{fd=5<socket:[6841240]>, events=POLLOUT}], 1, 0) = 1 ([{fd=5, revents=POLLOUT}])
[...]
Execute strace and print additional information related to socket file descriptors.
$ sudo strace -s 1024 -yy -e trace=%network -f $(pgrep php-fpm | paste -s | sed -e 's/\([0-9]\+\)/-p \1/g' -e 's/\t/ /g')
[...] [pid 27294] sendto(10<TCP:[192.0.2.11:51044->192.0.2.21:6379]>, "*2\r\n$4\r\nAUTH\r\n$9\r\njr3kH4dEq\r\n", 29, MSG_DONTWAIT, NULL, 0) = 29 [pid 27294] recvfrom(10<TCP:[192.0.2.11:51044->192.0.2.21:6379]>, "+", 1, MSG_PEEK, NULL, NULL) = 1 [pid 27294] recvfrom(10<TCP:[192.0.2.11:51044->192.0.2.21:6379]>, "+OK\r\n", 8192, MSG_DONTWAIT, NUL L, NULL) = 5 [...]
This is a random password intended only to illustrate this example.
