Don't drop NOTICE messages in isolation tests.

tglsfdc · tglsfdc · commit b1016834d325 · 2019-09-10T12:04:57.000-04:00
For its entire existence, isolationtester.c has forced client_min_messages to WARNING, but that seems like a very poor choice of test design. It should be up to individual test scripts to manage whether they emit notices and to ensure that the results are stable. (There were no NOTICE messages in the original set of isolation tests, so this was certainly dead code when committed, but perhaps it was needed at some earlier point.) It's possible that the original motivation was due to platform-dependent variations in the timing of stdout vs. stderr output. That should be moot since commits 73bcb76/6eda3e9c2, but just in case, adjust isotesterNoticeProcessor to print to stdout not stderr. (stderr seems like the wrong thing anyway: it should be for error printouts not expected test output.) Back-patch of commit ebd4992 into v12. I'll separately push this into older branches, but this is as much change as v12 needs. Discussion: https://postgr.es/m/14616.1564251339@sss.pgh.pa.us 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
@@ -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/expected/plpgsql-toast.out b/src/test/isolation/expected/plpgsql-toast.out
@@ -22,7 +22,7 @@ do $$
     delete from test1;
     commit;
     perform pg_advisory_lock(1);
-    raise notice 'x = %', x;
+    raise notice 'length(x) = %', length(x);
   end;
 $$;
  <waiting ...>
@@ -35,6 +35,7 @@ step unlock:
 pg_advisory_unlock
 
 t              
+s1: NOTICE:  length(x) = 6000
 step assign1: <... completed>
 
 starting permutation: lock assign2 vacuum unlock
@@ -59,7 +60,7 @@ do $$
     delete from test1;
     commit;
     perform pg_advisory_lock(1);
-    raise notice 'x = %', x;
+    raise notice 'length(x) = %', length(x);
   end;
 $$;
  <waiting ...>
@@ -72,6 +73,7 @@ step unlock:
 pg_advisory_unlock
 
 t              
+s1: NOTICE:  length(x) = 6000
 step assign2: <... completed>
 
 starting permutation: lock assign3 vacuum unlock
@@ -97,7 +99,7 @@ do $$
     delete from test1;
     commit;
     perform pg_advisory_lock(1);
-    raise notice 'r = %', r;
+    raise notice 'length(r) = %', length(r::text);
   end;
 $$;
  <waiting ...>
@@ -110,6 +112,7 @@ step unlock:
 pg_advisory_unlock
 
 t              
+s1: NOTICE:  length(r) = 6004
 step assign3: <... completed>
 
 starting permutation: lock assign4 vacuum unlock
@@ -134,7 +137,7 @@ do $$
     delete from test1;
     commit;
     perform pg_advisory_lock(1);
-    raise notice 'r = %', r;
+    raise notice 'length(r) = %', length(r::text);
   end;
 $$;
  <waiting ...>
@@ -147,6 +150,7 @@ step unlock:
 pg_advisory_unlock
 
 t              
+s1: NOTICE:  length(r) = 6004
 step assign4: <... completed>
 
 starting permutation: lock assign5 vacuum unlock
@@ -173,7 +177,7 @@ do $$
     delete from test1;
     commit;
     perform pg_advisory_lock(1);
-    raise notice 'r = %', r;
+    raise notice 'length(r) = %', length(r::text);
   end;
 $$;
  <waiting ...>
@@ -186,4 +190,5 @@ step unlock:
 pg_advisory_unlock
 
 t              
+s1: NOTICE:  length(r) = 6002
 step assign5: <... completed>
diff --git a/src/test/isolation/isolationtester.c b/src/test/isolation/isolationtester.c
@@ -187,18 +187,6 @@ main(int argc, char **argv)
 								 blackholeNoticeProcessor,
 								 NULL);
 
-		/*
-		 * Suppress NOTIFY messages, which otherwise pop into results at odd
-		 * places.
-		 */
-		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(1);
-		}
-		PQclear(res);
-
 		/* Get the backend pid for lock wait checking. */
 		res = PQexec(conns[i], "SELECT pg_catalog.pg_backend_pid()");
 		if (PQresultStatus(res) == PGRES_TUPLES_OK)
@@ -921,7 +909,7 @@ printResultSet(PGresult *res)
 static void
 isotesterNoticeProcessor(void *arg, const char *message)
 {
-	fprintf(stderr, "%s: %s", (char *) arg, message);
+	printf("%s: %s", (char *) arg, message);
 }
 
 /* notice processor, hides the message */
diff --git a/src/test/isolation/specs/plpgsql-toast.spec b/src/test/isolation/specs/plpgsql-toast.spec
@@ -40,7 +40,7 @@ do $$
     delete from test1;
     commit;
     perform pg_advisory_lock(1);
-    raise notice 'x = %', x;
+    raise notice 'length(x) = %', length(x);
   end;
 $$;
 }
@@ -56,7 +56,7 @@ do $$
     delete from test1;
     commit;
     perform pg_advisory_lock(1);
-    raise notice 'x = %', x;
+    raise notice 'length(x) = %', length(x);
   end;
 $$;
 }
@@ -73,7 +73,7 @@ do $$
     delete from test1;
     commit;
     perform pg_advisory_lock(1);
-    raise notice 'r = %', r;
+    raise notice 'length(r) = %', length(r::text);
   end;
 $$;
 }
@@ -89,7 +89,7 @@ do $$
     delete from test1;
     commit;
     perform pg_advisory_lock(1);
-    raise notice 'r = %', r;
+    raise notice 'length(r) = %', length(r::text);
   end;
 $$;
 }
@@ -107,7 +107,7 @@ do $$
     delete from test1;
     commit;
     perform pg_advisory_lock(1);
-    raise notice 'r = %', r;
+    raise notice 'length(r) = %', length(r::text);
   end;
 $$;
 }
