Fix isolationtester race condition for notices sent before blocking.

If a test sends a notice just before blocking, it's possible on
slow machines for isolationtester to detect the blocked state before
it's consumed the notice.  (For this to happen, the notice would have
to arrive after isolationtester has waited for data for 10ms, so on
fast/lightly-loaded machines it's hard to reproduce the failure.)
But, if we have seen the backend as blocked, it's certainly already
sent any notices it's going to send.  Therefore, one more round of
PQconsumeInput and PQisBusy should be enough to collect and process
any such notices.

This appears to explain the instability noted in commit ebd499282, so undo
the hack therein to not print notices from insert-conflict-specconflict.

Patch by me, diagnosis by Andres Freund.

Discussion: https://postgr.es/m/14616.1564251339@sss.pgh.pa.us

diff --git a/src/test/isolation/expected/insert-conflict-specconflict.out b/src/test/isolation/expected/insert-conflict-specconflict.out
index 5726bdb8e896afd10d847e737a9f700a8a1c8e6c..20cc421b8723a6b704756532992f5da7e386d2a5 100644 (file)
--- a/src/test/isolation/expected/insert-conflict-specconflict.out
+++ b/src/test/isolation/expected/insert-conflict-specconflict.out
@@ -13,7 +13,11 @@ pg_advisory_locksess           lock
 step controller_show: SELECT * FROM upserttest;
 key            data           
 
+s1: NOTICE:  called for k1
+s1: NOTICE:  blocking 3
 step s1_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s1') ON CONFLICT (blurt_and_lock(key)) DO UPDATE SET data = upserttest.data || ' with conflict update s1'; <waiting ...>
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 3
 step s2_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s2') ON CONFLICT (blurt_and_lock(key)) DO UPDATE SET data = upserttest.data || ' with conflict update s2'; <waiting ...>
 step controller_show: SELECT * FROM upserttest;
 key            data           
@@ -30,10 +34,14 @@ step controller_unlock_1_3: SELECT pg_advisory_unlock(1, 3);
 pg_advisory_unlock
 
 t              
+s1: NOTICE:  called for k1
+s1: NOTICE:  blocking 2
 step controller_unlock_2_3: SELECT pg_advisory_unlock(2, 3);
 pg_advisory_unlock
 
 t              
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 2
 step controller_show: SELECT * FROM upserttest;
 key            data           
 
@@ -50,6 +58,10 @@ step controller_unlock_1_2: SELECT pg_advisory_unlock(1, 2);
 pg_advisory_unlock
 
 t              
+s1: NOTICE:  called for k1
+s1: NOTICE:  blocking 2
+s1: NOTICE:  called for k1
+s1: NOTICE:  blocking 2
 step s1_upsert: <... completed>
 step controller_show: SELECT * FROM upserttest;
 key            data           
@@ -69,7 +81,11 @@ pg_advisory_locksess           lock
 step controller_show: SELECT * FROM upserttest;
 key            data           
 
+s1: NOTICE:  called for k1
+s1: NOTICE:  blocking 3
 step s1_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s1') ON CONFLICT (blurt_and_lock(key)) DO UPDATE SET data = upserttest.data || ' with conflict update s1'; <waiting ...>
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 3
 step s2_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s2') ON CONFLICT (blurt_and_lock(key)) DO UPDATE SET data = upserttest.data || ' with conflict update s2'; <waiting ...>
 step controller_show: SELECT * FROM upserttest;
 key            data           
@@ -86,10 +102,14 @@ step controller_unlock_1_3: SELECT pg_advisory_unlock(1, 3);
 pg_advisory_unlock
 
 t              
+s1: NOTICE:  called for k1
+s1: NOTICE:  blocking 2
 step controller_unlock_2_3: SELECT pg_advisory_unlock(2, 3);
 pg_advisory_unlock
 
 t              
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 2
 step controller_show: SELECT * FROM upserttest;
 key            data           
 
@@ -106,6 +126,10 @@ step controller_unlock_2_2: SELECT pg_advisory_unlock(2, 2);
 pg_advisory_unlock
 
 t              
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 2
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 2
 step s2_upsert: <... completed>
 step controller_show: SELECT * FROM upserttest;
 key            data           
