psql 15beta1 does not print notices on the console until transaction completes

pg.ddx.io  pgsql-bugs@postgresql.org mailing list archive  
help / color / mirror / Atom feed

psql 15beta1 does not print notices on the console until transaction completes
16+ messages / 6 participants
[nested] [flat]

Commits from this thread:
  2022-06-09 e77de23fbb  psql: Show notices immediately (again)

* psql 15beta1 does not print notices on the console until transaction completes
@ 2022-05-29 20:11 Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 20:27 ` Re: psql 15beta1 does not print notices on the console until transaction completes Tom Lane <tgl@sss.pgh.pa.us>
  2022-05-29 20:47 ` Re: psql 15beta1 does not print notices on the console until transaction completes Adrian Klaver <adrian.klaver@aklaver.com>
  0 siblings, 2 replies; 16+ messages in thread

From: Alastair McKinley @ 2022-05-29 20:11 UTC (permalink / raw)
  To: pgsql-general@lists.postgresql.org <pgsql-general@lists.postgresql.org>

Hi all,

I notice this change in behaviour with psql in 15beta1 when testing an existing codebase.

I didn't see any mention of this change in the release notes and it surprised me.

Using this test function:

    create or replace function test_notice() returns void as 
    $$ 
    begin 
        raise notice 'hello'; 
        perform pg_sleep(10); 
    end; $$ language plpgsql;

In psql 15beta1, the "hello" message only appears on the console when the transaction completes.

in psql 14.3, it appears immediately as I would have expected.

Is there a way to change psql behaviour to display notices immediately as in versions < 15? 

Best regards,

Alastair

^ permalink  raw  reply  [nested|flat] 16+ messages in thread

* Re: psql 15beta1 does not print notices on the console until transaction completes
  2022-05-29 20:11 psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
@ 2022-05-29 20:27 ` Tom Lane <tgl@sss.pgh.pa.us>
  2022-05-30 09:05   ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  1 sibling, 1 reply; 16+ messages in thread

From: Tom Lane @ 2022-05-29 20:27 UTC (permalink / raw)
  To: Alastair McKinley <a.mckinley@analyticsengines.com>; +Cc: pgsql-bugs@lists.postgresql.org, Peter Eisentraut <peter.eisentraut@enterprisedb.com>; Fabien COELHO <coelho@cri.ensmp.fr>

[ redirecting to -bugs ]

Alastair McKinley <a.mckinley@analyticsengines.com> writes:
> Using this test function:

>     create or replace function test_notice() returns void as 
>     $$ 
>     begin 
>         raise notice 'hello'; 
>         perform pg_sleep(10); 
>     end; $$ language plpgsql;

> In psql 15beta1, the "hello" message only appears on the console when the transaction completes.
> in psql 14.3, it appears immediately as I would have expected.

A quick cross-check confirms that this is a psql, not server,
behavior change.  I didn't bisect, but I'm betting this is a
side-effect of 7844c9918 (Show all query results by default).

I agree it's pretty undesirable, so I'm adding it as an open issue.

			regards, tom lane





^ permalink  raw  reply  [nested|flat] 16+ messages in thread

* Re: psql 15beta1 does not print notices on the console until transaction completes
  2022-05-29 20:11 psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 20:27 ` Re: psql 15beta1 does not print notices on the console until transaction completes Tom Lane <tgl@sss.pgh.pa.us>
@ 2022-05-30 09:05   ` Fabien COELHO <coelho@cri.ensmp.fr>
  2022-05-30 17:53     ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  0 siblings, 1 reply; 16+ messages in thread

From: Fabien COELHO @ 2022-05-30 09:05 UTC (permalink / raw)
  To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: Alastair McKinley <a.mckinley@analyticsengines.com>; PostgreSQL Bugs <pgsql-bugs@lists.postgresql.org>; Peter Eisentraut <peter.eisentraut@enterprisedb.com>


> Alastair McKinley <a.mckinley@analyticsengines.com> writes:
>> Using this test function:
>
>>     create or replace function test_notice() returns void as
>>     $$
>>     begin
>>         raise notice 'hello';
>>         perform pg_sleep(10);
>>     end; $$ language plpgsql;
>
>> In psql 15beta1, the "hello" message only appears on the console when the transaction completes.
>> in psql 14.3, it appears immediately as I would have expected.
>
> A quick cross-check confirms that this is a psql, not server,
> behavior change.  I didn't bisect, but I'm betting this is a
> side-effect of 7844c9918 (Show all query results by default).

Yep, that is indeed possible, there is some hocus-pocus around notices 
there because they arrive somehow in any order.

> I agree it's pretty undesirable, so I'm adding it as an open issue.

Ok.

-- 
Fabien.





^ permalink  raw  reply  [nested|flat] 16+ messages in thread

* Re: psql 15beta1 does not print notices on the console until transaction completes
  2022-05-29 20:11 psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 20:27 ` Re: psql 15beta1 does not print notices on the console until transaction completes Tom Lane <tgl@sss.pgh.pa.us>
  2022-05-30 09:05   ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
