Sync isolationtester's handling of notice/warning messages with HEAD.

Back-patch relevant parts of these commits:
30717637c Fix isolationtester race condition for notices sent before blocking
ebd499282 Don't drop NOTICE messages in isolation tests
a28e10e82 Indicate session name in isolationtester notices

This ensures that older versions of the isolationtester will handle
NOTICE/WARNING messages the same way as HEAD and v12 do.  While this
isn't fixing any critical problem right now, it seems like a prudent
change to prevent surprises (like we had yesterday...) with
back-patches of future isolation test changes.

Back-patch as far as 9.6.  Due to the significant changes we made in
isolationtester in 9.6, back-patching isolation tests further than
that is going to be risky anyway; besides, this patch doesn't apply
cleanly before that.

Discussion: https://postgr.es/m/E1i7IqC-0000Uc-5H@gemulon.postgresql.org

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 f6316ad52a6af003f813499d66d2e3319cc23eec..1daa9d2b7c463360d8b712c6853bcc3a63f4c8f7 100644 (file)
--- a/src/test/isolation/isolationtester.c
+++ b/src/test/isolation/isolationtester.c
@@ -50,6 +50,8 @@ static int    step_qsort_cmp(const void *a, const void *b);
 static int     step_bsearch_cmp(const void *a, const void *b);
 
 static void printResultSet(PGresult *res);
+static void isotesterNoticeProcessor(void *arg, const char *message);
+static void blackholeNoticeProcessor(void *arg, const char *message);
 
 /* close all connections and exit */
 static void
@@ -174,16 +176,19 @@ main(int argc, char **argv)
                }
 
                /*
-                * Suppress NOTIFY messages, which otherwise pop into results at odd
-                * places.
+                * Set up notice processors for the user-defined connections, so that
+                * messages can get printed prefixed with the session names.  The
+                * control connection gets a "blackhole" processor instead (hides all
+                * messages).
                 */
-               res = PQexec(conns[i], "SET client_min_messages = warning;");
-               if (PQresultStatus(res) != PGRES_COMMAND_OK)
-               {
-                       fprintf(stderr, "message level setup failed: %s", PQerrorMessage(conns[i]));
-                       exit_nicely();
-               }
-               PQclear(res);
+               if (i != 0)
+                       PQsetNoticeProcessor(conns[i],
+                                                                isotesterNoticeProcessor,
+                                                                (void *) (testspec->sessions[i - 1]->name));
+               else
+                       PQsetNoticeProcessor(conns[i],
+                                                                blackholeNoticeProcessor,
+                                                                NULL);
 
                /* Get the backend pid for lock wait checking. */
                res = PQexec(conns[i], "SELECT pg_backend_pid()");
@@ -753,6 +758,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);
@@ -883,3 +910,17 @@ printResultSet(PGresult *res)
                printf("\n");
        }
 }
+
+/* notice processor, prefixes each message with the session name */
+static void
+isotesterNoticeProcessor(void *arg, const char *message)
+{
+       printf("%s: %s", (char *) arg, message);
+}
+
+/* notice processor, hides the message */
+static void
+blackholeNoticeProcessor(void *arg, const char *message)
+{
+       /* do nothing */
+}