关闭

nginx 1.6.2源码分析1 499问题

476人阅读 评论(0) 收藏 举报
分类:

网上的解释:

http://www.lc365.net/blog/b/23997/


首先尝试从代码上解释问题:

首先要找到打印499日志的地方,看调用的逻辑

log时的栈

#0  ngx_http_log_request_time (r=0x15590f0, buf=0x15d8b63 "", op=0x15d40e0) at src/http/modules/ngx_http_log_module.c:773
#1  0x00000000004330e6 in ngx_http_log_handler (r=0x15590f0) at src/http/modules/ngx_http_log_module.c:308
#2  0x000000000042a5b4 in ngx_http_log_request (r=r@entry=0x15590f0) at src/http/ngx_http_request.c:3509
#3  0x000000000042b44b in ngx_http_free_request (r=r@entry=0x15590f0, rc=rc@entry=0) at src/http/ngx_http_request.c:3456
#4  0x000000000042b584 in ngx_http_close_request (r=0x15590f0, rc=rc@entry=0) at src/http/ngx_http_request.c:3403
#5  0x000000000042b931 in ngx_http_terminate_handler (r=<optimized out>) at src/http/ngx_http_request.c:2498
#6  0x000000000042b21c in ngx_http_run_posted_requests (c=c@entry=0x2acb98b14420) at src/http/ngx_http_request.c:2225
#7  0x000000000042b2bb in ngx_http_request_handler (ev=<optimized out>) at src/http/ngx_http_request.c:2191
#8  0x0000000000420338 in ngx_epoll_process_events (cycle=<optimized out>, timer=<optimized out>, flags=<optimized out>) at src/event/modules/ngx_epoll_module.c:691
#9  0x0000000000418f94 in ngx_process_events_and_timers (cycle=cycle@entry=0x15b4c30) at src/event/ngx_event.c:248
#10 0x000000000041ee0f in ngx_worker_process_cycle (cycle=0x15b4c30, data=<optimized out>) at src/os/unix/ngx_process_cycle.c:816
#11 0x000000000041d686 in ngx_spawn_process (cycle=cycle@entry=0x15b4c30, proc=proc@entry=0x41ed43 <ngx_worker_process_cycle>, data=data@entry=0x17, 
    name=name@entry=0x467df4 "worker process", respawn=respawn@entry=-4) at src/os/unix/ngx_process.c:198
#12 0x000000000041e145 in ngx_start_worker_processes (cycle=cycle@entry=0x15b4c30, n=32, type=type@entry=-4) at src/os/unix/ngx_process_cycle.c:364
#13 0x000000000041fb12 in ngx_master_process_cycle (cycle=0x15b4c30, cycle@entry=0x15590f0) at src/os/unix/ngx_process_cycle.c:249
#14 0x0000000000404160 in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:407


log的输出格式

static ngx_str_t  ngx_http_combined_fmt =
    ngx_string("$remote_addr - $remote_user [$time_local] "
               "\"$request\" $status $body_bytes_sent "
               "\"$http_referer\" \"$http_user_agent\"");


然后通过适当更改源码,捕获出现499栈的时候的栈

(gdb) p status
$1 = 499
(gdb) bt
#0  ngx_http_log_status (r=0x84be80, 
    buf=0x85f465 "qxz1:200 62 \"-\" 0.001 qxz2:0.001\n- 10.1.242.133 [2015-07-07T16:21:55+08:00] \"GET /qiso3?if=video&key=kldby HTTP/1.1\" qxz1:200 62 \"-\" 0.001 qxz2:0.001\n- 10.1.242.133 [2015-07-07T16:21:55+08:00] \"GET /q"..., op=0x858368) at src/http/modules/ngx_http_log_module.c:806
