Date: Wed, 24 Oct 2018 18:34:51 -0300
From: Alvaro Herrera <alvherre@2ndquadrant.com>
To: Pg Hackers <pgsql-hackers@postgresql.org>
Subject: notice processors for isolationtester
Message-ID: <20181024213451.75nh3f3dctmcdbfq@alvherre.pgsql>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="mstlmmlpv7pjqkw7"
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
User-Agent: NeoMutt/20180716
Precedence: bulk


--mstlmmlpv7pjqkw7
Content-Type: text/plain; charset=iso-8859-1
Content-Disposition: inline
Content-Transfer-Encoding: 8bit

Recently while testing a patch I found it immensely useful to
distinguish which session each WARNING message came from, when bespoke
tests were run under isolationtester.  Current code does not show that,
so I developed this patch adding notice processors, and then it does.

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

--mstlmmlpv7pjqkw7
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment; filename="isolationtester-notices.patch"
Content-Transfer-Encoding: quoted-printable

commit dbbd8840ab070ced5dcd1eefaa67319bd9747b0c=1B[m
Author:     Alvaro Herrera <alvherre@alvh.no-ip.org>
AuthorDate: Thu Sep 27 16:37:43 2018 -0300
CommitDate: Wed Oct 24 18:31:00 2018 -0300

    Have isolationtester prefix WARNING with session name

diff --git a/src/test/isolation/expected/vacuum-concurrent-drop.out b/src/t=
est/isolation/expected/vacuum-concurrent-drop.out
index bb92e80b92..cf348d7e5d 100644
--- a/src/test/isolation/expected/vacuum-concurrent-drop.out
+++ b/src/test/isolation/expected/vacuum-concurrent-drop.out
@@ -10,7 +10,7 @@ step drop_and_commit:
 	DROP TABLE part2;
 	COMMIT;
=20
-WARNING:  skipping vacuum of "part2" --- relation no longer exists
+s2: WARNING:  skipping vacuum of "part2" --- relation no longer exists
 step vac_specified: <... completed>
=20
 starting permutation: lock vac_all_parts drop_and_commit
@@ -35,7 +35,7 @@ step drop_and_commit:
 	DROP TABLE part2;
 	COMMIT;
=20
-WARNING:  skipping analyze of "part2" --- relation no longer exists
+s2: WARNING:  skipping analyze of "part2" --- relation no longer exists
 step analyze_specified: <... completed>
=20
 starting permutation: lock analyze_all_parts drop_and_commit
@@ -60,7 +60,7 @@ step drop_and_commit:
 	DROP TABLE part2;
 	COMMIT;
=20
-WARNING:  skipping vacuum of "part2" --- relation no longer exists
+s2: WARNING:  skipping vacuum of "part2" --- relation no longer exists
 step vac_analyze_specified: <... completed>
=20
 starting permutation: lock vac_analyze_all_parts drop_and_commit
diff --git a/src/test/isolation/expected/vacuum-conflict.out b/src/test/iso=
lation/expected/vacuum-conflict.out
index 06ac75ef23..ffde537305 100644
--- a/src/test/isolation/expected/vacuum-conflict.out
+++ b/src/test/isolation/expected/vacuum-conflict.out
@@ -4,7 +4,7 @@ starting permutation: s1_begin s1_lock s2_auth s2_vacuum s1=
_commit s2_reset
 step s1_begin: BEGIN;
 step s1_lock: LOCK vacuum_tab IN SHARE UPDATE EXCLUSIVE MODE;
 step s2_auth: SET ROLE regress_vacuum_conflict;
-WARNING:  skipping "vacuum_tab" --- only table or database owner can vacuu=
m it
+s2: WARNING:  skipping "vacuum_tab" --- only table or database owner can v=
acuum it
 step s2_vacuum: VACUUM vacuum_tab;
 step s1_commit: COMMIT;
 step s2_reset: RESET ROLE;
@@ -12,7 +12,7 @@ step s2_reset: RESET ROLE;
 starting permutation: s1_begin s2_auth s2_vacuum s1_lock s1_commit s2_reset
 step s1_begin: BEGIN;
 step s2_auth: SET ROLE regress_vacuum_conflict;
-WARNING:  skipping "vacuum_tab" --- only table or database owner can vacuu=
m it
+s2: WARNING:  skipping "vacuum_tab" --- only table or database owner can v=
acuum it
 step s2_vacuum: VACUUM vacuum_tab;
 step s1_lock: LOCK vacuum_tab IN SHARE UPDATE EXCLUSIVE MODE;
 step s1_commit: COMMIT;
@@ -22,14 +22,14 @@ starting permutation: s1_begin s2_auth s1_lock s2_vacuu=
m s1_commit s2_reset
 step s1_begin: BEGIN;
 step s2_auth: SET ROLE regress_vacuum_conflict;
 step s1_lock: LOCK vacuum_tab IN SHARE UPDATE EXCLUSIVE MODE;
-WARNING:  skipping "vacuum_tab" --- only table or database owner can vacuu=
m it
+s2: WARNING:  skipping "vacuum_tab" --- only table or database owner can v=
acuum it
 step s2_vacuum: VACUUM vacuum_tab;
 step s1_commit: COMMIT;
 step s2_reset: RESET ROLE;
=20
 starting permutation: s2_auth s2_vacuum s1_begin s1_lock s1_commit s2_reset
 step s2_auth: SET ROLE regress_vacuum_conflict;
-WARNING:  skipping "vacuum_tab" --- only table or database owner can vacuu=
m it
+s2: WARNING:  skipping "vacuum_tab" --- only table or database owner can v=
acuum it
 step s2_vacuum: VACUUM vacuum_tab;
 step s1_begin: BEGIN;
 step s1_lock: LOCK vacuum_tab IN SHARE UPDATE EXCLUSIVE MODE;
@@ -40,7 +40,7 @@ starting permutation: s1_begin s1_lock s2_auth s2_analyze=
 s1_commit s2_reset
 step s1_begin: BEGIN;
 step s1_lock: LOCK vacuum_tab IN SHARE UPDATE EXCLUSIVE MODE;
 step s2_auth: SET ROLE regress_vacuum_conflict;
-WARNING:  skipping "vacuum_tab" --- only table or database owner can analy=
ze it
+s2: WARNING:  skipping "vacuum_tab" --- only table or database owner can a=
nalyze it
 step s2_analyze: ANALYZE vacuum_tab;
 step s1_commit: COMMIT;
 step s2_reset: RESET ROLE;
@@ -48,7 +48,7 @@ step s2_reset: RESET ROLE;
 starting permutation: s1_begin s2_auth s2_analyze s1_lock s1_commit s2_res=
et
 step s1_begin: BEGIN;
 step s2_auth: SET ROLE regress_vacuum_conflict;
-WARNING:  skipping "vacuum_tab" --- only table or database owner can analy=
ze it
+s2: WARNING:  skipping "vacuum_tab" --- only table or database owner can a=
nalyze it
 step s2_analyze: ANALYZE vacuum_tab;
 step s1_lock: LOCK vacuum_tab IN SHARE UPDATE EXCLUSIVE MODE;
 step s1_commit: COMMIT;
@@ -58,14 +58,14 @@ starting permutation: s1_begin s2_auth s1_lock s2_analy=
ze s1_commit s2_reset
 step s1_begin: BEGIN;
 step s2_auth: SET ROLE regress_vacuum_conflict;
 step s1_lock: LOCK vacuum_tab IN SHARE UPDATE EXCLUSIVE MODE;
-WARNING:  skipping "vacuum_tab" --- only table or database owner can analy=
ze it
+s2: WARNING:  skipping "vacuum_tab" --- only table or database owner can a=
nalyze it
 step s2_analyze: ANALYZE vacuum_tab;
 step s1_commit: COMMIT;
 step s2_reset: RESET ROLE;
=20
 starting permutation: s2_auth s2_analyze s1_begin s1_lock s1_commit s2_res=
et
 step s2_auth: SET ROLE regress_vacuum_conflict;
-WARNING:  skipping "vacuum_tab" --- only table or database owner can analy=
ze it
+s2: WARNING:  skipping "vacuum_tab" --- only table or database owner can a=
nalyze it
 step s2_analyze: ANALYZE vacuum_tab;
 step s1_begin: BEGIN;
 step s1_lock: LOCK vacuum_tab IN SHARE UPDATE EXCLUSIVE MODE;
diff --git a/src/test/isolation/expected/vacuum-skip-locked.out b/src/test/=
isolation/expected/vacuum-skip-locked.out
index 95ca4569cc..99db281a15 100644
--- a/src/test/isolation/expected/vacuum-skip-locked.out
+++ b/src/test/isolation/expected/vacuum-skip-locked.out
@@ -5,7 +5,7 @@ step lock_share:
 	BEGIN;
 	LOCK part1 IN SHARE MODE;
=20
-WARNING:  skipping vacuum of "part1" --- lock not available
+s2: WARNING:  skipping vacuum of "part1" --- lock not available
 step vac_specified: VACUUM (SKIP_LOCKED) part1, part2;
 step commit:=20
 	COMMIT;
@@ -26,7 +26,7 @@ step lock_share:
 	BEGIN;
 	LOCK part1 IN SHARE MODE;
=20
-WARNING:  skipping analyze of "part1" --- lock not available
+s2: WARNING:  skipping analyze of "part1" --- lock not available
 step analyze_specified: ANALYZE (SKIP_LOCKED) part1, part2;
 step commit:=20
 	COMMIT;
@@ -47,7 +47,7 @@ step lock_share:
 	BEGIN;
 	LOCK part1 IN SHARE MODE;
=20
-WARNING:  skipping vacuum of "part1" --- lock not available
+s2: WARNING:  skipping vacuum of "part1" --- lock not available
 step vac_analyze_specified: VACUUM (ANALYZE, SKIP_LOCKED) part1, part2;
 step commit:=20
 	COMMIT;
@@ -68,7 +68,7 @@ step lock_share:
 	BEGIN;
 	LOCK part1 IN SHARE MODE;
=20
-WARNING:  skipping vacuum of "part1" --- lock not available
+s2: WARNING:  skipping vacuum of "part1" --- lock not available
 step vac_full_specified: VACUUM (SKIP_LOCKED, FULL) part1, part2;
 step commit:=20
 	COMMIT;
@@ -89,7 +89,7 @@ step lock_access_exclusive:
 	BEGIN;
 	LOCK part1 IN ACCESS EXCLUSIVE MODE;
=20
-WARNING:  skipping vacuum of "part1" --- lock not available
+s2: WARNING:  skipping vacuum of "part1" --- lock not available
 step vac_specified: VACUUM (SKIP_LOCKED) part1, part2;
 step commit:=20
 	COMMIT;
@@ -110,7 +110,7 @@ step lock_access_exclusive:
 	BEGIN;
 	LOCK part1 IN ACCESS EXCLUSIVE MODE;
=20
-WARNING:  skipping analyze of "part1" --- lock not available
+s2: WARNING:  skipping analyze of "part1" --- lock not available
 step analyze_specified: ANALYZE (SKIP_LOCKED) part1, part2;
 step commit:=20
 	COMMIT;
@@ -132,7 +132,7 @@ step lock_access_exclusive:
 	BEGIN;
 	LOCK part1 IN ACCESS EXCLUSIVE MODE;
=20
-WARNING:  skipping vacuum of "part1" --- lock not available
+s2: WARNING:  skipping vacuum of "part1" --- lock not available
 step vac_analyze_specified: VACUUM (ANALYZE, SKIP_LOCKED) part1, part2;
 step commit:=20
 	COMMIT;
@@ -154,7 +154,7 @@ step lock_access_exclusive:
 	BEGIN;
 	LOCK part1 IN ACCESS EXCLUSIVE MODE;
=20
-WARNING:  skipping vacuum of "part1" --- lock not available
+s2: WARNING:  skipping vacuum of "part1" --- lock not available
 step vac_full_specified: VACUUM (SKIP_LOCKED, FULL) part1, part2;
 step commit:=20
 	COMMIT;
diff --git a/src/test/isolation/isolationtester.c b/src/test/isolation/isol=
ationtester.c
index 62097ab961..e2638553f6 100644
--- a/src/test/isolation/isolationtester.c
+++ b/src/test/isolation/isolationtester.c
@@ -48,6 +48,8 @@ static int	step_qsort_cmp(const void *a, const void *b);
 static int	step_bsearch_cmp(const void *a, const void *b);
=20
 static void printResultSet(PGresult *res);
+static void isotesterNoticeProcessor(void *arg, const char *message);
+static void blackholeNoticeProcessor(void *arg, const char *message);
=20
 /* close all connections and exit */
 static void
@@ -172,6 +174,21 @@ main(int argc, char **argv)
 		}
=20
 		/*
+		 * 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).
+		 */
+		if (i !=3D 0)
+			PQsetNoticeProcessor(conns[i],
+								 isotesterNoticeProcessor,
+								 (void *) (testspec->sessions[i - 1]->name));
+		else
+			PQsetNoticeProcessor(conns[i],
+								 blackholeNoticeProcessor,
+								 NULL);
+
+		/*
 		 * Suppress NOTIFY messages, which otherwise pop into results at odd
 		 * places.
 		 */
@@ -881,3 +898,17 @@ printResultSet(PGresult *res)
 		printf("\n");
 	}
 }
+
+/* notice processor, prefixes each message with the session name */
+static void
+isotesterNoticeProcessor(void *arg, const char *message)
+{
+	fprintf(stderr, "%s: %s", (char *) arg, message);
+}
+
+/* notice processor, hides the message */
+static void
+blackholeNoticeProcessor(void *arg, const char *message)
+{
+	/* do nothing */
+}

--mstlmmlpv7pjqkw7--