在docker以FPM-PHP運行php，慢日誌致使的BUG分析

時間 2019-11-13

標籤 docker fpm php 運行日誌致使 bug 分析欄目 Docker 简体版

原文原文鏈接

問題描述：php

最近將IOS書城容器化，切換流量後。正常的業務測試了通常，都沒發現問題。線上的錯誤監控系統也沒有報警，覺得遷移工做又告一段落了，暗暗的鬆了一口氣。緊接着，報警郵件來了，查看發現是一個蘋果支付相關接口調用的curl錯誤，錯誤碼爲"56"，錯誤描述爲：「Failure with receiving network data」接收網絡數據失敗。html

機器 : 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共計錯誤：11python

問題分析：linux

總體的業務流程：用戶使用蘋果支付，客戶端拿到用戶支付後用戶返回的code，傳給php，php 使用curl post提交給用戶中心，用戶中心拿到code後請去蘋果支付的接口驗證是否合法。nginx

懷疑方向：git

一、code有超過4000個字節長度，而curl post提交超過1024個字節後，會發送100-continue，將請求分爲2步。github

二、書城服務器與接口服務器之間的網絡問題web

三、libcurl的BUG（PHP這邊的HTTP Clinet使用的libcurl庫封裝的）docker

四、php7存在相關的bugc#

五、docker當前版本存在bug

懷疑驗證：

一、經過本地向用戶中心支付接口發起請求，打印頭信息，頭信息確實返回了兩次，第一次爲"100-continue"。鳥哥在官網的文章中提過相似問題，在curl代碼中增長設置項，將"Expect"設爲空，而後測試，發現不會分步驟了，本地測試代碼沒有報錯。而後提交上線。

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

curl設置Expect

發現錯誤並無解決，報錯依然存在。還原以前的代碼，排除掉懷疑1。

二、將抓網卡數據包的命令給運維，讓其幫忙加一下任務，監聽網卡流量信息。當發現問題後，停掉腳本，發給咱們。咱們根據錯誤郵件報警時間與網卡流量中的記錄進行對照

找出具體的數據包信息。命令以下：

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

tcpdump 抓包

後我就等着發報警郵件，發現報警以後，讓運維終止掉腳本，而後經過"wireshark"分析，對比一下正常的和有問題的：

（正常狀況）

(有問題的)

能夠從序列號11-12看到有問題的tcp鏈接在超過2秒後，client端（1.1）自動發送了FIN。服務端進行了確認，可是序列號14看到，大概4s後服務端才返回數據，這個時候客戶端已經不接受數據了。

這個時候又引入了一個懷疑點，跟書城服務器的網絡參數配置有關。

三、經過命令"sysctl -a | grep tcp" 查看linux內核配置的tcp相關的參數。通過各類查資料發現沒有一個是跟當前2秒中斷對應的上的。排除掉 懷疑2

四、php請求apple/pay接口是這設置的10S超時，爲何2S就返回了呢，會不會是libcurl定時器的BUG呢？

帶着問題繼續找答案，php通常請求服務接口代碼以下。

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。

五、難道是PHP的BUG,最新剛剛升級到PHP7。

在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的慢日誌實現方式是這樣的：

一、調用ptrace的PTRACE_ATTACH命令，master會進程經過向子進程發送SIGSTOP信號，此時子進程會變成TASK_TRACED狀態，被追蹤狀態。

即：ptrace(PTRACE_ATTACH, pid, 0, 0)); 這行代碼

二、調用ptrace的PTRACE_PEEKDATA命令，來獲取子進程的棧調用信息。

即：ptrace(PTRACE_PEEKDATA, traced_pid, (void *) addr, 0); 這行代碼

三、調用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 繼續執行。

六、將docker版本從1.10.3升級到1.11.2，經過步驟5的測試，發現問題不存在。

結論：

一、罪魁禍首是docker1.10.3的SIGCONT信號處理BUG，並且fpm slowlog配置"request_slowlog_timeout=2s"調用了ptrace正好發送了SIGCONT信號。

二、php curl接口以前設置的超時時間爲10秒，而因爲支付接口請求蘋果支付那邊的時間比較長，會出現不少超時現象

問題解決辦法：

一、目前先經過關閉fpm的slowlog來解決（臨時）

二、後續會全量升級docker版本（永久）

相關標籤/搜索

每日一句

每一个你不满意的现在，都有一个你没有努力的曾经。