From: Tom Lane <tgl@sss.pgh.pa.us>
To: pgsql-hackers@lists.postgresql.org
Subject: Gripes about walsender command processing
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="----- =_aaaaaaaaaa0"
Content-ID: <880141.1600026427.0@sss.pgh.pa.us>
Date: Sun, 13 Sep 2020 15:47:51 -0400
Message-ID: <880181.1600026471@sss.pgh.pa.us>
Precedence: bulk

------- =_aaaaaaaaaa0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <880141.1600026427.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable

While trying to understand a recent buildfarm failure [1], I got annoyed
by the fact that a walsender exposes its last SQL command in
pg_stat_activity even when that was a long time ago and what it's been
doing since then is replication commands.  This leads to *totally*
misleading reports, for instance in [1] we read

2020-09-13 19:10:09.632 CEST [5f5e526d.242415:4] LOG:  server process (PID=
 2368853) was terminated by signal 11: Segmentation fault
2020-09-13 19:10:09.632 CEST [5f5e526d.242415:5] DETAIL:  Failed process w=
as running: SELECT pg_catalog.set_config('search_path', '', false);

even though the process's own log messages paint a much better picture of
reality:

2020-09-13 19:10:07.302 CEST [5f5e526f.242555:1] LOG:  connection received=
: host=3D[local]
2020-09-13 19:10:07.303 CEST [5f5e526f.242555:2] LOG:  replication connect=
ion authorized: user=3Dbf application_name=3Dsub2
2020-09-13 19:10:07.303 CEST [5f5e526f.242555:3] LOG:  statement: SELECT p=
g_catalog.set_config('search_path', '', false);
2020-09-13 19:10:07.334 CEST [5f5e526f.242555:4] LOG:  received replicatio=
n command: IDENTIFY_SYSTEM
2020-09-13 19:10:07.335 CEST [5f5e526f.242555:5] LOG:  received replicatio=
n command: START_REPLICATION SLOT "sub2" LOGICAL 0/0 (proto_version '2', p=
ublication_names '"pub2"')
2020-09-13 19:10:07.335 CEST [5f5e526f.242555:6] LOG:  starting logical de=
coding for slot "sub2"
2020-09-13 19:10:07.335 CEST [5f5e526f.242555:7] DETAIL:  Streaming transa=
ctions committing after 0/159EB38, reading WAL from 0/159EB00.
2020-09-13 19:10:07.335 CEST [5f5e526f.242555:8] LOG:  logical decoding fo=
und consistent point at 0/159EB00
2020-09-13 19:10:07.335 CEST [5f5e526f.242555:9] DETAIL:  There are no run=
ning transactions.

I think that walsenders ought to report their current replication command
as though it were a SQL command.  They oughta set debug_query_string, too.

While trying to fix this, I also observed that exec_replication_command
fails to clean up the temp context it made for parsing the command string,
if that turns out to be a SQL command.  This very accidentally fails to
lead to a long-term memory leak, because that context will be a child of
MessageContext so it'll be cleaned out in the next iteration of
PostgresMain's main loop.  But it's still unacceptably sloppy coding
IMHO, and it's closely related to a lot of other randomness in the
function; it'd be better to have a separate early-exit path for SQL
commands.

Attached find a proposed fix for these things.

What I'd really like to do is adjust pgstat_report_activity so that
callers are *required* to provide some kind of command string when
transitioning into STATE_RUNNING state, ie something like

	Assert(state =3D=3D STATE_RUNNING ? cmd_str !=3D NULL : cmd_str =3D=3D NU=
LL);

However, before we could do that, we'd have to clean up the rat's nest
of seemingly-inserted-with-the-aid-of-a-dartboard pgstat_report_activity
calls in replication/logical/worker.c.  I couldn't make heads or tails
of what is going on there, so I did not try.

BTW, while I didn't change it here, isn't the second
SnapBuildClearExportedSnapshot call in exec_replication_command just
useless?  We already did that before parsing the command.

			regards, tom lane

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Didiacanthus&=
dt=3D2020-09-13%2016%3A54%3A03


------- =_aaaaaaaaaa0
Content-Type: text/x-diff; name="clean-up-exec_replication_command.patch";
	charset="us-ascii"
Content-ID: <880141.1600026427.2@sss.pgh.pa.us>
Content-Description: clean-up-exec_replication_command.patch
Content-Transfer-Encoding: quoted-printable

