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.
$ 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.