From feddd203edc7175ed7463f39078cd5f573fae308 Mon Sep 17 00:00:00 2001 From: Justin Pryzby Date: Fri, 1 Jan 2021 19:38:57 -0600 Subject: [PATCH 1/3] Report text parameters during errors in typinput Since v13, bind parameters have been logged during errors in BIND/EXECUTE, but the BIND errors didn't happen during type conversion, which misses cases involving simple VALUES() lists. This patch also includes the bind parameters in errors which happen during the typinput function, for text mode bind parameters. For example: $ python3.5 -c "import pg,time; db=pg.DB('dbname=postgres host=/var/run/postgresql port=5432 host=/tmp'); q = db.query(\"SET log_parameter_max_length_on_error=-1;\"); db.prepare('p', 'SELECT \$1::smallint'); db.query_prepared('p',66666);" 2021-01-01 19:40:24.777 CST [5330] ERROR: value "66666" is out of range for type smallint 2021-01-01 19:40:24.777 CST [5330] CONTEXT: unnamed portal with parameters: $1 = '66666' This can be useful to determine which is out of range when there are many bind params. See also: commit ba79cb5dc commit 0b34e7d30 https://www.postgresql.org/message-id/flat/CANfkH5k-6nNt-4cSv1vPB80nq2BZCzhFVR5O4VznYbsX0wZmow@mail.gmail.com Mention column name in error messages --- src/backend/tcop/postgres.c | 185 +++++++++++++------ src/bin/pgbench/t/001_pgbench_with_server.pl | 18 ++ 2 files changed, 146 insertions(+), 57 deletions(-) diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index bb5ccb4578..95be9ba460 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -1759,14 +1759,130 @@ exec_bind_message(StringInfo input_message) snapshot_set = true; } + /* + * Set the error callback so that parameters are logged, as needed. + * This has no effect until params->paramValuesStr is set. + */ + params_data.portalName = portal->name; + params_data.params = NULL; + params_errcxt.previous = error_context_stack; + params_errcxt.callback = ParamsErrorCallback; + params_errcxt.arg = (void *) ¶ms_data; + error_context_stack = ¶ms_errcxt; + /* * Fetch parameters, if any, and store in the portal's memory context. */ if (numParams > 0) { char **knownTextValues = NULL; /* allocate on first use */ + int32 *plengths; + char **pstrings; + bool textonly = true; + + plengths = palloc0(numParams * sizeof(*plengths)); + + /* Indexed by paramno, but not used for nulls */ + pstrings = palloc0(numParams * sizeof(*pstrings)); params = makeParamList(numParams); + params_data.params = params; + + /* + * Do two loops to allow parameters to be displayed in error + * reports during typinput. + * On the first pass, just save the offset and length of each param; + * On the second pass, convert the params to the required type. + * If that fails, text params have already been saved and can + * be displayed by the error callack. + */ + + for (int paramno = 0; paramno < numParams; paramno++) + { + int32 plength; + int16 pformat; + char *pstring; + MemoryContext oldcxt; + + plength = plengths[paramno] = pq_getmsgint(input_message, 4); + + /* Minimal amount needed for error callback */ + params->params[paramno].ptype = psrc->param_types[paramno]; + params->params[paramno].isnull = (plength == -1); + + if (params->params[paramno].isnull) + continue; + + pstrings[paramno] = unconstify(char *, pq_getmsgbytes(input_message, plength)); + + if (log_parameter_max_length_on_error == 0) + continue; + + if (numPFormats > 1) + pformat = pformats[paramno]; + else if (numPFormats > 0) + pformat = pformats[0]; + else + pformat = 0; /* default = text */ + + if (pformat != 0) + { + textonly = false; + continue; + } + + /* + * Since we might need to log parameters later, save a copy of the + * converted string in MessageContext; + */ + + pstring = pg_client_to_server(pstrings[paramno], plength); + oldcxt = MemoryContextSwitchTo(MessageContext); + + if (knownTextValues == NULL) + knownTextValues = + palloc0(numParams * sizeof(char *)); + + if (log_parameter_max_length_on_error < 0) + { + knownTextValues[paramno] = pstrdup(pstring); + knownTextValues[paramno][plength] = 0; + } + else + { + /* + * We can trim the saved string, knowing that we + * won't print all of it. But we must copy at + * least two more full characters than + * BuildParamLogString wants to use; otherwise it + * might fail to include the trailing ellipsis. + */ + char csave = pstring[plength]; + pstring[plength] = 0; + knownTextValues[paramno] = + pnstrdup(pstring, + log_parameter_max_length_on_error + + 2 * MAX_MULTIBYTE_CHAR_LEN); + pstring[plength] = csave; + } + + MemoryContextSwitchTo(oldcxt); + if (pstring != pstrings[paramno]) + pfree(pstring); + } + + /* + * Once all parameters have been received, prepare for printing them + * in errors, if configured to do so. (This is saved in the portal, + * so that they'll appear when the query is executed later.) + * If all parameters are text, this is done before calling the input + * function, to allow reporting values during errors there. + */ + if (log_parameter_max_length_on_error != 0 && textonly) + // (numPFormats == 0 || (numPFormats == 1 && pformats[0] == 0))) + params->paramValuesStr = BuildParamLogString(params, + knownTextValues, + log_parameter_max_length_on_error); for (int paramno = 0; paramno < numParams; paramno++) { @@ -1778,13 +1894,11 @@ exec_bind_message(StringInfo input_message) char csave; int16 pformat; - plength = pq_getmsgint(input_message, 4); + plength = plengths[paramno]; isNull = (plength == -1); if (!isNull) { - const char *pvalue = pq_getmsgbytes(input_message, plength); - /* * Rather than copying data around, we just set up a phony * StringInfo pointing to the correct portion of the message @@ -1793,7 +1907,7 @@ exec_bind_message(StringInfo input_message) * trailing null. This is grotty but is a big win when * dealing with very large parameter strings. */ - pbuf.data = unconstify(char *, pvalue); + pbuf.data = pstrings[paramno]; pbuf.maxlen = plength + 1; pbuf.len = plength; pbuf.cursor = 0; @@ -1833,45 +1947,9 @@ exec_bind_message(StringInfo input_message) pval = OidInputFunctionCall(typinput, pstring, typioparam, -1); - /* - * If we might need to log parameters later, save a copy of - * the converted string in MessageContext; then free the - * result of encoding conversion, if any was done. - */ - if (pstring) - { - if (log_parameter_max_length_on_error != 0) - { - MemoryContext oldcxt; - - oldcxt = MemoryContextSwitchTo(MessageContext); - - if (knownTextValues == NULL) - knownTextValues = - palloc0(numParams * sizeof(char *)); - - if (log_parameter_max_length_on_error < 0) - knownTextValues[paramno] = pstrdup(pstring); - else - { - /* - * We can trim the saved string, knowing that we - * won't print all of it. But we must copy at - * least two more full characters than - * BuildParamLogString wants to use; otherwise it - * might fail to include the trailing ellipsis. - */ - knownTextValues[paramno] = - pnstrdup(pstring, - log_parameter_max_length_on_error - + 2 * MAX_MULTIBYTE_CHAR_LEN); - } - - MemoryContextSwitchTo(oldcxt); - } - if (pstring != pbuf.data) - pfree(pstring); - } + /* free the result of encoding conversion, if any was done. */ + if (pstring && pstring != pbuf.data) + pfree(pstring); } else if (pformat == 1) /* binary mode */ { @@ -1923,15 +2001,16 @@ exec_bind_message(StringInfo input_message) } /* - * Once all parameters have been received, prepare for printing them - * in errors, if configured to do so. (This is saved in the portal, - * so that they'll appear when the query is executed later.) + * If there are any non-text parameters, enable parameter output only + * after calling the input functions */ - if (log_parameter_max_length_on_error != 0) - params->paramValuesStr = - BuildParamLogString(params, + if (log_parameter_max_length_on_error != 0 && !textonly) + params->paramValuesStr = BuildParamLogString(params, knownTextValues, log_parameter_max_length_on_error); + + pfree(plengths); + pfree(pstrings); } else params = NULL; @@ -1939,14 +2018,6 @@ exec_bind_message(StringInfo input_message) /* Done storing stuff in portal's context */ MemoryContextSwitchTo(oldContext); - /* Set the error callback so that parameters are logged, as needed */ - params_data.portalName = portal->name; - params_data.params = params; - params_errcxt.previous = error_context_stack; - params_errcxt.callback = ParamsErrorCallback; - params_errcxt.arg = (void *) ¶ms_data; - error_context_stack = ¶ms_errcxt; - /* Get the result format codes */ numRFormats = pq_getmsgint(input_message, 2); if (numRFormats > 0) diff --git a/src/bin/pgbench/t/001_pgbench_with_server.pl b/src/bin/pgbench/t/001_pgbench_with_server.pl index daffc18e52..936ae80f91 100644 --- a/src/bin/pgbench/t/001_pgbench_with_server.pl +++ b/src/bin/pgbench/t/001_pgbench_with_server.pl @@ -350,6 +350,7 @@ $node->append_conf('postgresql.conf', . "log_parameter_max_length = 7\n" . "log_parameter_max_length_on_error = -1"); $node->reload; + pgbench( '-n -t1 -c1 -M prepared', 2, @@ -389,6 +390,23 @@ like( "parameter report truncates"); $log = undef; +# Check that errors happen during BIND phase, too +pgbench( + '-n -t1 -c1 -M prepared', + 2, + [], + [ + qr{ERROR: invalid input syntax for type smallint: "1a"}, + qr{CONTEXT: unnamed portal with parameters: \$1 = '1a'} + ], + 'server parameter logging', + { + '001_param_6' => q{select '1a' as value \gset +select :value::smallint; +} + }); + + # Restore default logging config $node->append_conf('postgresql.conf', "log_min_duration_statement = -1\n" -- 2.17.0