#1  0x0000000000433157 in ngx_http_log_handler (r=0x84be80) at src/http/modules/ngx_http_log_module.c:308
#2  0x000000000042a604 in ngx_http_log_request (r=r@entry=0x84be80) at src/http/ngx_http_request.c:3509
#3  0x000000000042b49b in ngx_http_free_request (r=r@entry=0x84be80, rc=rc@entry=0) at src/http/ngx_http_request.c:3456
#4  0x000000000042b5d4 in ngx_http_close_request (r=0x84be80, rc=rc@entry=0) at src/http/ngx_http_request.c:3403
#5  0x000000000042b981 in ngx_http_terminate_handler (r=<optimized out>) at src/http/ngx_http_request.c:2498
#6  0x000000000042b26c in ngx_http_run_posted_requests (c=c@entry=0x2b716e351420) at src/http/ngx_http_request.c:2225
#7  0x000000000042b30b in ngx_http_request_handler (ev=<optimized out>) at src/http/ngx_http_request.c:2191
#8  0x0000000000419416 in ngx_event_process_posted (cycle=cycle@entry=0x8400f0, posted=0x691b98 <ngx_posted_events>) at src/event/ngx_event_posted.c:40
#9  0x000000000041904b in ngx_process_events_and_timers (cycle=cycle@entry=0x8400f0) at src/event/ngx_event.c:275
#10 0x000000000041ee5f in ngx_worker_process_cycle (cycle=0x8400f0, data=<optimized out>) at src/os/unix/ngx_process_cycle.c:816
#11 0x000000000041d6d6 in ngx_spawn_process (cycle=cycle@entry=0x8400f0, proc=proc@entry=0x41ed93 <ngx_worker_process_cycle>, data=data@entry=0x7, 
    name=name@entry=0x467e54 "worker process", respawn=respawn@entry=-3) at src/os/unix/ngx_process.c:198
#12 0x000000000041e195 in ngx_start_worker_processes (cycle=cycle@entry=0x8400f0, n=32, type=type@entry=-3) at src/os/unix/ngx_process_cycle.c:364
#13 0x000000000041f54b in ngx_master_process_cycle (cycle=cycle@entry=0x8400f0) at src/os/unix/ngx_process_cycle.c:136
#14 0x00000000004041b0 in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:407


Breakpoint 6, ngx_http_finalize_request (r=r@entry=0x84be80, rc=rc@entry=499) at src/http/ngx_http_request.c:2299
2299        ngx_http_terminate_request(r, rc);
(gdb) bt
#0  ngx_http_finalize_request (r=r@entry=0x84be80, rc=rc@entry=499) at src/http/ngx_http_request.c:2299
#1  0x000000000043a5ac in ngx_http_upstream_finalize_request (r=r@entry=0x84be80, u=u@entry=0x89dc28, rc=rc@entry=499) at src/http/ngx_http_upstream.c:3534
#2  0x000000000043a7bb in ngx_http_upstream_check_broken_connection (r=0x84be80, ev=0x2b716f051280) at src/http/ngx_http_upstream.c:1110
#3  0x000000000043a974 in ngx_http_upstream_rd_check_broken_connection (r=<optimized out>) at src/http/ngx_http_upstream.c:987
#4  0x000000000042b303 in ngx_http_request_handler (ev=<optimized out>) at src/http/ngx_http_request.c:2188
#5  0x0000000000420388 in ngx_epoll_process_events (cycle=<optimized out>, timer=<optimized out>, flags=<optimized out>) at src/event/modules/ngx_epoll_module.c:691
#6  0x0000000000418fe4 in ngx_process_events_and_timers (cycle=cycle@entry=0x8400f0) at src/event/ngx_event.c:248
#7  0x000000000041ee5f in ngx_worker_process_cycle (cycle=0x8400f0, data=<optimized out>) at src/os/unix/ngx_process_cycle.c:816
#8  0x000000000041d6d6 in ngx_spawn_process (cycle=cycle@entry=0x8400f0, proc=proc@entry=0x41ed93 <ngx_worker_process_cycle>, data=data@entry=0x1c, 
    name=name@entry=0x467e54 "worker process", respawn=respawn@entry=-3) at src/os/unix/ngx_process.c:198
#9  0x000000000041e195 in ngx_start_worker_processes (cycle=cycle@entry=0x8400f0, n=32, type=type@entry=-3) at src/os/unix/ngx_process_cycle.c:364
#10 0x000000000041f54b in ngx_master_process_cycle (cycle=cycle@entry=0x8400f0) at src/os/unix/ngx_process_cycle.c:136
#11 0x00000000004041b0 in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:407


最终问题集中在

src/http/ngx_http_upstream.c:1110

这点,要触发499,必须两个条件ev->pending_eof ==1和cacheable==0,但从源码分析,cacheable==0的地方很多,而ev->pending_eof ==1不确定精确含义是什么, end of file?

在复现的情况下,抓包发现,请看文件2.pcap,其中一个异常点,存在这样的报文,比如tcp.port == 7139 的报文,在发送完get请求后,就直接fin了,这样nginx会怎么想?

会不会是这个fin导致nignx出现了499?这个似乎和源码中的ngx_http_upstream_rd_check_broken_connection 和ev->pending_eof ==1相互呼应。

因此两个方法:

对应报文和日志,查看这个非正常fin的地方是否和出现499的日志的时间对应,但是发现并不完全对应。

