log bind parameter values on error

On 15/12/2018 00:04, Alexey Bashtanov wrote:

I'd like to propose a patch to log bind parameter values not only when
logging duration,
but also on error (timeout in particular) or in whatever situation the
statement normally gets logged.
This mostly could be useful when the request originator doesn't log them
either, so it's hard
to reproduce the problem.

That's a reasonable problem to solve.

So I decided to cache textual representations on bind stage,
which is especially easy if the client uses text protocol.

That sounds like a plausible approach. Have you done any performance
measurements?

In your patch, I would organize the changes to the portal API a bit
differently. Don't change the signature of CreatePortal(). Get rid of
PortalSetCurrentTop() and PortalClearCurrentTop(). Just have a global
variable CurrentPortal and set it directly. And then change
GetCurrentPortalBindParameters() to take a Portal as argument. This can
all happen inside postgres.c without changing the Portal APIs.

In fact, maybe don't use the Portal structure at all and just store the
saved textualized values inside postgres.c in a static variable.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

That sounds like a plausible approach. Have you done any performance
measurements?

No I haven't yet

In your patch, I would organize the changes to the portal API a bit
differently. Don't change the signature of CreatePortal().

okay

Get rid of PortalSetCurrentTop() and PortalClearCurrentTop().

I'll remove them from Portal API, but possibly have them in postgres.c
if you don't mind, just to avoid code duplication.
Renamed and maybe even inlined.

Just have a global
variable CurrentPortal and set it directly. And then change
GetCurrentPortalBindParameters() to take a Portal as argument. This can
all happen inside postgres.c without changing the Portal APIs.

Okay, will do

In fact, maybe don't use the Portal structure at all and just store the
saved textualized values inside postgres.c in a static variable.

Unlike SQL, parameters may spend much more memory, so I'd have them
in portal memory context to make sure the memory is released earlier
rather than later.
Tracking individual variable lifetime like we do with debug_query_string
sounds doable but a bit non-straightforward to me,
see e.g. the tricks we do with transaction commands.

Also, I'd like to avoid early forming of the error string, as we may
need to combine
them differently in future, e.g. when logging in various logging formats
or languages.
One-by-one pfree-ing doesn't look tempting either.

Do you think it would be acceptable to leave them cached in parameters
structure?

Best,
  Alex

On 02/01/2019 23:53, Alexey Bashtanov wrote:

In fact, maybe don't use the Portal structure at all and just store the
saved textualized values inside postgres.c in a static variable.

Unlike SQL, parameters may spend much more memory, so I'd have them
in portal memory context to make sure the memory is released earlier
rather than later.

Having them in the portal structure is different from having it in the
portal memory context. Although there is perhaps value in keeping them
together.

Do you think it would be acceptable to leave them cached in parameters
structure?

Let's see how it looks.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Hello Peter,

Unlike SQL, parameters may spend much more memory, so I'd have them
in portal memory context to make sure the memory is released earlier
rather than later.

Having them in the portal structure is different from having it in the
portal memory context. Although there is perhaps value in keeping them
together.

yeah, to avoid pointers to deallocated areas

Let's see how it looks.

please see attached

Best,
  Alex

please see attached

sorry, some unintended changes sneaked in, please see the corrected patch

There appears to be a problem with how this affects current logging
behavior.

I'm using

pgbench -M extended -S -T 10 bench

to test the extended protocol.

Unpatched, with log_statement=all, you get something like

LOG: execute <unnamed>: SELECT abalance FROM pgbench_accounts WHERE aid
= $1;
DETAIL: parameters: $1 = '30223'

With your patch, with log_statement=all and log_parameters=on, you get
the same, but with log_statement=all and log_parameters=off you get

LOG: execute <unnamed>: SELECT abalance FROM pgbench_accounts WHERE aid
= $1;
DETAIL: parameters: $1 = UNKNOWN TYPE

We should probably keep the existing parameter logging working as before.

This also raises the question of the new parameter name. Parameters are
already logged. So the name should perhaps be more like
log_parameters_on_error.

Some API notes on your patch: I think you can change
get_portal_bind_parameters() to take a ParamListInfo, since you're not
doing anything with the Portal other than grab the parameters. And that
would allow you to keep the signature of errdetail_params() unchanged.

I did some performance tests using the commands shown above and didn't
find any problems. Obviously the default pgbench stuff isn't very
parameter-intensive. Do you have tests with more and larger parameter
values?

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Hi Peter,