@@ -127,7 +151,11 @@ key            data
 
 step s1_begin: BEGIN;
 step s2_begin: BEGIN;
+s1: NOTICE:  called for k1
+s1: NOTICE:  blocking 3
 step s1_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s1') ON CONFLICT (blurt_and_lock(key)) DO UPDATE SET data = upserttest.data || ' with conflict update s1'; <waiting ...>
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 3
 step s2_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s2') ON CONFLICT (blurt_and_lock(key)) DO UPDATE SET data = upserttest.data || ' with conflict update s2'; <waiting ...>
 step controller_show: SELECT * FROM upserttest;
 key            data           
@@ -144,10 +172,14 @@ step controller_unlock_1_3: SELECT pg_advisory_unlock(1, 3);
 pg_advisory_unlock
 
 t              
+s1: NOTICE:  called for k1
+s1: NOTICE:  blocking 2
 step controller_unlock_2_3: SELECT pg_advisory_unlock(2, 3);
 pg_advisory_unlock
 
 t              
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 2
 step controller_show: SELECT * FROM upserttest;
 key            data           
 
@@ -163,10 +195,16 @@ step controller_unlock_2_2: SELECT pg_advisory_unlock(2, 2);
 pg_advisory_unlock
 
 t              
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 2
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 2
 step controller_show: SELECT * FROM upserttest;
 key            data           
 
 step s1_commit: COMMIT;
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 2
 step s2_upsert: <... completed>
 step controller_show: SELECT * FROM upserttest;
 key            data           

diff --git a/src/test/isolation/isolationtester.c b/src/test/isolation/isolationtester.c
index 6ab19b1e597b323ed627e57c0490fcd35e23a0c4..3ed055106b4e4da88df6c4a7d563b2cf733fa2f9 100644 (file)
--- a/src/test/isolation/isolationtester.c
+++ b/src/test/isolation/isolationtester.c
@@ -752,6 +752,28 @@ try_complete_step(Step *step, int flags)
 
                                if (waiting)    /* waiting to acquire a lock */
                                {
+                                       /*
+                                        * Since it takes time to perform the lock-check query,
+                                        * some data --- notably, NOTICE messages --- might have
+                                        * arrived since we looked.  We must call PQconsumeInput
+                                        * and then PQisBusy to collect and process any such
+                                        * messages.  In the (unlikely) case that PQisBusy then
+                                        * returns false, we might as well go examine the
+                                        * available result.
+                                        */
+                                       if (!PQconsumeInput(conn))
+                                       {
+                                               fprintf(stderr, "PQconsumeInput failed: %s\n",
+                                                               PQerrorMessage(conn));
+                                               exit(1);
+                                       }
+                                       if (!PQisBusy(conn))
+                                               break;
+
+                                       /*
+                                        * conn is still busy, so conclude that the step really is
+                                        * waiting.
+                                        */
                                        if (!(flags & STEP_RETRY))
                                                printf("step %s: %s <waiting ...>\n",
                                                           step->name, step->sql);

diff --git a/src/test/isolation/specs/insert-conflict-specconflict.spec b/src/test/isolation/specs/insert-conflict-specconflict.spec
index 2d16fae1b1b12e0e640a80459bcc100c2e22f59d..3a70484fc299f09db6d12fe4586213447135f5be 100644 (file)
--- a/src/test/isolation/specs/insert-conflict-specconflict.spec
+++ b/src/test/isolation/specs/insert-conflict-specconflict.spec
@@ -51,9 +51,6 @@ session "s1"
 setup
 {
   SET default_transaction_isolation = 'read committed';
-  -- on very slow machines, the notices come out in unpredictable order,
-  -- so hide them
-  SET client_min_messages = warning;
   SET spec.session = 1;
 }
 step "s1_begin"  { BEGIN; }
@@ -64,9 +61,6 @@ session "s2"
 setup
 {
   SET default_transaction_isolation = 'read committed';
-  -- on very slow machines, the notices come out in unpredictable order,
-  -- so hide them
-  SET client_min_messages = warning;
   SET spec.session = 2;
 }
 step "s2_begin"  { BEGIN; }