Bug in pgbench prepared statements
Hi,
I noticed something that looks like a bug in pgbench when using the
prepared protocol. pgbench assumes that all prepared statements are
prepared correctly, even if they contain errors (e.g. syntax, column/table
doesn't exist, etc.).
My test script is just:
SELECT one;
The output looks something like this:
$ pgbench -f test.sql --protocol prepared -d postgres
[...]
pgbench: client 0 executing script "test.sql"
pgbench: client 0 preparing P_0
pgbench: error: ERROR: column "one" does not exist
LINE 1: SELECT one;
^
pgbench: client 0 sending P_0
pgbench: client 0 receiving
pgbench: client 0 receiving
pgbench: error: client 0 script 0 aborted in command 0 query 0: ERROR:
prepared statement "P_0" does not exist
transaction type: test.sql
[...]
Normally this wouldn't be a big deal, although by itself the output is
confusing, since the second error, while technically true, is not what
caused the test run to fail. In my case, I was using pgbench to validate
the correctness of prepared statements implementation in our pooler. Having
the second error sent me on quite a debugging session until I realized that
my fix was actually working.
Patch attached, if there is any interest in fixing this small bug.
Cheers!
Lev
postgresml.org
Attachments:
pgbench.patchapplication/octet-stream; name=pgbench.patchDownload
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 2e1650d..a1d6aed 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -3080,14 +3080,14 @@ allocCStatePrepared(CState *st)
/*
* Prepare the SQL command from st->use_file at command_num.
*/
-static void
+static bool
prepareCommand(CState *st, int command_num)
{
Command *command = sql_script[st->use_file].commands[command_num];
/* No prepare for non-SQL commands */
if (command->type != SQL_COMMAND)
- return;
+ return true;
if (!st->prepared)
allocCStatePrepared(st);
@@ -3099,11 +3099,15 @@ prepareCommand(CState *st, int command_num)
pg_log_debug("client %d preparing %s", st->id, command->prepname);
res = PQprepare(st->con, command->prepname,
command->argv[0], command->argc - 1, NULL);
- if (PQresultStatus(res) != PGRES_COMMAND_OK)
+ if (PQresultStatus(res) != PGRES_COMMAND_OK) {
pg_log_error("%s", PQerrorMessage(st->con));
+ return false;
+ }
PQclear(res);
st->prepared[st->use_file][command_num] = true;
}
+
+ return true;
}
/*
@@ -3177,7 +3181,8 @@ sendCommand(CState *st, Command *command)
{
const char *params[MAX_ARGS];
- prepareCommand(st, st->command);
+ if (!prepareCommand(st, st->command))
+ return false;
getQueryParams(&st->variables, command, params);
pg_log_debug("client %d sending %s", st->id, command->prepname);
On Wed Nov 29, 2023 at 7:38 PM CST, Lev Kokotov wrote:
Patch attached, if there is any interest in fixing this small bug.
I see prepareCommand() is called one more time in
prepareCommandsInPipeline(). Should you also check the return value
there?
It may also be useful to throw this patch on the January commitfest if
no one else comes along to review/commit it. This first set of changes
looks good to me.
--
Tristan Partin
Neon (https://neon.tech)
I see prepareCommand() is called one more time in
prepareCommandsInPipeline(). Should you also check the return value
there?
Yes, good catch. New patch attached.
It may also be useful to throw this patch on the January commitfest if
no one else comes along to review/commit it.
First time contributing, not familiar with the process here, but happy to
learn.
Best,
Lev
postgresml.org
On Thu, Nov 30, 2023 at 2:10 PM Tristan Partin <tristan@neon.tech> wrote:
Show quoted text
On Wed Nov 29, 2023 at 7:38 PM CST, Lev Kokotov wrote:
Patch attached, if there is any interest in fixing this small bug.
I see prepareCommand() is called one more time in
prepareCommandsInPipeline(). Should you also check the return value
there?It may also be useful to throw this patch on the January commitfest if
no one else comes along to review/commit it. This first set of changes
looks good to me.--
Tristan Partin
Neon (https://neon.tech)
Attachments:
pgbench.patchapplication/octet-stream; name=pgbench.patchDownload
From 352b363ea5125945a4a44c061e9aaa8a5caf0af6 Mon Sep 17 00:00:00 2001
From: Lev Kokotov <lev.kokotov@gmail.com>
Date: Wed, 29 Nov 2023 17:22:00 -0800
Subject: [PATCH] Abort run if prepared statement fails
---
src/bin/pgbench/pgbench.c | 30 +++++++++++++++++++++---------
1 file changed, 21 insertions(+), 9 deletions(-)
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 2e1650d0ad34..37f3db14b9ca 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -3080,14 +3080,14 @@ allocCStatePrepared(CState *st)
/*
* Prepare the SQL command from st->use_file at command_num.
*/
-static void
+static bool
prepareCommand(CState *st, int command_num)
{
Command *command = sql_script[st->use_file].commands[command_num];
/* No prepare for non-SQL commands */
if (command->type != SQL_COMMAND)
- return;
+ return true;
if (!st->prepared)
allocCStatePrepared(st);
@@ -3099,11 +3099,15 @@ prepareCommand(CState *st, int command_num)
pg_log_debug("client %d preparing %s", st->id, command->prepname);
res = PQprepare(st->con, command->prepname,
command->argv[0], command->argc - 1, NULL);
- if (PQresultStatus(res) != PGRES_COMMAND_OK)
+ if (PQresultStatus(res) != PGRES_COMMAND_OK) {
pg_log_error("%s", PQerrorMessage(st->con));
+ return false;
+ }
PQclear(res);
st->prepared[st->use_file][command_num] = true;
}
+
+ return true;
}
/*
@@ -3113,7 +3117,7 @@ prepareCommand(CState *st, int command_num)
* This sets the ->prepared flag for each relevant command as well as the
* \startpipeline itself, but doesn't move the st->command counter.
*/
-static void
+static bool
prepareCommandsInPipeline(CState *st)
{
int j;
@@ -3131,7 +3135,7 @@ prepareCommandsInPipeline(CState *st)
* though we don't actually prepare this command.
*/
if (st->prepared[st->use_file][st->command])
- return;
+ return true;
for (j = st->command + 1; commands[j] != NULL; j++)
{
@@ -3139,10 +3143,13 @@ prepareCommandsInPipeline(CState *st)
commands[j]->meta == META_ENDPIPELINE)
break;
- prepareCommand(st, j);
+ if (!prepareCommand(st, j)) {
+ return false;
+ }
}
st->prepared[st->use_file][st->command] = true;
+ return true;
}
/* Send a SQL command, using the chosen querymode */
@@ -3177,7 +3184,8 @@ sendCommand(CState *st, Command *command)
{
const char *params[MAX_ARGS];
- prepareCommand(st, st->command);
+ if (!prepareCommand(st, st->command))
+ return false;
getQueryParams(&st->variables, command, params);
pg_log_debug("client %d sending %s", st->id, command->prepname);
@@ -4424,8 +4432,12 @@ executeMetaCommand(CState *st, pg_time_usec_t *now)
* ISOLATION LEVEL SERIALIZABLE in a pipeline would fail due to a
* snapshot having been acquired by the prepare within the pipeline.
*/
- if (querymode == QUERY_PREPARED)
- prepareCommandsInPipeline(st);
+ if (querymode == QUERY_PREPARED) {
+ if (!prepareCommandsInPipeline(st)) {
+ commandFailed(st, "startpipeline", "failed to prepare commands in pipeline");
+ return CSTATE_ABORTED;
+ }
+ }
if (PQpipelineStatus(st->con) != PQ_PIPELINE_OFF)
{
On Thu, Nov 30, 2023 at 07:15:54PM -0800, Lev Kokotov wrote:
I see prepareCommand() is called one more time in
prepareCommandsInPipeline(). Should you also check the return value
there?Yes, good catch. New patch attached.
Agreed that this is not really helpful as it stands
It may also be useful to throw this patch on the January commitfest if
no one else comes along to review/commit it.First time contributing, not familiar with the process here, but happy to
learn.
The patch you have sent does not apply cleanly on the master branch,
could you rebase please?
FWIW, I am a bit confused by the state of sendCommand(). Wouldn't it
better to consume the errors from PQsendQueryPrepared() and
PQsendQueryParams() when these fail?
--
Michael
The patch you have sent does not apply cleanly on the master branch,
could you rebase please?
Attached. PR against master also here
<https://github.com/postgres/postgres/pull/147>, just to make sure it's
mergeable <https://github.com/postgres/postgres/pull/147.patch>.
Wouldn't it
better to consume the errors from PQsendQueryPrepared() and
PQsendQueryParams() when these fail?
The error is returned in PQPrepare(), which happens only in QUERY_PREPARED
mode, so PQsendQueryParams() does not apply, and before
PQsendQueryPrepared() is called, so catching the error from
PQsendQueryPrepared() is exactly what's causing the bug: ERROR: prepared
statement "P_0" does not exist.
Best,
Lev
postgresml.org
On Thu, Nov 30, 2023 at 11:19 PM Michael Paquier <michael@paquier.xyz>
wrote:
Show quoted text
On Thu, Nov 30, 2023 at 07:15:54PM -0800, Lev Kokotov wrote:
I see prepareCommand() is called one more time in
prepareCommandsInPipeline(). Should you also check the return value
there?Yes, good catch. New patch attached.
Agreed that this is not really helpful as it stands
It may also be useful to throw this patch on the January commitfest if
no one else comes along to review/commit it.First time contributing, not familiar with the process here, but happy to
learn.The patch you have sent does not apply cleanly on the master branch,
could you rebase please?FWIW, I am a bit confused by the state of sendCommand(). Wouldn't it
better to consume the errors from PQsendQueryPrepared() and
PQsendQueryParams() when these fail?
--
Michael
Attachments:
pgbench2.patchapplication/octet-stream; name=pgbench2.patchDownload
From 9c37fa7c83ba35bea7632496b9e557fbdf2cb802 Mon Sep 17 00:00:00 2001
From: Lev Kokotov <lev.kokotov@gmail.com>
Date: Wed, 29 Nov 2023 17:22:00 -0800
Subject: [PATCH] Abort run if prepared statement fails
---
src/bin/pgbench/pgbench.c | 30 +++++++++++++++++++++---------
1 file changed, 21 insertions(+), 9 deletions(-)
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 2e1650d0ad34..37f3db14b9ca 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -3080,14 +3080,14 @@ allocCStatePrepared(CState *st)
/*
* Prepare the SQL command from st->use_file at command_num.
*/
-static void
+static bool
prepareCommand(CState *st, int command_num)
{
Command *command = sql_script[st->use_file].commands[command_num];
/* No prepare for non-SQL commands */
if (command->type != SQL_COMMAND)
- return;
+ return true;
if (!st->prepared)
allocCStatePrepared(st);
@@ -3099,11 +3099,15 @@ prepareCommand(CState *st, int command_num)
pg_log_debug("client %d preparing %s", st->id, command->prepname);
res = PQprepare(st->con, command->prepname,
command->argv[0], command->argc - 1, NULL);
- if (PQresultStatus(res) != PGRES_COMMAND_OK)
+ if (PQresultStatus(res) != PGRES_COMMAND_OK) {
pg_log_error("%s", PQerrorMessage(st->con));
+ return false;
+ }
PQclear(res);
st->prepared[st->use_file][command_num] = true;
}
+
+ return true;
}
/*
@@ -3113,7 +3117,7 @@ prepareCommand(CState *st, int command_num)
* This sets the ->prepared flag for each relevant command as well as the
* \startpipeline itself, but doesn't move the st->command counter.
*/
-static void
+static bool
prepareCommandsInPipeline(CState *st)
{
int j;
@@ -3131,7 +3135,7 @@ prepareCommandsInPipeline(CState *st)
* though we don't actually prepare this command.
*/
if (st->prepared[st->use_file][st->command])
- return;
+ return true;
for (j = st->command + 1; commands[j] != NULL; j++)
{
@@ -3139,10 +3143,13 @@ prepareCommandsInPipeline(CState *st)
commands[j]->meta == META_ENDPIPELINE)
break;
- prepareCommand(st, j);
+ if (!prepareCommand(st, j)) {
+ return false;
+ }
}
st->prepared[st->use_file][st->command] = true;
+ return true;
}
/* Send a SQL command, using the chosen querymode */
@@ -3177,7 +3184,8 @@ sendCommand(CState *st, Command *command)
{
const char *params[MAX_ARGS];
- prepareCommand(st, st->command);
+ if (!prepareCommand(st, st->command))
+ return false;
getQueryParams(&st->variables, command, params);
pg_log_debug("client %d sending %s", st->id, command->prepname);
@@ -4424,8 +4432,12 @@ executeMetaCommand(CState *st, pg_time_usec_t *now)
* ISOLATION LEVEL SERIALIZABLE in a pipeline would fail due to a
* snapshot having been acquired by the prepare within the pipeline.
*/
- if (querymode == QUERY_PREPARED)
- prepareCommandsInPipeline(st);
+ if (querymode == QUERY_PREPARED) {
+ if (!prepareCommandsInPipeline(st)) {
+ commandFailed(st, "startpipeline", "failed to prepare commands in pipeline");
+ return CSTATE_ABORTED;
+ }
+ }
if (PQpipelineStatus(st->con) != PQ_PIPELINE_OFF)
{
On Fri, Dec 01, 2023 at 07:06:40PM -0800, Lev Kokotov wrote:
Attached. PR against master also here
<https://github.com/postgres/postgres/pull/147>, just to make sure it's
mergeable <https://github.com/postgres/postgres/pull/147.patch>.
Thanks for the updated patch. It looks sensible seen from here.
+ if (PQresultStatus(res) != PGRES_COMMAND_OK) {
pg_log_error("%s", PQerrorMessage(st->con));
+ return false;
+ }Each bracket should be on its own line, that's the format used
elsewhere in the code.
Did you notice that this fails some of the regression tests? You can
enable these with --enable-tap-tests. Here is the failure:
[13:57:19.960](0.000s) not ok 241 - pgbench script error: sql syntax error stderr /(?^:prepared statement .* does not exist)/
[13:57:19.960](0.000s)
[13:57:19.960](0.000s) # Failed test 'pgbench script error: sql syntax error stderr /(?^:prepared statement .* does not exist)/'
# at t/001_pgbench_with_server.pl line 1150.
[13:57:19.960](0.000s) # 'pgbench: error: ERROR: syntax error at or near ";"
# LINE 1: SELECT 1 + ;
# ^
# pgbench: error: client 0 aborted in command 0 (SQL) of script 0; SQL command send failed
# pgbench: error: Run was aborted; the above results are incomplete.
# '
# doesn't match '(?^:prepared statement .* does not exist)'
The test case expects a syntax error as per its name, but we've just
bothered checking for the last pattern of the error generated since
it has been introduced in ed8a7c6fcf92. I would be more restrictive
and just update the error output in the test, to reflect the error we
want to show up, aka a "syntax error".
--
Michael