php打印warning日志引发的core追查
內(nèi)容
春節(jié)期間線上出了兩個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
根據(jù)堆棧可以看出core發(fā)生在php-fpm在accept一個新請求時，在對上一個請求(請求異常終止?)進行資源釋放時core掉的，線上的php訪問模式是apache+fastcgi+php的模式。一層層堆棧往下看：
1)???????? f 0
已經(jīng)被寫壞了，沒有什么有用信息
2)???????? f 1
打印zend_hash_destroy函數(shù)的參數(shù)
(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的數(shù)據(jù)結構可以上網(wǎng)上搜一下，有很多介紹。這個hashtable已經(jīng)被寫壞了，各個節(jié)點指向的內(nèi)存0×1000701,該內(nèi)存地址在gdb中都是一個不能訪問的內(nèi)存。依然沒有什么有用信息。
3)???????? f 2
查看源碼，打印fcgi_close的參數(shù)
(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, ‘<’ 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;
} *
調(diào)用zend_hash_destroy(&req->env)進行銷毀的是req的成員env，這個成員變量是一個hashtable，該hashtable已經(jīng)被上一個請求寫壞了，導致新請求在釋放上一個請求時core掉。
req->out_buf數(shù)組是php-cgi和apache進行交互的內(nèi)存緩沖區(qū)，簡單看了一下，目前out_buf中的內(nèi)容全部為simple_xml_load…這個PHP WARNNING，類似的錯誤信息出現(xiàn)在out_buf中的原因是PHP需要通過fastcgi協(xié)議打印錯誤信息到apache的error_log中。req->out_pos指針則指向當前buf末尾。
gdb) p req->out_pos – req->out_buf
$2 = 8312
BUF的末尾位置已經(jīng)超過了聲明的大小8192,所以可以判斷后面的env成員變量已經(jīng)在寫out_buf的過程中被寫壞了。PHP中有一個重要的全局變量sapi_globals，通過閱讀PHP源碼得知，新請求的sapi_globals請求數(shù)據(jù)填充在fcgi_accept_request完成之后的init_request_info函數(shù)中，所以當前內(nèi)存中的sapi_globals仍然是上次請求的殘留信息
(gdb) p sapi_globals
從數(shù)據(jù)中得知導致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數(shù)組，緩存寫滿后就會flush出去。但不管是正常輸出，還是錯誤信息輸出，所有類型的輸出全部會緩存到同一段out_buf中，而這些內(nèi)容輸出的時候需要寫到不同的fd中。所以fastcgi采用的方法是在每一種輸出內(nèi)容前加入一個8字節(jié)的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之后輸出的內(nèi)容長度(類似于Nshead中的body_len的作用)、內(nèi)容類型等等，每一段內(nèi)容都是fcgi_header+content這種形式。out_buf中允許緩存多對fcgi_header+content，然后在flush的時候?qū)懙絘pache的不同fd中。req->out_hdr指針用來保存當前buf中正在使用的head地址，req->out_pos指針指向當前BUF的末尾位置，req->out_buf指針指向當前buf的起始位置。
(2)??? 函數(shù)介紹
a. ?? fcgi_write函數(shù)
fcgi_write函數(shù)會通過判斷out_hdr指針對當前buf中的fcgi_header進行檢查，如果沒有header(即out_hdr指針為空)就會調(diào)用open_packet函數(shù)插入一個新的header。
req->out_hdr = (fcgi_header*) req->out_pos;
req->out_hdr->type = type;
req->out_pos += sizeof(fcgi_header);
注意：這段代碼并沒有對out_pos做越界檢查，這為之后的數(shù)組越界埋下了隱患。
如果遇到一種跟當前head類型不同的輸出，則會調(diào)用close_packet函數(shù)填充當前header中的數(shù)據(jù)，然后重新開啟一個新的header。需要寫的內(nèi)容會寫到out_pos指針之后。當out_buf全部寫滿之后，就會調(diào)用fcgi_flush函數(shù)把out_buf中的內(nèi)容寫出去。
b.????? fcgi_flush函數(shù)
每次調(diào)用fcgi_flush函數(shù)首先會調(diào)用close_packet函數(shù)填充fcgi_header中的數(shù)據(jù)，并把req->out_hdr指針置為NULL。
問題發(fā)生在fcgi_flush函數(shù)的異常分支上
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 = 緩沖區(qū)初始
out_pos = out_buf+8192
out_hdr = NULL
如果下一次再調(diào)用fcgi_write首先會判斷req->out_hdr是否為NULL，由于上次調(diào)用失敗的fcgi_flush已經(jīng)把out_hdr指針置為NULL，所以這個地方就會越過out_buf數(shù)組下標寫一個8字節(jié)的fcgi_header。
三個指針的值就變成了
out_buf = 緩沖區(qū)初始
out_pos = out_buf+8192+8
out_hdr = out_buf +8192
out_pos的越界就從此開始了。由于目前out_buf仍然是滿的，所以會繼續(xù)調(diào)用fcgi_flush函數(shù)。而該函數(shù)會首先會通過close_packet把req->out_hdr置為NULL。
out_buf = 緩沖區(qū)初始
out_pos = out_buf+8192+8
out_hdr = NULL
后續(xù)每次調(diào)用fcgi_write都會先寫一個8字節(jié)header，從而進入fcgi_write和fcgi_flush的循環(huán)，每次調(diào)用fcgi_write都導致out_pos向后越界8個字節(jié)。我們core中的out_pos-8192正好是8的整數(shù)倍，證明了這個猜想。
(3)???? 問題分析
fcgi_wrire函數(shù)調(diào)用fcgi_flush失敗后是會return? -1的
if (!fcgi_flush(req, 0)) {
return -1;
}
那為什么fcgi_write失敗之后，PHP依然會繼續(xù)調(diào)用該函數(shù)呢。調(diào)用fcgi_wtite的函數(shù)有兩個地方。
第一個地方是sapi_cgibin_ub_write+ sapi_cgibin_single_write：
函數(shù)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;
}
函數(shù)sapi_cgibin_ub_write：
ret = sapi_cgibin_single_write(ptr, remaining TSRMLS_CC);
if (!ret) {
php_handle_aborted_connection();
return str_length – remaining;
}
正常的PHP內(nèi)容輸出調(diào)用的是sapi_cgibin_ub_write函數(shù)，如果寫失敗，該函數(shù)會直接斷開PHP請求。所以問題不會出現(xiàn)在這里。
第二個是地方函數(shù)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函數(shù)的返回值。這個函數(shù)的用途是PHP通過fastcgi打印錯誤信息到apache的error_log中。如果PHP持續(xù)的出Warning，沒有正常的內(nèi)容輸出。Fcgi_wtite函數(shù)就會一直被調(diào)用，如果在寫的過程中客戶端斷開連接等原因?qū)е耭cgi_flush失敗。就會復現(xiàn)上面發(fā)現(xiàn)的問題。
分析到這里，問題已經(jīng)比較明了了。我們出core的請求需要與后端HTTP Service進行27次HTTP交互獲取xml數(shù)據(jù)。假設每次訪問請求響應都超時(500ms)，解析空的返回結果就會觸發(fā)simple xml語法解析錯誤導致出PHP warning。27次交互*2次重試會變?yōu)?4次HTTP交互。如果全部超時則會觸發(fā)54次PHP Warning，即需要調(diào)用54次fcgi_write。大約30次出錯后out_buf就會被寫滿，然后進行fcgi_flush。如果這時候客戶端早已斷開連接(用戶受不了慢，自己關掉)，就會出現(xiàn)out_buf越界的問題。
于是等下一次請求為上一次請求收尸時，杯具就發(fā)生了^_^
出core的必要條件有兩個：
1.????? PHP腳本持續(xù)觸發(fā)PHP Warning
出錯函數(shù)調(diào)用的是sapi_cgi_log_message函數(shù)。該函數(shù)中沒有判斷fcgi_write的返回值，所以即使flush出錯，PHP腳本依然會繼續(xù)運行。
2.????? PHP持續(xù)出錯過程中，客戶端主動斷開連接。
三、 線下復現(xiàn)
寫一個簡單的PHP腳本
<?php
$i = 200;
while($i –){
usleep(100000);
$str = ‘a(chǎn)fadasdfad >x’;
$xml = simplexml_load_string($str, null, LIBXML_NOCDATA);
}
使用壓力工具開啟大壓力進行訪問，等apache進程滿了就停掉壓力(主動斷開連接)，然后重新開啟壓力，后續(xù)的新請求就會全部出core。Core的堆棧和線上的core完全一樣。
四、 解決方案
方案一：修改fastcgi代碼和cgi_main代碼
- 修改sapi_cgi_log_message，增加對返回值的判斷，出錯就斷開php連接
- 修改fcgi_flush函數(shù)，寫失敗的情況下重置out_pos到buf的初始位置
if (safe_write(req, req->out_buf, len) != len) {
req->keep = 0;
req->out_pos = req->out_buf;
return 0;
}
雖然該core在理論上很多請求都可能觸發(fā)，比較容易復現(xiàn)，但該core的觸發(fā)條件比
較極端，不太容易觸發(fā)。且修改修改源碼的代價過高，不利于后續(xù)PHP版本升級。
方案二：線上的php錯誤信息全部是打印到apache的錯誤日志中的，其實在php.ini
中可以指定error_log的文件位置，這樣就不會調(diào)用sapi_cgi_log_message函數(shù)了？
為了證實這個猜想，閱讀了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配置是否有效，如果該配置存在，則直接打到該配置指向的日志文件中，不再調(diào)用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環(huán)境標準。
轉自：http://stblog.baidu-tech.com/?p=752
總結
以上是生活随笔為你收集整理的php打印warning日志引发的core追查的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： 燕翎义薄云天观看地址
- 下一篇： 超级负载均衡