@ 2022-05-30 17:53     ` Fabien COELHO <coelho@cri.ensmp.fr>
  2022-05-31 11:51       ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  0 siblings, 1 reply; 16+ messages in thread

From: Fabien COELHO @ 2022-05-30 17:53 UTC (permalink / raw)
  To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: Alastair McKinley <a.mckinley@analyticsengines.com>; PostgreSQL Bugs <pgsql-bugs@lists.postgresql.org>; Peter Eisentraut <peter.eisentraut@enterprisedb.com>


Hello Tom,

>>>     create or replace function test_notice() returns void as
>>>     $$
>>>     begin
>>>         raise notice 'hello';
>>>         perform pg_sleep(10);
>>>     end; $$ language plpgsql;
>> 
>>> In psql 15beta1, the "hello" message only appears on the console when the 
>>> transaction completes.
>>> in psql 14.3, it appears immediately as I would have expected.
>> 
>> A quick cross-check confirms that this is a psql, not server,
>> behavior change.  I didn't bisect, but I'm betting this is a
>> side-effect of 7844c9918 (Show all query results by default).
>
> Yep, that is indeed possible, there is some hocus-pocus around notices there 
> because they arrive somehow in any order.
>
>> I agree it's pretty undesirable, so I'm adding it as an open issue.
>
> Ok.

I've looked into it. This behavior is triggered by the fact that "psql" is 
trying to keep notices and results in some logical order.

The issue did not arise before because intermediate results where coldly 
discarded, so it did not show whether they were discarded before of after 
some notice was already shown:-)

If notices are to be shown "right away", it means that some notice may be 
shown *before* the previous result has been shown, just because psql may 
not have had time to process it and they are just sent through the 
protocol and arriving for the next result, as shown with the attached 
patch on non-regression tests:

   SELECT 1 AS one \; SELECT warn('1.5') \; SELECT 2 AS two ;
  +NOTICE:  warn 1.5
  +CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
    one
   -----
      1
   (1 row)

  -NOTICE:  warn 1.5
  -CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
    warn
   ------
    t

Now the second statement warning is shown before the first statement 
output. I'm pretty sure that the initial order shoul show up from time to 
time, just because of the underlying race condition.

Would this be okay? It simplifies the code significantly, but introduces 
possible race conditions in the output, which could be hidden from the non 
regression tests by removing the tests…

If notices are to be shown "right away" when processing a result, but not 
quite "right away" when the previous result is not yet finished, this is 
probably achievable but would require some effort and not so clear code. 
Maybe psql could not get the next result when we do not need to know which 
is last, but the execution would have somehow 2 different paths. I have to 
try to see how terrible or not the resulting code would be.

Another approach could be do drop the "only show the last result" 
compatibility, because then "psql" would not need to know that a result is 
the last, which requires to trigger the next one before closing the 
previous one, hence opening the race condition.

Thoughts?

-- 
Fabien.

Attachments:

psql-notices-1.patch (text/x-diff, 4.2K) download
diff --git a/src/bin/psql/common.c b/src/bin/psql/common.c
index 03e6d9ce8f..974959c595 100644
--- a/src/bin/psql/common.c
+++ b/src/bin/psql/common.c
@@ -1061,44 +1061,6 @@ PrintQueryResult(PGresult *result, bool last, bool is_watch, const printQueryOpt
 	return success;
 }
 
-/*
- * Data structure and functions to record notices while they are
- * emitted, so that they can be shown later.
- *
- * We need to know which result is last, which requires to extract
- * one result in advance, hence two buffers are needed.
- */
-struct t_notice_messages
-{
-	PQExpBufferData messages[2];
-	int			current;
-};
-
-/*
- * Store notices in appropriate buffer, for later display.
- */
-static void
-AppendNoticeMessage(void *arg, const char *msg)
-{
-	struct t_notice_messages *notices = arg;
-
-	appendPQExpBufferStr(&notices->messages[notices->current], msg);
-}
-
-/*
- * Show notices stored in buffer, which is then reset.
- */
-static void
-ShowNoticeMessage(struct t_notice_messages *notices)
-{
-	PQExpBufferData *current = &notices->messages[notices->current];
-
-	if (*current->data != '\0')
-		pg_log_info("%s", current->data);
-	resetPQExpBuffer(current);
-}
-
-
 /*
  * SendQuery: send the query string to the backend
  * (and print out result)
@@ -1483,7 +1445,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 	instr_time	before,
 				after;
 	PGresult   *result;
-	struct t_notice_messages notices;
 
 	if (timing)
 		INSTR_TIME_SET_CURRENT(before);
@@ -1513,12 +1474,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 		return 0;
 	}
 
-	/* intercept notices */
-	notices.current = 0;
-	initPQExpBuffer(&notices.messages[0]);
-	initPQExpBuffer(&notices.messages[1]);
-	PQsetNoticeProcessor(pset.db, AppendNoticeMessage, &notices);
-
 	/* first result */
 	result = PQgetResult(pset.db);
 
@@ -1536,7 +1491,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 			 */
 			const char *error = PQresultErrorMessage(result);
 
-			ShowNoticeMessage(&notices);
 			if (strlen(error))
 				pg_log_info("%s", error);
 
@@ -1601,8 +1555,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 		if (result_status == PGRES_COPY_IN ||
 			result_status == PGRES_COPY_OUT)
 		{
-			ShowNoticeMessage(&notices);
-
 			if (is_watch)
 			{
 				ClearOrSaveAllResults();
@@ -1610,12 +1562,7 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 				return -1;
 			}
 
-			/* use normal notice processor during COPY */
-			PQsetNoticeProcessor(pset.db, NoticeProcessor, NULL);
-
 			success &= HandleCopyResult(&result);
-
-			PQsetNoticeProcessor(pset.db, AppendNoticeMessage, &notices);
 		}
 
 		/*
@@ -1623,9 +1570,7 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 		 * string, it will return NULL.  Otherwise, we'll have other results
 		 * to process.  We need to do that to check whether this is the last.
 		 */
-		notices.current ^= 1;
 		next_result = PQgetResult(pset.db);
-		notices.current ^= 1;
 		last = (next_result == NULL);
 
 		/*
@@ -1647,9 +1592,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 			*elapsed_msec = INSTR_TIME_GET_MILLISEC(after);
 		}
 
-		/* notices already shown above for copy */
-		ShowNoticeMessage(&notices);
-
 		/* this may or may not print something depending on settings */
 		if (result != NULL)
 			success &= PrintQueryResult(result, last, false, opt, printQueryFout);
@@ -1659,7 +1601,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 			SetResultVariables(result, true);
 
 		ClearOrSaveResult(result);
-		notices.current ^= 1;
 		result = next_result;
 
 		if (cancel_pressed)
@@ -1669,11 +1610,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 		}
 	}
 
-	/* reset notice hook */
-	PQsetNoticeProcessor(pset.db, NoticeProcessor, NULL);
-	termPQExpBuffer(&notices.messages[0]);
-	termPQExpBuffer(&notices.messages[1]);
-
 	/* may need this to recover from conn loss during COPY */
 	if (!CheckConnection())
 		return -1;


^ permalink  raw  reply  [nested|flat] 16+ messages in thread

* Re: psql 15beta1 does not print notices on the console until transaction completes
  2022-05-29 20:11 psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 20:27 ` Re: psql 15beta1 does not print notices on the console until transaction completes Tom Lane <tgl@sss.pgh.pa.us>
  2022-05-30 09:05   ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  2022-05-30 17:53     ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
@ 2022-05-31 11:51       ` Fabien COELHO <coelho@cri.ensmp.fr>
  2022-06-03 18:25         ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  0 siblings, 1 reply; 16+ messages in thread

From: Fabien COELHO @ 2022-05-31 11:51 UTC (permalink / raw)
  To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: Alastair McKinley <a.mckinley@analyticsengines.com>; PostgreSQL Bugs <pgsql-bugs@lists.postgresql.org>; Peter Eisentraut <peter.eisentraut@enterprisedb.com>


>>>>     create or replace function test_notice() returns void as
>>>>     $$
>>>>     begin
>>>>         raise notice 'hello';
>>>>         perform pg_sleep(10);
>>>>     end; $$ language plpgsql;
>>> 
>>>> In psql 15beta1, the "hello" message only appears on the console when 
>>>> the transaction completes. in psql 14.3, it appears immediately as I 
>>>> would have expected.

[...]

> I've looked into it. This behavior is triggered by the fact that "psql" is 
> trying to keep notices and results in some logical order.
>
> The issue did not arise before because intermediate results where coldly 
> discarded, so it did not show whether they were discarded before of after 
> some notice was already shown:-)
>
> If notices are to be shown "right away", it means that some notice may be 
> shown *before* the previous result has been shown, just because psql may not 
> have had time to process it and they are just sent through the protocol and 
> arriving for the next result, as shown with the attached patch on 
> non-regression tests:
>
>  SELECT 1 AS one \; SELECT warn('1.5') \; SELECT 2 AS two ;
> +NOTICE:  warn 1.5
> +CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
>   one
>  -----
>     1
>  (1 row)
>
> -NOTICE:  warn 1.5
> -CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
>   warn
>  ------
>   t
>
> Now the second statement warning is shown before the first statement output. 
> I'm pretty sure that the initial order shoul show up from time to time, just 
> because of the underlying race condition.
>
> Would this be okay? It simplifies the code significantly, but introduces 
> possible race conditions in the output, which could be hidden from the non 
> regression tests by removing the tests…

This would be the simplest solution.

> If notices are to be shown "right away" when processing a result, but not 
> quite "right away" when the previous result is not yet finished, this is 
> probably achievable but would require some effort and not so clear code.

> Maybe psql could not get the next result when we do not need to know which is 
> last, but the execution would have somehow 2 different paths. I have to try 
> to see how terrible or not the resulting code would be.

I've tried that (see v2 attached), but it does not work as I hoped: the 
fact that a result has not yet been extracted does not preclude the server 
from sending the notices relating to a statement, so delaying the 
getResult does not fix the display order problem in anyway. I was quite 
naïve.

> Another approach could be do drop the "only show the last result" 
> compatibility, because then "psql" would not need to know that a result is 
> the last, which requires to trigger the next one before closing the previous 
> one, hence opening the race condition.

That would not work, either, for the reason stated above.

In order to have the best of both world, this requires more hopus-pocus: 
accumulating the notices *but* displaying them as soon as dealing with a 
statement is done *and* also while waiting for getResult. I see how I can 
try to reduce a lot the out-of-order window… but not how to fully get rid 
of it.

-- 
Fabien.

Attachments:

psql-notices-2.patch (text/x-diff, 5.1K) download
diff --git a/src/bin/psql/common.c b/src/bin/psql/common.c
index 03e6d9ce8f..71b33e2c34 100644
--- a/src/bin/psql/common.c
+++ b/src/bin/psql/common.c
@@ -1061,44 +1061,6 @@ PrintQueryResult(PGresult *result, bool last, bool is_watch, const printQueryOpt
 	return success;
 }
 
-/*
- * Data structure and functions to record notices while they are
- * emitted, so that they can be shown later.
- *
- * We need to know which result is last, which requires to extract
- * one result in advance, hence two buffers are needed.
- */
-struct t_notice_messages
-{
-	PQExpBufferData messages[2];
-	int			current;
-};
-
-/*
- * Store notices in appropriate buffer, for later display.
- */
-static void
-AppendNoticeMessage(void *arg, const char *msg)
-{
-	struct t_notice_messages *notices = arg;
-
-	appendPQExpBufferStr(&notices->messages[notices->current], msg);
-}
-
-/*
- * Show notices stored in buffer, which is then reset.
- */
-static void
-ShowNoticeMessage(struct t_notice_messages *notices)
-{
-	PQExpBufferData *current = &notices->messages[notices->current];
-
-	if (*current->data != '\0')
-		pg_log_info("%s", current->data);
-	resetPQExpBuffer(current);
-}
-
-
 /*
  * SendQuery: send the query string to the backend
  * (and print out result)
@@ -1483,7 +1445,7 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 	instr_time	before,
 				after;
 	PGresult   *result;
-	struct t_notice_messages notices;
+	bool		need_last = pset.gset_prefix || pset.gexec_flag || pset.crosstab_flag || !pset.show_all_results;
 
 	if (timing)
 		INSTR_TIME_SET_CURRENT(before);
@@ -1513,12 +1475,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 		return 0;
 	}
 
-	/* intercept notices */
-	notices.current = 0;
-	initPQExpBuffer(&notices.messages[0]);
-	initPQExpBuffer(&notices.messages[1]);
-	PQsetNoticeProcessor(pset.db, AppendNoticeMessage, &notices);
-
 	/* first result */
 	result = PQgetResult(pset.db);
 
@@ -1536,7 +1492,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 			 */
 			const char *error = PQresultErrorMessage(result);
 
-			ShowNoticeMessage(&notices);
 			if (strlen(error))
 				pg_log_info("%s", error);
 
@@ -1601,8 +1556,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 		if (result_status == PGRES_COPY_IN ||
 			result_status == PGRES_COPY_OUT)
 		{
-			ShowNoticeMessage(&notices);
-
 			if (is_watch)
 			{
 				ClearOrSaveAllResults();
@@ -1610,12 +1563,7 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 				return -1;
 			}
 
-			/* use normal notice processor during COPY */
-			PQsetNoticeProcessor(pset.db, NoticeProcessor, NULL);
-
 			success &= HandleCopyResult(&result);
-
-			PQsetNoticeProcessor(pset.db, AppendNoticeMessage, &notices);
 		}
 
 		/*
@@ -1623,9 +1571,7 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 		 * string, it will return NULL.  Otherwise, we'll have other results
 		 * to process.  We need to do that to check whether this is the last.
 		 */
-		notices.current ^= 1;
-		next_result = PQgetResult(pset.db);
-		notices.current ^= 1;
+		next_result = need_last ? PQgetResult(pset.db) : NULL;
 		last = (next_result == NULL);
 
 		/*
@@ -1647,9 +1593,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 			*elapsed_msec = INSTR_TIME_GET_MILLISEC(after);
 		}
 
-		/* notices already shown above for copy */
-		ShowNoticeMessage(&notices);
-
 		/* this may or may not print something depending on settings */
 		if (result != NULL)
 			success &= PrintQueryResult(result, last, false, opt, printQueryFout);
@@ -1659,8 +1602,7 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 			SetResultVariables(result, true);
 
 		ClearOrSaveResult(result);
-		notices.current ^= 1;
-		result = next_result;
+		result = need_last ? next_result : PQgetResult(pset.db);
 
 		if (cancel_pressed)
 		{
@@ -1669,11 +1611,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 		}
 	}
 
-	/* reset notice hook */
-	PQsetNoticeProcessor(pset.db, NoticeProcessor, NULL);
-	termPQExpBuffer(&notices.messages[0]);
-	termPQExpBuffer(&notices.messages[1]);
-
 	/* may need this to recover from conn loss during COPY */
 	if (!CheckConnection())
 		return -1;
diff --git a/src/test/regress/expected/psql.out b/src/test/regress/expected/psql.out
index 2a38a93a3b..baedf04ba5 100644
--- a/src/test/regress/expected/psql.out
+++ b/src/test/regress/expected/psql.out
@@ -5335,13 +5335,13 @@ CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
 
 -- \gset applies to last query only
 SELECT 3 AS three \; SELECT warn('3.5') \; SELECT 4 AS four \gset
+NOTICE:  warn 3.5
+CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
  three 
 -------
      3
 (1 row)
 
-NOTICE:  warn 3.5
-CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
  warn 
 ------
  t


^ permalink  raw  reply  [nested|flat] 16+ messages in thread

* Re: psql 15beta1 does not print notices on the console until transaction completes
  2022-05-29 20:11 psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 20:27 ` Re: psql 15beta1 does not print notices on the console until transaction completes Tom Lane <tgl@sss.pgh.pa.us>
  2022-05-30 09:05   ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  2022-05-30 17:53     ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  2022-05-31 11:51       ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
@ 2022-06-03 18:25         ` Fabien COELHO <coelho@cri.ensmp.fr>
  2022-06-07 12:05           ` Re: psql 15beta1 does not print notices on the console until transaction completes Peter Eisentraut <peter.eisentraut@enterprisedb.com>
  0 siblings, 1 reply; 16+ messages in thread

From: Fabien COELHO @ 2022-06-03 18:25 UTC (permalink / raw)
  To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: Alastair McKinley <a.mckinley@analyticsengines.com>; PostgreSQL Bugs <pgsql-bugs@lists.postgresql.org>; Peter Eisentraut <peter.eisentraut@enterprisedb.com>


>> I've looked into it. This behavior is triggered by the fact that "psql" is 
>> trying to keep notices and results in some logical order.
>> 
>> The issue did not arise before because intermediate results where coldly 
>> discarded, so it did not show whether they were discarded before of after 
>> some notice was already shown:-)
>> 
>> If notices are to be shown "right away", it means that some notice may be 
>> shown *before* the previous result has been shown, just because psql may 
>> not have had time to process it and they are just sent through the protocol 
>> and arriving for the next result, as shown with the attached patch on 
>> non-regression tests:
>>
>>  SELECT 1 AS one \; SELECT warn('1.5') \; SELECT 2 AS two ;
>> +NOTICE:  warn 1.5
>> +CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
>>   one
>>  -----
>>     1
>>  (1 row)
>> 
>> -NOTICE:  warn 1.5
>> -CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
>>   warn
>>  ------
>>   t
>>
>> Now the second statement warning is shown before the first statement 
>> output. I'm pretty sure that the initial order shoul show up from time to 
>> time, just because of the underlying race condition.
>> 
>> Would this be okay? It simplifies the code significantly, but introduces 
>> possible race conditions in the output, which could be hidden from the non 
>> regression tests by removing the tests…
>
> This would be the simplest solution.
>
>> If notices are to be shown "right away" when processing a result, but not 
>> quite "right away" when the previous result is not yet finished, this is 
>> probably achievable but would require some effort and not so clear code.
>
>> Maybe psql could not get the next result when we do not need to know which 
>> is last, but the execution would have somehow 2 different paths. I have to 
>> try to see how terrible or not the resulting code would be.
>
> I've tried that (see v2 attached), but it does not work as I hoped: the fact 
> that a result has not yet been extracted does not preclude the server from 
> sending the notices relating to a statement, so delaying the getResult does 
> not fix the display order problem in anyway. I was quite naïve.
>
>> Another approach could be do drop the "only show the last result" 
>> compatibility, because then "psql" would not need to know that a result is 
>> the last, which requires to trigger the next one before closing the 
>> previous one, hence opening the race condition.
>
> That would not work, either, for the reason stated above.
>
> In order to have the best of both world, this requires more hopus-pocus: 
> accumulating the notices *but* displaying them as soon as dealing with a 
> statement is done *and* also while waiting for getResult. I see how I can try 
> to reduce a lot the out-of-order window… but not how to fully get rid of it.

After more investigation and quite a few variants, the end result is that 
you cannot have the best of both words in all cases, i.e. instantaneous 
notices while keeping the order of results and their notices. The 
underlying reason for that is that some cases (gexec and others,) need to 
know which result is last because they need to to something special about 
it, which always requires to wait for the next result before doing 
anything with the previous one, so if the next one takes time, then the 
previous one is somehow suspended.

In the previous setting, because intermediate results where coldly 
skipped, the user could not see whether notices for one statement where 
coming before or after some result, so all was well hidden, you just got 
the notices as they were sent and the final result displayed. The 
underlying truth was that it depended:-)

My short term recommendation is to remove the attempt at keeping the 
notice/result order for a tradeoff of getting the notices as soon as they 
are emitted, i.e. basically patch 1 and the acceptance of the diffs, 
called 1-bis in the attached. Alternatively, the attached patch 3 keeps 
the order in the simple case, but not in the gset case, at the price of 
some complexity. I would not bet too much that these codes are immune to 
race conditions.

-- 
Fabien.

Attachments: download all (2 files, .tar.gz)

psql-notices-1-bis.patch (text/x-diff, 5.1K) download
diff --git a/src/bin/psql/common.c b/src/bin/psql/common.c
index 03e6d9ce8f..974959c595 100644
--- a/src/bin/psql/common.c
+++ b/src/bin/psql/common.c
@@ -1061,44 +1061,6 @@ PrintQueryResult(PGresult *result, bool last, bool is_watch, const printQueryOpt
 	return success;
 }
 
-/*
- * Data structure and functions to record notices while they are
- * emitted, so that they can be shown later.
- *
- * We need to know which result is last, which requires to extract
- * one result in advance, hence two buffers are needed.
- */
-struct t_notice_messages
-{
-	PQExpBufferData messages[2];
-	int			current;
-};
-
-/*
- * Store notices in appropriate buffer, for later display.
- */
-static void
-AppendNoticeMessage(void *arg, const char *msg)
-{
-	struct t_notice_messages *notices = arg;
-
-	appendPQExpBufferStr(&notices->messages[notices->current], msg);
-}
-
-/*
- * Show notices stored in buffer, which is then reset.
- */
-static void
-ShowNoticeMessage(struct t_notice_messages *notices)
-{
-	PQExpBufferData *current = &notices->messages[notices->current];
-
-	if (*current->data != '\0')
-		pg_log_info("%s", current->data);
-	resetPQExpBuffer(current);
-}
-
-
 /*
  * SendQuery: send the query string to the backend
  * (and print out result)
@@ -1483,7 +1445,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 	instr_time	before,
 				after;
 	PGresult   *result;
-	struct t_notice_messages notices;
 
 	if (timing)
 		INSTR_TIME_SET_CURRENT(before);
@@ -1513,12 +1474,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 		return 0;
 	}
 
-	/* intercept notices */
-	notices.current = 0;
-	initPQExpBuffer(&notices.messages[0]);
-	initPQExpBuffer(&notices.messages[1]);
-	PQsetNoticeProcessor(pset.db, AppendNoticeMessage, &notices);
-
 	/* first result */
 	result = PQgetResult(pset.db);
 
@@ -1536,7 +1491,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 			 */
 			const char *error = PQresultErrorMessage(result);
 
-			ShowNoticeMessage(&notices);
 			if (strlen(error))
 				pg_log_info("%s", error);
 
@@ -1601,8 +1555,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 		if (result_status == PGRES_COPY_IN ||
 			result_status == PGRES_COPY_OUT)
 		{
-			ShowNoticeMessage(&notices);
-
 			if (is_watch)
 			{
 				ClearOrSaveAllResults();
@@ -1610,12 +1562,7 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 				return -1;
 			}
 
-			/* use normal notice processor during COPY */
-			PQsetNoticeProcessor(pset.db, NoticeProcessor, NULL);
-
 			success &= HandleCopyResult(&result);
-
-			PQsetNoticeProcessor(pset.db, AppendNoticeMessage, &notices);
 		}
 
 		/*
@@ -1623,9 +1570,7 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 		 * string, it will return NULL.  Otherwise, we'll have other results
 		 * to process.  We need to do that to check whether this is the last.
 		 */
-		notices.current ^= 1;
 		next_result = PQgetResult(pset.db);
-		notices.current ^= 1;
 		last = (next_result == NULL);
 
 		/*
@@ -1647,9 +1592,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 			*elapsed_msec = INSTR_TIME_GET_MILLISEC(after);
 		}
 
-		/* notices already shown above for copy */
-		ShowNoticeMessage(&notices);
-
 		/* this may or may not print something depending on settings */
 		if (result != NULL)
 			success &= PrintQueryResult(result, last, false, opt, printQueryFout);
@@ -1659,7 +1601,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 			SetResultVariables(result, true);
 
 		ClearOrSaveResult(result);
-		notices.current ^= 1;
 		result = next_result;
 
 		if (cancel_pressed)
@@ -1669,11 +1610,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 		}
 	}
 
-	/* reset notice hook */
-	PQsetNoticeProcessor(pset.db, NoticeProcessor, NULL);
-	termPQExpBuffer(&notices.messages[0]);
-	termPQExpBuffer(&notices.messages[1]);
-
 	/* may need this to recover from conn loss during COPY */
 	if (!CheckConnection())
 		return -1;
diff --git a/src/test/regress/expected/psql.out b/src/test/regress/expected/psql.out
index 2a38a93a3b..60acbd1241 100644
--- a/src/test/regress/expected/psql.out
+++ b/src/test/regress/expected/psql.out
@@ -5316,13 +5316,13 @@ AS $$
 $$;
 -- show both
 SELECT 1 AS one \; SELECT warn('1.5') \; SELECT 2 AS two ;
+NOTICE:  warn 1.5
+CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
  one 
 -----
    1
 (1 row)
 
-NOTICE:  warn 1.5
-CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
  warn 
 ------
  t
@@ -5335,13 +5335,13 @@ CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
 
 -- \gset applies to last query only
 SELECT 3 AS three \; SELECT warn('3.5') \; SELECT 4 AS four \gset
+NOTICE:  warn 3.5
+CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
  three 
 -------
      3
 (1 row)
 
-NOTICE:  warn 3.5
-CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
  warn 
 ------
  t


psql-notices-3.patch (text/x-diff, 8.1K) download
diff --git a/src/bin/psql/common.c b/src/bin/psql/common.c
index 03e6d9ce8f..3a525839a7 100644
--- a/src/bin/psql/common.c
+++ b/src/bin/psql/common.c
@@ -1063,26 +1063,28 @@ PrintQueryResult(PGresult *result, bool last, bool is_watch, const printQueryOpt
 
 /*
  * Data structure and functions to record notices while they are
- * emitted, so that they can be shown later.
- *
- * We need to know which result is last, which requires to extract
- * one result in advance, hence two buffers are needed.
+ * emitted, so that they can be shown later. "print" tells whether
+ * to print or to store the messages.
  */
 struct t_notice_messages
 {
-	PQExpBufferData messages[2];
-	int			current;
+	PQExpBufferData	messages;
+	volatile bool	print;
 };
 
 /*
  * Store notices in appropriate buffer, for later display.
+ * This function is called by a signal handler.
  */
 static void
-AppendNoticeMessage(void *arg, const char *msg)
+AppendOrPrintNoticeMessage(void *arg, const char *msg)
 {
 	struct t_notice_messages *notices = arg;
 
-	appendPQExpBufferStr(&notices->messages[notices->current], msg);
+	if (notices->print)
+		pg_log_info("%s", msg);
+	else
+		appendPQExpBufferStr(&notices->messages, msg);
 }
 
 /*
@@ -1091,11 +1093,18 @@ AppendNoticeMessage(void *arg, const char *msg)
 static void
 ShowNoticeMessage(struct t_notice_messages *notices)
 {
-	PQExpBufferData *current = &notices->messages[notices->current];
+	bool print = notices->print;
+	PQExpBufferData *shown = &notices->messages;
 
-	if (*current->data != '\0')
-		pg_log_info("%s", current->data);
-	resetPQExpBuffer(current);
+	/* avoid race condition on the buffer which could lose messages */
+	notices->print = true;
+
+	if (*shown->data != '\0')
+		pg_log_info("%s", shown->data);
+	resetPQExpBuffer(shown);
+
+	/* restore previous printing status */
+	notices->print = print;
 }
 
 
@@ -1478,6 +1487,8 @@ static int
 ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_gone_p,
 						   bool is_watch, const printQueryOpt *opt, FILE *printQueryFout)
 {
+	/* whether we need to know whether a result is the last early */
+	bool		need_last = pset.gset_prefix || pset.gexec_flag || pset.crosstab_flag || !pset.show_all_results;
 	bool		timing = pset.timing;
 	bool		success;
 	instr_time	before,
@@ -1513,11 +1524,10 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 		return 0;
 	}
 
-	/* intercept notices */
-	notices.current = 0;
-	initPQExpBuffer(&notices.messages[0]);
-	initPQExpBuffer(&notices.messages[1]);
-	PQsetNoticeProcessor(pset.db, AppendNoticeMessage, &notices);
+	/* intercept notices, or not, depending on show mode */
+	notices.print = true;
+	initPQExpBuffer(&notices.messages);
+	PQsetNoticeProcessor(pset.db, AppendOrPrintNoticeMessage, &notices);
 
 	/* first result */
 	result = PQgetResult(pset.db);
@@ -1528,6 +1538,13 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 		PGresult   *next_result;
 		bool		last;
 
+		/*
+		 * Notices coming in from now on are attributed to the next (future) result,
+		 * so direct printing is suspended till this current result is displayed, but
+		 * only if it is really going to be displayed.
+		 */
+		notices.print = !pset.show_all_results;
+
 		if (!AcceptResult(result, false))
 		{
 			/*
@@ -1536,10 +1553,13 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 			 */
 			const char *error = PQresultErrorMessage(result);
 
-			ShowNoticeMessage(&notices);
 			if (strlen(error))
 				pg_log_info("%s", error);
 
+			/* then reactivate notice flow till next result */
+			notices.print = true;
+			ShowNoticeMessage(&notices);
+
 			CheckConnection();
 			if (!is_watch)
 				SetResultVariables(result, false);
@@ -1566,6 +1586,9 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 			else
 				result = PQgetResult(pset.db);
 
+			/* suspend notice flow again after the result, if needed */
+			notices.print = !pset.show_all_results;
+
 			/*
 			 * Get current timing measure in case an error occurs
 			 */
@@ -1601,8 +1624,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 		if (result_status == PGRES_COPY_IN ||
 			result_status == PGRES_COPY_OUT)
 		{
-			ShowNoticeMessage(&notices);
-
 			if (is_watch)
 			{
 				ClearOrSaveAllResults();
@@ -1610,22 +1631,38 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 				return -1;
 			}
 
-			/* use normal notice processor during COPY */
-			PQsetNoticeProcessor(pset.db, NoticeProcessor, NULL);
+			/* back to normal notice processor during COPY */
+			notices.print = true;
+			ShowNoticeMessage(&notices);
 
 			success &= HandleCopyResult(&result);
 
-			PQsetNoticeProcessor(pset.db, AppendNoticeMessage, &notices);
+			notices.print = !pset.show_all_results;
 		}
 
 		/*
 		 * Check PQgetResult() again.  In the typical case of a single-command
 		 * string, it will return NULL.  Otherwise, we'll have other results
 		 * to process.  We need to do that to check whether this is the last.
+		 *
+		 * Note that notices are possibly suspended while waiting for the next
+		 * result because the previous result has not been displayed yet.
+		 *
+		 * If the next queries takes some time, the output of the current query
+		 * is suspended, eg "SELECT 0 \; SELECT take_long_time() \gset" will wait
+		 * before showing the initial 0. The notices are shown anyway, possibly out
+		 * of order, as a tradeoff between keeping the order vs delaying the notices.
 		 */
-		notices.current ^= 1;
-		next_result = PQgetResult(pset.db);
-		notices.current ^= 1;
+		if (need_last)
+		{
+			notices.print = true;
+			ShowNoticeMessage(&notices);
+			next_result = PQgetResult(pset.db);
+			notices.print = !pset.show_all_results;
+		}
+		else
+			next_result = NULL;
+
 		last = (next_result == NULL);
 
 		/*
@@ -1647,19 +1684,28 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 			*elapsed_msec = INSTR_TIME_GET_MILLISEC(after);
 		}
 
-		/* notices already shown above for copy */
-		ShowNoticeMessage(&notices);
-
 		/* this may or may not print something depending on settings */
 		if (result != NULL)
+		{
 			success &= PrintQueryResult(result, last, false, opt, printQueryFout);
 
+			/* reactivate notice flow after printing the result */
+			notices.print = true;
+			ShowNoticeMessage(&notices);
+		}
+
+		/* we need to know whether it was the last now anyway */
+		if (!need_last)
+		{
+			next_result = PQgetResult(pset.db);
+			last = (next_result == NULL);
+		}
+
 		/* set variables on last result if all went well */
 		if (!is_watch && last && success)
 			SetResultVariables(result, true);
 
 		ClearOrSaveResult(result);
-		notices.current ^= 1;
 		result = next_result;
 
 		if (cancel_pressed)
@@ -1669,10 +1715,13 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
 		}
 	}
 
-	/* reset notice hook */
+	/* reset standard notice hook */
 	PQsetNoticeProcessor(pset.db, NoticeProcessor, NULL);
-	termPQExpBuffer(&notices.messages[0]);
-	termPQExpBuffer(&notices.messages[1]);
+
+	/* flush notices if any, before cleaning up */
+	notices.print = true;
+	ShowNoticeMessage(&notices);
+	termPQExpBuffer(&notices.messages);
 
 	/* may need this to recover from conn loss during COPY */
 	if (!CheckConnection())
diff --git a/src/test/regress/expected/psql.out b/src/test/regress/expected/psql.out
index 2a38a93a3b..baedf04ba5 100644
--- a/src/test/regress/expected/psql.out
+++ b/src/test/regress/expected/psql.out
@@ -5335,13 +5335,13 @@ CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
 
 -- \gset applies to last query only
 SELECT 3 AS three \; SELECT warn('3.5') \; SELECT 4 AS four \gset
+NOTICE:  warn 3.5
+CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
  three 
 -------
      3
 (1 row)
 
-NOTICE:  warn 3.5
-CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
  warn 
 ------
  t


^ permalink  raw  reply  [nested|flat] 16+ messages in thread

* Re: psql 15beta1 does not print notices on the console until transaction completes
  2022-05-29 20:11 psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 20:27 ` Re: psql 15beta1 does not print notices on the console until transaction completes Tom Lane <tgl@sss.pgh.pa.us>
  2022-05-30 09:05   ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  2022-05-30 17:53     ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  2022-05-31 11:51       ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  2022-06-03 18:25         ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
@ 2022-06-07 12:05           ` Peter Eisentraut <peter.eisentraut@enterprisedb.com>
  2022-06-08 10:16             ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  0 siblings, 1 reply; 16+ messages in thread

From: Peter Eisentraut @ 2022-06-07 12:05 UTC (permalink / raw)
  To: Fabien COELHO <coelho@cri.ensmp.fr>; Tom Lane <tgl@sss.pgh.pa.us>; +Cc: Alastair McKinley <a.mckinley@analyticsengines.com>; PostgreSQL Bugs <pgsql-bugs@lists.postgresql.org>

On 03.06.22 20:25, Fabien COELHO wrote:
> My short term recommendation is to remove the attempt at keeping the 
> notice/result order for a tradeoff of getting the notices as soon as 
> they are emitted, i.e. basically patch 1 and the acceptance of the 
> diffs, called 1-bis in the attached.

I agree with this solution.  Do you want to keep the tests, do you think 
they are going to be stable?  I suppose we could try and find out.





^ permalink  raw  reply  [nested|flat] 16+ messages in thread

* Re: psql 15beta1 does not print notices on the console until transaction completes
  2022-05-29 20:11 psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 20:27 ` Re: psql 15beta1 does not print notices on the console until transaction completes Tom Lane <tgl@sss.pgh.pa.us>
  2022-05-30 09:05   ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  2022-05-30 17:53     ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  2022-05-31 11:51       ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  2022-06-03 18:25         ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  2022-06-07 12:05           ` Re: psql 15beta1 does not print notices on the console until transaction completes Peter Eisentraut <peter.eisentraut@enterprisedb.com>
@ 2022-06-08 10:16             ` Fabien COELHO <coelho@cri.ensmp.fr>
  2022-06-09 07:38               ` Re: psql 15beta1 does not print notices on the console until transaction completes Peter Eisentraut <peter.eisentraut@enterprisedb.com>
  0 siblings, 1 reply; 16+ messages in thread

From: Fabien COELHO @ 2022-06-08 10:16 UTC (permalink / raw)
  To: Peter Eisentraut <peter.eisentraut@enterprisedb.com>; +Cc: Tom Lane <tgl@sss.pgh.pa.us>; Alastair McKinley <a.mckinley@analyticsengines.com>; PostgreSQL Bugs <pgsql-bugs@lists.postgresql.org>


>> My short term recommendation is to remove the attempt at keeping the 
>> notice/result order for a tradeoff of getting the notices as soon as they 
>> are emitted, i.e. basically patch 1 and the acceptance of the diffs, called 
>> 1-bis in the attached.
>
> I agree with this solution.  Do you want to keep the tests, do you think they 
> are going to be stable?  I suppose we could try and find out.

I think that we should try to keep them, and remove them only if they are 
proven unstable, which may happen. The buildfarm will tell.

-- 
Fabien.





^ permalink  raw  reply  [nested|flat] 16+ messages in thread

* Re: psql 15beta1 does not print notices on the console until transaction completes
  2022-05-29 20:11 psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 20:27 ` Re: psql 15beta1 does not print notices on the console until transaction completes Tom Lane <tgl@sss.pgh.pa.us>
  2022-05-30 09:05   ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  2022-05-30 17:53     ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  2022-05-31 11:51       ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  2022-06-03 18:25         ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
  2022-06-07 12:05           ` Re: psql 15beta1 does not print notices on the console until transaction completes Peter Eisentraut <peter.eisentraut@enterprisedb.com>
  2022-06-08 10:16             ` Re: psql 15beta1 does not print notices on the console until transaction completes Fabien COELHO <coelho@cri.ensmp.fr>
@ 2022-06-09 07:38               ` Peter Eisentraut <peter.eisentraut@enterprisedb.com>
  0 siblings, 0 replies; 16+ messages in thread

From: Peter Eisentraut @ 2022-06-09 07:38 UTC (permalink / raw)
  To: Fabien COELHO <coelho@cri.ensmp.fr>; +Cc: Tom Lane <tgl@sss.pgh.pa.us>; Alastair McKinley <a.mckinley@analyticsengines.com>; PostgreSQL Bugs <pgsql-bugs@lists.postgresql.org>

On 08.06.22 12:16, Fabien COELHO wrote:
>>> My short term recommendation is to remove the attempt at keeping the 
>>> notice/result order for a tradeoff of getting the notices as soon as 
>>> they are emitted, i.e. basically patch 1 and the acceptance of the 
>>> diffs, called 1-bis in the attached.
>>
>> I agree with this solution.  Do you want to keep the tests, do you 
>> think they are going to be stable?  I suppose we could try and find out.
> 
> I think that we should try to keep them, and remove them only if they 
> are proven unstable, which may happen. The buildfarm will tell.

Ok, committed as you submitted.






^ permalink  raw  reply  [nested|flat] 16+ messages in thread

* Re: psql 15beta1 does not print notices on the console until transaction completes
  2022-05-29 20:11 psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
@ 2022-05-29 20:47 ` Adrian Klaver <adrian.klaver@aklaver.com>
  2022-05-29 20:59   ` Re: psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 20:59   ` Re: psql 15beta1 does not print notices on the console until transaction completes Adrian Klaver <adrian.klaver@aklaver.com>
  1 sibling, 2 replies; 16+ messages in thread

From: Adrian Klaver @ 2022-05-29 20:47 UTC (permalink / raw)
  To: Alastair McKinley <a.mckinley@analyticsengines.com>; pgsql-general@lists.postgresql.org <pgsql-general@lists.postgresql.org>

On 5/29/22 13:11, Alastair McKinley wrote:
> Hi all,
> 
> I notice this change in behaviour with psql in 15beta1 when testing an existing codebase.
> 
> I didn't see any mention of this change in the release notes and it surprised me.
> 
> Using this test function:
> 
>      create or replace function test_notice() returns void as
>      $$
>      begin
>          raise notice 'hello';
>          perform pg_sleep(10);
>      end; $$ language plpgsql;
> 
> In psql 15beta1, the "hello" message only appears on the console when the transaction completes.

I am not seeing that.

Can you provide more information about how you are running test_notice()?

> 
> in psql 14.3, it appears immediately as I would have expected.
> 
> Is there a way to change psql behaviour to display notices immediately as in versions < 15?
> 
> Best regards,
> 
> Alastair
> 


-- 
Adrian Klaver
adrian.klaver@aklaver.com





^ permalink  raw  reply  [nested|flat] 16+ messages in thread

* Re: psql 15beta1 does not print notices on the console until transaction completes
  2022-05-29 20:11 psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 20:47 ` Re: psql 15beta1 does not print notices on the console until transaction completes Adrian Klaver <adrian.klaver@aklaver.com>
@ 2022-05-29 20:59   ` Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 21:14     ` Re: psql 15beta1 does not print notices on the console until transaction completes Adrian Klaver <adrian.klaver@aklaver.com>
  1 sibling, 1 reply; 16+ messages in thread

From: Alastair McKinley @ 2022-05-29 20:59 UTC (permalink / raw)
  To: Adrian Klaver <adrian.klaver@aklaver.com>; pgsql-general@lists.postgresql.org <pgsql-general@lists.postgresql.org>

>
> From: Adrian Klaver <adrian.klaver@aklaver.com>
> Sent: 29 May 2022 21:47To: Alastair McKinley <a.mckinley@analyticsengines.com>; pgsql-general@lists.postgresql.org <pgsql-general@lists.postgresql.org>Subject: Re: psql 15beta1 does not print notices on the console until transaction completes
>
> On 5/29/22 13:11, Alastair McKinley wrote:
> > Hi all,
> >
> > I notice this change in behaviour with psql in 15beta1 when testing an existing codebase.
> >
> > I didn't see any mention of this change in the release notes and it surprised me.
> >
> > Using this test function:
> >
> >      create or replace function test_notice() returns void as
> >      $$
> >      begin
> >          raise notice 'hello';
> >          perform pg_sleep(10);
> >      end; $$ language plpgsql;
> >
> > In psql 15beta1, the "hello" message only appears on the console when the transaction completes.
>
> I am not seeing that.
>
> Can you provide more information about how you are running test_notice()?
>

Hi Adrian,

I am running the function "select test_notice();" from the psql console with psql/server versions 15beta1.

In psql 15beta1, the notice appears only after the function returns/transaction completes.

If I execute the same function from psql 14.3 and server 15beta1, the notice appears on the psql console immediately as expected, before the pg_sleep() completes.

It's reproducible for me, I just double checked it.

I think Tom was able to reproduce this by the sounds of his response?

Best regards,

Alastair

> >
> > in psql 14.3, it appears immediately as I would have expected.
> >
> > Is there a way to change psql behaviour to display notices immediately as in versions < 15?
> >
> > Best regards,
> >
> > Alastair
> >
>
>
> --
> Adrian Klaver
> adrian.klaver@aklaver.com

^ permalink  raw  reply  [nested|flat] 16+ messages in thread

* Re: psql 15beta1 does not print notices on the console until transaction completes
  2022-05-29 20:11 psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 20:47 ` Re: psql 15beta1 does not print notices on the console until transaction completes Adrian Klaver <adrian.klaver@aklaver.com>
  2022-05-29 20:59   ` Re: psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
@ 2022-05-29 21:14     ` Adrian Klaver <adrian.klaver@aklaver.com>
  2022-05-29 22:03       ` Re: psql 15beta1 does not print notices on the console until transaction completes Tom Lane <tgl@sss.pgh.pa.us>
  0 siblings, 1 reply; 16+ messages in thread

From: Adrian Klaver @ 2022-05-29 21:14 UTC (permalink / raw)
  To: Alastair McKinley <a.mckinley@analyticsengines.com>; pgsql-general@lists.postgresql.org <pgsql-general@lists.postgresql.org>

On 5/29/22 13:59, Alastair McKinley wrote:
>  >
>  > From: Adrian Klaver <adrian.klaver@aklaver.com>
>  > Sent: 29 May 2022 21:47To: Alastair McKinley 

> Hi Adrian,
> 
> I am running the function "select test_notice();" from the psql console 
> with psql/server versions 15beta1.
> 
> In psql 15beta1, the notice appears only after the function 
> returns/transaction completes.
> 
> If I execute the same function from psql 14.3 and server 15beta1, the 
> notice appears on the psql console immediately as expected, before the 
> pg_sleep() completes.
> 
> It's reproducible for me, I just double checked it.

Yeah, I see the same thing  after using the new psql.

> 
> I think Tom was able to reproduce this by the sounds of his response?

I have not received that post yet. I do see it in the archives. I had 
already tried:

\set SHOW_ALL_RESULTS off

which is supposed to restore to previous behavior, but it did not lead 
to the 14.3 result.

> 
> Best regards,
> 
> Alastair
> 

-- 
Adrian Klaver
adrian.klaver@aklaver.com





^ permalink  raw  reply  [nested|flat] 16+ messages in thread

* Re: psql 15beta1 does not print notices on the console until transaction completes
  2022-05-29 20:11 psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 20:47 ` Re: psql 15beta1 does not print notices on the console until transaction completes Adrian Klaver <adrian.klaver@aklaver.com>
  2022-05-29 20:59   ` Re: psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 21:14     ` Re: psql 15beta1 does not print notices on the console until transaction completes Adrian Klaver <adrian.klaver@aklaver.com>
@ 2022-05-29 22:03       ` Tom Lane <tgl@sss.pgh.pa.us>
  2022-05-30 00:00         ` Re: psql 15beta1 does not print notices on the console until transaction completes Adrian Klaver <adrian.klaver@aklaver.com>
  0 siblings, 1 reply; 16+ messages in thread

From: Tom Lane @ 2022-05-29 22:03 UTC (permalink / raw)
  To: Adrian Klaver <adrian.klaver@aklaver.com>; +Cc: Alastair McKinley <a.mckinley@analyticsengines.com>; pgsql-general@lists.postgresql.org <pgsql-general@lists.postgresql.org>

Adrian Klaver <adrian.klaver@aklaver.com> writes:
> On 5/29/22 13:59, Alastair McKinley wrote:
>> I think Tom was able to reproduce this by the sounds of his response?

> I have not received that post yet. I do see it in the archives.

I re-addressed it to pgsql-bugs, maybe you are not subscribed to that?

			regards, tom lane





^ permalink  raw  reply  [nested|flat] 16+ messages in thread

* Re: psql 15beta1 does not print notices on the console until transaction completes
  2022-05-29 20:11 psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 20:47 ` Re: psql 15beta1 does not print notices on the console until transaction completes Adrian Klaver <adrian.klaver@aklaver.com>
  2022-05-29 20:59   ` Re: psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 21:14     ` Re: psql 15beta1 does not print notices on the console until transaction completes Adrian Klaver <adrian.klaver@aklaver.com>
  2022-05-29 22:03       ` Re: psql 15beta1 does not print notices on the console until transaction completes Tom Lane <tgl@sss.pgh.pa.us>
@ 2022-05-30 00:00         ` Adrian Klaver <adrian.klaver@aklaver.com>
  2022-05-30 00:02           ` Re: psql 15beta1 does not print notices on the console until transaction completes Rob Sargent <robjsargent@gmail.com>
  0 siblings, 1 reply; 16+ messages in thread

From: Adrian Klaver @ 2022-05-30 00:00 UTC (permalink / raw)
  To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: Alastair McKinley <a.mckinley@analyticsengines.com>; pgsql-general@lists.postgresql.org <pgsql-general@lists.postgresql.org>

On 5/29/22 15:03, Tom Lane wrote:
> Adrian Klaver <adrian.klaver@aklaver.com> writes:
>> On 5/29/22 13:59, Alastair McKinley wrote:
>>> I think Tom was able to reproduce this by the sounds of his response?
> 
>> I have not received that post yet. I do see it in the archives.
> 
> I re-addressed it to pgsql-bugs, maybe you are not subscribed to that?

I am not, still I see it here:

https://www.postgresql.org/list/pgsql-general/since/202205290000/

And when I click on the message:

https://www.postgresql.org/message-id/3662994.1653856025%40sss.pgh.pa.us

Lists: 	pgsql-bugs pgsql-general

I will admit that the mailing list software is a mystery to me, so it is 
entirely possible I am misreading the above.

> 
> 			regards, tom lane


-- 
Adrian Klaver
adrian.klaver@aklaver.com





^ permalink  raw  reply  [nested|flat] 16+ messages in thread

* Re: psql 15beta1 does not print notices on the console until transaction completes
  2022-05-29 20:11 psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 20:47 ` Re: psql 15beta1 does not print notices on the console until transaction completes Adrian Klaver <adrian.klaver@aklaver.com>
  2022-05-29 20:59   ` Re: psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 21:14     ` Re: psql 15beta1 does not print notices on the console until transaction completes Adrian Klaver <adrian.klaver@aklaver.com>
  2022-05-29 22:03       ` Re: psql 15beta1 does not print notices on the console until transaction completes Tom Lane <tgl@sss.pgh.pa.us>
  2022-05-30 00:00         ` Re: psql 15beta1 does not print notices on the console until transaction completes Adrian Klaver <adrian.klaver@aklaver.com>
@ 2022-05-30 00:02           ` Rob Sargent <robjsargent@gmail.com>
  0 siblings, 0 replies; 16+ messages in thread

From: Rob Sargent @ 2022-05-30 00:02 UTC (permalink / raw)
  To: pgsql-general@lists.postgresql.org

On 5/29/22 18:00, Adrian Klaver wrote:
> On 5/29/22 15:03, Tom Lane wrote:
>> Adrian Klaver <adrian.klaver@aklaver.com> writes:
>>> On 5/29/22 13:59, Alastair McKinley wrote:
>>>> I think Tom was able to reproduce this by the sounds of his response?
>>
>>> I have not received that post yet. I do see it in the archives.
>>
>> I re-addressed it to pgsql-bugs, maybe you are not subscribed to that?
>
> I am not, still I see it here:
>
> https://www.postgresql.org/list/pgsql-general/since/202205290000/
>
> And when I click on the message:
>
> https://www.postgresql.org/message-id/3662994.1653856025%40sss.pgh.pa.us
>
> Lists:     pgsql-bugs pgsql-general
>
> I will admit that the mailing list software is a mystery to me, so it 
> is entirely possible I am misreading the above.
>
FWIW, I didn't see Tom's first (bugs) post either.  Nor am I subscribed 
to bugs





^ permalink  raw  reply  [nested|flat] 16+ messages in thread

* Re: psql 15beta1 does not print notices on the console until transaction completes
  2022-05-29 20:11 psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
  2022-05-29 20:47 ` Re: psql 15beta1 does not print notices on the console until transaction completes Adrian Klaver <adrian.klaver@aklaver.com>
@ 2022-05-29 20:59   ` Adrian Klaver <adrian.klaver@aklaver.com>
  1 sibling, 0 replies; 16+ messages in thread

From: Adrian Klaver @ 2022-05-29 20:59 UTC (permalink / raw)
  To: Alastair McKinley <a.mckinley@analyticsengines.com>; pgsql-general@lists.postgresql.org <pgsql-general@lists.postgresql.org>

On 5/29/22 13:47, Adrian Klaver wrote:
> On 5/29/22 13:11, Alastair McKinley wrote:
>> Hi all,

>> In psql 15beta1, the "hello" message only appears on the console when 
>> the transaction completes.
> 
> I am not seeing that.

I take that back, I was using psql 14.3 to connect to the 15 instance. 
When I changed to psql 15 I saw the same thing.

> 

>> Best regards,
>>
>> Alastair
>>
> 
> 


-- 
Adrian Klaver
adrian.klaver@aklaver.com





^ permalink  raw  reply  [nested|flat] 16+ messages in thread

end of thread, other threads:[~2022-06-09 07:38 UTC | newest]

Thread overview: 16+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2022-05-29 20:11 psql 15beta1 does not print notices on the console until transaction completes Alastair McKinley <a.mckinley@analyticsengines.com>
2022-05-29 20:27 ` Tom Lane <tgl@sss.pgh.pa.us>
2022-05-30 09:05   ` Fabien COELHO <coelho@cri.ensmp.fr>
2022-05-30 17:53     ` Fabien COELHO <coelho@cri.ensmp.fr>
2022-05-31 11:51       ` Fabien COELHO <coelho@cri.ensmp.fr>
2022-06-03 18:25         ` Fabien COELHO <coelho@cri.ensmp.fr>
2022-06-07 12:05           ` Peter Eisentraut <peter.eisentraut@enterprisedb.com>
2022-06-08 10:16             ` Fabien COELHO <coelho@cri.ensmp.fr>
2022-06-09 07:38               ` Peter Eisentraut <peter.eisentraut@enterprisedb.com>
2022-05-29 20:47 ` Adrian Klaver <adrian.klaver@aklaver.com>
2022-05-29 20:59   ` Alastair McKinley <a.mckinley@analyticsengines.com>
2022-05-29 21:14     ` Adrian Klaver <adrian.klaver@aklaver.com>
2022-05-29 22:03       ` Tom Lane <tgl@sss.pgh.pa.us>
2022-05-30 00:00         ` Adrian Klaver <adrian.klaver@aklaver.com>
2022-05-30 00:02           ` Rob Sargent <robjsargent@gmail.com>
2022-05-29 20:59   ` Adrian Klaver <adrian.klaver@aklaver.com>

This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox