Re: Buildbot failure in Wildebeest Builder on whole buildset

[Mark Wielaard <mark@klomp.org>]

[-- Attachment #1: Type: text/plain, Size: 537 bytes --]

Hi,

On Mon, Sep 06, 2021 at 10:02:11PM +0200, Mark Wielaard wrote:
> Still looking for explanations of the other FAILS (which I cannot
> reproduce locally).

I think I finally got it. The thing that all the tests that are
(sometimes) failing have in commen is that they use SIGUSR1 or SIGUSR2
to trigger a new scan or groom cycle. But they don't check whether the
initial scan or groom cycle has finished. So the attached patch
explicitly does that before the first SIGUSR1 or SIGUSR2 is fired at
the debuginfod server.

Pushed,

Mark


[-- Attachment #2: 0001-tests-Make-sure-to-wait-for-initial-scan-and-groom-c.patch --]
[-- Type: text/x-diff, Size: 18080 bytes --]

From dbd4c8766ea80cb0b6294a6755a556017215eb99 Mon Sep 17 00:00:00 2001
From: Mark Wielaard <mark@klomp.org>
Date: Tue, 7 Sep 2021 01:50:51 +0200
Subject: [PATCH] tests: Make sure to wait for initial scan and groom cycle

At startup the debuginfod server does a scan and groom cycle. Make
sure to wait for that before triggering a new one with SIGUSR1 or
SIGURST2.

Signed-off-by: Mark Wielaard <mark@klomp.org>
---
 tests/ChangeLog                            | 17 +++++++++++++++++
 tests/run-debuginfod-archive-groom.sh      | 13 +++++++++----
 tests/run-debuginfod-archive-rename.sh     | 12 ++++++++----
 tests/run-debuginfod-archive-test.sh       |  4 +++-
 tests/run-debuginfod-artifact-running.sh   |  8 +++++---
 tests/run-debuginfod-dlopen.sh             |  6 +++++-
 tests/run-debuginfod-extraction.sh         |  6 ++++--
 tests/run-debuginfod-federation-link.sh    |  9 +++++++--
 tests/run-debuginfod-federation-metrics.sh |  2 +-
 tests/run-debuginfod-federation-sqlite.sh  | 10 +++++++---
 tests/run-debuginfod-malformed.sh          |  5 ++++-
 tests/run-debuginfod-regex.sh              |  7 +++++--
 tests/run-debuginfod-tmp-home.sh           |  5 ++++-
 tests/run-debuginfod-writable.sh           |  5 ++++-
 14 files changed, 83 insertions(+), 26 deletions(-)

diff --git a/tests/ChangeLog b/tests/ChangeLog
index 436a1c45..61080c52 100644
--- a/tests/ChangeLog
+++ b/tests/ChangeLog
@@ -1,3 +1,20 @@
+2021-09-06  Mark Wielaard  <mark@klomp.org>
+
+	* run-debuginfod-archive-groom.sh: Wait for initial scan and groom
+	cycle.
+	* run-debuginfod-archive-rename.sh: Likewise.
+	* run-debuginfod-federation-sqlite.sh: Likewise.
+	* run-debuginfod-archive-test.sh: Wait for initial scan cycle.
+	* run-debuginfod-artifact-running.sh: Likewise.
+	* run-debuginfod-dlopen.sh: Likewise.
+	* run-debuginfod-extraction.sh: Likewise.
+	* run-debuginfod-federation-link.sh: Likewise.
+	* run-debuginfod-federation-metrics.sh: Likewise.
+	* run-debuginfod-malformed.sh: Likewise.
+	* run-debuginfod-regex.sh: Likewise.
+	* run-debuginfod-tmp-home.sh: Likewise.
+	* run-debuginfod-writable.sh: Likewise.
+
 2021-09-06  Mark Wielaard  <mark@klomp.org>
 
 	* run-debuginfod-archive-groom.sh: Set DEBUGINFOD_URLS after starting
diff --git a/tests/run-debuginfod-archive-groom.sh b/tests/run-debuginfod-archive-groom.sh
index 1e616448..1e7bd67a 100755
--- a/tests/run-debuginfod-archive-groom.sh
+++ b/tests/run-debuginfod-archive-groom.sh
@@ -57,9 +57,12 @@ cp -rvp ${abs_srcdir}/debuginfod-rpms R
 if [ "$zstd" = "false" ]; then  # nuke the zstd fedora 31 ones
     rm -vrf R/debuginfod-rpms/fedora31
 fi
+
+# wait till the initial scan is done before triggering a new one
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
 kill -USR1 $PID1
 # Now there should be 1 files in the index
-wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 2
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 
@@ -72,7 +75,7 @@ tempfiles vlog3
 cp -rvp ${abs_srcdir}/debuginfod-tars Z
 kill -USR1 $PID1
 # Wait till both files are in the index and scan/index fully finished
-wait_ready $PORT1 'thread_work_total{role="traverse"}' 2
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 3
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 ########################################################################
@@ -83,7 +86,7 @@ txz=$(find Z -name \*tar.xz | wc -l)
 
 kill -USR1 $PID1  # two hits of SIGUSR1 may be needed to resolve .debug->dwz->srefs
 # Wait till both files are in the index and scan/index fully finished
-wait_ready $PORT1 'thread_work_total{role="traverse"}' 3
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 4
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 
@@ -136,9 +139,11 @@ RPM_BUILDID=d44d42cbd7d915bc938c81333a21e355a6022fb7 # in rhel6/ subdir
 # Drop some of the artifacts, run a groom cycle; confirm that
 # debuginfod has forgotten them, but remembers others
 rm -r R/debuginfod-rpms/rhel6/*
+
+wait_ready $PORT1 'thread_work_total{role="groom"}' 1
 kill -USR2 $PID1  # groom cycle
 ## 1 groom cycle already took place at/soon-after startup, so -USR2 makes 2
-wait_ready $PORT1 'thread_work_total{role="groom"}' 1
+wait_ready $PORT1 'thread_work_total{role="groom"}' 2
 # Expect 4 rpms containing 2 buildids to be deleted by the groom
 wait_ready $PORT1 'groomed_total{decision="stale"}' 4
 
diff --git a/tests/run-debuginfod-archive-rename.sh b/tests/run-debuginfod-archive-rename.sh
index 7ad4786e..4fc1b441 100755
--- a/tests/run-debuginfod-archive-rename.sh
+++ b/tests/run-debuginfod-archive-rename.sh
@@ -49,9 +49,11 @@ if [ "$zstd" = "false" ]; then  # nuke the zstd fedora 31 ones
     rm -vrf R/debuginfod-rpms/fedora31
 fi
 
+# Make sure the initial scan is done
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
 kill -USR1 $PID1
 # Now there should be 1 files in the index
-wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 2
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 
@@ -63,23 +65,25 @@ SHA=f4a1a8062be998ae93b8f1cd744a398c6de6dbb1
 # there are two copies of the same buildid in the index, one for the
 # no-longer-existing file name, and one under the new name.
 
+# Make sure the initial groom cycle has been done
+wait_ready $PORT1 'thread_work_total{role="groom"}' 1
 # run a groom cycle to force server to drop its fdcache
 kill -USR2 $PID1  # groom cycle
 wait_ready $PORT1 'thread_work_total{role="groom"}' 2
 # move it around a couple of times to make it likely to hit a nonexistent entry during iteration
 mv R/debuginfod-rpms/rhel7 R/debuginfod-rpms/rhel7renamed
 kill -USR1 $PID1  # scan cycle
-wait_ready $PORT1 'thread_work_total{role="traverse"}' 2
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 3
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 mv R/debuginfod-rpms/rhel7renamed R/debuginfod-rpms/rhel7renamed2
 kill -USR1 $PID1  # scan cycle
-wait_ready $PORT1 'thread_work_total{role="traverse"}' 3
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 4
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 mv R/debuginfod-rpms/rhel7renamed2 R/debuginfod-rpms/rhel7renamed3
 kill -USR1 $PID1  # scan cycle
-wait_ready $PORT1 'thread_work_total{role="traverse"}' 4
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 5
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 
diff --git a/tests/run-debuginfod-archive-test.sh b/tests/run-debuginfod-archive-test.sh
index 1ec57bba..9f7454bc 100755
--- a/tests/run-debuginfod-archive-test.sh
+++ b/tests/run-debuginfod-archive-test.sh
@@ -38,6 +38,8 @@ tempfiles vlog$PORT1
 errfiles vlog$PORT1
 # Server must become ready
 wait_ready $PORT1 'ready' 1
+# And make sure first scan is done
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
 
 # Be patient when run on a busy machine things might take a bit.
 export DEBUGINFOD_TIMEOUT=10
@@ -55,7 +57,7 @@ fi
 
 kill -USR1 $PID1
 # Wait till both files are in the index and scan/index fully finished
-wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 2
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 
diff --git a/tests/run-debuginfod-artifact-running.sh b/tests/run-debuginfod-artifact-running.sh
index e96cb966..4eae0200 100755
--- a/tests/run-debuginfod-artifact-running.sh
+++ b/tests/run-debuginfod-artifact-running.sh
@@ -51,9 +51,11 @@ export DEBUGINFOD_TIMEOUT=10
 
 # Server must become ready
 wait_ready $PORT1 'ready' 1
-kill -USR1 $PID1
-
+# And the initial scan should have been done
 wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
+
+kill -USR1 $PID1
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 2
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 
@@ -76,7 +78,7 @@ tempfiles F/prog2 F/prog2.debug
 
 kill -USR1 $PID1
 # Now there should be 3 files in the index
-wait_ready $PORT1 'thread_work_total{role="traverse"}' 2
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 3
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 
diff --git a/tests/run-debuginfod-dlopen.sh b/tests/run-debuginfod-dlopen.sh
index 0f2d13e2..5f33394a 100755
--- a/tests/run-debuginfod-dlopen.sh
+++ b/tests/run-debuginfod-dlopen.sh
@@ -70,9 +70,13 @@ BUILDID=`env LD_LIBRARY_PATH=$ldpath ${abs_builddir}/../src/readelf \
 
 mv p+r%o\$g F
 mv p+r%o\$g.debug F
+
+# Make sure the initial scan has finished.
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
+
 kill -USR1 $PID1
 # Wait till both files are in the index.
-wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 2
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 
diff --git a/tests/run-debuginfod-extraction.sh b/tests/run-debuginfod-extraction.sh
index e984f32f..4750f184 100755
--- a/tests/run-debuginfod-extraction.sh
+++ b/tests/run-debuginfod-extraction.sh
@@ -54,9 +54,11 @@ fi
 
 cp -rvp ${abs_srcdir}/debuginfod-tars Z
 
+# Make sure the initial scan has finished
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
 kill -USR1 $PID1
 # Wait till both files are in the index and scan/index fully finished
-wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 2
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 
@@ -71,7 +73,7 @@ wait_ready $PORT1 'scanned_files_total{source=".tar.bz2 archive"}' $tb2
 
 kill -USR1 $PID1  # two hits of SIGUSR1 may be needed to resolve .debug->dwz->srefs
 # Wait till both files are in the index and scan/index fully finished
-wait_ready $PORT1 'thread_work_total{role="traverse"}' 2
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 3
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 
diff --git a/tests/run-debuginfod-federation-link.sh b/tests/run-debuginfod-federation-link.sh
index 42b8f101..1aef7174 100755
--- a/tests/run-debuginfod-federation-link.sh
+++ b/tests/run-debuginfod-federation-link.sh
@@ -62,6 +62,9 @@ BUILDID=`env LD_LIBRARY_PATH=$ldpath ${abs_builddir}/../src/readelf \
 
 mv prog F
 mv prog.debug F
+
+# Make sure initial scan was done
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
 kill -USR1 $PID1
 # Wait till both files are in the index.
 wait_ready $PORT1 'thread_work_total{role="traverse"}' 2
@@ -83,9 +86,11 @@ tempfiles ${DB}_2
 
 wait_ready $PORT2 'ready' 1
 
+# Make sure initial scan was done
+wait_ready $PORT2 'thread_work_total{role="traverse"}' 1
 kill -USR1 $PID2
 # Wait till both files are in the index.
-wait_ready $PORT2 'thread_work_total{role="traverse"}' 1
+wait_ready $PORT2 'thread_work_total{role="traverse"}' 2
 wait_ready $PORT2 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT2 'thread_busy{role="scan"}' 0
 
@@ -99,7 +104,7 @@ if type bsdtar 2>/dev/null; then
     # copy in the deb files
     cp -rvp ${abs_srcdir}/debuginfod-debs/*deb D
     kill -USR1 $PID2
-    wait_ready $PORT2 'thread_work_total{role="traverse"}' 2
+    wait_ready $PORT2 'thread_work_total{role="traverse"}' 3
     wait_ready $PORT2 'thread_work_pending{role="scan"}' 0
     wait_ready $PORT2 'thread_busy{role="scan"}' 0
 
diff --git a/tests/run-debuginfod-federation-metrics.sh b/tests/run-debuginfod-federation-metrics.sh
index 2e7550a6..0cc4c2f7 100755
--- a/tests/run-debuginfod-federation-metrics.sh
+++ b/tests/run-debuginfod-federation-metrics.sh
@@ -45,7 +45,7 @@ errfiles vlog$PORT1
 
 wait_ready $PORT1 'ready' 1
 
-kill -USR1 $PID1
+# Wait till initial scan is done
 wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
diff --git a/tests/run-debuginfod-federation-sqlite.sh b/tests/run-debuginfod-federation-sqlite.sh
index a323b98e..5a18b4bb 100755
--- a/tests/run-debuginfod-federation-sqlite.sh
+++ b/tests/run-debuginfod-federation-sqlite.sh
@@ -59,7 +59,7 @@ errfiles vlog$PORT1
 
 wait_ready $PORT1 'ready' 1
 
-kill -USR1 $PID1
+# Wait till initial scan is done
 wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
@@ -73,13 +73,17 @@ tempfiles vlog$PORT2
 errfiles vlog$PORT2
 tempfiles ${DB}_2
 wait_ready $PORT2 'ready' 1
+# Wait till initial scan is done
+wait_ready $PORT2 'thread_work_total{role="traverse"}' 1
+# And initial groom cycle
+wait_ready $PORT1 'thread_work_total{role="groom"}' 1
 
 export DEBUGINFOD_URLS='http://127.0.0.1:'$PORT2 
 if type bsdtar 2>/dev/null; then
     # copy in the deb files
     cp -rvp ${abs_srcdir}/debuginfod-debs/*deb D
     kill -USR1 $PID2
-    wait_ready $PORT2 'thread_work_total{role="traverse"}' 1
+    wait_ready $PORT2 'thread_work_total{role="traverse"}' 2
     wait_ready $PORT2 'thread_work_pending{role="scan"}' 0
     wait_ready $PORT2 'thread_busy{role="scan"}' 0
 
@@ -177,7 +181,7 @@ wait_ready $PORT1 'thread_work_total{role="traverse"}' 2
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 kill -USR2 $PID1
-wait_ready $PORT1 'thread_work_total{role="groom"}' 1
+wait_ready $PORT1 'thread_work_total{role="groom"}' 2
 curl -s http://127.0.0.1:$PORT1/buildid/beefbeefbeefd00dd00d/debuginfo > /dev/null || true
 curl -s http://127.0.0.1:$PORT1/metrics | grep 'error_count.*sqlite'
 # Run the tests again without the servers running. The target file should
diff --git a/tests/run-debuginfod-malformed.sh b/tests/run-debuginfod-malformed.sh
index eb504181..3bc9e799 100755
--- a/tests/run-debuginfod-malformed.sh
+++ b/tests/run-debuginfod-malformed.sh
@@ -40,6 +40,9 @@ tempfiles vlog$PORT1
 errfiles vlog$PORT1
 # Server must become ready
 wait_ready $PORT1 'ready' 1
+# And an initial scan should be done
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
+
 export DEBUGINFOD_URLS=http://127.0.0.1:$PORT1/   # or without trailing /
 
 # Be patient when run on a busy machine things might take a bit.
@@ -70,7 +73,7 @@ mv p+r%o\$g F
 mv p+r%o\$g.debug F
 kill -USR1 $PID1
 # Wait till both files are in the index.
-wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 2
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 
diff --git a/tests/run-debuginfod-regex.sh b/tests/run-debuginfod-regex.sh
index 32ddf6ff..6837ea86 100755
--- a/tests/run-debuginfod-regex.sh
+++ b/tests/run-debuginfod-regex.sh
@@ -37,7 +37,10 @@ env LD_LIBRARY_PATH=$ldpath ${abs_builddir}/../debuginfod/debuginfod \
 PID1=$!
 tempfiles vlog$PORT1
 errfiles vlog$PORT1
+
+# Wait till the server is ready and an initial scan has been done
 wait_ready $PORT1 'ready' 1
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
 
 # Compile a simple program, strip its debuginfo and save the build-id.
 # Also move the debuginfo into another directory so that elfutils
@@ -55,7 +58,7 @@ tempfiles F/prog.debug F/prog
 
 kill -USR1 $PID1
 # Wait till both files are in the index.
-wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 2
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 cp ${DB} ${DB}.backup
@@ -79,7 +82,7 @@ errfiles vlog$PORT2
 # Server must become ready
 wait_ready $PORT2 'ready' 1
 
-kill -USR2 $PID1
+# Wait till the initial groom cycle has been done
 wait_ready $PORT2 'thread_work_total{role="groom"}' 1
 wait_ready $PORT2 'groom{statistic="archive d/e"}'  0
 wait_ready $PORT2 'groom{statistic="archive sdef"}' 0
diff --git a/tests/run-debuginfod-tmp-home.sh b/tests/run-debuginfod-tmp-home.sh
index 25b89be4..dc9accb0 100755
--- a/tests/run-debuginfod-tmp-home.sh
+++ b/tests/run-debuginfod-tmp-home.sh
@@ -40,6 +40,9 @@ tempfiles vlog$PORT1
 errfiles vlog$PORT1
 # Server must become ready
 wait_ready $PORT1 'ready' 1
+# And initial scan should be done
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
+
 export DEBUGINFOD_URLS=http://127.0.0.1:$PORT1/   # or without trailing /
 
 # Be patient when run on a busy machine things might take a bit.
@@ -71,7 +74,7 @@ mv p+r%o\$g F
 mv p+r%o\$g.debug F
 kill -USR1 $PID1
 # Wait till both files are in the index.
-wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 2
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 
diff --git a/tests/run-debuginfod-writable.sh b/tests/run-debuginfod-writable.sh
index 0bc70379..69ececb3 100755
--- a/tests/run-debuginfod-writable.sh
+++ b/tests/run-debuginfod-writable.sh
@@ -39,6 +39,9 @@ tempfiles vlog$PORT1
 errfiles vlog$PORT1
 # Server must become ready
 wait_ready $PORT1 'ready' 1
+# And initial scan should be done
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
+
 export DEBUGINFOD_URLS=http://127.0.0.1:$PORT1/   # or without trailing /
 
 # Be patient when run on a busy machine things might take a bit.
@@ -67,7 +70,7 @@ mv p+r%o\$g F
 mv p+r%o\$g.debug F
 kill -USR1 $PID1
 # Wait till both files are in the index.
-wait_ready $PORT1 'thread_work_total{role="traverse"}' 1
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 2
 wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
 wait_ready $PORT1 'thread_busy{role="scan"}' 0
 
-- 
2.32.0