[PATCH] t/lei-sigpipe: attempt to improve diagnostics for stuck test

[Eric Wong <e@80x24.org>]

Julien Moutinho <julm+public-inbox@sourcephile.fr> wrote:
> With Inline::C, and with Nix's sandbox
> --------------------------------------
> 
> Using (in pkgs/servers/mail/public-inbox/default.nix):
> > preCheck = ''
> >   perl certs/create-certs.perl
> >   export HOME=$(mktemp -d)
> >   mkdir -p $HOME/.cache/public-inbox/inline-c
> > '';
> 
> $ nix -L build -f . public-inbox
> > [...]
> > perl5.34.0-public-inbox> t/lei-refresh-mail-sync.t .... ok
> Hangs like forever after this line, while on t/lei-sigpipe.t:
> 
> $ ps auxwwf
> > root     1755997  0.0  0.0 453172  2800 ?        Ssl  déc.04   0:03 nix-daemon --daemon
> > root     1811429  0.0  0.0 453652  1928 ?        Ssl  déc.04   0:00  \_ nix-daemon 1757028
> > root     1811455  0.0  0.0 453652  2004 ?        Ssl  déc.04   0:00  \_ nix-daemon 1757031
> > root     1839837  0.0  0.0 453652  1832 ?        Ssl  déc.04   0:00  \_ nix-daemon 1757027
> > root     1839841  0.0  0.0 453652  1996 ?        Ssl  déc.04   0:00  \_ nix-daemon 1757030
> > root     1839856  0.0  0.0 453652  1832 ?        Ssl  déc.04   0:00  \_ nix-daemon 1757029
> > root     3135741  0.0  0.2 603352 17080 ?        Ssl  01:05   0:00  \_ nix-daemon 3135672
> > nixbld1  3137110  0.0  0.0   5200  4072 ?        Ss   01:05   0:01      \_ bash -e /nix/store/qf3mzpvsmkrw963xchbivcci06078n13-builder.sh
> > nixbld1  3140619  0.0  0.0   4996  4012 ?        S    01:05   0:00          \_ make SHELL=/nix/store/l0wlqpbsvh1pgvhcdhw7qkka3d31si7k-bash-5.1-p8/bin/bash VERBOSE=y test
> > nixbld1  3140633  0.0  0.1  17188 13352 ?        S    01:05   0:01          |   \_ /nix/store/vslsa0l17xjcrdgm2knwj0z5hlvf73m7-perl-5.34.0/bin/perl -MExtUtils::Command::MM -MTest::Harness -e undef *Test::Harness::Switches; test_harness(0, 'blib/lib', 'blib/arch') t/admin.t t/altid.t t/altid_v2.t t/cgi.t t/cmd_ipc.t t/content_hash.t t/dir_idle.t t/edit.t t/eml_content_disposition.t t/eml_content_type.t t/epoll.t t/extindex-psgi.t t/extsearch.t t/fake_inotify.t t/feed.t t/gcf2.t t/gcf2_client.t t/httpd.t t/idx_stack.t t/imap.t t/imap_searchqp.t t/imapd-tls.t t/imapd.t t/inbox_idle.t t/index-git-times.t t/indexlevels-mirror.t t/ipc.t t/kqnotify.t t/lei-auto-watch.t t/lei-convert.t t/lei-daemon.t t/lei-export-kw.t t/lei-externals.t t/lei-import-http.t t/lei-import-imap.t t/lei-import-maildir.t t/lei-import-nntp.t t/lei-import.t t/lei-index.t t/lei-inspect.t t/lei-lcat.t t/lei-p2q.t t/lei-q-kw.t t/lei-q-remote-import.t t/lei-q-save.t t/lei-q-thread.t t/lei-refresh-mail-sync.t t/lei-sigpipe.t t/lei-tag.t t/lei-up.t t/lei-watch.t t/lei.t t/lei_dedupe.t t/lei_external.t t/lei_lcat.t t/lei_mail_sync.t t/lei_overview.t t/lei_saved_search.t t/lei_store.t t/lei_to_mail.t t/lei_xsearch.t t/mbox_lock.t t/mbox_reader.t t/mdir_reader.t t/mime.t t/miscsearch.t t/net_reader-imap.t t/nntpd-tls.t t/nntpd.t t/nodatacow.t t/on_destroy.t t/plack.t t/psgi_attach.t t/psgi_bad_mids.t t/psgi_mount.t t/psgi_multipart_not.t t/psgi_scan_all.t t/psgi_search.t t/psgi_v2.t t/rename_noreplace.t t/reply.t t/search-thr-index.t t/shared_kv.t t/solver_git.t t/thread-index-gap.t t/uri_imap.t t/uri_nntps.t t/v2dupindex.t t/www_altid.t t/xcpdb-reshard.t t/www_static.t t/watch_multiple_headers.t t/watch_maildir_v2.t t/watch_maildir.t t/watch_imap.t t/watch_filter_rubylang.t t/view.t t/v2reindex.t t/v2mirror.t t/v2mda.t t/v2index-late-dupe.t t/v2-add-remove-add.t t/v1reindex.t t/v1-add-remove-add.t t/time.t t/thread-cycle.t t/spamcheck_spamc.t t/sigfd.t t/replace.t t/reindex-time-range.t t/qspawn.t t/purge.t t/psgi_text.t t/precheck.t t/over.t t/nulsubject.t t/nntpd-v2.t t/nntp.t t/multi-mid.t t/msgtime.t t/msgmap.t t/msg_iter.t t/mid.t t/mda_filter_rubylang.t t/mda.t t/linkify.t t/init.t t/indexlevels-mirror-v1.t t/inbox.t t/import.t t/imap_tracker.t t/hval.t t/httpd-unix.t t/httpd-https.t t/httpd-corner.t t/gzip_filter.t t/git.t t/filter_vger.t t/filter_subjecttag.t t/filter_rubylang.t t/filter_mirror.t t/filter_base.t t/emergency.t t/ds-poll.t t/ds-leak.t t/ds-kqxs.t t/config_limiter.t t/config.t t/address.t
> > nixbld1  3145719  0.0  0.4  44576 35640 ?        S    01:09   0:01          |       \_ t/lei-sigpipe.t
> > nixbld1  3145743  0.0  0.1  14388 10388 ?        S    01:09   0:00          |           \_ /nix/store/vslsa0l17xjcrdgm2knwj0z5hlvf73m7-perl-5.34.0/bin/perl -w -I/nix/store/vslsa0l17xjcrdgm2knwj0z5hlvf73m7-perl-5.34.0/lib/perl5/site_perl -I/nix/store/1hdx7bxjwqrfnalalkgbwi32l45h8z7b-perl5.34.0-Mail-IMAPClient-3.42/lib/perl5/site_perl -I/nix/st blib/script/lei q -q -t z:1..
> > nixbld1  3145724  0.0  0.5  50504 42160 ?        S    01:09   0:00          \_ lei-daemon /build/pi-lei-sigpipe-7522-WoHO/lei-daemon/xdg_run/lei/5.seq.sock
> > nixbld1  3145730  0.0  0.4  50092 39736 ?        S    01:09   0:00              \_ lei/store /build/pi-lei-sigpipe-7522-WoHO/lei-daemon/.local/share
> 
> t/lei-sigpipe.t is on:
> > 01:30:29.508334 clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=1, tv_nsec=0}, 0x7fffffff5090) = 0 <1.000360>
> > 01:30:30.509837 clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=1, tv_nsec=0}, 0x7fffffff5090) = 0 <1.000186>
> > 01:30:31.510259 clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=1, tv_nsec=0}, 0x7fffffff5090) = 0 <1.000175>
> > [...]

