请教一个日志输出不匹配的测试问题

whatacold · 2015-12-26T13:05:50+00:00

恩，我这里只是为了说 openresty 中的 socket 实例化操作&#...

请教一个日志输出不匹配的测试问题

whatacold

Hi all,

我试着跑lua-resty-upstream-healthcheck[1]的测试集（12月8号更新的，

4d1ef911f300315857fcd8b3899ca577f50a48f1），

但是却跑失败了，因为error.log输出数量不匹配，加`--- ONLY`仅测试TEST 1的结果：

$ make test

PATH=/usr/local/openresty/nginx/sbin:$PATH prove -I../test-nginx/lib -r t

t/sanity.t .. # I found ONLY: maybe you're debugging?

t/sanity.t .. 1/14

# Failed test 'TEST 1: health check (good case), status ignored by default - grep_error_log_out (req 0)'

# at /home/whatacold/workspace/github/openresty/lua-resty-upstream-healthcheck/../test-nginx/lib/Test/Nginx/Socket.pm line 1041.

# 'healthcheck: peer 127.0.0.1:12354 was checked to be ok

# healthcheck: peer 127.0.0.1:12355 was checked to be ok

...

# healthcheck: peer 127.0.0.1:12356 was checked to be ok

# '

# doesn't match '(?^:^healthcheck: peer 127\.0\.0\.1:12354 was checked to be ok

# healthcheck: peer 127\.0\.0\.1:12355 was checked to be ok

# healthcheck: peer 127\.0\.0\.1:12356 was checked to be ok

# (?:healthcheck: peer 127\.0\.0\.1:12354 was checked to be ok

# healthcheck: peer 127\.0\.0\.1:12355 was checked to be ok

# healthcheck: peer 127\.0\.0\.1:12356 was checked to be ok

# ){3,5}$)'

# Looks like you planned 14 tests but ran 8.

# Looks like you failed 1 test of 8 run.

t/sanity.t .. Dubious, test returned 1 (wstat 256, 0x100)

Failed 7/14 subtests

Test Summary Report

-------------------

t/sanity.t (Wstat: 256 Tests: 8 Failed: 1)

Failed test: 3

Non-zero exit status: 1

Parse errors: Bad plan. You planned 14 tests but ran 8.

Files=1, Tests=8, 1 wallclock secs ( 0.03 usr 0.00 sys + 0.20 cusr 0.02 csys = 0.25 CPU)

Result: FAIL

Makefile:17: recipe for target 'test' failed

make: *** [test] Error 1

实际包含8次checked ok组的日志，与测试期望的4-6次不符（如果没有理解错的话）：

$ ack checked t/servroot/logs/error.log | head -n 6

2015/12/26 12:43:58 [debug] 5129#0: [lua] healthcheck.lua:65: debug(): healthcheck: peer 127.0.0.1:12354 was checked to be ok

2015/12/26 12:43:58 [debug] 5129#0: [lua] healthcheck.lua:65: debug(): healthcheck: peer 127.0.0.1:12355 was checked to be ok

2015/12/26 12:43:58 [debug] 5129#0: [lua] healthcheck.lua:65: debug(): healthcheck: peer 127.0.0.1:12356 was checked to be ok

2015/12/26 12:43:58 [debug] 5129#0: [lua] healthcheck.lua:65: debug(): healthcheck: peer 127.0.0.1:12354 was checked to be ok

2015/12/26 12:43:58 [debug] 5129#0: [lua] healthcheck.lua:65: debug(): healthcheck: peer 127.0.0.1:12355 was checked to be ok

2015/12/26 12:43:58 [debug] 5129#0: [lua] healthcheck.lua:65: debug(): healthcheck: peer 127.0.0.1:12356 was checked to be ok

$ ack checked t/servroot/logs/error.log | wc -l

在此请教几点疑问：

1. 因为看qa.openresty.org上的报告都是测试通过的，且我checkout代码到几个月之前也是有失败，

所以应该是测试方法不对？

2. 这个测试案例不知道是持续多久？我看log大约是2s，

但是sanity.t中的`--- timeout`指定6s，不知道是啥作用:(

（其中指定了0.1s检查一次upstream，输出debug日志，即此关系到上边输出的日志个数）

谢谢！

PS 不知这样贴代码是否方便查看，如果姿势不对，麻烦指出:)

[1] https://github.com/openresty/lua-resty-upstream-healthcheck

whatacold

一共有10处使用{n,m}匹配次数的地方都有问题，我把m设置大点就能够跑过。

例如：

@@ -122,7 +122,7 @@ healthcheck: peer 127\.0\.0\.1:12356 was checked to be ok

(?:healthcheck: peer 127\.0\.0\.1:12354 was checked to be ok

healthcheck: peer 127\.0\.0\.1:12355 was checked to be ok

healthcheck: peer 127\.0\.0\.1:12356 was checked to be ok

-){3,5}$/

+){3,50}$/

agentzh

Hello!

2015-12-25 21:05 GMT-08:00  <what...@gmail.com>:
> 我试着跑lua-resty-upstream-healthcheck[1]的测试集（12月8号更新的，
> 4d1ef911f300315857fcd8b3899ca577f50a48f1），
> 但是却跑失败了，因为error.log输出数量不匹配，加`--- ONLY`仅测试TEST 1的结果：
>
>     $ make test
>     PATH=/usr/local/openresty/nginx/sbin:$PATH prove -I../test-nginx/lib -r
> t
>     t/sanity.t .. # I found ONLY: maybe you're debugging?
>     t/sanity.t .. 1/14
>     #   Failed test 'TEST 1: health check (good case), status ignored by
> default - grep_error_log_out (req 0)'
>     #   at
> /home/whatacold/workspace/github/openresty/lua-resty-upstream-healthcheck/../test-nginx/lib/Test/Nginx/Socket.pm
> line 1041.
>     #                   'healthcheck: peer 127.0.0.1:12354 was checked to be
> ok
>     # healthcheck: peer 127.0.0.1:12355 was checked to be ok
>     ...
>     ...
>     # healthcheck: peer 127.0.0.1:12356 was checked to be ok

你这里省略掉了输出，这里究竟有多少条？8 条？没省略的贴出来看一眼？

> 在此请教几点疑问：
>
> 1. 因为看qa.openresty.org上的报告都是测试通过的，且我checkout代码到几个月之前也是有失败，
>    所以应该是测试方法不对？
>

是啊，我各种虚机里，还有物理机都没有失败哈。

> 2. 这个测试案例不知道是持续多久？我看log大约是2s，
>    但是sanity.t中的`--- timeout`指定6s，不知道是啥作用:(
>    （其中指定了0.1s检查一次upstream，输出debug日志，即此关系到上边输出的日志个数）
>

是的，对于你那么那个失败的 TEST 1 用例而言，设置的 100ms 检查一次，而总共停 0.52s, 所以最多应是检查 5
次。当然如果系统负载高，运行慢，则少于 5 次也是可能的。但如果多于 5 次，我就不太好理解了。你的机器是否足够正常？

Regards,
-agentzh

whatacold

On Saturday, December 26, 2015 at 2:38:40 PM UTC+8, agentzh wrote:

Hello!

你这里省略掉了输出，这里究竟有多少条？8 条？没省略的贴出来看一眼？

8组24条，完整内容如下：

$ make test

PATH=/usr/local/openresty/nginx/sbin:$PATH prove -I../test-nginx/lib -r t

t/sanity.t .. # I found ONLY: maybe you're debugging?

t/sanity.t .. 3/14

# Failed test 'TEST 1: health check (good case), status ignored by default - grep_error_log_out (req 0)'

# at /home/whatacold/workspace/github/openresty/lua-resty-upstream-healthcheck/../test-nginx/lib/Test/Nginx/Socket.pm line 1041.

# 'healthcheck: peer 127.0.0.1:12354 was checked to be ok

# healthcheck: peer 127.0.0.1:12355 was checked to be ok

# healthcheck: peer 127.0.0.1:12356 was checked to be ok

# healthcheck: peer 127.0.0.1:12354 was checked to be ok

# healthcheck: peer 127.0.0.1:12355 was checked to be ok

# healthcheck: peer 127.0.0.1:12356 was checked to be ok

# healthcheck: peer 127.0.0.1:12354 was checked to be ok

# healthcheck: peer 127.0.0.1:12355 was checked to be ok

# healthcheck: peer 127.0.0.1:12356 was checked to be ok

# healthcheck: peer 127.0.0.1:12354 was checked to be ok

# healthcheck: peer 127.0.0.1:12355 was checked to be ok

# healthcheck: peer 127.0.0.1:12356 was checked to be ok

# healthcheck: peer 127.0.0.1:12354 was checked to be ok

# healthcheck: peer 127.0.0.1:12355 was checked to be ok

# healthcheck: peer 127.0.0.1:12356 was checked to be ok

# healthcheck: peer 127.0.0.1:12354 was checked to be ok

# healthcheck: peer 127.0.0.1:12355 was checked to be ok

# healthcheck: peer 127.0.0.1:12356 was checked to be ok

# healthcheck: peer 127.0.0.1:12354 was checked to be ok

# healthcheck: peer 127.0.0.1:12355 was checked to be ok

# healthcheck: peer 127.0.0.1:12356 was checked to be ok

# healthcheck: peer 127.0.0.1:12354 was checked to be ok

# healthcheck: peer 127.0.0.1:12355 was checked to be ok

# healthcheck: peer 127.0.0.1:12356 was checked to be ok

# '

# doesn't match '(?^:^healthcheck: peer 127\.0\.0\.1:12354 was checked to be ok

# healthcheck: peer 127\.0\.0\.1:12355 was checked to be ok

# healthcheck: peer 127\.0\.0\.1:12356 was checked to be ok

# (?:healthcheck: peer 127\.0\.0\.1:12354 was checked to be ok

# healthcheck: peer 127\.0\.0\.1:12355 was checked to be ok

# healthcheck: peer 127\.0\.0\.1:12356 was checked to be ok

# ){3,5}$)'

# Looks like you planned 14 tests but ran 8.

# Looks like you failed 1 test of 8 run.

t/sanity.t .. Dubious, test returned 1 (wstat 256, 0x100)

Failed 7/14 subtests

Test Summary Report

-------------------

t/sanity.t (Wstat: 256 Tests: 8 Failed: 1)

Failed test: 3

Non-zero exit status: 1

Parse errors: Bad plan. You planned 14 tests but ran 8.

Files=1, Tests=8, 1 wallclock secs ( 0.02 usr 0.00 sys + 0.20 cusr 0.03 csys = 0.25 CPU)

Result: FAIL

Makefile:17: recipe for target 'test' failed

make: *** [test] Error 1

是的，对于你那么那个失败的 TEST 1 用例而言，设置的 100ms 检查一次，而总共停 0.52s, 所以最多应是检查 5
次。当然如果系统负载高，运行慢，则少于 5 次也是可能的。但如果多于 5 次，我就不太好理解了。你的机器是否足够正常？

机器就是我自己的笔记本，就开了终端浏览器和一个虚拟机:

$ uptime

14:56:54 up 4:20, 5 users, load average: 0.37, 0.53, 0.83

$ free -m

total used free shared buff/cache available

Mem: 7889 4290 513 597 3084 2876

Swap: 0 0 0

（突然理解了这里测试用时，就是一次请求，在请求中通过sleep使得运行了“一段时间” :P）

agentzh

Hello!

On Fri, Dec 25, 2015 at 11:00 PM,  <what...@gmail.com> wrote:
>
> 8组24条，完整内容如下：
>

你这里执行的次数比期望的更多就不太好解释了，因为机器负载较高时，其会比期望的次数更低。难道你这台机器的时间精度有问题？你使用的是较新版本的
OpenResty 吗？确认 Test::Nginx 测试台是 git master 里的最新版本？

你得在测试用例以及库的 Lua 代码里面自己加些调试语言进行分析了。可以先把测试集用例缩减得尽可能地小些，比如减少 server 次数和 sleep 的总时长。

>
> （突然理解了这里测试用时，就是一次请求，在请求中通过sleep使得运行了“一段时间” :P）
>

是的。

Regards,
-agentzh

whatacold

On Saturday, December 26, 2015 at 3:30:55 PM UTC+8, agentzh wrote:

Hello!

你这里执行的次数比期望的更多就不太好解释了，因为机器负载较高时，其会比期望的次数更低。难道你这台机器的时间精度有问题？你使用的是较新版本的
OpenResty 吗？确认 Test::Nginx 测试台是 git master 里的最新版本？

OpenResty是用的1.9.3.2正式版编译的。

Test::Nginx是从github clone的，安装方法参考网上一篇博文[1]。

发行版用的Fedora 22.

你得在测试用例以及库的 Lua 代码里面自己加些调试语言进行分析了。可以先把测试集用例缩减得尽可能地小些，比如减少 server 次数和 sleep 的总时长。

多谢春哥建议，我自己捣鼓捣鼓看看。

[1] http://uncledou.org/archives/48

doujiang24

Hello,

我这里也可以复现这个问题

最终定位到原因在这里[1]，拿日志之前会先 sleep

在 Makefile 里加入 export TEST_NGINX_SLEEP=0; 所有测试都通过了

然后顺手搜索了下 opboys [2]，果然有 env TEST_NGINX_SLEEP 0.015;

或许，把 test-nginx 的 default 值改为 0.015 比较合适？

1. https://github.com/openresty/test-nginx/blob/master/lib/Test/Nginx/Util.pm#L565

2. https://github.com/openresty/opsboy/search?utf8=%E2%9C%93&q=TEST_NGINX_SLEEP

在 2015年12月26日下午5:01， <what...@gmail.com>写道：

On Saturday, December 26, 2015 at 3:30:55 PM UTC+8, agentzh wrote:
Hello!

你这里执行的次数比期望的更多就不太好解释了，因为机器负载较高时，其会比期望的次数更低。难道你这台机器的时间精度有问题？你使用的是较新版本的
OpenResty 吗？确认 Test::Nginx 测试台是 git master 里的最新版本？

OpenResty是用的1.9.3.2正式版编译的。
Test::Nginx是从github clone的，安装方法参考网上一篇博文[1]。
发行版用的Fedora 22.

你得在测试用例以及库的 Lua 代码里面自己加些调试语言进行分析了。可以先把测试集用例缩减得尽可能地小些，比如减少 server 次数和 sleep 的总时长。

多谢春哥建议，我自己捣鼓捣鼓看看。

[1] http://uncledou.org/archives/48

--

agentzh

Hello!

2016-01-19 0:11 GMT-08:00 DeJiang Zhu:
> 在 Makefile 里加入 export TEST_NGINX_SLEEP=0;  所有测试都通过了
> 然后顺手搜索了下 opboys [2]，果然有 env TEST_NGINX_SLEEP 0.015;
>
> 或许，把 test-nginx 的 default 值改为 0.015 比较合适？
>

OK，好的。欢迎提 PR :)

Regards,
-agentzh