diff --git a/src/test/isolation/expected/insert-conflict-specconflict.out b/src/test/isolation/expected/insert-conflict-specconflict.out index 5726bdb8e89..20cc421b872 100644 --- 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'; +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'; 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'; +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'; 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'; +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'; 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 9a387e3eb2d..744627ff277 100644 --- a/src/test/isolation/isolationtester.c +++ b/src/test/isolation/isolationtester.c @@ -47,6 +47,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 @@ -171,16 +173,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()"); @@ -750,6 +755,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 \n", step->name, step->sql); @@ -880,3 +907,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 */ +}