使用一个简单程序,先发送一个get请求,然后发送一个reset,这样看499的情况:

// test.cpp : Defines the entry point for the console application.
//


#include "stdafx.h"
#include <stdio.h>
#include <Winsock2.h>
#pragma comment(lib, "ws2_32.lib")
void main();
int _tmain(int argc, _TCHAR* argv[])
{
main();
return 0;
}


/***************************************************************************
     Following variables and functions are used for simulating


****************************************************************************/
char * requestMsg[] ={ 
              "GET /qiso3?if=video&key=kldby HTTP/1.1\r\n"
              "Host: 10.77.42.29\r\n"
              "User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:34.0) Gecko/20100101 Firefox/34.0\r\n"
              "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8\r\n"
              "Accept-Language: zh-cn,zh;q=0.8,en-us;q=0.5,en;q=0.3\r\n"
              "Accept-Encoding: gzip, deflate\r\n"
              "Connection: keep-alive\r\n"
              "\r\n"
 };


int requestSock;/*simulate a client on device, this is the socket*/


//客户端
#include< stdio.h >
#include< stdlib.h >
#include< windows.h >
#include< winsock.h >
#include< string.h >


#pragma comment( lib, "ws2_32.lib" )


#define PORT 80//554
#define MAXDATASIZE 100
#define MAX_LEN 1500


void main( void )
{


int iClientSock;
struct sockaddr_in ServerAddr;


int numbytes;
char buf[ MAXDATASIZE ] = { 0 };
char ip[20];
char ipdefault[]="10.77.42.29";
char recvBuf[MAX_LEN];  
int j=0;
char c;


WSADATA WSAData;
if( WSAStartup( MAKEWORD( 1, 1 ), &WSAData ) )
{
printf( "initialization error!\n" );
WSACleanup( );
exit( 0 );
}




printf("set server ip address:\n\r1 ip set by user;\n\r2 default %s\n\r",ipdefault);
c=getchar();
switch(c)
{
case '1':
scanf("%s",ip);
break;
default:
strcpy(ip,ipdefault);
}


do
{
ServerAddr.sin_family = AF_INET;
ServerAddr.sin_port = htons( PORT );
ServerAddr.sin_addr.s_addr = inet_addr(ip);//记得换IP
memset( &( ServerAddr.sin_zero ), 0, sizeof( ServerAddr.sin_zero ) );
if( ( iClientSock = socket( AF_INET, SOCK_STREAM, 0 ) ) == -1 )
{
printf( "创建套接字失败!\n" );
WSACleanup( );
exit( 0 );
}
if( connect( iClientSock, ( struct sockaddr * ) & ServerAddr, sizeof( struct sockaddr ) ) == -1 )
{
printf("connect失败!");
WSACleanup( );
exit( 0 );
}
char c;
        int  i =0;
numbytes = send( iClientSock, requestMsg[i], strlen( requestMsg[i] ), 0 );
if( numbytes == -1 )
{
printf( "send调用失败!\n" );
WSACleanup();
exit( 0 );
}


printf( "sent %d bytes to %s\n", numbytes, inet_ntoa( ServerAddr.sin_addr ) );
printf("msg:%s",requestMsg[i]);


j=recv(iClientSock,recvBuf,MAX_LEN,0);// 接受客户端消息 


if(j>0)

printf("recv(len:%d): \n\r",i); 
recvBuf[j]='\0';
printf("msg:%s",recvBuf);
}

c=getchar();
closesocket( iClientSock );
continue;
c=getchar();
}while(1);
c=getchar();
closesocket( iClientSock );
WSACleanup( );

使用这个程序,复现了问题。说明是客户端的fin reset导致499

而一般客户端强制断开链接可能是浏览器关闭 强制刷新或者超时等操作。


如果客户端的请求已经被回复的情况下,是不会复现499的问题的,因为这时候的断开链接是可以接受的。

问题是,nginx中,保存了怎样的数据结构,对于一个事件?为什么已经回复请求的就不会复现这个问题?


请听下回分解。


参考

http://chenzhenianqing.cn/articles/742.html nginx upstream的解释

http://www.cnblogs.com/jianxie/p/3990377.html   nginx的命令

http://www.2cto.com/net/201310/251896.html tcp的三次和四次握手

0
0

查看评论
* 以上用户言论只代表其个人观点,不代表CSDN网站的观点或立场
    个人资料
    • 访问:8429次
    • 积分:396
    • 等级:
    • 排名:千里之外
    • 原创:33篇
    • 转载:1篇
    • 译文:0篇
    • 评论:0条
    文章分类