在docker以FPM-PHP运行php，慢日志导致的BUG分析

问题描述：

        最近将IOS书城容器化，切换流量后。正常的业务测试了一般，都没发现问题。线上的错误监控系统也没有报警，以为迁移工作又告一段落了，暗暗的松了一口气。紧接着，报警邮件来了，查看发现是一个苹果支付相关接口调用的curl错误，错误码为"56"，错误描述为：“Failure with receiving network data”接收网络数据失败。

机器 : 192.168.1.1
当前URL : /xxx/recharge/apple?xxxxxxxxxxxxx
接口URL : http://192.168.1.2:18000/third/apple/pay
错误信息 : Failure with receiving network data.
错误码 : 56
type : curl
时间 : 2016-09-19 22:09:37 +0800 从09-19 21:20:15到09-19 22:09:38共计错误：11

问题分析：

   整体的业务流程：用户使用苹果支付，客户端拿到用户支付后用户返回的code，传给php，php 使用curl post提交给用户中心，用户中心拿到code后请去苹果支付的接口验证是否合法。

   怀疑方向：

            1、code有超过4000个字节长度，而curl post提交超过1024个字节后，会发送100-continue，将请求分为2步。

            2、书城服务器与接口服务器之间的网络问题

            3、libcurl的BUG（PHP这边的HTTP Clinet使用的libcurl库封装的）

            4、php7存在相关的bug

            5、docker当前版本存在bug

怀疑验证：

    1、 通过本地向用户中心支付接口发起请求，打印头信息，头信息确实返回了两次，第一次为"100-continue"。鸟哥在官网的文章中提过类似问题，在curl代码中增加设置项，将"Expect"设为空，然后测试，发现不会分步骤了，本地测试代码没有报错。然后提交上线。

1 curl_setopt($ch, CURLOPT_HTTPHEADER, array('Expect:'));

curl设置Expect

 发现错误并没有解决，报错依然存在。还原之前的代码，排除掉怀疑1。

2、将抓网卡数据包的命令给运维，让其帮忙加一下任务，监听网卡流量信息。当发现问题后，停掉脚本，发给我们。我们根据错误邮件报警时间与网卡流量中的记录进行对照

找出具体的数据包信息。命令如下：

1 tcpdump -i team0 host 192.168.7.154 and port 29000 -w /tmp/apple_pay.cap

tcpdump 抓包

后我就等着发报警邮件，发现报警之后，让运维终止掉脚本，然后通过"wireshark"分析，对比一下正常的和有问题的： 

                          

           

 

1 $ch = curl_init();//初始化curl
2 curl_setopt($ch, CURLOPT_URL, "http://192.168.7.154:29000/third/apple/pay");//设置curl请求URL
3 curl_setopt($ch, CURLOPT_TIMEOUT, 10);//设置超时
4 curl_setopt($ch, CURLOPT_POSTFIELDS, array(k=>v));//设置POST请求的数据
5 $data = curl_exec($ch);//执行请求，并获取响应数据
6 curl_close($ch); //关闭

php curl请求设置

继续深入到  curl_exec php源码中 https://github.com/php/php-src/blob/2a71140d54e956f11acbe33f2681d27086874d2e/ext/curl/interface.c#L3016

 1 PHP_FUNCTION(curl_exec)
 2 {
 3     CURLcode    error;
 4     zval        *zid;
 5     php_curl    *ch;
 6     if (zend_parse_parameters(ZEND_NUM_ARGS(), "r", &zid) == FAILURE) {
 7         return;
 8     }
 9     if ((ch = (php_curl*)zend_fetch_resource(Z_RES_P(zid), le_curl_name, le_curl)) == NULL) {
10         RETURN_FALSE;
11     }
12     _php_curl_verify_handlers(ch, 1);
13     _php_curl_cleanup_handle(ch);
14     error = curl_easy_perform(ch->cp);
15     ........................
16     ........................
17     ........................
18 }

php 内核中curl_exec的实现

发现PHP的curl_exec函数最终调用 libcurl中的curl_easy_perform函数，线上服务的libcurl是7.29.0版本，继续看libcurl源码

ibcurl 提供的C函数API大概如下，可以看出来php的curl只是对libcurl做了一个简单的封装。libcurl API列表

1 //libcurl 提供的C函数API大概如下
2 curl = curl_easy_init(); 
3 curl_easy_setopt(curl, CURLOPT_URL, "http://xxx/");
4 res = curl_easy_perform(curl); 
5 curl_easy_cleanup(curl);

libcurl 调用的基本函数

curl 设置定时器的流程大概如下：

curl_easy_perform    curl_multi_wait    Curl_poll

 

 1 int Curl_wait_ms(int timeout_ms)
 2 {
 3   if(!timeout_ms)
 4     return 0;
 5   if(timeout_ms < 0) {
 6     SET_SOCKERRNO(EINVAL);
 7     return -1;
 8   }
 9   pending_ms = timeout_ms;
10   initial_tv = curlx_tvnow();
11   do {
12 #if defined(HAVE_POLL_FINE)
13     r = poll(NULL, 0, pending_ms);
14 #else
15     pending_tv.tv_sec = pending_ms / 1000;
16     pending_tv.tv_usec = (pending_ms % 1000) * 1000;
17     r = select(0, NULL, NULL, NULL, &pending_tv);
18 #endif /* HAVE_POLL_FINE */
19     if(r != -1)
20       break;
21     error = SOCKERRNO;
22     if(error && error_not_EINTR)
23       break;
24     pending_ms = timeout_ms - elapsed_ms;
25     if(pending_ms <= 0)
26       break;
27   } while(r == -1);
28    
29   if(r)
30     r = -1;
31   return r;
32 }

libcurl 中的Curl_wait_ms函数

 整个libcurl的超时机制都没有问题，基本排除怀疑3。

   在docker里面测试 s.php测试代码如下：

1 sleep(5);
2 echo "asdadadasdsad";

php设置sleep

以http的方式请求这个php

[root@BJ-M5-PHP-7-225 apad]# time curl "http://127.0.0.1:8046/s.php"
asdadadasdsad
real    0m2.010s
user    0m0.004s
sys     0m0.005s

 

很奇怪的问题出现了 real 0m2.010s ，明明是sleep 5 秒为啥只执行了2 秒就结束了，而且还返回了数据。

php s.php 执行正常

php -S 127.0.0.1:8046（php内置的web server） 执行正常

python以web server的方式

 1 #!/usr/bin/env python
 2 # -*- coding: utf-8 -*-
 3 import tornado.httpserver
 4 import tornado.ioloop
 5 import tornado.options
 6 import tornado.web
 7 import time
 8 from tornado.options import define, options
 9 define("port", default=8888, help="run on the given port", type=int)
10 class MainHandler(tornado.web.RequestHandler):
11     def get(self):
12         time.sleep(5)
13         self.write("Hello, world")
14  
15 def main():
16     tornado.options.parse_command_line()
17     application = tornado.web.Application([
18         (r"/", MainHandler),
19     ])
20     http_server = tornado.httpserver.HTTPServer(application)
21     http_server.listen(options.port)
22     tornado.ioloop.IOLoop.current().start()
23  
24 if __name__ == "__main__":
25     main()

View Code

执行正常

nginx sleep 5 执行正常

1   location /sub1 {
2     echo_sleep 5;
3     echo "hello world";
4 }

View Code

 

    上面测试均在docker 1.10.3容量里面进行， 在物理机器上并无此问题。经过上面的测试发现，在docker 1.10.3只有以PHP-FPM运行时，才会出现此问题。

    猜想可能是fpm的问题，看了一下php-fpm.conf的配置信息。发现了request_slowlog_timeout=2s，重大发现，唯一一个2s有点重合的点。立即把修改了10s，结果测试sleep 5 正常了。

   request_slowlog_timeout是记录FPM方式执行php的慢日志时间，超过设置的时间就会有慢日志记录。很好奇为什么超过request_slowlog_timeout执行的php会出现问题，物理机为什么是正常？带着问题继续看FPM。

经过分析fpm源码，发现了使用request_slowlog_timeout的流程。在fpm work 进程处理请求时，master进程做健康检查，其中就有slowlog_timeout。

fpm_pctl_check_request_timeout源码

1 if (child->slow_logged.tv_sec == 0 && slowlog_timeout &&
2             proc.request_stage == FPM_REQUEST_EXECUTING && tv.tv_sec >= slowlog_timeout) {
3          
4     str_purify_filename(purified_script_filename, proc.script_filename, sizeof(proc.script_filename));
5     child->slow_logged = proc.accepted;
6     child->tracer = fpm_php_trace;//记录执行慢的php栈调用的回调函数
7     fpm_trace_signal(child->pid);//调用ptrace函数，追踪进程
8     ....................
9 }

fpm_pctl_check_request_timeout 慢日志记录

pm_trace_signal源码

 1 //开始追踪进程
 2 int fpm_trace_signal(pid_t pid){
 3     if (0 > ptrace(PTRACE_ATTACH, pid, 0, 0)) {
 4         zlog(ZLOG_SYSERROR, "failed to ptrace(ATTACH) child %d", pid);
 5         return -1;
 6     }
 7     return 0;
 8 }
 9 //关闭追踪
10 int fpm_trace_close(pid_t pid){
11     if (0 > ptrace(PTRACE_DETACH, pid, (void *) 1, 0)) {
12         zlog(ZLOG_SYSERROR, "failed to ptrace(DETACH) child %d", pid);
13         return -1;
14     }
15     traced_pid = 0;
16     return 0;
17 }
18 //获取栈调用信息
19 int fpm_trace_get_long(long addr, long *data){
20     errno = 0;
21     *data = ptrace(PTRACE_PEEKDATA, traced_pid, (void *) addr, 0);
22     if (errno) {
23         zlog(ZLOG_SYSERROR, "failed to ptrace(PEEKDATA) pid %d", traced_pid);
24         return -1;
25     }
26     return 0;
27 }

获取php栈调用的函数

关键性函数来了ptrace

ptrace解释:

       ptrace 提供了一种机制使得父进程可以观察和控制子进程的执行过程，ptrace 还可以检查和修改该子进程的可执行文件在内存中的镜像及该子进程所使用的寄存器中的值。这种用法通常来说，主要用于实现对进程插断点和跟踪子进程的系统调用。是的你没有想错，strace、gdb就是通过它实现的。

      为啥说ptrace是关键性函数呢？看如下两种strace跟踪系统调用。

 1 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 2 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], SA_RESTORER, 0x7fc8f5ee7670}, 8) = 0
 3 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 4 nanosleep({5, 0}, {2, 499689873}) = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
 5 --- SIGSTOP {si_signo=SIGSTOP, si_code=SI_USER, si_pid=1879, si_uid=0} ---
 6 --- stopped by SIGSTOP ---
 7 --- SIGCONT {si_signo=SIGCONT, si_code=SI_USER, si_pid=1879, si_uid=0} ---
 8 restart_syscall(<... resuming interrupted call ...>) = 0  //请注意这行
 9 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
10 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], SA_RESTORER, 0x7fc8f5ee7670}, 8) = 0
11 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0

正常的strace追踪

 1 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 2 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], SA_RESTORER, 0x7fc8f5ee7670}, 8) = 0
 3 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 4 nanosleep({5, 0}, {2, 499689873}) = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
 5 --- SIGSTOP {si_signo=SIGSTOP, si_code=SI_USER, si_pid=1879, si_uid=0} ---
 6 --- stopped by SIGSTOP ---
 7 --- SIGCONT {si_signo=SIGCONT, si_code=SI_USER, si_pid=1879, si_uid=0} ---
 8 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 9 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], SA_RESTORER, 0x7fc8f5ee7670}, 8) = 0
10 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0

异常的strace追踪，在docker 1.10.3中

看出来区别没？注意正常strace追踪的第8行，restart_syscall(<... resuming interrupted call ...>)，重新恢复中断的调用。

PHP的慢日志实现方式是这样的：

      1、调用ptrace的PTRACE_ATTACH命令，master会进程通过向子进程发送SIGSTOP信号，此时子进程会变成TASK_TRACED状态，被追踪状态。

          即：ptrace(PTRACE_ATTACH, pid, 0, 0)); 这行代码

     2、 调用ptrace的PTRACE_PEEKDATA命令，来获取子进程的栈调用信息。

          即：ptrace(PTRACE_PEEKDATA, traced_pid, (void *) addr, 0); 这行代码

    3、 调用ptrace的PTRACE_DETACH命令，结束追踪。master会进程通过向子进程发送 PTRACE_CONT信号，此时子进程会变成TASK_RUNING状态。

          即：ptrace(PTRACE_DETACH, pid,(void *) 1, 0); 这行代码

    问题在于 docker 1.10.3 中 收到 SIGCONT信号后，并没有执行restart_syscall，恢复进程执行的上下文，改变了进程运行时上下文。

    因此子进程受到SIGSTOP到SIGCONT这段时间内，正在被执行的函数由于运行时上下文导致执行异常。后面的代码继续执行。

      sleep(5);
      echo "asdadadasdsad";

      php中的这两行代码，在执行到sleep(5)的过程中，触发了fpm的慢日志记录，进程被暂停，等到恢复时，由于docker 1.10.3BUG，进程上下文被改变导致sleep执行出问题，但是后面的echo 继续执行。

   6、将docker版本从1.10.3升级到1.11.2，通过步骤5的测试，发现问题不存在。

结论：

      1、罪魁祸首是docker1.10.3的SIGCONT信号处理BUG，而且fpm slowlog配置"request_slowlog_timeout=2s"调用了ptrace正好发送了SIGCONT信号。

      2、php curl接口之前设置的超时时间为10秒，而由于支付接口请求苹果支付那边的时间比较长，会出现很多超时现象

问题解决办法：

    1、目前先通过关闭fpm的slowlog来解决（临时）

    2、后续会全量升级docker版本（永久）