Skip to content

tests: stabilize flaky tests in CI - #2523

Open
tzssangglass wants to merge 2 commits into
openresty:masterfrom
tzssangglass:fix-socket-tests-dns
Open

tzssangglass wants to merge 2 commits into
openresty:masterfrom
tzssangglass:fix-socket-tests-dns

Conversation

@tzssangglass

@tzssangglass tzssangglass commented Sep 6, 2026

Copy link
Copy Markdown
Contributor

tests: fix flaky tests in CI

This PR fixes the flaky tests that keep showing up in the CI matrix, with root-cause analysis and local reproduction for each.

### t/014-bugs.t, t/058-tcp-socket.t — resolver fails on "localhost" (dropped)

Superseded by #2528, which fixed the same root cause properly: the CI dnsmasq now serves localhost and trailing-dot.test from local --host-records and TEST_NGINX_RESOLVER=127.0.0.1 is exported, so these tests pass unmodified. This branch no longer touches either file.

t/189-http2-subreq-error-wakeup.t — file dies with "IPC::Run: timeout on timer" (exit 29)

Evidence: job 101756976592

Root cause: test-nginx arms IPC::Run::timeout() with the exact same value it passes to curl's --max-time, and the IPC::Run timer checks integer-second time() with a 1s fudge (IPC/Run/Timer.pm: end_time = start_time + interval + 1), while curl's clock starts a few milliseconds later (after fork+exec). When curl's launch phase crosses a whole-second boundary — easy on a loaded runner — curl's deadline lands after the harness timer's end_time, so the harness kills curl before its own --max-time fires and croaks, aborting the whole test file (Test::Builder exits with the failed-subtest count, e.g. 29) and leaving --- shutdown_error_log checks to fail spuriously.

Fix: --- curl_options: --max-time=0.9 in the three timeout blocks. curl_options is appended after the scaffold's own --max-time, so curl honors the later, smaller value and always self-expires strictly before the harness timer — the race window disappears. A general fix for test-nginx itself (give IPC::Run::timeout slack over --max-time) will be submitted upstream separately.

t/024-access/on-abort.t TEST 7 — "callback done: +OK" missing

Evidence: job 101756976782

Root cause: the error.log check is one-shot (no polling) and --- wait: 0.2 was the entire budget for abort detection plus the on_abort callback's cosocket roundtrip to redis (~0.22s). On loaded runners this window is regularly blown (locally: a 220ms redis reply still passes, 260ms reliably fails).

Fix: bump --- wait to 1s.

t/128-duplex-tcp-socket.t TEST 4 — tcp_query truncated (7/10 of 11 bytes)

Evidence: job 102101640297, job 102101640217

Root cause: the test sends flush_all\r\n one byte at a time (1ms sleeps); the mock TCP server flushes the received query to tcp_query_file after every recv (atomic rename), and the test side reads the file exactly once after --- wait: 0.05. On a loaded runner the forked mock server gets starved between recvs, so the check samples the file while it still holds a 7- or 10-byte prefix (got 'flush_a', expected 11 bytes).

Fix: bump --- wait to 0.5s so the mock server can drain the kernel buffer.

Known remaining flake (not addressed here)

t/109-timer-hup.t TEST 3 occasionally flips both timer assertions when the HUP reload is slow enough that the old worker's 3s timer expires normally (prematurely expired: false) instead of being aborted. This is a HUP-timing assumption baked into the test, orthogonal to the fixes above; keeping it under observation for now.

I hereby granted the copyright of the changes in this pull request
to the authors of this lua-nginx-module project.

@tzssangglass

Copy link
Copy Markdown
Contributor Author

Lint PR should be fixed by:#2522

@tzssangglass
tzssangglass force-pushed the fix-socket-tests-dns branch 2 times, most recently from 6aed999 to 7bd03b4 Compare September 8, 2026 14:26
@tzssangglass tzssangglass changed the title tests: resolve sslip.io instead of localhost via the public resolver tests: stabilize flaky tests in CI Sep 8, 2026
@tzssangglass

Copy link
Copy Markdown
Contributor Author

@zhuizhuhaomeng PTAL