With your patch, with log_statement=all and log_parameters=on, you get
the same, but with log_statement=all and log_parameters=off you get

LOG: execute <unnamed>: SELECT abalance FROM pgbench_accounts WHERE aid
= $1;
DETAIL: parameters: $1 = UNKNOWN TYPE

Thanks for spotting this, I've fixed it, see the new patch attached.

This also raises the question of the new parameter name. Parameters are
already logged. So the name should perhaps be more like
log_parameters_on_error.

Done

Some API notes on your patch: I think you can change
get_portal_bind_parameters() to take a ParamListInfo, since you're not
doing anything with the Portal other than grab the parameters. And that
would allow you to keep the signature of errdetail_params() unchanged.

Done

I did some performance tests using the commands shown above and didn't
find any problems. Obviously the default pgbench stuff isn't very
parameter-intensive. Do you have tests with more and larger parameter
values?

I've done some tests, but they are not very reproducible:
the difference between runs is more than the difference between master
vs feature branch
and log_parameters_on_error on vs off.

I was using a small java app, it tested the speed using only a single
connection.
See its code and the results attached.

I'm sorry for the delay, feel free to move it to next commitfest if needed.

Best,
  Alex

On Mon, Jan 28, 2019 at 12:15:51AM +0000, Alexey Bashtanov wrote:

I'm sorry for the delay, feel free to move it to next commitfest if
needed.

Done.
--
Michael

This piece in your patch probably doesn't belong:

+                       elog(WARNING, "params->hasTextValues=%d,
IsAbortedTransactionBlockState()=%d",
+                                          params->hasTextValues &&
IsAbortedTransactionBlockState());

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Hi,

On 2018-12-14 23:04:26 +0000, Alexey Bashtanov wrote:

Unfortunately, when enabled, the feature comes with some memory and CPU
overhead,
as we cannot convert certain values to text when in aborted transaction.

Have you analyzed how invasive it'd be to delay that till we actually
can safely start a [sub]transaction to do that logging? Probably too
expensive, but it seems like something that ought to be analyzed.

- Andres

Hi,

tiny scroll-through review.

On 2019-01-28 00:15:51 +0000, Alexey Bashtanov wrote:

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index b6f5822..997e6e8 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6274,6 +6274,23 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
</listitem>
</varlistentry>

+     <varlistentry id="guc-log-parameters-on-error" xreflabel="log_parameters_on_error">
+      <term><varname>log_parameters_on_error</varname> (<type>boolean</type>)
+      <indexterm>
+       <primary><varname>log_parameters_on_error</varname> configuration parameter</primary>
+      </indexterm>
+      </term>
+      <listitem>
+       <para>
+        Controls whether the statement is logged with bind parameter values. 
+        It adds some overhead, as postgres will cache textual
+        representations of parameter values in memory for all statements,
+        even if they eventually do not get logged. The default is
+        <literal>off</literal>. Only superusers can change this setting.
+       </para>
+      </listitem>
+     </varlistentry>

This needs a bit of language polishing.

@@ -31,6 +31,8 @@
* set of parameter values.  If dynamic parameter hooks are present, we
* intentionally do not copy them into the result.  Rather, we forcibly
* instantiate all available parameter values and copy the datum values.
+ *
+ * We don't copy textual representations here.
*/

That probably needs to be expanded on. Including a comment about what
guarantees that there are no memory lifetime issues.

-				/* Free result of encoding conversion, if any */
-				if (pstring && pstring != pbuf.data)
-					pfree(pstring);
+				if (pstring)
+				{
+					if (need_text_values)
+					{
+						if (pstring == pbuf.data)
+						{
+							/*
+							 * Copy textual representation to portal context.
+							 */
+							params->params[paramno].textValue =
+															pstrdup(pstring);
+						}
+						else
+						{
+							/* Reuse the result of encoding conversion for it */
+							params->params[paramno].textValue = pstring;
+						}
+					}
+					else
+					{
+						/* Free result of encoding conversion */
+						if (pstring != pbuf.data)
+							pfree(pstring);
+					}
+				}

So the parameters we log here haven't actually gone through the output
function? Isn't that an issue? I mean that'll cause the contents to
differ from the non-error case, no? And differs from the binary protocol
case?

