Build failure: spamassassin

Scrumplex commented 1 year ago

Steps To Reproduce

Steps to reproduce the behavior:

build spamassassin at f2406198ea0e4e37d4380d0e20336c575b8f8ef9 (nixos-unstable at the time of writing)

Build log

https://hydra.nixos.org/build/227386996

Additional context

Add any other context about the problem here.

Git bisect seems to suggest that the recent bump for poppler is the cause:

# bad: [f2406198ea0e4e37d4380d0e20336c575b8f8ef9] Merge pull request #242861 from r-ryantm/auto-update/ani-cli
# good: [4a729ce4b1fe5ec4fffc71c67c96aa5184ebb462] Merge pull request #242323 from hercules-ci/add-labeler-module-system
git bisect start 'f2406198ea0e4e37d4380d0e20336c575b8f8ef9' '4a729ce4b1fe5ec4fffc71c67c96aa5184ebb462'
# good: [e7c90c1dcbe49094e0cb148dcb108c75647644c2] Merge pull request #242670 from jmbaur/update-xilinx-bootgen
git bisect good e7c90c1dcbe49094e0cb148dcb108c75647644c2
# bad: [170b6714ad98897c95ba26b58e1e693e1274a903] poppler: 23.02.0 → 23.07.0
git bisect bad 170b6714ad98897c95ba26b58e1e693e1274a903
# good: [5a01208e9ee2e467e11cc509873c2a49c315e658] Merge pull request #242542 from blaggacao/init-python-annotated-types
git bisect good 5a01208e9ee2e467e11cc509873c2a49c315e658
# good: [2aa2a03767ae0536149fd9b8d1299407f4aaaa3a] Merge pull request #242815 from r-ryantm/auto-update/gotrue-supabase
git bisect good 2aa2a03767ae0536149fd9b8d1299407f4aaaa3a
# good: [b9cdb7a6ced9eb0c91fbec595aed8e24d83b0468] Merge pull request #237365 from msfjarvis/hs/fix-fzf-tmux
git bisect good b9cdb7a6ced9eb0c91fbec595aed8e24d83b0468
# good: [70c518a59332fee4e2dd340180806625e9f7ed11] Merge pull request #242738 from r-ryantm/auto-update/python310Packages.mlflow
git bisect good 70c518a59332fee4e2dd340180806625e9f7ed11
# good: [d7ef505ab0c07a8c627485ff97f14f93c5d2987e] Merge pull request #242767 from r-ryantm/auto-update/ryujinx
git bisect good d7ef505ab0c07a8c627485ff97f14f93c5d2987e
# good: [e2078e747c791cf839664d584628f5f2ee89a32a] Merge pull request #242775 from r-ryantm/auto-update/cbmc
git bisect good e2078e747c791cf839664d584628f5f2ee89a32a
# first bad commit: [170b6714ad98897c95ba26b58e1e693e1274a903] poppler: 23.02.0 → 23.07.0

Notify maintainers

@qknight @alyssais

Metadata

Please run nix-shell -p nix-info --run "nix-info -m" and paste the result.

 - system: `"x86_64-linux"`
 - host os: `Linux 6.4.1-zen1, NixOS, 23.11 (Tapir), 23.11.20230710.4a729ce`
 - multi-user?: `yes`
 - sandbox: `yes`
 - version: `nix-env (Nix) 2.15.1`
 - channels(scrumplex): `""`
 - channels(root): `"nixos"`
 - nixpkgs: `/etc/nix/channels/nixpkgs`

jtojnar commented 1 year ago

The Hydra log reports:

Test Summary Report
-------------------
t/spamd_ssl.t                   (Wstat: 1536 (exited 6) Tests: 9 Failed: 6)
  Failed tests:  2, 4-5, 7-9
  Non-zero exit status: 6
Files=210, Tests=3655, 312 wallclock secs ( 1.64 usr  0.33 sys + 186.28 cusr 71.28 csys = 259.53 CPU)

But I got a different test failing when I tried to switch to nixos-unstable (e74e684):

Details