Huh? but it's stuck in sysread() as noted below...

I'm not sure where clock_nanosleep(2) calls are coming from with
a 1s interval.  I doubt I'd ever loop clock_nanosleep(CLOCK_REALTIME
no matter how messed up my brain gets :P

I do use nanosleep(2) with a 100ms interval on sendmsg
ENOBUFS|ENOMEM|ETOOMANYREFS in Spawn.pm and that's a different
syscall.  From what I can tell, Mail::IMAPClient doesn't
clock_nanosleep, nor does Perl itself...

Sleeping on CLOCK_REALTIME seems wrong outside of a cron-like
scheduler...

> lei-daemon store is on:
> > 01:31:03.834708 epoll_wait(5,

OK, that's normal.

> Looks like it is waiting on sysread() in
> https://public-inbox.org/public-inbox.git/tree/t/lei-sigpipe.t#n35

OK, that makes more sense...

> This test does succeed outside Nix's sandbox:
> $ (cd public-inbox-1.7.0; export PERL_INLINE_DIRECTORY=$PWD/inline-c; rm -rf $PERL_INLINE_DIRECTORY; mkdir $PERL_INLINE_DIRECTORY; prove -bvw t/lei-sigpipe.t )

OK, <snip>

> More surprisingly, it even succeeds when run manually
> inside the hanging Nix sandbox:

OK, <snip>

> Even more strange, Dominique was able to reproduce
> the hang this morning, but no longer tonight..

It's been a while, and I can't reproduce it.  Maybe this patch will help
with diagnosis:

------------8<---------
Subject: [PATCH] t/lei-sigpipe: attempt to improve diagnostics for stuck test

This may help diagnose a difficult-to-reproduce test failure on NixOS.

Link: https://public-inbox/meta/20211209013743.okzgim7bbrpahks7@sourcephile.fr/
---
 t/lei-sigpipe.t | 8 +++++++-
 1 file changed, 7 insertions(+), 1 deletion(-)

diff --git a/t/lei-sigpipe.t b/t/lei-sigpipe.t
index d9738b07..6b2772a6 100644
--- a/t/lei-sigpipe.t
+++ b/t/lei-sigpipe.t
@@ -27,11 +27,17 @@ EOM
 		}
 
 		lei_ok(qw(import), $f) if $imported++ == 0;
-		open my $errfh, '+>', "$ENV{HOME}/stderr.log" or xbail $!;
+		open my $errfh, '+>>', "$ENV{HOME}/stderr.log" or xbail $!;
 		my $opt = { run_mode => 0, 2 => $errfh, 1 => $w };
 		my $cmd = [qw(lei q -q -t), @$out, 'z:1..'];
 		my $tp = start_script($cmd, undef, $opt);
 		close $w;
+		vec(my $rvec = '', fileno($r), 1) = 1;
+		if (!select($rvec, undef, undef, 30)) {
+			seek($errfh, 0, 0) or xbail $!;
+			my $s = do { local $/; <$errfh> };
+			xbail "lei q had no output after 30s, stderr=$s";
+		}
 		is(sysread($r, my $buf, 1), 1, 'read one byte');
 		close $r; # trigger SIGPIPE
 		$tp->join;