test::ngnix client http keepalive情况下，只有超时后才能收到响应

roidinev · 2016-09-14T10:17:08+00:00

Hello在 2016年9月13日下午8:41，高岩 <crasya...@gmail.com>写道：比&#x5982...

test::ngnix client http keepalive情况下，只有超时后才能收到响应

roidinev

用raw req eval构造 req。

nginx errlog 见附件。

从log看，6s超时（在test:nginx里data部分设置）后client断开keepalive连接，收到响应。

但是从log看，在6s前，nginx已经say response了。

2016/09/14 10:08:39 [info] 24996#24996: *1 [lua] TCosocket.lua:127: setkeepalive(): Thrift Cosocket reused times: 1, client: 127.0.0.1, server: localhost, request: "GET /t/ HTTP/1.1", host: "s3.dnion.com:8081"
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua tcp socket set keepalive: saving connection 00007FA6F7946FF8
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua tcp socket clear current socket connection
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua tcp socket keepalive timeout: 60000 ms
2016/09/14 10:08:39 [debug] 24996#24996: *1 event timer add: 11: 60000:1473818979552
2016/09/14 10:08:39 [debug] 24996#24996: lua tcp socket keepalive close handler check stale events
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua finalize socket
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua http cleanup free: 00007FA6F7989428
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua reuse free buf chain, but reallocate memory because 2479 >= 93, cl:00007FA6F7989440, p:00007FA6F79897D8
2016/09/14 10:08:39 [debug] 24996#24996: *1 posix_memalign: 00007FA6F798D7A0:4096 @16
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua say response
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua capture header filter, uri "/t/"
2016/09/14 10:08:39 [debug] 24996#24996: *1 HTTP/1.1 200 OK^M
Server: openresty/1.9.15.1^M
Date: Wed, 14 Sep 2016 02:08:39 GMT^M
Content-Type: application/xml^M
Connection: keep-alive^M
x-amz-request-id: tx00000000000000000027b-0057835f2e-107b-default^M
content-length: 2478^M

2016/09/14 10:08:39 [debug] 24996#24996: *1 write new buf t:1 f:0 00007FA6F7989928, pos 00007FA6F7989928, size: 228 file: 0, size: 0
2016/09/14 10:08:39 [debug] 24996#24996: *1 http write filter: l:0 f:0 s:228
2016/09/14 10:08:39 [debug] 24996#24996: *1 http output filter "/t/?"
2016/09/14 10:08:39 [debug] 24996#24996: *1 http copy filter: "/t/?"
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua capture body filter, uri "/t/"
2016/09/14 10:08:39 [debug] 24996#24996: *1 http postpone filter "/t/?" 00007FA6F7989440
2016/09/14 10:08:39 [debug] 24996#24996: *1 write old buf t:1 f:0 00007FA6F7989928, pos 00007FA6F7989928, size: 228 file: 0, size: 0
2016/09/14 10:08:39 [debug] 24996#24996: *1 write new buf t:1 f:0 00007FA6F798D7C0, pos 00007FA6F798D7C0, size: 2479 file: 0, size: 0
2016/09/14 10:08:39 [debug] 24996#24996: *1 http write filter: l:0 f:0 s:2707
2016/09/14 10:08:39 [debug] 24996#24996: *1 http write filter limit 0
2016/09/14 10:08:39 [debug] 24996#24996: *1 writev: 2707 of 2707
2016/09/14 10:08:39 [debug] 24996#24996: *1 http write filter 0000000000000000
2016/09/14 10:08:39 [debug] 24996#24996: *1 http copy filter: 0 "/t/?"
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua reuse free buf memory 2479 >= 6, cl:00007FA6F7989440, p:00007FA6F798D7C0
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua say response
2016/09/14 10:08:39 [debug] 24996#24996: *1 http output filter "/t/?"
2016/09/14 10:08:39 [debug] 24996#24996: *1 http copy filter: "/t/?"
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua capture body filter, uri "/t/"
2016/09/14 10:08:39 [debug] 24996#24996: *1 http postpone filter "/t/?" 00007FA6F7989440
2016/09/14 10:08:39 [debug] 24996#24996: *1 write new buf t:1 f:0 00007FA6F798D7C0, pos 00007FA6F798D7C0, size: 6 file: 0, size: 0
2016/09/14 10:08:39 [debug] 24996#24996: *1 http write filter: l:0 f:0 s:6
2016/09/14 10:08:39 [debug] 24996#24996: *1 http copy filter: 0 "/t/?"
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua allocate new chainlink and new buf of size 0, cl:00007FA6F7989A10
2016/09/14 10:08:39 [debug] 24996#24996: *1 http output filter "/t/?"
2016/09/14 10:08:39 [debug] 24996#24996: *1 http copy filter: "/t/?"
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua capture body filter, uri "/t/"
2016/09/14 10:08:39 [debug] 24996#24996: *1 http postpone filter "/t/?" 00007FA6F7989A10
2016/09/14 10:08:39 [debug] 24996#24996: *1 write old buf t:1 f:0 00007FA6F798D7C0, pos 00007FA6F798D7C0, size: 6 file: 0, size: 0
2016/09/14 10:08:39 [debug] 24996#24996: *1 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2016/09/14 10:08:39 [debug] 24996#24996: *1 http write filter: l:0 f:1 s:6
2016/09/14 10:08:39 [debug] 24996#24996: *1 http write filter limit 0
2016/09/14 10:08:39 [debug] 24996#24996: *1 writev: 6 of 6
2016/09/14 10:08:39 [debug] 24996#24996: *1 http write filter 0000000000000000
2016/09/14 10:08:39 [debug] 24996#24996: *1 http copy filter: 0 "/t/?"
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua flush asynchronously
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua exit with code 200
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua resume returned 1
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua thread yielded
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua thread aborting request with status 200
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua request cleanup: forcible=0
2016/09/14 10:08:39 [debug] 24996#24996: *1 http set discard body
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua sending last buf of the response body
2016/09/14 10:08:39 [debug] 24996#24996: *1 http output filter "/t/?"
2016/09/14 10:08:39 [debug] 24996#24996: *1 http copy filter: "/t/?"
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua capture body filter, uri "/t/"
2016/09/14 10:08:39 [debug] 24996#24996: *1 http postpone filter "/t/?" 00007FFDF667D9F0
2016/09/14 10:08:39 [debug] 24996#24996: *1 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2016/09/14 10:08:39 [debug] 24996#24996: *1 http write filter: l:1 f:0 s:0
2016/09/14 10:08:39 [debug] 24996#24996: *1 http copy filter: 0 "/t/?"
2016/09/14 10:08:39 [debug] 24996#24996: *1 lua run thread returned 0
2016/09/14 10:08:39 [debug] 24996#24996: *1 http finalize request: 0, "/t/?" a:1, c:1
2016/09/14 10:08:39 [debug] 24996#24996: *1 set http keepalive handler
                                                                           
2016/09/14 10:08:39 [debug] 24996#24996: *1 http close request
2016/09/14 10:08:39 [debug] 24996#24996: *1 http log handler
2016/09/14 10:08:39 [debug] 24996#24996: *1 free: 00007FA6F798C790
2016/09/14 10:08:39 [debug] 24996#24996: *1 free: 00007FA6F7987F30, unused: 0
2016/09/14 10:08:39 [debug] 24996#24996: *1 free: 00007FA6F7988F40, unused: 880
2016/09/14 10:08:39 [debug] 24996#24996: *1 free: 00007FA6F798D7A0, unused: 1585
2016/09/14 10:08:39 [debug] 24996#24996: *1 free: 00007FA6F7940960
2016/09/14 10:08:39 [debug] 24996#24996: *1 hc free: 0000000000000000 0
2016/09/14 10:08:39 [debug] 24996#24996: *1 hc busy: 0000000000000000 0
2016/09/14 10:08:39 [debug] 24996#24996: *1 tcp_nodelay
2016/09/14 10:08:39 [debug] 24996#24996: *1 reusable connection: 1
2016/09/14 10:08:39 [debug] 24996#24996: *1 event timer add: 10: 68000:1473818987552
2016/09/14 10:08:39 [debug] 24996#24996: *1 post event 00007FA6F7951640
2016/09/14 10:08:39 [debug] 24996#24996: keepalive dummy handler
2016/09/14 10:08:39 [debug] 24996#24996: timer delta: 7
2016/09/14 10:08:39 [debug] 24996#24996: posted event 00007FA6F7951640
2016/09/14 10:08:39 [debug] 24996#24996: *1 delete posted event 00007FA6F7951640
2016/09/14 10:08:39 [debug] 24996#24996: *1 http keepalive handler
2016/09/14 10:08:39 [debug] 24996#24996: *1 malloc: 00007FA6F7940960:1024
2016/09/14 10:08:39 [debug] 24996#24996: *1 recv: fd:10 -1 of 1024
2016/09/14 10:08:39 [debug] 24996#24996: *1 recv() not ready (11: Resource temporarily unavailable)
2016/09/14 10:08:39 [debug] 24996#24996: *1 free: 00007FA6F7940960
2016/09/14 10:08:39 [debug] 24996#24996: worker cycle
2016/09/14 10:08:39 [debug] 24996#24996: epoll timer: 60000
2016/09/14 10:08:45 [debug] 24996#24996: epoll: fd:10 ev:2001 d:00007FA6F7946F10
2016/09/14 10:08:45 [debug] 24996#24996: *1 http keepalive handler
2016/09/14 10:08:45 [debug] 24996#24996: *1 malloc: 00007FA6F7940960:1024
2016/09/14 10:08:45 [debug] 24996#24996: *1 recv: fd:10 0 of 1024
2016/09/14 10:08:45 [info] 24996#24996: *1 client 127.0.0.1 closed keepalive connection
2016/09/14 10:08:45 [debug] 24996#24996: *1 close http connection: 10

doujiang24

Hello

1. 你可以用 TEST_NGINX_NO_CLEAN 来调试 [1]

2. 最好贴上你的测试代码，有可能是你的其他错误导致

3. 最好不要用附件，直接放在一个大家都能打开的网页比较合适

1> https://metacpan.org/pod/Test::Nginx::Socket#TEST_NGINX_NO_CLEAN

在 2016年9月14日上午10:17， <roi...@gmail.com>写道：

用raw req eval构造 req。

nginx errlog 见附件。
从log看，6s超时（在test:nginx里data部分设置）后client断开keepalive连接，收到响应。
但是从log看，在6s前，nginx已经say response了。

--

inevity

确实采用NOCLEAN方式进行测试。

test：nginx打印输出见https://paste.ubuntu.com/23188261/

我开了test-nginx/lib/Test/Nginx/Socket.pm 的do selecting 和read bytes的warn 打印。

从log中可以看到，先读1024字节（包括headers和部分chuck body）然后读剩余body。

我们可以看到，很快就读完了服务器发送的chuck respone，但是test：：ngixn客户端还在继续读（那时

没有什么可读的了）

直到超时端口连接。

从log中我打印出相应的curl命令，并直接测试服务器，curl正常。但是观察curl机器和server之间的连接，

在curl结束后，连接也处于time wait了，并没有保持了。

在服务端，只使用了content hander，在那些body输出完后，显示ngx.exit,ngx.eof,等等，

都没有对这个问题起作用。

在 2016年9月16日星期五 UTC+8下午5:14:06，doujiang写道：

Hello

1. 你可以用 TEST_NGINX_NO_CLEAN 来调试 [1]
2. 最好贴上你的测试代码，有可能是你的其他错误导致
3. 最好不要用附件，直接放在一个大家都能打开的网页比较合适

1> https://metacpan.org/pod/Test::Nginx::Socket#TEST_NGINX_NO_CLEAN

在 2016年9月14日上午10:17， <roid...@gmail.com>写道：
用raw req eval构造 req。