diff --git a/src/backend/replication/walsender.c b/src/backend/replication=
/walsender.c
index 3f756b470a..9a2b154797 100644
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -1545,6 +1545,9 @@ exec_replication_command(const char *cmd_string)
 =

 	CHECK_FOR_INTERRUPTS();
 =

+	/*
+	 * Parse the command.
+	 */
 	cmd_context =3D AllocSetContextCreate(CurrentMemoryContext,
 										"Replication command context",
 										ALLOCSET_DEFAULT_SIZES);
@@ -1560,15 +1563,38 @@ exec_replication_command(const char *cmd_string)
 =

 	cmd_node =3D replication_parse_result;
 =

+	/*
+	 * If it's a SQL command, just clean up our mess and return false; the
+	 * caller will take care of executing it.
+	 */
+	if (IsA(cmd_node, SQLCmd))
+	{
+		if (MyDatabaseId =3D=3D InvalidOid)
+			ereport(ERROR,
+					(errmsg("cannot execute SQL commands in WAL sender for physical repl=
ication")));
+
+		MemoryContextSwitchTo(old_context);
+		MemoryContextDelete(cmd_context);
+
+		/* Tell the caller that this wasn't a WalSender command. */
+		return false;
+	}
+
+	/*
+	 * Report query to various monitoring facilities.  For this purpose, we
+	 * report replication commands just like SQL commands.
+	 */
+	debug_query_string =3D cmd_string;
+
+	pgstat_report_activity(STATE_RUNNING, cmd_string);
+
 	/*
 	 * Log replication command if log_replication_commands is enabled. Even
 	 * when it's disabled, log the command with DEBUG1 level for backward
-	 * compatibility. Note that SQL commands are not logged here, and will b=
e
-	 * logged later if log_statement is enabled.
+	 * compatibility.
 	 */
-	if (cmd_node->type !=3D T_SQLCmd)
-		ereport(log_replication_commands ? LOG : DEBUG1,
-				(errmsg("received replication command: %s", cmd_string)));
+	ereport(log_replication_commands ? LOG : DEBUG1,
+			(errmsg("received replication command: %s", cmd_string)));
 =

 	/*
 	 * CREATE_REPLICATION_SLOT ... LOGICAL exports a snapshot. If it was
@@ -1578,10 +1604,9 @@ exec_replication_command(const char *cmd_string)
 		SnapBuildClearExportedSnapshot();
 =

 	/*
-	 * For aborted transactions, don't allow anything except pure SQL, the
-	 * exec_simple_query() will handle it correctly.
+	 * Disallow replication commands in aborted transaction blocks.
 	 */
-	if (IsAbortedTransactionBlockState() && !IsA(cmd_node, SQLCmd))
+	if (IsAbortedTransactionBlockState())
 		ereport(ERROR,
 				(errcode(ERRCODE_IN_FAILED_SQL_TRANSACTION),
 				 errmsg("current transaction is aborted, "
@@ -1597,9 +1622,6 @@ exec_replication_command(const char *cmd_string)
 	initStringInfo(&reply_message);
 	initStringInfo(&tmpbuf);
 =

-	/* Report to pgstat that this process is running */
-	pgstat_report_activity(STATE_RUNNING, NULL);
-
 	switch (cmd_node->type)
 	{
 		case T_IdentifySystemCmd:
@@ -1651,17 +1673,6 @@ exec_replication_command(const char *cmd_string)
 			}
 			break;
 =

-		case T_SQLCmd:
-			if (MyDatabaseId =3D=3D InvalidOid)
-				ereport(ERROR,
-						(errmsg("cannot execute SQL commands in WAL sender for physical rep=
lication")));
-
-			/* Report to pgstat that this process is now idle */
-			pgstat_report_activity(STATE_IDLE, NULL);
-
-			/* Tell the caller that this wasn't a WalSender command. */
-			return false;
-
 		default:
 			elog(ERROR, "unrecognized replication command node tag: %u",
 				 cmd_node->type);
@@ -1677,6 +1688,7 @@ exec_replication_command(const char *cmd_string)
 =

 	/* Report to pgstat that this process is now idle */
 	pgstat_report_activity(STATE_IDLE, NULL);
+	debug_query_string =3D NULL;
 =

 	return true;
 }

------- =_aaaaaaaaaa0--