An overview of the
When there are 500 or 502 errors in the online service access, it is urgent to deal with and troubleshoot the problem. What should we do? You can locate the problem by analyzing some error logs or tracing the php-fpm process.
nginx error_log
error_log of nginx is defined in the nginx configuration file
server {
listen 80;
server_name localhost;
root /var/www;
access_log /Users/jiao/logs/default.access.log;
error_log /Users/jiao/logs/default.error.log;
location / {
index index.html index.htm index.php;
autoindex on;
}
location = /info {
allow 127.0.0.1;
deny all;
rewrite (.*) /.info.php;
}
location ~ \.php$ {
root /var/www;
fastcgi_pass 127.0.0.1:9000;
fastcgi_index index.php;
fastcgi_param SCRIPT_FILENAME /var/www$fastcgi_script_name;
include /usr/local/etc/nginx/fastcgi_params;
}
}Check the error_log
[
➜ tail /Users/jiao/logs/default.error.log 2019/07/17 11:08:18 [error] 77416#0: *76 kevent() reported about an closed connection (54: Connection reset by peer) while reading response header from upstream, client: 127.0.0.1, server: localhost, request: “GET / HTTP/1.1”, upstream: “fastcgi://127.0.0.1:9000”, host: “localhost”
]
Connection reset by peer has been detected and the connection has been reset. At this point, you can check error_log of php-fpm again to further analyze the problem
php-fpm error_log
The error_log of php-fpm is defined in the php-fpm.conf file configuration
; Error log file
; If it's set to "syslog", log is sent to syslogd instead of being written
; in a local file.
; Note: the default prefix is /usr/local/var
; Default Value: log/php-fpm.log
error_log = log/php-fpm.logSo error_log looks like this
➜ tail /usr/local/var/log/php-fpm.log
[17-Jul-2019 10:49:54] NOTICE: [pool www] child 81948 started
[17-Jul-2019 11:08:18] WARNING: [pool www] child 77537, script '/var/www/index.php' (request: "GET /index.php") execution timed out (3.801267 sec), terminating
[17-Jul-2019 11:08:18] WARNING: [pool www] child 77537 exited on signal 15 (SIGTERM) after 1503.113967 seconds from start
[17-Jul-2019 11:08:18] NOTICE: [pool www] child 94339 startedCan see is a request/var/www/index php file a timeout
dtruss
dtruss is a dynamic trace command that can trace processes according to PID, name
dtruss can be used in mac environment, and strace and pstack can be used in linux environment
➜ dtruss
USAGE: dtruss [-acdefholLs] [-t syscall] { -p PID | -n name | command | -W name } -p PID # examine this PID
-n name # examine this process name
-t syscall # examine this syscall only
-W name # wait for a process matching this name
-a # print all details
-c # print syscall counts
-d # print relative times (us)
-e # print elapsed times (us)
-f # follow children
-l # force printing pid/lwpid
-o # print on cpu times
-s # print stack backtraces
-L # don't print pid/lwpid
-b bufsize # dynamic variable buf sizeeg,
dtruss df -h # run and examine "df -h"
dtruss -p 1871 # examine PID 1871
dtruss -n tar # examine all processes called "tar"
dtruss -f test.sh # run test.sh and follow childrenTracking php - fpm: sudo dtruss -a -n php-fpm
Visit the web page at this point and you can see the trace content
21416/0x3479b6: 1559 63 3 getrusage(0x0, 0x7FFEE1EC0760, 0x0) = 0 0
21416/0x3479b6: 1561 4 0 getrusage(0xFFFFFFFFFFFFFFFF, 0x7FFEE1EC0760, 0x0) = 0 0
21416/0x3479b6: 1627 77 17 poll(0x7FFEE1EC08C0, 0x1, 0x1388) = 1 0
dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
21416/0x3479b6: 1872 29 24 lstat64("/var/www/index.php\0", 0x7FFEE1ECFF38, 0x0) = 0 0
21416/0x3479b6: 1884 9 6 lstat64("/var/www\0", 0x7FFEE1ECFDF8, 0x0) = 0 0
21416/0x3479b6: 1889 6 3 lstat64("/var\0", 0x7FFEE1ECFCB8, 0x0) = 0 0
21416/0x3479b6: 1899 12 8 readlink("/var\0", 0x7FFEE1ED0090, 0x400) = 11 0
21416/0x3479b6: 1905 6 4 lstat64("/private/var\0", 0x7FFEE1ECFB78, 0x0) = 0 0
21416/0x3479b6: 1917 6 3 lstat64("/private\0", 0x7FFEE1ECFA38, 0x0) = 0 0
21416/0x3479b6: 2178 18 14 stat64("/var/www/.user.ini\0", 0x7FFEE1ED0240, 0x0) = -1 Err#2
21416/0x3479b6: 2217 5 1 setitimer(0x2, 0x7FFEE1ED07E0, 0x0) = 0 0
21416/0x3479b6: 2225 4 0 sigaction(0x1B, 0x7FFEE1ED0788, 0x7FFEE1ED07B0) = 0 0
21416/0x3479b6: 2237 5 1 sigprocmask(0x2, 0x7FFEE1ED0804, 0x0) = 0x0 0
21416/0x3479b6: 3643 48 40 open_nocancel(".\0", 0x0, 0x1) = 5 0
21416/0x3479b6: 3648 7 3 fstat64(0x5, 0x7FFEE1ED0110, 0x0) = 0 0
21416/0x3479b6: 3653 7 2 fcntl_nocancel(0x5, 0x32, 0x10F252158) = 0 0
21416/0x3479b6: 3661 12 7 close_nocancel(0x5) = 0 0
21416/0x3479b6: 3670 10 7 stat64("/usr/local/var\0", 0x7FFEE1ED0080, 0x0) = 0 0
21416/0x3479b6: 3681 11 8 chdir("/var/www\0", 0x0, 0x0) = 0 0
21416/0x3479b6: 3698 4 0 setitimer(0x2, 0x7FFEE1ED02D0, 0x0) = 0 0
21416/0x3479b6: 3710 6 3 fcntl(0x3, 0x8, 0x10F3FD858) = 0 0
21416/0x3479b6: 3733 9 6 stat64("/private/var/www/index.php\0", 0x7FFEE1ECFF10, 0x0) = 0 0
74904/0x332630: 723125 1073381 19 kevent(0x9, 0x0, 0x0) = 0 0
74902/0x332629: 770666 1073387 17 kevent(0x8, 0x0, 0x0) = 0 0
74904/0x332630: 723165 1061954 20 kevent(0x9, 0x0, 0x0) = 0 0
74902/0x332629: 770709 1061954 20 kevent(0x8, 0x0, 0x0) = 0 0
74904/0x332630: 723201 1074786 16 kevent(0x9, 0x0, 0x0) = 0 0
74902/0x332629: 770747 1074783 16 kevent(0x8, 0x0, 0x0) = 0 0
74904/0x332630: 723229 1069141 13 kevent(0x9, 0x0, 0x0) = 0 0
74902/0x332629: 770777 1069145 11 kevent(0x8, 0x0, 0x0) = 0 0
21416/0x3479b6: 3942 3902233 7 __semwait_signal(0x703, 0x0, 0x1) = -1 Err#4
74902/0x332629: 770814 103 25 kill(21416, 15) = 0 0
dtrace: error on enabled probe ID 2172 (ID 161: syscall::write:return): invalid kernel access in action #13 at DIF offset 68
dtrace: error on enabled probe ID 2172 (ID 161: syscall::write:return): invalid kernel access in action #13 at DIF offset 68
74902/0x332629: 771325 7 2 sigreturn(0x7FFEE1ECFC40, 0x1E, 0xC1A4B78E0404663A) = 0 Err#-2
74902/0x332629: 771336 7 3 kevent(0x8, 0x0, 0x0) = 1 0
dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
74902/0x332629: 771352 11 7 wait4(0xFFFFFFFFFFFFFFFF, 0x7FFEE1ED0748, 0x3) = 21416 0
dtrace: error on enabled probe ID 2172 (ID 161: syscall::write:return): invalid kernel access in action #13 at DIF offset 68
74902/0x332629: 773511 1957 1899 fork() = 28060 0
28060/0x3754c5: 125: 0: 0 fork() = 0 0
28060/0x3754c5: 128 9 2 bsdthread_register(0x7FFF6774C418, 0x7FFF6774C408, 0x2000) = -1 Err#22
dtrace: error on enabled probe ID 2172 (ID 161: syscall::write:return): invalid kernel access in action #13 at DIF offset 68
74902/0x332629: 773737 4 1 wait4(0xFFFFFFFFFFFFFFFF, 0x7FFEE1ED0748, 0x3) = 0 0
74902/0x332629: 773742 6 3 read(0x5, "\0", 0x1) = -1 Err#35
28060/0x3754c5: 320 4 0 getpid(0x0, 0x0, 0x0) = 28060 0
28060/0x3754c5: 328 7 2 __mac_syscall(0x7FFF67758A17, 0x4, 0x7FFEE1ED0208) = -1 Err#45
28060/0x3754c5: 332 5 2 csops(0x6D9C, 0xB, 0x7FFEE1ED0248) = -1 Err#22
28060/0x3754c5: 755 14 11 dup2(0x1, 0x2, 0x0) = 2 0
28060/0x3754c5: 797 89 22 close(0x4) = 0 0
28060/0x3754c5: 806 11 6 dup2(0x7, 0x0, 0x0) = 0 0
28060/0x3754c5: 817 4 0 geteuid(0x0, 0x0, 0x0) = 501 0
28060/0x3754c5: 820 3 0 close(0x5) = 0 0
28060/0x3754c5: 821 3 0 close(0x6) = 0 0
28060/0x3754c5: 824 5 1 sigaction(0xF, 0x7FFEE1ED0688, 0x0) = 0 0
28060/0x3754c5: 825 3 0 sigaction(0x2, 0x7FFEE1ED0688, 0x0) = 0 0
28060/0x3754c5: 827 3 0 sigaction(0x1E, 0x7FFEE1ED0688, 0x0) = 0 0
28060/0x3754c5: 828 3 0 sigaction(0x1F, 0x7FFEE1ED0688, 0x0) = 0 0
28060/0x3754c5: 829 3 0 sigaction(0x14, 0x7FFEE1ED0688, 0x0) = 0 0
28060/0x3754c5: 830 3 0 sigaction(0x3, 0x7FFEE1ED0688, 0x0) = 0 0
28060/0x3754c5: 1043 3 0 close(0x7) = 0 0You can see the functions performed at the bottom of the system, such as lstat64 obtaining the file content information, kill(21416, 15)kill dropping the php-fpm process, fork() producing the new php-fpm process. If you are interested, you can further study the role of each instruction
reference