nginx errlog 见附件。
从log看，6s超时（在test:nginx里data部分设置）后client断开keepalive连接，收到响应。
但是从log看，在6s前，nginx已经say response了。

--

inevity

附上简单的测试代码

use Test::Nginx::Socket 'no_plan';

no_long_string();

log_level 'debug';

no_root_location();

no_shuffle();

run_tests();

__DATA__

=== TEST 1: http://ip/ keepalive

--- config

location /test {

content_by_lua_block {

local head = "ListAllMyBucketsResult"

local tail = "</Buckets>" .. "</ListAllMyBucketsResult>"

ngx.header["Content-Type"] = "application/xml"

ngx.say(head)

ngx.say(tail)

}

--- request

GET /test

--- more_headers

connection: keep-alive

--- response_body_like eval

qr/([^L]*)istAllMyBucketsResult(\S+)/

--- error_code: 200

--- timeout: 10

--- no_error_log

[error]

--- curl

--- ONLY

在 2016年9月16日星期五 UTC+8下午5:14:06，doujiang写道：

Hello

1. 你可以用 TEST_NGINX_NO_CLEAN 来调试 [1]
2. 最好贴上你的测试代码，有可能是你的其他错误导致
3. 最好不要用附件，直接放在一个大家都能打开的网页比较合适

1> https://metacpan.org/pod/Test::Nginx::Socket#TEST_NGINX_NO_CLEAN

在 2016年9月14日上午10:17， <roid...@gmail.com>写道：
用raw req eval构造 req。

nginx errlog 见附件。
从log看，6s超时（在test:nginx里data部分设置）后client断开keepalive连接，收到响应。
但是从log看，在6s前，nginx已经say response了。

--

doujiang24

Hello

在 2016年9月17日上午3:58，保建国 <ine...@gmail.com>写道：

确实采用NOCLEAN方式进行测试。
test：nginx打印输出见https://paste.ubuntu.com/23188261/

我开了test-nginx/lib/Test/Nginx/Socket.pm 的do selecting 和read bytes的warn 打印。

从log中可以看到，先读1024字节（包括headers和部分chuck body）然后读剩余body。
我们可以看到，很快就读完了服务器发送的chuck respone，但是test：：ngixn客户端还在继续读（那时
没有什么可读的了）
直到超时端口连接。

确实 test-nginx 的实现中，并没有在读响应的时候判断 chunked 的结束符，而是在读完之后才解析 chunked 的内容

https://github.com/openresty/test-nginx/blob/master/lib/Test/Nginx/Socket.pm#L1864

如果你确实需要 Connection: keepalive 来构建你的测试用例，那得改改 test-nginx 了

从log中我打印出相应的curl命令，并直接测试服务器，curl正常。但是观察curl机器和server之间的连接，
在curl结束后，连接也处于time wait了，并没有保持了。

这个正常，因为 curl 已经执行完毕，是需要把连接关了

在服务端，只使用了content hander，在那些body输出完后，显示ngx.exit,ngx.eof,等等，
都没有对这个问题起作用。

在 2016年9月16日星期五 UTC+8下午5:14:06，doujiang写道：
Hello

1. 你可以用 TEST_NGINX_NO_CLEAN 来调试 [1]
2. 最好贴上你的测试代码，有可能是你的其他错误导致
3. 最好不要用附件，直接放在一个大家都能打开的网页比较合适

1> https://metacpan.org/pod/Test::Nginx::Socket#TEST_NGINX_NO_CLEAN

在 2016年9月14日上午10:17， <roid...@gmail.com>写道：
用raw req eval构造 req。

nginx errlog 见附件。
从log看，6s超时（在test:nginx里data部分设置）后client断开keepalive连接，收到响应。
但是从log看，在6s前，nginx已经say response了。

--

--

inevity

这里content-length下也是同样的结果。

doujiang24

2016-09-17 17:33 GMT+08:00 保建国 <ine...@gmail.com>:

这里content-length下也是同样的结果。

是的，header 和 body 都是读完了才解析的

--