else
{
+		/*
+		 * We do it for non-xact commands only, as an xact command
+		 * 1) shouldn't have any parameters to log;
+		 * 2) may have the portal dropped early.
+		 */
+		Assert(current_top_portal == NULL);
+		current_top_portal = portal;
+		portalParams = NULL;
+

"it"? ISTM the comment doesn't really stand on its own?

+/*
+ * get_portal_bind_parameters
+ * 		Get the string containing parameters data, is used for logging.
+ *
+ * Can return NULL if there are no parameters in the portal
+ * or the portal is not valid, or the text representations of the parameters are
+ * not available. If returning a non-NULL value, it allocates memory
+ * for the returned string in the current context, and it's the caller's
+ * responsibility to pfree() it if needed.
+ */
+char *
+get_portal_bind_parameters(ParamListInfo params)
+{
+	StringInfoData param_str;
+
+	/* No parameters to format */
+	if (!params || params->numParams == 0)
+		return NULL;
+
+			elog(WARNING, "params->hasTextValues=%d, IsAbortedTransactionBlockState()=%d",
+				           params->hasTextValues && IsAbortedTransactionBlockState());

Err, huh?

Greetings,

Andres Freund

Hello Anders and Peter,

Thanks for your messages.
Please see the new patch version attached.

Have you analyzed how invasive it'd be to delay that till we actually
can safely start a [sub]transaction to do that logging? Probably too
expensive, but it seems like something that ought to be analyzed.

The fundamental problem here is that the output functions for the types
of the values to be logged may be present only in the transaction
that has just been aborted.

Also I don't like the idea of doing complex operations in the error handler,
as it increases the chances of cascading errors.

I thought of pre-calculating types' output functions instead of their
results,
but that would work for certain built-in types only.

+     <varlistentry id="guc-log-parameters-on-error" xreflabel="log_parameters_on_error">
+      <term><varname>log_parameters_on_error</varname> (<type>boolean</type>)
+      <indexterm>
+       <primary><varname>log_parameters_on_error</varname> configuration parameter</primary>
+      </indexterm>
+      </term>
+      <listitem>
+       <para>
+        Controls whether the statement is logged with bind parameter values.
+        It adds some overhead, as postgres will cache textual
+        representations of parameter values in memory for all statements,
+        even if they eventually do not get logged. The default is
+        <literal>off</literal>. Only superusers can change this setting.
+       </para>
+      </listitem>
+     </varlistentry>

This needs a bit of language polishing.

I would appreciate if you had any suggestions, as my English isn't great.

@@ -31,6 +31,8 @@
* set of parameter values.  If dynamic parameter hooks are present, we
* intentionally do not copy them into the result.  Rather, we forcibly
* instantiate all available parameter values and copy the datum values.
+ *
+ * We don't copy textual representations here.
*/

That probably needs to be expanded on. Including a comment about what
guarantees that there are no memory lifetime issues.

What kind of memory lifetime issues do you mean?
We're not copying textual representations, so the worst can happen
is they don't get logged when appropriate. Luckily, we never use this
function when copying to a portal we use for logging, I added this to
the comment. Do you think it's any better?

So the parameters we log here haven't actually gone through the output
function? Isn't that an issue? I mean that'll cause the contents to
differ from the non-error case, no? And differs from the binary protocol
case?

I don't think it's much of a problem. Text input and output functions are
meant to match, but the CREATE TYPE spec isn't too specific about what
it means.
Of course it does not mean that typoutput(typinput(foo)) is always
exactly foo.
However, I really hope that at least typinput(typoutput(foo)) = foo,
where "=" is the correspondent operator registered in postgres.

If a cheeky client passes '007' as a numeric value I don't mind it being
sometimes logged as '007' and sometimes as '7', depending on the settings.
It anyway denotes the same number, and we'll know what to pass to
reproduce the problem.
For binary protocol it'll be '7' as well, as it'll undergo the typrecv
and then typoutput procedures.

else
{
+		/*
+		 * We do it for non-xact commands only, as an xact command
+		 * 1) shouldn't have any parameters to log;
+		 * 2) may have the portal dropped early.
+		 */
+		Assert(current_top_portal == NULL);
+		current_top_portal = portal;
+		portalParams = NULL;
+

"it"? ISTM the comment doesn't really stand on its own?

Thanks, I fixed the comment and some code around it.

+/*
+ * get_portal_bind_parameters
+ * 		Get the string containing parameters data, is used for logging.
+ *
+ * Can return NULL if there are no parameters in the portal
+ * or the portal is not valid, or the text representations of the parameters are
+ * not available. If returning a non-NULL value, it allocates memory
+ * for the returned string in the current context, and it's the caller's
+ * responsibility to pfree() it if needed.
+ */
+char *
+get_portal_bind_parameters(ParamListInfo params)
+{
+	StringInfoData param_str;
+
+	/* No parameters to format */
+	if (!params || params->numParams == 0)
+		return NULL;
+
+			elog(WARNING, "params->hasTextValues=%d, IsAbortedTransactionBlockState()=%d",
+				           params->hasTextValues && IsAbortedTransactionBlockState());

Err, huh?

This was some debugging, I threw it away now.

Best,
 Alex

On 2019-02-15 15:02, Alexey Bashtanov wrote:

Hello Anders and Peter,

Thanks for your messages.
Please see the new patch version attached.

In my testing, I couldn't get this patch to do anything. Could you
please share your testing steps?

I did

postgres -D data --log-parameters-on-error=on

pgbench -i bench

alter table pgbench_accounts alter column aid type smallint;

pgbench -M extended -S -T 10 bench

This will then error out on type overflows, but I don't see any
parameters being logged:

ERROR: value "62812" is out of range for type smallint
STATEMENT: SELECT abalance FROM pgbench_accounts WHERE aid = $1;

(In this case the error message contains the parameter value, so it's
not a very practical case, but it should work, it seems.)

Meanwhile, I have committed a patch that refactors the ParamListInfo
initialization a bit, so you don't have to initialize hasTextValues in a
bunch of places unrelated to your core code. So please rebase your
patch on that.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Hi Alexey,

On 3/14/19 12:38 PM, Peter Eisentraut wrote:

Meanwhile, I have committed a patch that refactors the ParamListInfo
initialization a bit, so you don't have to initialize hasTextValues in a
bunch of places unrelated to your core code. So please rebase your
patch on that.

It's been two weeks with no new patch or answers to Peter's questions.
Since we are nearly at the end of the CF I'll target this patch for PG13
and mark it Returned with Feedback at the end of the CF if there's no
new patch by then.

Regards,
--
-David
david@pgmasters.net

Hello and sorry for weeks of silence.

Hello Anders and Peter,

Thanks for your messages.
Please see the new patch version attached.

In my testing, I couldn't get this patch to do anything. Could you
please share your testing steps?

Sure. Provided you're in the postgres checkout and you've run make in
src/test/examples/ this should work

CREATE SCHEMA testlibpq3;
SET search_path = testlibpq3;
CREATE TABLE test1_(i int4, t text, b bytea);
INSERT INTO test1_ VALUES(0, '', '');
CREATE VIEW test1 AS SELECT 1/i i, t, b FROM test1_;

-- will log only statement
\! ./src/test/examples/testlibpq3

ALTER SYSTEM SET log_parameters_on_error TO on;
SELECT pg_reload_conf();

-- will log statement with parameters
\! ./src/test/examples/testlibpq3

I did

postgres -D data --log-parameters-on-error=on

pgbench -i bench

alter table pgbench_accounts alter column aid type smallint;

pgbench -M extended -S -T 10 bench

This will then error out on type overflows, but I don't see any
parameters being logged:

ERROR: value "62812" is out of range for type smallint
STATEMENT: SELECT abalance FROM pgbench_accounts WHERE aid = $1;

(In this case the error message contains the parameter value, so it's
not a very practical case, but it should work, it seems.)

I guess this error occurred /while/ binding, so the parameters probably
weren't yet all bound by the time of error reporting.
That's why the error message came without parameters.

Meanwhile, I have committed a patch that refactors the ParamListInfo
initialization a bit, so you don't have to initialize hasTextValues in a
bunch of places unrelated to your core code. So please rebase your
patch on that.

Please find rebased patch attached.

I apologize for no reply before: I first thought my patch was really
faulty and knew I wouldn't have time to fix it these days, but it seems
to me it actually works.

Anyway, I don't suppose you manage to review it within the remaining few
days, so I'll rebase it again in the beginning of the next CF.

Best regards,
  Alexey

On 2019-03-29 15:55, Alexey Bashtanov wrote:

ERROR: value "62812" is out of range for type smallint
STATEMENT: SELECT abalance FROM pgbench_accounts WHERE aid = $1;

(In this case the error message contains the parameter value, so it's
not a very practical case, but it should work, it seems.)

I guess this error occurred /while/ binding, so the parameters probably
weren't yet all bound by the time of error reporting.
That's why the error message came without parameters.

I see. But I think that could be fixed. Change exec_bind_message() to
loop over the parameters twice: once to save them away, once to actually
process them. I think the case of a faulty input value is probably very
common, so it would be confusing if that didn't work.

I think this patch needs some tests. Manually testing it is cumbersome,
and as we are seeing now, it is not quite clear which cases it is
supposed to cover. There are also additional cases for binary
parameters, and there are additions to the CSV output format. We need
tests for all that so the behavior explains itself and doesn't have to
be rediscovered every time someone wants to look at this again.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 05/04/2019 12:23, Peter Eisentraut wrote:

On 2019-03-29 15:55, Alexey Bashtanov wrote:

ERROR: value "62812" is out of range for type smallint
STATEMENT: SELECT abalance FROM pgbench_accounts WHERE aid = $1;

(In this case the error message contains the parameter value, so it's
not a very practical case, but it should work, it seems.)

I guess this error occurred /while/ binding, so the parameters probably
weren't yet all bound by the time of error reporting.
That's why the error message came without parameters.

I see. But I think that could be fixed. Change exec_bind_message() to
loop over the parameters twice: once to save them away, once to actually
process them. I think the case of a faulty input value is probably very
common, so it would be confusing if that didn't work.

I understand this may sound lazy of me, however let me take this risk
and try to explain why I think logging them here in the same fashion
would be inconsistent.

The original feature is intended to log textual representations of
the bind parameter values, whereas the problem suggested to be solved
together with it is verbose logging of the part of the bind message that
failed to get converted to a Datum.

These are equivalent only under the following conditions:
1) the rest of the message was correctly formatted, so we can extract
something for each of the parameter values
2) the values have been passed in text mode
(all of them, not only the one failed to process)
3) the values have been passed in the server encoding

I think it would be a bit of inconsistent to log the parts of the message
only when we are lucky to satisfy the 3 conditions above.

If we are to log bind parameters message parsing and processing problems
more verbosely, what do you think of rather wrapping calls to
OidInputFunctionCall, OidReceiveFunctionCall and pg_client_to_server
into PG_TRY blocks and logging their arguments individually?

In case it doesn't work for any reason, I have an alternative idea on
how to log half-processed parameters.
Instead of hasTextValues store the number of parameters having
their textual representations successfully saved.
This way we will be able, in case of text mode,
save the original value and increment the counter
before the call to OidInputFunctionCall. When logging and not having values
for some parameters, we can print an ellipsis in the log to indicate there's
some more of them missing.

I think this patch needs some tests. Manually testing it is cumbersome,
and as we are seeing now, it is not quite clear which cases it is
supposed to cover. There are also additional cases for binary
parameters, and there are additions to the CSV output format. We need
tests for all that so the behavior explains itself and doesn't have to
be rediscovered every time someone wants to look at this again.

I have added a section into src/test/examples/testlibpq3.c,
please see attached.

As far as I could see these tests never run on "make check" or "make
installcheck",
hence the README change. Please correct me if I'm wrong.

I also failed to find an automatic way to test what actually gets logged
to the server log, at least not in the installcheck case.
I would appreciate if you had any suggestions about it.

Best regards,
  Alex

Please find the rebased patch attached.

Tested like the following.
Provided you're in the postgres checkout and you've run make in
src/test/examples/ and connected to db=postgres:

CREATE SCHEMA testlibpq3;
SET search_path = testlibpq3;
CREATE TABLE test1_(i int4, t text, b bytea);
INSERT INTO test1_ VALUES(0, '', '');
CREATE VIEW test1 AS SELECT 1/i i, t, b FROM test1_;

-- will log only statement
\! ./src/test/examples/testlibpq3

ALTER SYSTEM SET log_parameters_on_error TO on;
SELECT pg_reload_conf();

-- will log statement with parameters
\! ./src/test/examples/testlibpq3

Best regards,
  Alexey

Nice patch, thanks.

I didn't like abusing testlibpq3.c for your new stuff, so I moved it off
to a new file testlibpq5.c. I cleaned up a few other cosmetics things
about this -- v10 attached. I eventually noticed that this patch fails
to initialize each param's textValue to NULL, which probably explains
why you have to be so careful about only setting hasTextValues after the
whole loop. That seems a bit too trusting; I think it would be better
to set all these to NULL in makeParamList instead of leaving the memory
undefined. One way would be to have a for() look in makeParamList that
nullifies the member; another would be to use palloc0().

A third possibility is to inspect each caller of makeParamList and have
them all set textValue to NULL to each parameter.

I'm marking this waiting on author.

--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services