php+nginx 服务发生500 502错误排查思路

2bdenny 发布于2019-07-25 14:52 / 3636人阅读

摘要：概述当线上的服务中访问中出现或者错误时，需要紧急处理，排查问题，该怎么做可以通过分析一些错误日志或者跟踪进程来进行问题定位。

概述

当线上的服务中访问中出现500或者502错误时，需要紧急处理，排查问题，该怎么做？可以通过分析一些错误日志或者跟踪php-fpm进程来进行问题定位。

nginx error_log

nginx的error_log在nginx的配置文件中定义的

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;
    }
}

查看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，连接被重置了，此时可以再查看php-fpm的error_log进一步分析问题

php-fpm error_log

php-fpm的error_log在php-fpm.conf文件中配置中定义的

; 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.log

error_log里面的内容是这样的

➜  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 started

可以看到是请求/var/www/index.php文件出现了超时

dtruss

dtruss是动态跟踪命令，可以根据PID，name跟踪进程
mac环境下使用dtruss，linux环境可以使用strace，pstack

➜ 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 size

eg,

   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 children

跟踪php-fpm：sudo dtruss -a -n php-fpm
此时访问web页面，就可以看到跟踪内容

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", 0x7FFEE1ECFF38, 0x0)         = 0 0
21416/0x3479b6:      1884       9      6 lstat64("/var/www", 0x7FFEE1ECFDF8, 0x0)         = 0 0
21416/0x3479b6:      1889       6      3 lstat64("/var", 0x7FFEE1ECFCB8, 0x0)         = 0 0
21416/0x3479b6:      1899      12      8 readlink("/var", 0x7FFEE1ED0090, 0x400)         = 11 0
21416/0x3479b6:      1905       6      4 lstat64("/private/var", 0x7FFEE1ECFB78, 0x0)         = 0 0
21416/0x3479b6:      1917       6      3 lstat64("/private", 0x7FFEE1ECFA38, 0x0)         = 0 0
21416/0x3479b6:      2178      18     14 stat64("/var/www/.user.ini", 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(".", 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", 0x7FFEE1ED0080, 0x0)         = 0 0
21416/0x3479b6:      3681      11      8 chdir("/var/www", 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", 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, "", 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 0

可以看到系统底层执行的函数，如lstat64获取文件内容信息，kill(21416, 15)kill掉php-fpm进程，fork()出新的php-fpm进程，有兴趣可以深入研究每个指令的作用

参考

https://www.cnblogs.com/leezh...

云服务器 GPU云服务器 php 错误排查 php500错误云服务器出现502错误 502网关错误是什么错误

文章版权归作者所有，未经允许请勿转载,若此文章存在违规行为，您可以联系管理员删除。

转载请注明本文地址：https://www.ucloud.cn/yun/40542.html

PHP程序员必备基础

摘要：版本的特性并行的三次握手四次挥手粘包问题，连接池，攻击通信原理加密算法配置文件逐行理解与配置配置规则错误的排查架构原理的理解的了解配置文件进程数与和内存的关系垃圾回收内存泄漏运行过程协议与的区别注是扩展库版本是版本算法一致性 1,http (1)request reponse (2)code:200 302,304 400 404 403 500 502 504 nginx499 ...

Coly 2019-06-27 11:21 评论0 收藏0
React 实践项目（五）Docker Nginx 部署 React

摘要：在上已经有接近的数了，是目前最热门的前端框架。将整个应用打包发布，自动试用进行压缩与优化。毫无疑问，这些重担都将压在企业开发人员身上团队之间如何高效协调，快速交付产品，快速部署应用，以及满足企业业务需求，是开发人员亟需解决的问题。 React在Github上已经有接近70000的 star 数了，是目前最热门的前端框架。而我学习React也有一段时间了，现在就开始用 React+Red...

EscapedDog 2019-07-25 13:59 评论0 收藏0
React 实践项目（五）Docker Nginx 部署 React

摘要：在上已经有接近的数了，是目前最热门的前端框架。将整个应用打包发布，自动试用进行压缩与优化。毫无疑问，这些重担都将压在企业开发人员身上团队之间如何高效协调，快速交付产品，快速部署应用，以及满足企业业务需求，是开发人员亟需解决的问题。 React在Github上已经有接近70000的 star 数了，是目前最热门的前端框架。而我学习React也有一段时间了，现在就开始用 React+Red...

jsyzchen 2019-08-20 18:25 评论0 收藏0