php打印warning日志引發的core追查

來源:本站原創 專業IT吐槽 超過597 views圍觀 0條評論

TAG

fastcgi,php,core,fcgi_write,sapi

內容

春節期間線上出了兩個php-cgi的core,具體追查過程如下:

一、 Core信息

file core.xxx

bug.php-cgi.3611.1296586902: ELF 64-bit LSB core file AMD x86-64, version 1 (SYSV), SVR4-style, from ‘php-cgi’

gdb  ~/php5/bin/php-cgi  core.xxx


Core was generated by `~/php5/bin/php-cgi –fpm –fpm-config ~/php5/etc/php-fpm.co’.

Program terminated with signal 4, Illegal instruction.

(gdb) bt

#0  0×0000000001000707 in ?? ()

#1  0×00000000006b1402 in zend_hash_destroy (ht=0×7fbffff4f8)

at ~/self/xxx/soft/source/src/php/php-5.2.8/Zend/zend_hash.c:526

#2  0×0000000000732b2e in fcgi_close (req=0×7fbfffd4c0, force=0, destroy=Variable “destroy” is not available.

)

at ~/self/xxx/soft/source/src/php/php-5.2.8/sapi/cgi/fastcgi.c:894

#3  0×0000000000732d24 in fcgi_finish_request (req=0×7fbfffd4c0)

at ~/self/xxx/soft/source/src/php/php-5.2.8/sapi/cgi/fastcgi.c:1248

#4  0×0000000000732d49 in fcgi_accept_request (req=0×7fbfffd4c0)

at ~/self/xxx/soft/source/src/php/php-5.2.8/sapi/cgi/fastcgi.c:944

#5  0×00000000007352b8 in main (argc=4, argv=0×7fbffff698)

at ~/self/xxx/soft/source/src/php/php-5.2.8/sapi/cgi/cgi_main.c:2224

根據堆棧可以看出core發生在php-fpm在accept一個新請求時,在對上一個請求(請求異常終止?)進行資源釋放時core掉的,線上的php訪問模式是apache+fastcgi+php的模式。一層層堆棧往下看:

1)         f 0

已經被寫壞了,沒有什么有用信息

2)         f 1

打印zend_hash_destroy函數的參數

(gdb) p *ht

$5 = {nTableSize = 16779009, nTableMask = 0, nNumOfElements = 16779009, nNextFreeElement = 16779009,

pInternalPointer = 0×1000701, pListHead = 0×1000701, pListTail = 0×1000701, arBuckets = 0×1000701,

pDestructor = 0×1000701, persistent = 1 ‘\001′, nApplyCount = 7 ‘\a’, bApplyProtection = 0 ‘\0′}

PHP HashTbale的數據結構可以上網上搜一下,有很多介紹。這個hashtable已經被寫壞了,各個節點指向的內存0×1000701,該內存地址在gdb中都是一個不能訪問的內存。依然沒有什么有用信息。

3)         f 2

查看源碼,打印fcgi_close的參數

(gdb) p *req

$6 = {listen_socket = 0, fd = 11, id = 1, keep = 0, in_len = 0, in_pad = 0, out_hdr = 0×0,

out_pos = 0×7fbffffcf8 “\001\003″,

out_buf = “\001\a\000\001\037鳿000\000PHP Warning:  simplexml_load_string() [<a href=’function.simplexml-load-string’>function.simplexml-load-string</a>]: Entity: line 1: parser error : Start tag expected, ‘&lt;’ not found in /hom”…, reserved = “\001\a\000\001\000\000\000\000\001\a\000\001\000\000\000″, env = {nTableSize = 16779009,

nTableMask = 0, nNumOfElements = 16779009, nNextFreeElement = 16779009, pInternalPointer = 0×1000701,

pListHead = 0×1000701, pListTail = 0×1000701, arBuckets = 0×1000701, pDestructor = 0×1000701,

persistent = 1 ‘\001′, nApplyCount = 7 ‘\a’, bApplyProtection = 0 ‘\0′}}

(gdb) ptype req

type = struct _fcgi_request {

int listen_socket;

int fd;

int id;

int keep;

int in_len;

int in_pad;

fcgi_header *out_hdr;

unsigned char *out_pos;

unsigned char out_buf[8192];

unsigned char reserved[16];

HashTable env;

} *

調用zend_hash_destroy(&req->env)進行銷毀的是req的成員env,這個成員變量是一個hashtable,該hashtable已經被上一個請求寫壞了,導致新請求在釋放上一個請求時core掉。

req->out_buf數組是php-cgi和apache進行交互的內存緩沖區,簡單看了一下,目前out_buf中的內容全部為simple_xml_load…這個PHP WARNNING,類似的錯誤信息出現在out_buf中的原因是PHP需要通過fastcgi協議打印錯誤信息到apacheerror_log中。req->out_pos指針則指向當前buf末尾。

gdb) p req->out_pos – req->out_buf

$2 = 8312

BUF的末尾位置已經超過了聲明的大小8192,所以可以判斷后面的env成員變量已經在寫out_buf的過程中被寫壞了。PHP中有一個重要的全局變量sapi_globals,通過閱讀PHP源碼得知,新請求的sapi_globals請求數據填充在fcgi_accept_request完成之后的init_request_info函數中,所以當前內存中的sapi_globals仍然是上次請求的殘留信息

(gdb) p sapi_globals

從數據中得知導致core的罪魁禍首是線上某個功能的URL

二、 fastcgi源碼分析

(1)     源碼位置

fastcgi源碼位置:php5/sapi/cgi/fastcgi.c

cgi_main源碼位置:php5/sapi/cgi/cgi_main.c

(2)     結構體介紹

首先關注一下fcgi_request這個結構體

typedef struct _fcgi_request {

int            listen_socket;

#ifdef _WIN32

int            tcp;

#endif

int            fd;

int            id;

int            keep;

int            in_len;

int            in_pad;

fcgi_header    *out_hdr;

unsigned char  *out_pos;

unsigned char  out_buf[1024*8];

unsigned char  reserved[sizeof(fcgi_end_request_rec)];

HashTable      env;

} fcgi_request;

這個結構體貫穿整個fastcgi請求的處理流程。我們這次需要關注的是out_hdr、out_pos、out_buf這三個成員變量,fastcgi對apache交互的緩存使用out_buf數組,緩存寫滿后就會flush出去。但不管是正常輸出,還是錯誤信息輸出,所有類型的輸出全部會緩存到同一段out_buf中,而這些內容輸出的時候需要寫到不同的fd中。所以fastcgi采用的方法是在每一種輸出內容前加入一個8字節的fcgi_header

typedef struct _fcgi_header {

unsigned char version;

unsigned char type;

unsigned char requestIdB1;

unsigned char requestIdB0;

unsigned char contentLengthB1;

unsigned char contentLengthB0;

unsigned char paddingLength;

unsigned char reserved;

} fcgi_header;

fcgi_header的用途是用來標示header之后輸出的內容長度(類似于Nshead中的body_len的作用)、內容類型等等,每一段內容都是fcgi_header+content這種形式。out_buf中允許緩存多對fcgi_header+content,然后在flush的時候寫到apache的不同fd中。req->out_hdr指針用來保存當前buf中正在使用的head地址,req->out_pos指針指向當前BUF的末尾位置,req->out_buf指針指向當前buf的起始位置。

(2)    函數介紹

a.    fcgi_write函數

fcgi_write函數會通過判斷out_hdr指針對當前buf中的fcgi_header進行檢查,如果沒有header(即out_hdr指針為空)就會調用open_packet函數插入一個新的header。

req->out_hdr = (fcgi_header*) req->out_pos;

req->out_hdr->type = type;

req->out_pos += sizeof(fcgi_header);

注意:這段代碼并沒有對out_pos做越界檢查,這為之后的數組越界埋下了隱患。

如果遇到一種跟當前head類型不同的輸出,則會調用close_packet函數填充當前header中的數據,然后重新開啟一個新的header。需要寫的內容會寫到out_pos指針之后。當out_buf全部寫滿之后,就會調用fcgi_flush函數把out_buf中的內容寫出去。

b.      fcgi_flush函數

每次調用fcgi_flush函數首先會調用close_packet函數填充fcgi_header中的數據,并把req->out_hdr指針置為NULL。

問題發生在fcgi_flush函數的異常分支上

close_packet(req);//會導致req->out_hdr指針被置為NULL

if (safe_write(req, req->out_buf, len) != len) {

req->keep = 0;

//這里out_pos = out_buf+8192

return 0;

}

req->out_pos = req->out_buf;  //寫成功后會重置out_pos

return 1;

}

假如第一次fcgi_flush失敗后(失敗的原因很多,比如客戶端主動斷開連接)

這時候三個指針的值分別是:

out_buf = 緩沖區初始

out_pos = out_buf+8192

out_hdr = NULL

如果下一次再調用fcgi_write首先會判斷req->out_hdr是否為NULL,由于上次調用失敗的fcgi_flush已經把out_hdr指針置為NULL,所以這個地方就會越過out_buf數組下標寫一個8字節的fcgi_header。

三個指針的值就變成了

out_buf = 緩沖區初始

out_pos = out_buf+8192+8

out_hdr = out_buf +8192

out_pos的越界就從此開始了。由于目前out_buf仍然是滿的,所以會繼續調用fcgi_flush函數。而該函數會首先會通過close_packet把req->out_hdr置為NULL。

out_buf = 緩沖區初始

out_pos = out_buf+8192+8

out_hdr = NULL

后續每次調用fcgi_write都會先寫一個8字節header,從而進入fcgi_write和fcgi_flush的循環,每次調用fcgi_write都導致out_pos向后越界8個字節。我們core中的out_pos-8192正好是8的整數倍,證明了這個猜想。

(3)     問題分析

fcgi_wrire函數調用fcgi_flush失敗后是會return  -1的

if (!fcgi_flush(req, 0)) {

return -1;

}

那為什么fcgi_write失敗之后,PHP依然會繼續調用該函數呢。調用fcgi_wtite的函數有兩個地方。

第一個地方是sapi_cgibin_ub_write+ sapi_cgibin_single_write

函數sapi_cgibin_single_write

if (fcgi_is_fastcgi()) {

fcgi_request *request = (fcgi_request*) SG(server_context);

long ret = fcgi_write(request, FCGI_STDOUT, str, str_length);

if (ret <= 0) {

return 0;

}

return ret;

}

函數sapi_cgibin_ub_write

ret = sapi_cgibin_single_write(ptr, remaining TSRMLS_CC);

if (!ret) {

php_handle_aborted_connection();

return str_length – remaining;

}

正常的PHP內容輸出調用的是sapi_cgibin_ub_write函數,如果寫失敗,該函數會直接斷開PHP請求。所以問題不會出現在這里。

第二個是地方函數sapi_cgi_log_message

memcpy(buf, message, len);

memcpy(buf + len, “\n”, sizeof(“\n”));

fcgi_write(request, FCGI_STDERR, buf, len+1);

free(buf);

這里沒有判斷fcgi_write函數的返回值。這個函數的用途是PHP通過fastcgi打印錯誤信息到apache的error_log中。如果PHP持續的出Warning,沒有正常的內容輸出。Fcgi_wtite函數就會一直被調用,如果在寫的過程中客戶端斷開連接等原因導致fcgi_flush失敗。就會復現上面發現的問題。

分析到這里,問題已經比較明了了。我們出core的請求需要與后端HTTP Service進行27次HTTP交互獲取xml數據。假設每次訪問請求響應都超時(500ms),解析空的返回結果就會觸發simple xml語法解析錯誤導致出PHP warning。27次交互*2次重試會變為54次HTTP交互。如果全部超時則會觸發54次PHP Warning,即需要調用54次fcgi_write。大約30次出錯后out_buf就會被寫滿,然后進行fcgi_flush。如果這時候客戶端早已斷開連接(用戶受不了慢,自己關掉),就會出現out_buf越界的問題。

于是等下一次請求為上一次請求收尸時,杯具就發生了^_^

出core的必要條件有兩個:

1.      PHP腳本持續觸發PHP Warning

出錯函數調用的是sapi_cgi_log_message函數。該函數中沒有判斷fcgi_write的返回值,所以即使flush出錯,PHP腳本依然會繼續運行。

2.      PHP持續出錯過程中,客戶端主動斷開連接。

三、 線下復現

寫一個簡單的PHP腳本

<?php

$i = 200;

while($i –){

usleep(100000);

$str = ‘afadasdfad >x’;

$xml = simplexml_load_string($str, null, LIBXML_NOCDATA);

}

使用壓力工具開啟大壓力進行訪問,等apache進程滿了就停掉壓力(主動斷開連接),然后重新開啟壓力,后續的新請求就會全部出core。Core的堆棧和線上的core完全一樣。

四、 解決方案

方案一:修改fastcgi代碼和cgi_main代碼

  1. 修改sapi_cgi_log_message,增加對返回值的判斷,出錯就斷開php連接
  2. 修改fcgi_flush函數,寫失敗的情況下重置out_pos到buf的初始位置

if (safe_write(req, req->out_buf, len) != len) {

req->keep = 0;

req->out_pos = req->out_buf;

return 0;

}

雖然該core在理論上很多請求都可能觸發,比較容易復現,但該core的觸發條件比

較極端,不太容易觸發。且修改修改源碼的代價過高,不利于后續PHP版本升級。

方案二:線上的php錯誤信息全部是打印到apache的錯誤日志中的,其實在php.ini

中可以指定error_log的文件位置,這樣就不會調用sapi_cgi_log_message函數了?

為了證實這個猜想,閱讀了PHP的出錯部分源代碼:

PHPAPI void php_log_err(char *log_message TSRMLS_DC)

{

/* Try to use the specified logging location. */

if (PG(error_log) != NULL) {

if (!strcmp(PG(error_log), “syslog”)) {

php_syslog(LOG_NOTICE, “%.500s”, log_message);

return;

}

return;

}

if (sapi_module.log_message) {

sapi_module.log_message(log_message);

}

代碼首先會判斷error_log配置是否有效,如果該配置存在,則直接打到該配置指向的日志文件中,不再調用SAPI中可能會出問題的sapi_cgi_log_message。

PG(error_log) = core_globals.error_log

之前的core

(gdb) p core_globals.error_log

$3 = 0×0

而gdb  attach 一個正在運行的PHP進程(修改了php.ini)

(gdb) p core_globals.error_log

$1 = 0xb66b30 “~/php5/logs/php_error.log”

最后采用了方案二,并將其作為了線上的PHP環境標準。

 

 

李蕭明吐槽 像我們這種小網站被請求撐死是種幸福。

文章出自:CCIE那點事 http://www.qdxgqk.live/ 版權所有。本站文章除注明出處外,皆為作者原創文章,可自由引用,但請注明來源。 禁止全文轉載。
本文鏈接:http://www.qdxgqk.live/?p=920轉載請注明轉自CCIE那點事
如果喜歡:點此訂閱本站
  • 相關文章
  • 為您推薦
  • 各種觀點
?
暫時還木有人評論,坐等沙發!
發表評論

您必須 [ 登錄 ] 才能發表留言!

?
?
萌宠夺宝游戏