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, ‘&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协议打印错误信息到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