php打印warning日志引发的core追查-阿里云开发者社区

开发者社区> 技术小美> 正文

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

简介:
+关注继续查看

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环境标准。

 




















本文转自百度技术51CTO博客,原文链接:http://blog.51cto.com/baidutech/743756,如需转载请自行联系原作者

版权声明:本文内容由阿里云实名注册用户自发贡献,版权归原作者所有,阿里云开发者社区不拥有其著作权,亦不承担相应法律责任。具体规则请查看《阿里云开发者社区用户服务协议》和《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容,填写侵权投诉表单进行举报,一经查实,本社区将立刻删除涉嫌侵权内容。

相关文章
02_JNI中Java代码调用C代码,Android中使用log库打印日志,javah命令的使用,Android.mk文件的编写,交叉编译
 1  编写以下案例(下面的三个按钮都调用了底层的C语言): 项目案例的代码结构如下: 2 编写DataProvider的代码: package com.example.ndkpassdata;   public class DataProvider {         /**      * 计算x和y的加法  apktools      *
1007 0
PHP 打印调用函数入口地址(堆栈),方便调式
今天网站出现一个BUG,然后直接在数据库类里面写日志,看是哪条SQL出了问题,SQL语句到是找到了,但是不知道这条SQL语句来自何处,于是就想啊,如果能有一个办法,查看当前正在运行的这个方法是被哪个方法调用的,以及上一个方法又是哪个方法调用的,以此类推,找到入口地址多好啊。
686 0
ThinkPHP 接入 SeasLog 日志组件
【背景】 为实现开发前期联调bug 定位、线上bug快速定位、快速响应,遂暂为斐讯路由后台 Api 模块添加日志记录支持。 【SeasLog 简介】 1. 国产log组件 2. 简洁配置 3.应用简单、性能强劲 4.分模块、分级别记录日志。
1016 0
阿里云服务器端口号设置
阿里云服务器初级使用者可能面临的问题之一. 使用tomcat或者其他服务器软件设置端口号后,比如 一些不是默认的, mysql的 3306, mssql的1433,有时候打不开网页, 原因是没有在ecs安全组去设置这个端口号. 解决: 点击ecs下网络和安全下的安全组 在弹出的安全组中,如果没有就新建安全组,然后点击配置规则 最后如上图点击添加...或快速创建.   have fun!  将编程看作是一门艺术,而不单单是个技术。
4495 0
PHP中利用文件锁实现日志写入和网站接口访问等常见场景下的并发控制
针对并发环境下网站、日志文件写入产生的脏数据、更新丢失等情况的解决思路之一
2588 0
从壹开始前后端分离【 .NET Core2.0 +Vue2.0 】框架之十 || AOP面向切面编程浅解析:简单日志记录 + 服务切面缓存
代码已上传Github+Gitee,文末有地址   上回《从壹开始前后端分离【 .NET Core2.0 Api + Vue 2.0 + AOP + 分布式】框架之九 || 依赖注入IoC学习 + AOP界面编程初探》咱们说到了依赖注入Autofac的使用,不知道大家对IoC的使用用怎样的感觉,我个人表示还是比较可行的,至少不用自己再关心一个个复杂的实例化服务对象了,直接通过接口就满足需求,当然还有其他的一些功能,我还没有说到,抛砖引玉嘛,大家如果有好的想法,欢迎留言,也可以来群里,大家一起学习讨论。
1228 0
+关注
4567
文章
0
问答
文章排行榜
最热
最新
相关电子书
更多
文娱运维技术
立即下载
《SaaS模式云原生数据仓库应用场景实践》
立即下载
《看见新力量:二》电子书
立即下载