Add more debugging information for bgworker termination tests of worker_spi

widowbird has failed again after af8837a10bc7, with the same symptoms of
a backend still lying around when attempting a database rename with a
bgworker connected to the database being renamed.

We are still not sure yet how the failure can be reached, if this is a
timing issue in the test or an actual bug in the logic used for
interruptible bgworkers.  This commit adds more debugging information in
the backend to help with the analysis as a temporary measure.

Another thing I have noticed is that the queries launching the dynamic
bgworkers or checking pg_stat_activity would connect to the database
renamed.  These are switched to use 'postgres'.  That will hopefully
remove some of the friction of the test, but I doubt that this is the
end of the story.

Discussion: https://postgr.es/m/abtJLEAsf1HZXWdR@paquier.xyz

diff --git a/src/backend/postmaster/bgworker.c b/src/backend/postmaster/bgworker.c
index 0104a86b9ecd3ee919635fd25567ee889945990f..d1fe3cc71ce4f02683c063b103bf48e675bbcdcc 100644 (file)
--- a/src/backend/postmaster/bgworker.c
+++ b/src/backend/postmaster/bgworker.c
@@ -1413,6 +1413,9 @@ TerminateBackgroundWorkersForDatabase(Oid databaseId)
 {
        bool            signal_postmaster = false;
 
+       elog(DEBUG1, "attempting worker termination for database %u",
+                databaseId);
+
        LWLockAcquire(BackgroundWorkerLock, LW_EXCLUSIVE);
 
        /*
@@ -1432,6 +1435,9 @@ TerminateBackgroundWorkersForDatabase(Oid databaseId)
                        {
                                slot->terminate = true;
                                signal_postmaster = true;
+
+                               elog(DEBUG1, "termination requested for worker (PID %d) on database %u",
+                                        (int) slot->pid, databaseId);
                        }
                }
        }

diff --git a/src/test/modules/worker_spi/t/002_worker_terminate.pl b/src/test/modules/worker_spi/t/002_worker_terminate.pl
index 6db80ffec88c0486993c9953628c07f39fb598f4..b0e6a5376d4c923ec08556c14f3dc0d85f30a096 100644 (file)
--- a/src/test/modules/worker_spi/t/002_worker_terminate.pl
+++ b/src/test/modules/worker_spi/t/002_worker_terminate.pl
@@ -24,7 +24,7 @@ sub launch_bgworker
 
        # Launch a background worker on the given database.
        my $pid = $node->safe_psql(
-               $database, qq(
+               'postgres', qq(
         SELECT worker_spi_launch($testcase, '$database'::regdatabase, 0, '{}', $interruptible);
     ));
 
@@ -32,7 +32,7 @@ sub launch_bgworker
        $node->wait_for_log(
                qr/LOG: .*worker_spi dynamic worker $testcase initialized with .*\..*/,
                $offset);
-       my $result = $node->safe_psql($database,
+       my $result = $node->safe_psql('postgres',
                "SELECT count(*) > 0 FROM pg_stat_activity WHERE pid = $pid;");
        is($result, 't', "dynamic bgworker $testcase launched");
 
@@ -52,6 +52,11 @@ sub run_bgworker_interruptible_test
                qr/terminating background worker \"worker_spi dynamic\" due to administrator command/,
                $offset);
 
+       # Postmaster entry reporting the worker as exiting.
+       $node->wait_for_log(
+               qr/LOG: .*background worker \"worker_spi dynamic\" \(PID $pid\) exited with exit code/,
+               $offset);
+
        my $result = $node->safe_psql('postgres',
                "SELECT count(*) = 0 FROM pg_stat_activity WHERE pid = $pid;");
        is($result, 't', "dynamic bgworker stopped for $testname");
@@ -63,6 +68,7 @@ $node->append_conf(
        "postgresql.conf", qq(
 autovacuum = off
 debug_parallel_query = off
+log_min_messages = debug1
 ));
 $node->start;