Comment thread t/014-bugs.t Outdated
location /t {
resolver $TEST_NGINX_RESOLVER ipv6=off;
set $myhost 'localhost.';
set $myhost '127.0.0.1.sslip.io.';

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is sslip.io stable?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it's stable.

nip.io and sslip.io have been in operation for over ten years. We have become so popular that our servers receive over 20k queries every second

from https://nip.io/

And I saw Racher use it to test DNS.

Another fix way is deploy CoreDNS in CI.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@zhuizhuhaomeng @tzssangglass I tried a different angle for these two tests in #2528, since even a stable sslip.io is still a third party the runners have to reach, and #2499 moved this CI away from resolving over the network.

While looking into it I found why the failures started: #2499 added the dnsmasq cache but dropped export TEST_NGINX_RESOLVER=8.8.4.4 without putting the cache's address in its place. Nothing sets that variable in CI any more, so every test file falls back to its own default:

$ENV{TEST_NGINX_RESOLVER} ||= '8.8.8.8';

So nginx's resolver directive queries a public resolver directly and the cache only ever serves the warm-up digs. Public resolvers do not answer localhost (RFC 6761 leaves that to the stub resolver), hence Host not found.

#2528 keeps the resolution local instead: export TEST_NGINX_RESOLVER=127.0.0.1, dnsmasq moved to 127.0.0.1:53, and localhost answered from --host-record since --no-hosts keeps /etc/hosts out. Port 53 is needed because t/087-udp-socket.t TEST 10 hands $TEST_NGINX_RESOLVER to setpeername() with port 53, so the resolver has to stay addressable as a bare IP. systemd-resolved's stub owns 127.0.0.53:53 only, and the step now fails loudly if dnsmasq is not listening on 127.0.0.1:53.

All four jobs are green there, with t/014-bugs.t, t/058-tcp-socket.t, t/087-udp-socket.t and t/129-ssl-socket.t all passing.

The rest of this PR — the --- wait and --max-time adjustments in t/024-access/on-abort.t, t/128-duplex-tcp-socket.t and t/189-http2-subreq-error-wakeup.t — covers different flakes and does not overlap, so please take this only as an alternative for the two resolver tests.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I use sslip.io because I thought that test case was supposed to use a real-world DNS server to check DNS queries with domain names ending in .

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@tzssangglass That's a fair point about the name itself: localhost. is a single label, while 127.0.0.1.sslip.io. is a multi-label FQDN, which is closer to what a real query looks like.

That can be covered without an outside service — one more record on the local dnsmasq:

--host-record=trailing-dot.test,127.0.0.1

and the test resolves trailing-dot.test. instead. The name keeps both the multiple labels and the trailing dot, and the answer still comes from a real DNS server, just a local one.

I will add that to #2528.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

make sense, I have updated this PR.

…n-abort.t

t/189 died mid-file with "IPC::Run: timeout on timer" and exit status
29: test-nginx arms IPC::Run::timeout() with the same value as curl's
--max-time, and the IPC::Run timer checks integer-second time() with a
1s fudge, so when curl's launch phase crosses a second boundary the
harness kills curl before its own --max-time fires and croaks,
aborting the whole file and leaving shutdown_error_log checks to fail
spuriously. Since the harness timer cannot be widened from the test
side, make curl self-expire strictly earlier instead: append
"--- curl_options: --max-time=0.9" (curl_options is appended after the
scaffold's own --max-time, so curl honors the later, smaller value),
leaving the IPC::Run timer more than a second of slack.

t/024-access/on-abort.t TEST 7 reads the error.log exactly once after
--- wait: 0.2 — the whole budget for abort detection plus the cosocket
roundtrip to redis; on loaded runners this window is regularly blown.
Bump the wait to 1s.

Flaky CI evidence:
https://github.com/openresty/lua-nginx-module/actions/runs/34126708814/job/101756976592?pr=2523
https://github.com/openresty/lua-nginx-module/actions/runs/34126708814/job/101756976782?pr=2523

Signed-off-by: tzssangglass <tzssangglass@gmail.com>
The mock TCP server flushes the received query to tcp_query_file after
every recv (Util.pm atomic-rename trick) and the test side reads the
file exactly once after --- wait: 0.05. TEST 4 sends "flush_all\r\n"
one byte at a time with 1ms sleeps, so on a loaded runner the forked
mock server gets starved between recvs and the check samples the file
while it still holds a 7- or 10-byte prefix (got 'flush_a', expected
11 bytes). Give the mock server 0.5s to drain the kernel buffer.

Flaky CI evidence:
https://github.com/openresty/lua-nginx-module/actions/runs/34238302357/job/102101640297?pr=2523
https://github.com/openresty/lua-nginx-module/actions/runs/34238302357/job/102101640217?pr=2523

Signed-off-by: tzssangglass <tzssangglass@gmail.com>
@u5surf

u5surf commented Sep 18, 2026

Copy link
Copy Markdown
Contributor

@tzssangglass Thanks for updating the PR.

One note on the BoringSSL + HTTP/3 job that went red there: it failed in t/124-init-worker.t TEST 21, which is unrelated to your change.

The log lines came out in this order:

lua close the global Lua VM <addr>
lua close the global Lua VM <addr> in the cache helper process 2335
lua close the global Lua VM <addr> in the cache helper process 2336
lua close the global Lua VM <addr>
lua close the global Lua VM <addr>

TEST 20 and TEST 22 accept that ordering — it is their fourth alternative. TEST 21 does not: it carries only three alternatives up front, and its copy of the fourth sits inside the trailing repeat group, where it cannot match the beginning. That copy also has a stray trailing space after \4, so it never matches a real log line either.

Adding the missing alternative to TEST 21 would fix this instance, but the pattern would still enumerate orderings, and the order these processes write their lines in is not fixed. Dropping the ordering altogether is simpler:

--- grep_error_log_out eval
qr/\Alua close the global Lua VM ([0-9A-F]+)(?: in the cache helper process \d+)?
(?:lua close the global Lua VM \1(?: in the cache helper process \d+)?
)*\z/

The backreference still pins every line to the same VM address. I ran it against all four orderings the current patterns enumerate and against the output above: all match, while a line with a different address or an unrelated line is still rejected. TEST 23 in the same file already checks these lines in an order-independent way.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants