[PATCH] [nginx-tests] Tests: Add sleep to sub_filter_multi.t for TEST_NGINX_UNSAFE=1

[Maxim Dounin]

Hello!

On Wed, Jun 19, 2024 at 07:15:53AM +0900, Hiroaki Nakamura wrote:

> # HG changeset patch
> # User Hiroaki Nakamura <hnakamur at gmail.com>
> # Date 1718746554 -32400
> #      Wed Jun 19 06:35:54 2024 +0900
> # Node ID 8d9e1bc9721896618b0bb4095e39be46ca8fc280
> # Parent  a095b971fbcc99a77206173f6130d5ff2681c389
> Add sleep to sub_filter_multi for NGINX_TEST_UNSAFE=1
> 
> Without this fix, sub_filter_multi.t fails like below:
> ```
> $ sudo -u nginx TEST_NGINX_UNSAFE=1
> TEST_NGINX_BINARY=../freenginx/objs/nginx prove sub_filter_multi.t
> sub_filter_multi.t .. 37/44
> #   Failed test 'shortbuf match 1.3'
> #   at sub_filter_multi.t line 366.
> #                   undef
> #     doesn't match '(?^:(+ABCDE){3})'
> sub_filter_multi.t .. 42/44
> #   Failed test 'shortbuf match 5'
> #   at sub_filter_multi.t line 376.
> #                   undef
> #     doesn't match '(?^:+ABCDE(-*nyABCDE){2})'
> # Looks like you failed 2 tests of 44.
> sub_filter_multi.t .. Dubious, test returned 2 (wstat 512, 0x200)
> Failed 2/44 subtests
> ```
> 
> diff -r a095b971fbcc -r 8d9e1bc97218 sub_filter_multi.t
> --- a/sub_filter_multi.t        Tue Jun 04 18:38:01 2024 +0300
> +++ b/sub_filter_multi.t        Wed Jun 19 06:35:54 2024 +0900
> @@ -363,8 +363,8 @@
>         qr/(+A){3}/, 'shortbuf match 1.1');
>  like(http_get('/shortbuf/match1?a=' . 'abpatternyzABCD' x 3),
>         qr/(+ABCD){3}/, 'shortbuf match 1.2');
> -like(http_get('/shortbuf/match1?a=' . 'abpatternyzABCDE' x 3),
> -       qr/(+ABCDE){3}/, 'shortbuf match 1.3');
> +like(http_get('/shortbuf/match1?a=' . 'abpatternyzABCDE' x 3, sleep => 1),
> +               qr/(+ABCDE){3}/, 'shortbuf match 1.3');
>  like(http_get('/shortbuf/match2?a=' . 'abpatternyzAabpaernyzB' x 2),
>         qr/(+A-B){2}/, 'shortbuf match 2.1 (multiple replace)');
>  like(http_get('/shortbuf/match2?a=' . 'abpatternyzAabpaernyz' x 2),
> @@ -373,7 +373,7 @@
>         qr/(+A*){3}/, 'shortbuf match 3 (1 byte search pattern)');
>  like(http_get('/shortbuf/match4?a=' . 'pattABCDEFGHI' x 3),
>         qr/(+ABCDEFGHI){3}/, 'shortbuf match 4');
> -like(http_get('/shortbuf/match5?a=abpatternyzABCDE' . 'abpatternyABCDE' x 2),
> +like(http_get('/shortbuf/match5?a=abpatternyzABCDE' .
> 'abpatternyABCDE' x 2, sleep => 1),
>         qr/+ABCDE(-*nyABCDE){2}/, 'shortbuf match 5');
>  }

Thanks for the patch.

Using the "sleep" option looks wrong to me: it is designed to 
introduce a pause before sending the request body, and such a 
pause is not needed in these tests.

Instead, test failures you are seeing seems to be a result of the 
fact that tests in question take a lot of time, and http_get() 
times out while waiting for responses.

Overall, it looks like the tests are suboptimal and very fragile: 
they use "limit_rate 4; limit_rate_after 160;" on the upstream 
server, which results in 1 second response time for each 4 
bytes (over 164 bytes which are sent initially).  For example, the 
"shortbuf match 5" test, currently results in 147 bytes of 
the response headers and uses 46 bytes of the response body, so 
the last response byte is sent after 8 seconds - which is exactly 
the timeout value http_get() uses.  As such, the test is highly 
likely to fail.

Most likely, the test took slightly less time when it was 
initially written due to slightly shorter response headers, and 
therefore used to succeed.  Accordingly, a quick fix would be to 
use a larger limit_rate_after value, such as 165 or 170.

A better fix would be to rewrite all these tests with embedded 
Perl, similarly to how it is done in sub_filter_perl.t, so 
multiple buffers will be generated without any unneeded delays.  
This will make the tests much more robust and much faster.  Not 
sure it worth the effort though, especially given that these tests 
are under TEST_NGINX_UNSAFE and thus not really expected to be run 
automatically.

Below is a patch to bump limit_rate_after to 170, please take a 
look if it works for you:

# HG changeset patch
# User Maxim Dounin <mdounin at mdounin.ru>
# Date 1718843281 -10800
#      Thu Jun 20 03:28:01 2024 +0300
# Node ID 9ed5047551e7455353d61c3b7e955e959a594050
# Parent  a095b971fbcc99a77206173f6130d5ff2681c389
Tests: adjusted sub_filter_multi.t limit rate settings.

With previous settings some tests with short buffers, which are under
TEST_NGINX_UNSAFE, used to hit 8 seconds timeout in http_get(), leading
to test failures.

Reported by Hiroaki Nakamura,
https://freenginx.org/pipermail/nginx-devel/2024-June/000373.html

diff --git a/sub_filter_multi.t b/sub_filter_multi.t
--- a/sub_filter_multi.t
+++ b/sub_filter_multi.t
@@ -244,7 +244,7 @@ http {
         listen       127.0.0.1:8081;
 
         limit_rate 4;
-        limit_rate_after 160;
+        limit_rate_after 170;
 
         location / {
             return 200 $arg_a;


-- 
Maxim Dounin
http://mdounin.ru/