``` perl5.36.0-SpamAssassin> ===( 2364;178 0/3 77/93 77/93 0/10 87/98 16/33 7/35 ... )===spam_pid not found: Sleeping 5 - Retry # 19 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 5 - Retry # 18 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 6 - Retry # 17 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 6 - Retry # 16 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 6 - Retry # 15 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 6 - Retry # 14 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 7 - Retry # 13 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 7 - Retry # 12 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 7 - Retry # 11 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 7 - Retry # 10 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 8 - Retry # 9 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 8 - Retry # 8 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 8 - Retry # 7 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 8 - Retry # 6 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 9 - Retry # 5 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 9 - Retry # 4 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 9 - Retry # 3 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 9 - Retry # 2 perl5.36.0-SpamAssassin> spam_pid not found: Sleeping 10 - Retry # 1 perl5.36.0-SpamAssassin> spamd start failed - Could not find a valid PID. perl5.36.0-SpamAssassin> End Debug log ------------------- perl5.36.0-SpamAssassin> Jul 15 19:29:58.215 [8550] dbg: logger: adding facilities: all perl5.36.0-SpamAssassin> Jul 15 19:29:58.215 [8550] dbg: logger: logging level is DBG perl5.36.0-SpamAssassin> Jul 15 19:29:58.216 [8550] dbg: logger: successfully opened file log/spamd_unix_and_tcp.yu0ha2/d.spamd_unix_and_tcp/spamd.err.0.timestamped perl5.36.0-SpamAssassin> Jul 15 19:29:58.217 [8550] dbg: logger: successfully added file method perl5.36.0-SpamAssassin> Jul 15 19:29:58.217 [8550] dbg: spamd: will perform setuids? 0 perl5.36.0-SpamAssassin> Jul 15 19:29:58.217 [8550] dbg: spamd: socket module of choice: IO::Socket::IP 0.41, Socket 2.033, have PF_INET, have PF_INET6, using legacy Socket6::getaddrinfo, AI_ADDRCONFIG is supported perl5.36.0-SpamAssassin> Jul 15 19:29:58.217 [8550] dbg: spamd: socket specification: "127.0.0.1", IP address: 127.0.0.1, port: 42474 perl5.36.0-SpamAssassin> Jul 15 19:29:58.217 [8550] dbg: spamd: attempting to listen on IP addresses: 127.0.0.1, port 42474 perl5.36.0-SpamAssassin> Jul 15 19:29:58.217 [8550] dbg: spamd: creating IO::Socket::IP socket: Listen: 4096, LocalAddr: 127.0.0.1, LocalPort: 42474, Proto: tcp, ReuseAddr: 1, Type: 1, V6Only: 1 perl5.36.0-SpamAssassin> Jul 15 19:29:58.217 [8550] dbg: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> server socket setup failed, retry 1: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> Jul 15 19:29:59.217 [8550] dbg: spamd: attempting to listen on IP addresses: 127.0.0.1, port 42474 perl5.36.0-SpamAssassin> Jul 15 19:29:59.217 [8550] dbg: spamd: creating IO::Socket::IP socket: Listen: 4096, LocalAddr: 127.0.0.1, LocalPort: 42474, Proto: tcp, ReuseAddr: 1, Type: 1, V6Only: 1 perl5.36.0-SpamAssassin> Jul 15 19:29:59.218 [8550] dbg: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> server socket setup failed, retry 2: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> Jul 15 19:30:00.218 [8550] dbg: spamd: attempting to listen on IP addresses: 127.0.0.1, port 42474 perl5.36.0-SpamAssassin> Jul 15 19:30:00.218 [8550] dbg: spamd: creating IO::Socket::IP socket: Listen: 4096, LocalAddr: 127.0.0.1, LocalPort: 42474, Proto: tcp, ReuseAddr: 1, Type: 1, V6Only: 1 perl5.36.0-SpamAssassin> Jul 15 19:30:00.218 [8550] dbg: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> server socket setup failed, retry 3: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> Jul 15 19:30:01.219 [8550] dbg: spamd: attempting to listen on IP addresses: 127.0.0.1, port 42474 perl5.36.0-SpamAssassin> Jul 15 19:30:01.219 [8550] dbg: spamd: creating IO::Socket::IP socket: Listen: 4096, LocalAddr: 127.0.0.1, LocalPort: 42474, Proto: tcp, ReuseAddr: 1, Type: 1, V6Only: 1 perl5.36.0-SpamAssassin> Jul 15 19:30:01.219 [8550] dbg: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> server socket setup failed, retry 4: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> Jul 15 19:30:02.220 [8550] dbg: spamd: attempting to listen on IP addresses: 127.0.0.1, port 42474 perl5.36.0-SpamAssassin> Jul 15 19:30:02.220 [8550] dbg: spamd: creating IO::Socket::IP socket: Listen: 4096, LocalAddr: 127.0.0.1, LocalPort: 42474, Proto: tcp, ReuseAddr: 1, Type: 1, V6Only: 1 perl5.36.0-SpamAssassin> Jul 15 19:30:02.220 [8550] dbg: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> server socket setup failed, retry 5: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> Jul 15 19:30:03.221 [8550] dbg: spamd: attempting to listen on IP addresses: 127.0.0.1, port 42474 perl5.36.0-SpamAssassin> Jul 15 19:30:03.221 [8550] dbg: spamd: creating IO::Socket::IP socket: Listen: 4096, LocalAddr: 127.0.0.1, LocalPort: 42474, Proto: tcp, ReuseAddr: 1, Type: 1, V6Only: 1 perl5.36.0-SpamAssassin> Jul 15 19:30:03.221 [8550] dbg: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> server socket setup failed, retry 6: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> Jul 15 19:30:04.222 [8550] dbg: spamd: attempting to listen on IP addresses: 127.0.0.1, port 42474 perl5.36.0-SpamAssassin> Jul 15 19:30:04.222 [8550] dbg: spamd: creating IO::Socket::IP socket: Listen: 4096, LocalAddr: 127.0.0.1, LocalPort: 42474, Proto: tcp, ReuseAddr: 1, Type: 1, V6Only: 1 perl5.36.0-SpamAssassin> Jul 15 19:30:04.222 [8550] dbg: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> server socket setup failed, retry 7: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> Jul 15 19:30:05.223 [8550] dbg: spamd: attempting to listen on IP addresses: 127.0.0.1, port 42474 perl5.36.0-SpamAssassin> Jul 15 19:30:05.223 [8550] dbg: spamd: creating IO::Socket::IP socket: Listen: 4096, LocalAddr: 127.0.0.1, LocalPort: 42474, Proto: tcp, ReuseAddr: 1, Type: 1, V6Only: 1 perl5.36.0-SpamAssassin> Jul 15 19:30:05.223 [8550] dbg: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> server socket setup failed, retry 8: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> Jul 15 19:30:06.223 [8550] dbg: spamd: attempting to listen on IP addresses: 127.0.0.1, port 42474 perl5.36.0-SpamAssassin> Jul 15 19:30:06.223 [8550] dbg: spamd: creating IO::Socket::IP socket: Listen: 4096, LocalAddr: 127.0.0.1, LocalPort: 42474, Proto: tcp, ReuseAddr: 1, Type: 1, V6Only: 1 perl5.36.0-SpamAssassin> Jul 15 19:30:06.224 [8550] dbg: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> server socket setup failed, retry 9: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> Jul 15 19:30:07.224 [8550] dbg: spamd: attempting to listen on IP addresses: 127.0.0.1, port 42474 perl5.36.0-SpamAssassin> Jul 15 19:30:07.224 [8550] dbg: spamd: creating IO::Socket::IP socket: Listen: 4096, LocalAddr: 127.0.0.1, LocalPort: 42474, Proto: tcp, ReuseAddr: 1, Type: 1, V6Only: 1 perl5.36.0-SpamAssassin> Jul 15 19:30:07.225 [8550] dbg: spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> spamd: could not create IO::Socket::IP socket on [127.0.0.1]:42474: Address already in use perl5.36.0-SpamAssassin> End Debug log ------------------- at t/SATest.pm line 760. perl5.36.0-SpamAssassin> Maybe you need to kill a running spamd process? perl5.36.0-SpamAssassin> Or the start took too long. Started at 1689449397, gave up at 1689449584 perl5.36.0-SpamAssassin> ===( 2423;318 0/3 86/93 86/93 2/10 11/35 12/32 0/? )========= Not found: flag = X-Spam-Flag: YES at t/spamd_unix_and_tcp.t line 20. perl5.36.0-SpamAssassin> # Failed test at t/SATest.pm line 929. perl5.36.0-SpamAssassin> Output can be examined in: log/spamd_unix_and_tcp.yu0ha2/d.spamd_unix_and_tcp/out.0 perl5.36.0-SpamAssassin> ===( 2451;320 0/3 7/10 14/35 17/32 0/4 0/? )================== Not found: flag = X-Spam-Flag: YES at t/spamd_unix_and_tcp.t line 35. perl5.36.0-SpamAssassin> # Failed test at t/SATest.pm line 929. perl5.36.0-SpamAssassin> Output can be examined in: log/spamd_unix_and_tcp.yu0ha2/d.spamd_unix_and_tcp/out.5 perl5.36.0-SpamAssassin> ===( 2457;322 0/3 9/10 15/35 19/32 1/4 0/12 )================# Looks like you failed 2 tests of 10. perl5.36.0-SpamAssassin> t/spamd_unix_and_tcp.t ............ Dubious, test returned 2 (wstat 512, 0x200) perl5.36.0-SpamAssassin> Failed 2/10 subtests perl5.36.0-SpamAssassin> Test Summary Report perl5.36.0-SpamAssassin> ------------------- perl5.36.0-SpamAssassin> t/spamd_unix_and_tcp.t (Wstat: 512 (exited 2) Tests: 10 Failed: 2) perl5.36.0-SpamAssassin> Failed tests: 3, 8 perl5.36.0-SpamAssassin> Non-zero exit status: 2 perl5.36.0-SpamAssassin> Files=210, Tests=3655, 342 wallclock secs ( 2.48 usr 0.42 sys + 359.14 cusr 151.24 csys = 513.28 CPU) perl5.36.0-SpamAssassin> Result: FAIL perl5.36.0-SpamAssassin> Failed 1/210 test programs. 2/3655 subtests failed. perl5.36.0-SpamAssassin> make: *** [Makefile:1493: test_dynamic] Error 255 ```

And it did not re-occur when I tried building my system for a second time.

I was also unable to reproduce the error on master (29bcead8405cfe4c00085843eb372cc43837bb9d).

So it looks like sometimes the tests just fail non-deterministically.

Scrumplex commented 5 months ago

Tests have started failing again for me :/

NixOS / nixpkgs