在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"设为空，然后测试，发现不会分步骤了，本地测试代码没有报错。然后提交上线。

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

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

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

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

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

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

     （正常情况）    

                          

        (有问题的)

           

     可以从序列号11-12看到有问题的tcp连接在超过2秒后，client端（1.1）自动发送了FIN。服务端进行了确认，但是序列号14看到，大概4s后服务端才返回数据，这个时候客户端已经不接受数据了。

    这个时候又引入了一个怀疑点，跟书城服务器的网络参数配置有关。

   

    3、通过命令"sysctl -a | grep tcp" 查看linux内核配置的tcp相关的参数。经过各种查资料发现没有一个是跟当前2秒中断对应的上的。排除掉怀疑2

 

   4、php请求apple/pay接口是这设置的10S超时，为什么2S就返回了呢，会不会是libcurl定时器的BUG呢？

       带着问题继续找答案，php一般请求服务接口代码如下。

 

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

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

PHP_FUNCTION(curl_exec)
{
    CURLcode    error;
    zval        *zid;
    php_curl    *ch;
    if (zend_parse_parameters(ZEND_NUM_ARGS(), "r", &zid) == FAILURE) {
        return;
    }
    if ((ch = (php_curl*)zend_fetch_resource(Z_RES_P(zid), le_curl_name, le_curl)) == NULL) {
        RETURN_FALSE;
    }
    _php_curl_verify_handlers(ch, 1);
    _php_curl_cleanup_handle(ch);
    error = curl_easy_perform(ch->cp);
    ........................
    ........................
    ........................
}

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

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

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

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

curl_easy_perform    curl_multi_wait    Curl_poll

int Curl_wait_ms(int timeout_ms)
{
  if(!timeout_ms)
    return 0;
  if(timeout_ms < 0) {
    SET_SOCKERRNO(EINVAL);
    return -1;
  }
  pending_ms = timeout_ms;
  initial_tv = curlx_tvnow();
  do {
#if defined(HAVE_POLL_FINE)
    r = poll(NULL, 0, pending_ms);
#else
    pending_tv.tv_sec = pending_ms / 1000;
    pending_tv.tv_usec = (pending_ms % 1000) * 1000;
    r = select(0, NULL, NULL, NULL, &pending_tv);
#endif /* HAVE_POLL_FINE */
    if(r != -1)
      break;
    error = SOCKERRNO;
    if(error && error_not_EINTR)
      break;
    pending_ms = timeout_ms - elapsed_ms;
    if(pending_ms <= 0)
      break;
  } while(r == -1);
   
  if(r)
    r = -1;
  return r;
}

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

   

   5、难道是PHP的BUG,最新刚刚升级到PHP7。

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

sleep(5);
echo "asdadadasdsad";

以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的方式

#!/usr/bin/env python
# -*- coding: utf-8 -*-
import tornado.httpserver
import tornado.ioloop
import tornado.options
import tornado.web
import time
from tornado.options import define, options
define("port", default=8888, help="run on the given port", type=int)
class MainHandler(tornado.web.RequestHandler):
    def get(self):
        time.sleep(5)
        self.write("Hello, world")
 
def main():
    tornado.options.parse_command_line()
    application = tornado.web.Application([
        (r"/", MainHandler),
    ])
    http_server = tornado.httpserver.HTTPServer(application)
    http_server.listen(options.port)
    tornado.ioloop.IOLoop.current().start()
 
if __name__ == "__main__":
    main()

执行正常

nginx sleep 5 执行正常

  location /sub1 {
    echo_sleep 5;
    echo "hello world";
}

    上面测试均在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源码

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

pm_trace_signal源码

//开始追踪进程
int fpm_trace_signal(pid_t pid){
    if (0 > ptrace(PTRACE_ATTACH, pid, 0, 0)) {
        zlog(ZLOG_SYSERROR, "failed to ptrace(ATTACH) child %d", pid);
        return -1;
    }
    return 0;
}
//关闭追踪
int fpm_trace_close(pid_t pid){
    if (0 > ptrace(PTRACE_DETACH, pid, (void *) 1, 0)) {
        zlog(ZLOG_SYSERROR, "failed to ptrace(DETACH) child %d", pid);
        return -1;
    }
    traced_pid = 0;
    return 0;
}
//获取栈调用信息
int fpm_trace_get_long(long addr, long *data){
    errno = 0;
    *data = ptrace(PTRACE_PEEKDATA, traced_pid, (void *) addr, 0);
    if (errno) {
        zlog(ZLOG_SYSERROR, "failed to ptrace(PEEKDATA) pid %d", traced_pid);
        return -1;
    }
    return 0;
}

关键性函数来了ptrace

ptrace解释:

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

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

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

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

看出来区别没？注意正常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版本（永久）