php打印warning日志引发的core追查
內容
春節期間線上出了兩個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, ‘<’ 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協議打印錯誤信息到apache的error_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代碼
- 修改sapi_cgi_log_message，增加對返回值的判斷，出錯就斷開php連接
- 修改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環境標準。
轉自：http://stblog.baidu-tech.com/?p=752
總結
以上是生活随笔為你收集整理的php打印warning日志引发的core追查的全部內容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： 燕翎义薄云天观看地址
- 下一篇： 超级负载均衡