control max length of parameter values logged
Hello
Patch ba79cb5 (for full discussion see [1]/messages/by-id/0146a67b-a22a-0519-9082-bc29756b93a2@imap.cc) introduces a feature to log
bind parameter values on error,
which greatly helps to reproduce errors artificially having only server
log -- thanks everyone who
reviewed and improved it!
However, it cuts the values, as some of the reviewers were worried log
could fill up too quickly.
This applies both to the new case of logging parameter values and to the
existing ones due to
log_min_duration_statement or log_statement.
This is a backwards-incompatible change, and also ruins the idea of
reproducible errors -- sorry Tom
I failed to second this idea [2]/messages/by-id/11425.1575927321@sss.pgh.pa.us in time, before the change was pushed.
I personally don't think that we necessarily need to cut the values, we
can rely on the users
being careful when using this feature -- in the same way we trusted them
use similarly dangerous
log_min_duration_statement and especially log_statement for ages. At
least it's better than having
no option to disable it. Alvaro's opinion was different [3]/messages/by-id/20191209200531.GA19848@alvherre.pgsql. What do you
think
of adding a parameter to limit max logged parameter length? See patch
attached.
Best, Alex
[1]: /messages/by-id/0146a67b-a22a-0519-9082-bc29756b93a2@imap.cc
[2]: /messages/by-id/11425.1575927321@sss.pgh.pa.us
[3]: /messages/by-id/20191209200531.GA19848@alvherre.pgsql
Attachments:
log_parameter_max_length_v001.patchtext/x-patch; charset=UTF-8; name=log_parameter_max_length_v001.patchDownload
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index c1128f89ec..0f40246c2d 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6645,6 +6645,28 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
</listitem>
</varlistentry>
+ <varlistentry id="guc-log-parameter-max-length" xreflabel="log_parameter_max_length">
+ <term><varname>log_parameter_max_length</varname> (<type>boolean</type>)
+ <indexterm>
+ <primary><varname>log_parameter_max_length</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ Controls whether to log parameters in full or cut them to a certain length.
+ Bind parameters can appear in the log as a result of
+ <xref linkend="guc-log-min-duration-statement"/>,
+ <xref linkend="guc-log-statement"/> or
+ <xref linkend="guc-log-parameters-on_error"/>
+ settings.
+ Zero (the default) disables cutting.
+ If this value is specified without units, it is taken as bytes.
+ Due to multibyte character and ellipsis, truncated values may be slightly shorter.
+ Only superusers can change this setting.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry id="guc-log-statement" xreflabel="log_statement">
<term><varname>log_statement</varname> (<type>enum</type>)
<indexterm>
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 0a6f80963b..acc31899d6 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1839,13 +1839,22 @@ exec_bind_message(StringInfo input_message)
if (knownTextValues == NULL)
knownTextValues =
palloc0(numParams * sizeof(char *));
- /*
- * Note: must copy at least two more full characters
- * than BuildParamLogString wants to see; otherwise it
- * might fail to include the ellipsis.
- */
- knownTextValues[paramno] =
- pnstrdup(pstring, 64 + 2 * MAX_MULTIBYTE_CHAR_LEN);
+
+ if (log_parameter_max_length != 0)
+ {
+ /*
+ * Note: must copy at least two more full characters
+ * than BuildParamLogString wants to see;
+ * otherwise it might fail to include the ellipsis.
+ */
+ knownTextValues[paramno] =
+ pnstrdup(pstring,
+ log_parameter_max_length
+ + 2 * MAX_MULTIBYTE_CHAR_LEN);
+ }
+ else
+ knownTextValues[paramno] = pstrdup(pstring);
+
MemoryContextSwitchTo(oldcxt);
}
if (pstring != pbuf.data)
@@ -1908,7 +1917,9 @@ exec_bind_message(StringInfo input_message)
*/
if (log_parameters_on_error)
params->paramValuesStr =
- BuildParamLogString(params, knownTextValues, 64);
+ BuildParamLogString(params,
+ knownTextValues,
+ log_parameter_max_length);
}
else
params = NULL;
@@ -2397,7 +2408,7 @@ errdetail_params(ParamListInfo params)
{
char *str;
- str = BuildParamLogString(params, NULL, 0);
+ str = BuildParamLogString(params, NULL, log_parameter_max_length);
if (str && str[0] != '\0')
errdetail("parameters: %s", str);
}
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 8228e1f390..f27efc6c24 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -543,6 +543,7 @@ int log_min_messages = WARNING;
int client_min_messages = NOTICE;
int log_min_duration_sample = -1;
int log_min_duration_statement = -1;
+int log_parameter_max_length = 0;
int log_temp_files = -1;
double log_statement_sample_rate = 1.0;
double log_xact_sample_rate = 0;
@@ -2834,6 +2835,17 @@ static struct config_int ConfigureNamesInt[] =
NULL, NULL, NULL
},
+ {
+ {"log_parameter_max_length", PGC_SUSET, LOGGING_WHAT,
+ gettext_noop("When logging a parameter value, only log first N bytes."),
+ gettext_noop("Zero to print values in full."),
+ GUC_UNIT_BYTE
+ },
+ &log_parameter_max_length,
+ 0, 0, INT_MAX,
+ NULL, NULL, NULL
+ },
+
{
{"bgwriter_delay", PGC_SIGHUP, RESOURCES_BGWRITER,
gettext_noop("Background writer sleep time between rounds."),
diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h
index ce93ace76c..72ab683ac6 100644
--- a/src/include/utils/guc.h
+++ b/src/include/utils/guc.h
@@ -235,6 +235,7 @@ typedef enum
/* GUC vars that are actually declared in guc.c, rather than elsewhere */
extern bool log_duration;
extern bool log_parameters_on_error;
+extern int log_parameter_max_length;
extern bool Debug_print_plan;
extern bool Debug_print_parse;
extern bool Debug_print_rewritten;
Alexey Bashtanov <bashtanov@imap.cc> writes:
I personally don't think that we necessarily need to cut the values, we
can rely on the users
being careful when using this feature -- in the same way we trusted them
use similarly dangerous
log_min_duration_statement and especially log_statement for ages. At
least it's better than having
no option to disable it. Alvaro's opinion was different [3]. What do you
think
of adding a parameter to limit max logged parameter length? See patch
attached.
This patch is failing to build docs (per the cfbot) and it also fails
check-world because you changed behavior tested by ba79cb5dc's test case.
Attached is an update that hopefully will make the cfbot happy.
I agree that something ought to be done here, but I'm not sure that
this is exactly what. It appears to me that there are three related
but distinct behaviors under discussion:
1. Truncation of bind parameters returned to clients in error message
detail fields.
2. Truncation of bind parameters written to the server log in logged
error messages.
3. Truncation of bind parameters written to the server log in non-error
statement logging actions (log_statement and variants).
Historically we haven't truncated any of these, I believe. As of
ba79cb5dc we forcibly truncate #1 and #2 at 64 bytes, but not #3.
Your patch proposes to provide a SUSET GUC that controls the
truncation length for all 3.
I think that the status quo as of ba79cb5dc is entirely unacceptable,
because there is no recourse if you want to find out why a statement
is failing and the reason is buried in some long parameter string.
However, this patch doesn't really fix it, because it still seems
pretty annoying that you need to be superuser to adjust what gets
sent back to the client. Maybe that isn't a problem in practice
(since the client presumably has the original parameter value laying
about), but it seems conceptually wrong.
On the other hand, that line of reasoning leads to wanting two
separate GUCs (one for #1 and one for the other two), which seems
like overkill, plus it's going to be hard/expensive to have the
outputs for #1 and #2 not be the same.
I do agree that it seems weird and random (not to say 100% backward)
that error cases provide only truncated values but routine query
logging insists on emitting full untruncated values. I should think
that the most common use-cases would want it the other way round.
So I feel like we'd better resolve these definitional questions about
what behavior we actually want. I agree that ba79cb5dc is not
terribly well thought out as it stands.
regards, tom lane
Attachments:
log_parameter_max_length_v2.patchtext/x-diff; charset=us-ascii; name=log_parameter_max_length_v2.patchDownload
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 371d783..b002df5 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6632,6 +6632,24 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
</listitem>
</varlistentry>
+ <varlistentry id="guc-log-parameter-max-length" xreflabel="log_parameter_max_length">
+ <term><varname>log_parameter_max_length</varname> (<type>integer</type>)
+ <indexterm>
+ <primary><varname>log_parameter_max_length</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ If greater than zero, bind parameter values reported in error
+ messages and statement-logging messages are trimmed to no more
+ than this many bytes.
+ If this value is specified without units, it is taken as bytes.
+ Zero (the default) disables trimming.
+ Only superusers can change this setting.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry id="guc-log-statement" xreflabel="log_statement">
<term><varname>log_statement</varname> (<type>enum</type>)
<indexterm>
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 9dba3b0..70ce5bb 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1843,13 +1843,24 @@ exec_bind_message(StringInfo input_message)
if (knownTextValues == NULL)
knownTextValues =
palloc0(numParams * sizeof(char *));
- /*
- * Note: must copy at least two more full characters
- * than BuildParamLogString wants to see; otherwise it
- * might fail to include the ellipsis.
- */
- knownTextValues[paramno] =
- pnstrdup(pstring, 64 + 2 * MAX_MULTIBYTE_CHAR_LEN);
+
+ if (log_parameter_max_length > 0)
+ {
+ /*
+ * 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
+ + 2 * MAX_MULTIBYTE_CHAR_LEN);
+ }
+ else
+ knownTextValues[paramno] = pstrdup(pstring);
+
MemoryContextSwitchTo(oldcxt);
}
if (pstring != pbuf.data)
@@ -1912,7 +1923,9 @@ exec_bind_message(StringInfo input_message)
*/
if (log_parameters_on_error)
params->paramValuesStr =
- BuildParamLogString(params, knownTextValues, 64);
+ BuildParamLogString(params,
+ knownTextValues,
+ log_parameter_max_length);
}
else
params = NULL;
@@ -2401,7 +2414,7 @@ errdetail_params(ParamListInfo params)
{
char *str;
- str = BuildParamLogString(params, NULL, 0);
+ str = BuildParamLogString(params, NULL, log_parameter_max_length);
if (str && str[0] != '\0')
errdetail("parameters: %s", str);
}
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 4c6d648..5749aed 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -544,6 +544,7 @@ int log_min_messages = WARNING;
int client_min_messages = NOTICE;
int log_min_duration_sample = -1;
int log_min_duration_statement = -1;
+int log_parameter_max_length = 0;
int log_temp_files = -1;
double log_statement_sample_rate = 1.0;
double log_xact_sample_rate = 0;
@@ -2836,6 +2837,17 @@ static struct config_int ConfigureNamesInt[] =
},
{
+ {"log_parameter_max_length", PGC_SUSET, LOGGING_WHAT,
+ gettext_noop("Limit logged parameter values to first N bytes."),
+ gettext_noop("Zero to print values in full."),
+ GUC_UNIT_BYTE
+ },
+ &log_parameter_max_length,
+ 0, 0, INT_MAX / 2,
+ NULL, NULL, NULL
+ },
+
+ {
{"bgwriter_delay", PGC_SIGHUP, RESOURCES_BGWRITER,
gettext_noop("Background writer sleep time between rounds."),
NULL,
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index e58e478..e16d63d 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -546,6 +546,8 @@
#log_lock_waits = off # log lock waits >= deadlock_timeout
#log_statement = 'none' # none, ddl, mod, all
#log_parameters_on_error = off # on error log statements with bind parameters
+#log_parameter_max_length = 0 # limit logged parameter values to
+ # N bytes; 0 means print in full
#log_replication_commands = off
#log_temp_files = -1 # log temporary files equal or larger
# than the specified size in kilobytes;
diff --git a/src/bin/pgbench/t/001_pgbench_with_server.pl b/src/bin/pgbench/t/001_pgbench_with_server.pl
index 25ea17f..d146e28 100644
--- a/src/bin/pgbench/t/001_pgbench_with_server.pl
+++ b/src/bin/pgbench/t/001_pgbench_with_server.pl
@@ -271,7 +271,9 @@ COMMIT;
});
# Verify server logging of parameters.
-$node->append_conf('postgresql.conf', "log_parameters_on_error = true");
+$node->append_conf('postgresql.conf',
+ "log_parameters_on_error = true\n" .
+ "log_parameter_max_length = 64");
$node->reload;
pgbench(
'-n -t1 -c1 -M prepared',
@@ -306,8 +308,8 @@ select column1::jsonb from (values (:value), (:long)) as q;
]
});
my $log = TestLib::slurp_file($node->logfile);
-like($log, qr[DETAIL: parameters: \$1 = '\{ invalid ', \$2 = '''Valame Dios!'' dijo Sancho; ''no le dije yo a vuestra merced que mirase bien lo que hacia\?'''],
- "parameter report does not truncate");
+like($log, qr[DETAIL: parameters: \$1 = '\{ invalid ', \$2 = '''Valame Dios!'' dijo Sancho; ''no le dije yo a vuestra merced que \.\.\.'],
+ "parameter report truncates");
$log = undef;
$node->append_conf('postgresql.conf', "log_min_duration_statement = -1");
diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h
index ce93ace..b4186c6 100644
--- a/src/include/utils/guc.h
+++ b/src/include/utils/guc.h
@@ -235,6 +235,7 @@ typedef enum
/* GUC vars that are actually declared in guc.c, rather than elsewhere */
extern bool log_duration;
extern bool log_parameters_on_error;
+extern int log_parameter_max_length;
extern bool Debug_print_plan;
extern bool Debug_print_parse;
extern bool Debug_print_rewritten;
On 2020-Mar-10, Tom Lane wrote:
I agree that something ought to be done here, but I'm not sure that
this is exactly what. It appears to me that there are three related
but distinct behaviors under discussion:1. Truncation of bind parameters returned to clients in error message
detail fields.
2. Truncation of bind parameters written to the server log in logged
error messages.
3. Truncation of bind parameters written to the server log in non-error
statement logging actions (log_statement and variants).Historically we haven't truncated any of these, I believe. As of
ba79cb5dc we forcibly truncate #1 and #2 at 64 bytes, but not #3.
Your patch proposes to provide a SUSET GUC that controls the
truncation length for all 3.
The reason I didn't change the other uses was precisely that it was
established behavior, but my opinion was that truncating them would
be better, now that we have code to handle doing so.
Maybe it would make sense to always log complete parameters for error
cases when that feature is enabled, and have the GUC only control the
lengths logged for non-error cases?
--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Alvaro Herrera <alvherre@2ndquadrant.com> writes:
Maybe it would make sense to always log complete parameters for error
cases when that feature is enabled, and have the GUC only control the
lengths logged for non-error cases?
I could get behind that. It's a bit different from the original
idea here, but I think it's closer to being real-world-useful.
Another way to slice this up would be to have a USERSET GUC that
controls truncation of parameter values in errors, and a separate
SUSET GUC that controls it for the non-error statement logging
cases. I'm not sure how much that's actually worth, but if we
feel that truncation in error cases can be useful, that's how
I'd vote to expose it.
regards, tom lane
On 2020-Mar-11, Tom Lane wrote:
Alvaro Herrera <alvherre@2ndquadrant.com> writes:
Maybe it would make sense to always log complete parameters for error
cases when that feature is enabled, and have the GUC only control the
lengths logged for non-error cases?I could get behind that. It's a bit different from the original
idea here, but I think it's closer to being real-world-useful.Another way to slice this up would be to have a USERSET GUC that
controls truncation of parameter values in errors, and a separate
SUSET GUC that controls it for the non-error statement logging
cases. I'm not sure how much that's actually worth, but if we
feel that truncation in error cases can be useful, that's how
I'd vote to expose it.
Either of these ideas work for me. I think I like the latter more,
since it allows to configure truncation in all cases. (I'm not really
sure I understand why one of them must be SUSET.)
The reason I'm so hot about parameter truncation is that we've seen
cases where customers' log files contain log lines many megabytes long
because of gigantic parameters; UUID arrays with tens of thousands of
entries, and such. Sometimes we see those in the normal "statement"
line because $customer interpolates into the query literal; normally the
"solution" is to move the params from interpolated into a parameter.
But if we log all parameters whole, that workaround no longer works, so
a way to clip is necessary.
I agree that truncating the value that can be disabled while not
truncating the values that cannot be disabled, is a bit silly.
I'm okay with the default being not to clip anything.
--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Alvaro Herrera <alvherre@2ndquadrant.com> writes:
On 2020-Mar-11, Tom Lane wrote:
Another way to slice this up would be to have a USERSET GUC that
controls truncation of parameter values in errors, and a separate
SUSET GUC that controls it for the non-error statement logging
cases. I'm not sure how much that's actually worth, but if we
feel that truncation in error cases can be useful, that's how
I'd vote to expose it.
Either of these ideas work for me. I think I like the latter more,
since it allows to configure truncation in all cases. (I'm not really
sure I understand why one of them must be SUSET.)
We generally suppose that GUCs that control statement logging should be
SUSET, so that unprivileged users don't get to hide their activity from
the log. On the other hand, I think it's okay for error logging (as
opposed to statement tracing) to be under user control, because the user
can simply avoid or trap an error if he doesn't want it to be logged.
The reason I'm so hot about parameter truncation is that we've seen
cases where customers' log files contain log lines many megabytes long
because of gigantic parameters; UUID arrays with tens of thousands of
entries, and such. Sometimes we see those in the normal "statement"
line because $customer interpolates into the query literal; normally the
"solution" is to move the params from interpolated into a parameter.
But if we log all parameters whole, that workaround no longer works, so
a way to clip is necessary.
Agreed, it seems like there's a fairly compelling case for being
able to clip.
I'm okay with the default being not to clip anything.
Also agreed. It's been like it is for a long time with not that
many complaints, so the case for changing the default behavior
seems a bit weak.
Barring other opinions, I think we have consensus here on what
to do. Alexey, will you update your patch?
regards, tom lane
On Thu, Mar 12, 2020 at 12:01:24PM -0400, Tom Lane wrote:
Alvaro Herrera <alvherre@2ndquadrant.com> writes:
The reason I'm so hot about parameter truncation is that we've seen
cases where customers' log files contain log lines many megabytes long
because of gigantic parameters; UUID arrays with tens of thousands of
entries, and such. Sometimes we see those in the normal "statement"
line because $customer interpolates into the query literal; normally the
"solution" is to move the params from interpolated into a parameter.
But if we log all parameters whole, that workaround no longer works, so
a way to clip is necessary.Agreed, it seems like there's a fairly compelling case for being
able to clip.I'm okay with the default being not to clip anything.
Also agreed. It's been like it is for a long time with not that
many complaints, so the case for changing the default behavior
seems a bit weak.Barring other opinions, I think we have consensus here on what
to do. Alexey, will you update your patch?
I am sorry --- I am confused. Why are we truncating or allowing control
of truncation of BIND parameter values, but have no such facility for
queries. Do we assume queries are shorter than BIND parameters, or is
it just that it is easier to trim BIND parameters than values embedded
in non-EXECUTE queries.
--
Bruce Momjian <bruce@momjian.us> https://momjian.us
EnterpriseDB https://enterprisedb.com
+ As you are, so once was I. As I am, so you will be. +
+ Ancient Roman grave inscription +
Bruce Momjian <bruce@momjian.us> writes:
I am sorry --- I am confused. Why are we truncating or allowing control
of truncation of BIND parameter values, but have no such facility for
queries. Do we assume queries are shorter than BIND parameters, or is
it just that it is easier to trim BIND parameters than values embedded
in non-EXECUTE queries.
The cases that Alvaro was worried about were enormous values supplied
via bind parameters. We haven't heard comparable complaints about
the statement text. Also, from a security standpoint, the contents
of the statement text are way more critical than the contents of
an out-of-line parameter; you can't do SQL injection from the latter.
So I think the audience for trimming would be a lot smaller for
statement-text trimming.
regards, tom lane
On 2020-Mar-14, Tom Lane wrote:
Bruce Momjian <bruce@momjian.us> writes:
I am sorry --- I am confused. Why are we truncating or allowing control
of truncation of BIND parameter values, but have no such facility for
queries. Do we assume queries are shorter than BIND parameters, or is
it just that it is easier to trim BIND parameters than values embedded
in non-EXECUTE queries.The cases that Alvaro was worried about were enormous values supplied
via bind parameters. We haven't heard comparable complaints about
the statement text.
To be more precise, I have seen cases of enormous statement text, but
those are fixed precisely by moving the bulk to parameters. So the
ability to trim the parameter is important. I've never seen a very
large query without the bulk being parameterizable.
Also, from a security standpoint, the contents
of the statement text are way more critical than the contents of
an out-of-line parameter; you can't do SQL injection from the latter.
That's a good point too.
So I think the audience for trimming would be a lot smaller for
statement-text trimming.
Nod. (I think if we really wanted to trim queries, it would have to be
something semantically sensible, not just trim whatever is at the end of
the statement literal. Say, only trim parts of the where clause that
are of the form "something op constant", and rules like that, plus put
placeholders to show that they were there. This sounds a lot of work to
figure out usefully ...)
--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Hi,
BIND parameter truncation is good to me.
Logs could be very hard to read due to
the very long parameters recorded.
Now, parameter is extracuted from left.
e.g. "AAAA-BBBB-CCCC-DDDD-EEEE" to "AAAA-BBBB-CCCC..."
Is not necessary from right?
e.g. "AAAA-BBBB-CCCC-DDDD-EEEE" to "...CCCC-DDDD-EEEE"
It is sometimes nice to be able to check
the last of strings. For example, if there
are difference only in the last of strings
of many parameters.
Best Regards,
Keisuke Kuroda
On Sun, Mar 15, 2020 at 08:48:33PM -0300, Alvaro Herrera wrote:
On 2020-Mar-14, Tom Lane wrote:
Bruce Momjian <bruce@momjian.us> writes:
I am sorry --- I am confused. Why are we truncating or allowing control
of truncation of BIND parameter values, but have no such facility for
queries. Do we assume queries are shorter than BIND parameters, or is
it just that it is easier to trim BIND parameters than values embedded
in non-EXECUTE queries.The cases that Alvaro was worried about were enormous values supplied
via bind parameters. We haven't heard comparable complaints about
the statement text.To be more precise, I have seen cases of enormous statement text, but
those are fixed precisely by moving the bulk to parameters. So the
ability to trim the parameter is important. I've never seen a very
large query without the bulk being parameterizable.
I don't claim our use is a common case or a good example but I'm going to offer
a data point.
We have very long query strings, even while using bind parameters.
Our loader process uses upsert and prepared statements.
So we might run: INSERT INTO t (k1,k2,a,b,...) VALUES($1,$2,$3,$4)
ON CONFLICT(k1,k2) DO UPDATE SET a=excluded.a,b=excluded.b
..which is fine, but we also have large number of columns - historically up to
1600. If a query fails, the error might be a query string 2+ pages long.
Looks like we have common cases (and executed many times) with:
24k long message and 86k long param string
70k long message and 10k long param string
Having full log on error is important, more to the client but also in the
server log. But it would be nice if we could reduce the server logs. Most of
the prepare string is of little value if there's no error: VALUES ($1,$2,$3,)
(but prepared query is at least better than repeating the query string).
Related: a year ago, I wrote about the repetition of the "PREPARE" statement in
query logs.
/messages/by-id/20190208132953.GF29720@telsasoft.com
Ultimately I withdrew that patch and switched to log_statement_min_duration.
Nod. (I think if we really wanted to trim queries, it would have to be
something semantically sensible, not just trim whatever is at the end of
the statement literal.
If it were easy, I would truncate query strings to a few hundred bytes.
--
Justin
Also agreed. It's been like it is for a long time with not that
many complaints, so the case for changing the default behavior
seems a bit weak.Barring other opinions, I think we have consensus here on what
to do. Alexey, will you update your patch?
Sorry for the delay, please could you have a look?
Best, Alex
Attachments:
log_parameter_max_length_v3.patchtext/x-patch; charset=UTF-8; name=log_parameter_max_length_v3.patchDownload
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 2de21903a1..35d420e026 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6713,6 +6713,38 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
</listitem>
</varlistentry>
+ <varlistentry id="guc-log-parameter-max-length" xreflabel="log_parameter_max_length">
+ <term><varname>log_parameter_max_length</varname> (<type>integer</type>)
+ <indexterm>
+ <primary><varname>log_parameter_max_length</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ If greater than zero, bind parameter values reported in non-error
+ statement-logging messages are trimmed to no more than this many bytes.
+ If this value is specified without units, it is taken as bytes.
+ Zero (the default) disables trimming. Only superusers can change this setting.
+ </para>
+ </listitem>
+ </varlistentry>
+
+ <varlistentry id="guc-log-parameter-max-length-on-error" xreflabel="log_parameter_max_length_on_error">
+ <term><varname>log_parameter_max_length_on_error</varname> (<type>integer</type>)
+ <indexterm>
+ <primary><varname>log_parameter_max_length_on_error</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ If greater than zero, bind parameter values reported in error messages
+ are trimmed to no more than this many bytes.
+ If this value is specified without units, it is taken as bytes.
+ Zero (the default) disables trimming.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry id="guc-log-statement" xreflabel="log_statement">
<term><varname>log_statement</varname> (<type>enum</type>)
<indexterm>
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 5b677863b9..ea2fe17e0b 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1846,13 +1846,24 @@ exec_bind_message(StringInfo input_message)
if (knownTextValues == NULL)
knownTextValues =
palloc0(numParams * sizeof(char *));
- /*
- * Note: must copy at least two more full characters
- * than BuildParamLogString wants to see; otherwise it
- * might fail to include the ellipsis.
- */
- knownTextValues[paramno] =
- pnstrdup(pstring, 64 + 2 * MAX_MULTIBYTE_CHAR_LEN);
+
+ if (log_parameter_max_length_on_error > 0)
+ {
+ /*
+ * 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);
+ }
+ else
+ knownTextValues[paramno] = pstrdup(pstring);
+
MemoryContextSwitchTo(oldcxt);
}
if (pstring != pbuf.data)
@@ -1915,7 +1926,9 @@ exec_bind_message(StringInfo input_message)
*/
if (log_parameters_on_error)
params->paramValuesStr =
- BuildParamLogString(params, knownTextValues, 64);
+ BuildParamLogString(params,
+ knownTextValues,
+ log_parameter_max_length_on_error);
}
else
params = NULL;
@@ -2404,7 +2417,7 @@ errdetail_params(ParamListInfo params)
{
char *str;
- str = BuildParamLogString(params, NULL, 0);
+ str = BuildParamLogString(params, NULL, log_parameter_max_length);
if (str && str[0] != '\0')
errdetail("parameters: %s", str);
}
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 79bc7ac8ca..a3903d1b16 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -544,6 +544,8 @@ int log_min_messages = WARNING;
int client_min_messages = NOTICE;
int log_min_duration_sample = -1;
int log_min_duration_statement = -1;
+int log_parameter_max_length = 0;
+int log_parameter_max_length_on_error = 0;
int log_temp_files = -1;
double log_statement_sample_rate = 1.0;
double log_xact_sample_rate = 0;
@@ -2855,6 +2857,28 @@ static struct config_int ConfigureNamesInt[] =
NULL, NULL, NULL
},
+ {
+ {"log_parameter_max_length", PGC_SUSET, LOGGING_WHAT,
+ gettext_noop("When logging statements, limit logged parameter values to first N bytes."),
+ gettext_noop("Zero to print values in full."),
+ GUC_UNIT_BYTE
+ },
+ &log_parameter_max_length,
+ 0, 0, INT_MAX / 2,
+ NULL, NULL, NULL
+ },
+
+ {
+ {"log_parameter_max_length_on_error", PGC_USERSET, LOGGING_WHAT,
+ gettext_noop("When reporting an error, limit logged parameter values to first N bytes."),
+ gettext_noop("Zero to print values in full."),
+ GUC_UNIT_BYTE
+ },
+ &log_parameter_max_length_on_error,
+ 0, 0, INT_MAX / 2,
+ NULL, NULL, NULL
+ },
+
{
{"bgwriter_delay", PGC_SIGHUP, RESOURCES_BGWRITER,
gettext_noop("Background writer sleep time between rounds."),
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index e9f8ca775d..8899f174c7 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -546,6 +546,10 @@
#log_lock_waits = off # log lock waits >= deadlock_timeout
#log_statement = 'none' # none, ddl, mod, all
#log_parameters_on_error = off # on error log statements with bind parameters
+#log_parameter_max_length = 0 # when logging statements, limit logged
+ # parameter values to N bytes; 0 means print in full
+#log_parameter_max_length_on_error = 0 # when logging an error limit logged
+ # parameter values to N bytes; 0 means print in full
#log_replication_commands = off
#log_temp_files = -1 # log temporary files equal or larger
# than the specified size in kilobytes;
diff --git a/src/bin/pgbench/t/001_pgbench_with_server.pl b/src/bin/pgbench/t/001_pgbench_with_server.pl
index 25ea17f7d1..1dbdb798c3 100644
--- a/src/bin/pgbench/t/001_pgbench_with_server.pl
+++ b/src/bin/pgbench/t/001_pgbench_with_server.pl
@@ -271,7 +271,10 @@ COMMIT;
});
# Verify server logging of parameters.
-$node->append_conf('postgresql.conf', "log_parameters_on_error = true");
+$node->append_conf('postgresql.conf',
+ "log_parameters_on_error = true\n" .
+ "log_parameter_max_length = 0\n" .
+ "log_parameter_max_length_on_error = 64");
$node->reload;
pgbench(
'-n -t1 -c1 -M prepared',
@@ -287,7 +290,6 @@ pgbench(
SELECT 1 / (random() / 2)::int, :one::int, :two::int;
}
});
-
$node->append_conf('postgresql.conf', "log_min_duration_statement = 0");
$node->reload;
pgbench(
@@ -310,7 +312,52 @@ like($log, qr[DETAIL: parameters: \$1 = '\{ invalid ', \$2 = '''Valame Dios!''
"parameter report does not truncate");
$log = undef;
-$node->append_conf('postgresql.conf', "log_min_duration_statement = -1");
+$node->append_conf('postgresql.conf',
+ "log_min_duration_statement = -1\n" .
+ "log_parameter_max_length = 7\n" .
+ "log_parameter_max_length_on_error = 0");
+$node->reload;
+pgbench(
+ '-n -t1 -c1 -M prepared',
+ 2,
+ [],
+ [
+ qr{ERROR: division by zero},
+ qr{CONTEXT: extended query with parameters: \$1 = '1', \$2 = NULL}
+ ],
+ 'server parameter logging',
+ {
+ '001_param_3' => q{select '1' as one \gset
+SELECT 1 / (random() / 2)::int, :one::int, :two::int;
+}
+ });
+
+$node->append_conf('postgresql.conf', "log_min_duration_statement = 0");
+$node->reload;
+pgbench(
+ '-n -t1 -c1 -M prepared',
+ 2,
+ [],
+ [
+ qr{ERROR: invalid input syntax for type json},
+ qr[CONTEXT: JSON data, line 1: \{ invalid\.\.\.[\r\n]+extended query with parameters: \$1 = '\{ invalid ', \$2 = '''Valame Dios!'' dijo Sancho; ''no le dije yo a vuestra merced que mirase bien lo que hacia\?']m
+ ],
+ 'server parameter logging',
+ {
+ '001_param_4' => q[select '{ invalid ' as value \gset
+select $$'Valame Dios!' dijo Sancho; 'no le dije yo a vuestra merced que mirase bien lo que hacia?'$$ as long \gset
+select column1::jsonb from (values (:value), (:long)) as q;
+]
+ });
+$log = TestLib::slurp_file($node->logfile);
+like($log, qr[DETAIL: parameters: \$1 = '\{ inval\.\.\.', \$2 = '''Valame\.\.\.'],
+ "parameter report truncates");
+$log = undef;
+
+$node->append_conf('postgresql.conf',
+ "log_parameter_max_length = 0\n" .
+ "log_min_duration_statement = -1\n" .
+ "log_parameters_on_error = false");
$node->reload;
# test expressions
diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h
index ce93ace76c..e314552cb8 100644
--- a/src/include/utils/guc.h
+++ b/src/include/utils/guc.h
@@ -235,6 +235,8 @@ typedef enum
/* GUC vars that are actually declared in guc.c, rather than elsewhere */
extern bool log_duration;
extern bool log_parameters_on_error;
+extern int log_parameter_max_length;
+extern int log_parameter_max_length_on_error;
extern bool Debug_print_plan;
extern bool Debug_print_parse;
extern bool Debug_print_rewritten;
Alexey Bashtanov <bashtanov@imap.cc> writes:
Sorry for the delay, please could you have a look?
Got it, will look tomorrow. (I think it's important to get this
done for v13, before we ship this behavior.)
regards, tom lane
Hi,
On Wed, Apr 01, 2020 at 01:52:48AM +0100, Alexey Bashtanov wrote:
+++ b/doc/src/sgml/config.sgml + <varlistentry id="guc-log-parameter-max-length" xreflabel="log_parameter_max_length"> + <term><varname>log_parameter_max_length</varname> (<type>integer</type>) + <indexterm> + <primary><varname>log_parameter_max_length</varname> configuration parameter</primary> + </indexterm> + </term> + <listitem> + <para> + If greater than zero, bind parameter values reported in non-error + statement-logging messages are trimmed to no more than this many bytes.
Can I suggest to say:
"Limit bind parameter values reported by non-error statement-logging messages
to this many bytes". Or,
"The maximum length of bind parameter values to log with non-error
statement-logging messages".
--- a/src/backend/utils/misc/guc.c +++ b/src/backend/utils/misc/guc.c @@ -2855,6 +2857,28 @@ static struct config_int ConfigureNamesInt[] = NULL, NULL, NULL },+ { + {"log_parameter_max_length", PGC_SUSET, LOGGING_WHAT, + gettext_noop("When logging statements, limit logged parameter values to first N bytes."), + gettext_noop("Zero to print values in full."),
Could you make zero a normal value and -1 the "special" value to disable
trimming ?
Setting to zero will avoid displaying parameters at all, setting to -1 wil
display values in full.
Cheers,
--
Justin
Hi,
+ If greater than zero, bind parameter values reported in non-error + statement-logging messages are trimmed to no more than this many bytes.Can I suggest to say:
"Limit bind parameter values reported by non-error statement-logging messages
to this many bytes". Or,"The maximum length of bind parameter values to log with non-error
statement-logging messages".
Okay I'll rephrase.
Could you make zero a normal value and -1 the "special" value to disable
trimming ?Setting to zero will avoid displaying parameters at all, setting to -1 wil
display values in full.
I can, but then for the sake of consistency I'll have to do the same for
log_parameter_max_length.
Then we'll end up with two ways to enable/disable parameter logging on
error:
using the primary boolean setting and setting length to 0.
One of them will require superuser privileges, the other one won't.
Do you think it's okay? I have no objections but I'm a bit worried
someone may find it clumsy.
Best, Alex
On Wed, Apr 01, 2020 at 10:10:55AM +0100, Alexey Bashtanov wrote:
Hi,
+ If greater than zero, bind parameter values reported in non-error + statement-logging messages are trimmed to no more than this many bytes.Can I suggest to say:
"Limit bind parameter values reported by non-error statement-logging messages
to this many bytes". Or,"The maximum length of bind parameter values to log with non-error
statement-logging messages".Okay I'll rephrase.
Could you make zero a normal value and -1 the "special" value to disable
trimming ?Setting to zero will avoid displaying parameters at all, setting to -1 wil
display values in full.I can, but then for the sake of consistency I'll have to do the same for
log_parameter_max_length.
Then we'll end up with two ways to enable/disable parameter logging on
error:
using the primary boolean setting and setting length to 0.
One of them will require superuser privileges, the other one won't.
I guess you're referring to log_parameters_on_error.
Does it have to be SUSET ?
Or maybe log_parameters_on_error doesn't need to exist at all, and setting
log_parameter_max_length=0 can be used to disable parameter logging.
I showed up late to this thread, so let's see what others think.
--
Justin
Justin Pryzby <pryzby@telsasoft.com> writes:
On Wed, Apr 01, 2020 at 10:10:55AM +0100, Alexey Bashtanov wrote:
Could you make zero a normal value and -1 the "special" value to disable
trimming ?
I can, but then for the sake of consistency I'll have to do the same for
log_parameter_max_length.
Then we'll end up with two ways to enable/disable parameter logging on
error:
using the primary boolean setting and setting length to 0.
One of them will require superuser privileges, the other one won't.
I guess you're referring to log_parameters_on_error.
Does it have to be SUSET ?
Or maybe log_parameters_on_error doesn't need to exist at all, and setting
log_parameter_max_length=0 can be used to disable parameter logging.
I showed up late to this thread, so let's see what others think.
I think Justin's got a point: defining zero this way is weirdly
inconsistent. -1, being clearly outside the domain of possible
length limits, makes more sense as a marker for "don't trim".
Alexey's right that having a separate boolean flag is pointless, but
I think we could just drop the boolean; we haven't shipped that yet.
The privilege argument seems irrelevant to me. We already decided
that the plan is (a) SUSET for non-error statement logging purposes and
(b) USERSET for logging caused by errors, and that would have to apply
to length limits as well as enable/disable ability. Otherwise a user
could pretty effectively disable logging by setting the length to 1.
regards, tom lane
Hi,
The privilege argument seems irrelevant to me. We already decided
that the plan is (a) SUSET for non-error statement logging purposes and
(b) USERSET for logging caused by errors, and that would have to apply
to length limits as well as enable/disable ability. Otherwise a user
could pretty effectively disable logging by setting the length to 1.
The only privilege that user can gain if we drop the boolean is to
*enable* logging parameters on error.
That gives user a little bit easier way to fill up the disk with logs,
but they anyway can do that if they want to.
If that's okay with everyone, please see the new version attached.
Best, Alex
Attachments:
log_parameter_max_length_v4.patchtext/x-patch; charset=UTF-8; name=log_parameter_max_length_v4.patchDownload
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 2de21903a1..3d7db57d74 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6690,29 +6690,48 @@ 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>)
+ <varlistentry id="guc-log-parameter-max-length" xreflabel="log_parameter_max_length">
+ <term><varname>log_parameter_max_length</varname> (<type>integer</type>)
<indexterm>
- <primary><varname>log_parameters_on_error</varname> configuration parameter</primary>
+ <primary><varname>log_parameter_max_length</varname> configuration parameter</primary>
</indexterm>
</term>
<listitem>
<para>
- Controls whether bind parameters are logged when a statement is logged
- as a result of <xref linkend="guc-log-min-error-statement"/>.
- It adds some overhead, as <productname>PostgreSQL</productname> will
- compute and store textual representations of parameter values in
- memory for all statements, even if they eventually do not get logged.
- This setting has no effect on statements logged due to
- <xref linkend="guc-log-min-duration-statement"/> or
- <xref linkend="guc-log-statement"/> settings, as they are always logged
- with parameters.
- The default is <literal>off</literal>.
+ If greater than zero, bind parameter values reported in non-error
+ statement-logging messages are trimmed to no more than this many bytes.
+ If this value is specified without units, it is taken as bytes.
+ Zero disables logging parameters with statements.
+ <literal>-1</literal> (the default) makes parameters logged in full.
Only superusers can change this setting.
</para>
</listitem>
</varlistentry>
+ <varlistentry id="guc-log-parameter-max-length-on-error" xreflabel="log_parameter_max_length_on_error">
+ <term><varname>log_parameter_max_length_on_error</varname> (<type>integer</type>)
+ <indexterm>
+ <primary><varname>log_parameter_max_length_on_error</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ If greater than zero, bind parameter values reported in error messages
+ are trimmed to no more than this many bytes.
+ If this value is specified without units, it is taken as bytes.
+ Zero (the default) disables logging parameters on error.
+ <literal>-1</literal> makes parameters logged in full.
+
+ This setting only affects statements logged as a result of
+ <xref linkend="guc-log-min-error-statement"/>.
+ Non-zero values add some overhead, as
+ <productname>PostgreSQL</productname> will compute and store textual
+ representations of parameter values in memory for all statements,
+ even if they eventually do not get logged.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry id="guc-log-statement" xreflabel="log_statement">
<term><varname>log_statement</varname> (<type>enum</type>)
<indexterm>
diff --git a/src/backend/nodes/params.c b/src/backend/nodes/params.c
index a57f9eea76..77328e17ff 100644
--- a/src/backend/nodes/params.c
+++ b/src/backend/nodes/params.c
@@ -269,7 +269,7 @@ RestoreParamList(char **start_address)
* can contain NULLs for any unknown individual values. NULL can be given if
* no parameters are known.
*
- * If maxlen is not zero, that's the maximum number of bytes of any one
+ * If maxlen is not -1, that's the maximum number of bytes of any one
* parameter value to be printed; an ellipsis is added if the string is
* longer. (Added quotes are not considered in this calculation.)
*/
@@ -280,6 +280,7 @@ BuildParamLogString(ParamListInfo params, char **knownTextValues, int maxlen)
oldCxt;
StringInfoData buf;
+ Assert(maxlen == -1 || maxlen > 0);
/*
* NB: think not of returning params->paramValuesStr! It may have been
* generated with a different maxlen, and so be unsuitable. Besides that,
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 5b677863b9..cbe4907e61 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1838,7 +1838,7 @@ exec_bind_message(StringInfo input_message)
*/
if (pstring)
{
- if (log_parameters_on_error)
+ if (log_parameter_max_length_on_error != 0)
{
MemoryContext oldcxt;
@@ -1846,13 +1846,24 @@ exec_bind_message(StringInfo input_message)
if (knownTextValues == NULL)
knownTextValues =
palloc0(numParams * sizeof(char *));
- /*
- * Note: must copy at least two more full characters
- * than BuildParamLogString wants to see; otherwise it
- * might fail to include the ellipsis.
- */
- knownTextValues[paramno] =
- pnstrdup(pstring, 64 + 2 * MAX_MULTIBYTE_CHAR_LEN);
+
+ if (log_parameter_max_length_on_error > 0)
+ {
+ /*
+ * 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);
+ }
+ else
+ knownTextValues[paramno] = pstrdup(pstring);
+
MemoryContextSwitchTo(oldcxt);
}
if (pstring != pbuf.data)
@@ -1913,9 +1924,11 @@ exec_bind_message(StringInfo input_message)
* errors, if configured to do so. (This is saved in the portal, so
* that they'll appear when the query is executed later.)
*/
- if (log_parameters_on_error)
+ if (log_parameter_max_length_on_error != 0)
params->paramValuesStr =
- BuildParamLogString(params, knownTextValues, 64);
+ BuildParamLogString(params,
+ knownTextValues,
+ log_parameter_max_length_on_error);
}
else
params = NULL;
@@ -2400,11 +2413,11 @@ errdetail_execute(List *raw_parsetree_list)
static int
errdetail_params(ParamListInfo params)
{
- if (params && params->numParams > 0)
+ if (log_parameter_max_length != 0 && params && params->numParams > 0)
{
char *str;
- str = BuildParamLogString(params, NULL, 0);
+ str = BuildParamLogString(params, NULL, log_parameter_max_length);
if (str && str[0] != '\0')
errdetail("parameters: %s", str);
}
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 79bc7ac8ca..538d940895 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -515,7 +515,6 @@ extern const struct config_enum_entry dynamic_shared_memory_options[];
* GUC option variables that are exported from this module
*/
bool log_duration = false;
-bool log_parameters_on_error = false;
bool Debug_print_plan = false;
bool Debug_print_parse = false;
bool Debug_print_rewritten = false;
@@ -544,6 +543,8 @@ int log_min_messages = WARNING;
int client_min_messages = NOTICE;
int log_min_duration_sample = -1;
int log_min_duration_statement = -1;
+int log_parameter_max_length = 0;
+int log_parameter_max_length_on_error = 0;
int log_temp_files = -1;
double log_statement_sample_rate = 1.0;
double log_xact_sample_rate = 0;
@@ -1381,15 +1382,6 @@ static struct config_bool ConfigureNamesBool[] =
false,
NULL, NULL, NULL
},
- {
- {"log_parameters_on_error", PGC_SUSET, LOGGING_WHAT,
- gettext_noop("Logs bind parameters of the logged statements where possible."),
- NULL
- },
- &log_parameters_on_error,
- false,
- NULL, NULL, NULL
- },
{
{"debug_print_parse", PGC_USERSET, LOGGING_WHAT,
gettext_noop("Logs each query's parse tree."),
@@ -2855,6 +2847,28 @@ static struct config_int ConfigureNamesInt[] =
NULL, NULL, NULL
},
+ {
+ {"log_parameter_max_length", PGC_SUSET, LOGGING_WHAT,
+ gettext_noop("When logging statements, limit logged parameter values to first N bytes."),
+ gettext_noop("Zero to print values in full."),
+ GUC_UNIT_BYTE
+ },
+ &log_parameter_max_length,
+ -1, -1, INT_MAX / 2,
+ NULL, NULL, NULL
+ },
+
+ {
+ {"log_parameter_max_length_on_error", PGC_USERSET, LOGGING_WHAT,
+ gettext_noop("When reporting an error, limit logged parameter values to first N bytes."),
+ gettext_noop("Zero to print values in full."),
+ GUC_UNIT_BYTE
+ },
+ &log_parameter_max_length_on_error,
+ 0, -1, INT_MAX / 2,
+ NULL, NULL, NULL
+ },
+
{
{"bgwriter_delay", PGC_SIGHUP, RESOURCES_BGWRITER,
gettext_noop("Background writer sleep time between rounds."),
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index e9f8ca775d..8c26ac90d1 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -545,7 +545,12 @@
# e.g. '<%u%%%d> '
#log_lock_waits = off # log lock waits >= deadlock_timeout
#log_statement = 'none' # none, ddl, mod, all
-#log_parameters_on_error = off # on error log statements with bind parameters
+#log_parameter_max_length = -1 # when logging statements, limit logged
+ # parameter values to N bytes;
+ # -1 means print in full, 0 to disable
+#log_parameter_max_length_on_error = 0 # when logging an error, limit logged
+ # parameter values to N bytes;
+ # -1 means print in full, 0 to disable
#log_replication_commands = off
#log_temp_files = -1 # log temporary files equal or larger
# than the specified size in kilobytes;
diff --git a/src/bin/pgbench/t/001_pgbench_with_server.pl b/src/bin/pgbench/t/001_pgbench_with_server.pl
index 25ea17f7d1..b7eb37d65d 100644
--- a/src/bin/pgbench/t/001_pgbench_with_server.pl
+++ b/src/bin/pgbench/t/001_pgbench_with_server.pl
@@ -271,7 +271,35 @@ COMMIT;
});
# Verify server logging of parameters.
-$node->append_conf('postgresql.conf', "log_parameters_on_error = true");
+# 1. Logging neither with errors nor with statements
+$node->append_conf('postgresql.conf',
+ "log_min_duration_statement = 0\n" .
+ "log_parameter_max_length = 0\n" .
+ "log_parameter_max_length_on_error = 0");
+$node->reload;
+pgbench(
+ '-n -t1 -c1 -M prepared',
+ 2,
+ [],
+ [
+ qr{ERROR: invalid input syntax for type json},
+ qr{(?!extended query with parameters)}
+ ],
+ 'server parameter logging',
+ {
+ '001_param_1' => q[select '{ invalid ' as value \gset
+select $$'Valame Dios!' dijo Sancho; 'no le dije yo a vuestra merced que mirase bien lo que hacia?'$$ as long \gset
+select column1::jsonb from (values (:value), (:long)) as q;
+]
+ });
+my $log = TestLib::slurp_file($node->logfile);
+unlike($log, qr[DETAIL: parameters: \$1 = '\{ invalid ',], "no parameters logged");
+$log = undef;
+
+# 2. Logging truncated parameters on error, full with statements
+$node->append_conf('postgresql.conf',
+ "log_parameter_max_length = -1\n" .
+ "log_parameter_max_length_on_error = 64");
$node->reload;
pgbench(
'-n -t1 -c1 -M prepared',
@@ -283,11 +311,10 @@ pgbench(
],
'server parameter logging',
{
- '001_param_1' => q{select '1' as one \gset
+ '001_param_2' => q{select '1' as one \gset
SELECT 1 / (random() / 2)::int, :one::int, :two::int;
}
});
-
$node->append_conf('postgresql.conf', "log_min_duration_statement = 0");
$node->reload;
pgbench(
@@ -300,17 +327,64 @@ pgbench(
],
'server parameter logging',
{
- '001_param_2' => q[select '{ invalid ' as value \gset
+ '001_param_3' => q[select '{ invalid ' as value \gset
select $$'Valame Dios!' dijo Sancho; 'no le dije yo a vuestra merced que mirase bien lo que hacia?'$$ as long \gset
select column1::jsonb from (values (:value), (:long)) as q;
]
});
-my $log = TestLib::slurp_file($node->logfile);
+$log = TestLib::slurp_file($node->logfile);
like($log, qr[DETAIL: parameters: \$1 = '\{ invalid ', \$2 = '''Valame Dios!'' dijo Sancho; ''no le dije yo a vuestra merced que mirase bien lo que hacia\?'''],
"parameter report does not truncate");
$log = undef;
-$node->append_conf('postgresql.conf', "log_min_duration_statement = -1");
+# 3. Logging full parameters on error, truncated with statements
+$node->append_conf('postgresql.conf',
+ "log_min_duration_statement = -1\n" .
+ "log_parameter_max_length = 7\n" .
+ "log_parameter_max_length_on_error = -1");
+$node->reload;
+pgbench(
+ '-n -t1 -c1 -M prepared',
+ 2,
+ [],
+ [
+ qr{ERROR: division by zero},
+ qr{CONTEXT: extended query with parameters: \$1 = '1', \$2 = NULL}
+ ],
+ 'server parameter logging',
+ {
+ '001_param_4' => q{select '1' as one \gset
+SELECT 1 / (random() / 2)::int, :one::int, :two::int;
+}
+ });
+
+$node->append_conf('postgresql.conf', "log_min_duration_statement = 0");
+$node->reload;
+pgbench(
+ '-n -t1 -c1 -M prepared',
+ 2,
+ [],
+ [
+ qr{ERROR: invalid input syntax for type json},
+ qr[CONTEXT: JSON data, line 1: \{ invalid\.\.\.[\r\n]+extended query with parameters: \$1 = '\{ invalid ', \$2 = '''Valame Dios!'' dijo Sancho; ''no le dije yo a vuestra merced que mirase bien lo que hacia\?']m
+ ],
+ 'server parameter logging',
+ {
+ '001_param_5' => q[select '{ invalid ' as value \gset
+select $$'Valame Dios!' dijo Sancho; 'no le dije yo a vuestra merced que mirase bien lo que hacia?'$$ as long \gset
+select column1::jsonb from (values (:value), (:long)) as q;
+]
+ });
+$log = TestLib::slurp_file($node->logfile);
+like($log, qr[DETAIL: parameters: \$1 = '\{ inval\.\.\.', \$2 = '''Valame\.\.\.'],
+ "parameter report truncates");
+$log = undef;
+
+# 3. Restore config
+$node->append_conf('postgresql.conf',
+ "log_min_duration_statement = -1\n" .
+ "log_parameter_max_length_on_error = 0\n" .
+ "log_parameter_max_length = -1");
$node->reload;
# test expressions
diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h
index ce93ace76c..a375914440 100644
--- a/src/include/utils/guc.h
+++ b/src/include/utils/guc.h
@@ -234,7 +234,8 @@ typedef enum
/* GUC vars that are actually declared in guc.c, rather than elsewhere */
extern bool log_duration;
-extern bool log_parameters_on_error;
+extern int log_parameter_max_length;
+extern int log_parameter_max_length_on_error;
extern bool Debug_print_plan;
extern bool Debug_print_parse;
extern bool Debug_print_rewritten;
Thanks for updating the patch.
On Thu, Apr 02, 2020 at 01:29:04AM +0100, Alexey Bashtanov wrote:
+ If greater than zero, bind parameter values reported in non-error + statement-logging messages are trimmed to no more than this many bytes. + If this value is specified without units, it is taken as bytes. + Zero disables logging parameters with statements. + <literal>-1</literal> (the default) makes parameters logged in full.
say: "..causes parameters to be logged in full".
Also..I just realized that this truncates *each* parameter, rather than
truncating the parameter list.
So say: "
|If greater than zero, each bind parameter value reported in a non-error
|statement-logging messages is trimmed to no more than this number of bytes.
+ Non-zero values add some overhead, as + <productname>PostgreSQL</productname> will compute and store textual + representations of parameter values in memory for all statements, + even if they eventually do not get logged.
say: "even if they are ultimately not logged"
+++ b/src/backend/nodes/params.c @@ -280,6 +280,7 @@ BuildParamLogString(ParamListInfo params, char **knownTextValues, int maxlen) oldCxt; StringInfoData buf;+ Assert(maxlen == -1 || maxlen > 0);
You can write: >= -1
- if (log_parameters_on_error) + if (log_parameter_max_length_on_error != 0)
I would write this as >= 0
+ if (log_parameter_max_length_on_error > 0) + { + /* + * 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);
The comment says we need at least 2 chars, but
log_parameter_max_length_on_error might be 1, so I think you can either add 64
byte fudge factor, like before, or do Max(log_parameter_max_length_on_error, 2).
+ } + else + knownTextValues[paramno] = pstrdup(pstring);
I suggest to handle the "== -1" case first and the > 0 case as "else".
Thanks,
--
Justin
Hi,
Please see the new version attached.
+ If greater than zero, bind parameter values reported in non-error + statement-logging messages are trimmed to no more than this many bytes. + If this value is specified without units, it is taken as bytes. + Zero disables logging parameters with statements. + <literal>-1</literal> (the default) makes parameters logged in full.say: "..causes parameters to be logged in full".
Also..I just realized that this truncates *each* parameter, rather than
truncating the parameter list.So say: "
|If greater than zero, each bind parameter value reported in a non-error
|statement-logging messages is trimmed to no more than this number of bytes.
okay
I also changed "trimmed to no more than this many bytes" to "trimmed to
this many bytes".
It's not that pedantic any more but hopefully less awkward.
+ Non-zero values add some overhead, as + <productname>PostgreSQL</productname> will compute and store textual + representations of parameter values in memory for all statements, + even if they eventually do not get logged.say: "even if they are ultimately not logged"
okay
+++ b/src/backend/nodes/params.c @@ -280,6 +280,7 @@ BuildParamLogString(ParamListInfo params, char **knownTextValues, int maxlen) oldCxt; StringInfoData buf;+ Assert(maxlen == -1 || maxlen > 0);
You can write: >= -1
no, I'm specifically checking they don't pass 0
- if (log_parameters_on_error) + if (log_parameter_max_length_on_error != 0)I would write this as >= 0
no, I'm specifically checking for both positives and -1
+ if (log_parameter_max_length_on_error > 0) + { + /* + * 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);The comment says we need at least 2 chars, but
log_parameter_max_length_on_error might be 1, so I think you can either add 64
byte fudge factor, like before, or do Max(log_parameter_max_length_on_error, 2).
That's the code I reused without deep analysis TBH.
I think it's mostly for to allocate the space for the ellipsis in case
it needs to be added,
not to copy any actual characters, that's why we add.
+ } + else + knownTextValues[paramno] = pstrdup(pstring);I suggest to handle the "== -1" case first and the > 0 case as "else".
Good, as long as I thought of this too, I'm changing that.
Best, Alex
Attachments:
log_parameter_max_length_v5.patchtext/x-patch; charset=UTF-8; name=log_parameter_max_length_v5.patchDownload
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 2de21903a1..21b65f2791 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6690,29 +6690,47 @@ 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>)
+ <varlistentry id="guc-log-parameter-max-length" xreflabel="log_parameter_max_length">
+ <term><varname>log_parameter_max_length</varname> (<type>integer</type>)
<indexterm>
- <primary><varname>log_parameters_on_error</varname> configuration parameter</primary>
+ <primary><varname>log_parameter_max_length</varname> configuration parameter</primary>
</indexterm>
</term>
<listitem>
<para>
- Controls whether bind parameters are logged when a statement is logged
- as a result of <xref linkend="guc-log-min-error-statement"/>.
- It adds some overhead, as <productname>PostgreSQL</productname> will
- compute and store textual representations of parameter values in
- memory for all statements, even if they eventually do not get logged.
- This setting has no effect on statements logged due to
- <xref linkend="guc-log-min-duration-statement"/> or
- <xref linkend="guc-log-statement"/> settings, as they are always logged
- with parameters.
- The default is <literal>off</literal>.
+ If greater than zero, each bind parameter value reported in non-error
+ statement-logging messages is trimmed to this many bytes.
+ If this value is specified without units, it is taken as bytes.
+ Zero disables logging parameters with statements.
+ <literal>-1</literal> (the default) makes parameters logged in full.
Only superusers can change this setting.
</para>
</listitem>
</varlistentry>
+ <varlistentry id="guc-log-parameter-max-length-on-error" xreflabel="log_parameter_max_length_on_error">
+ <term><varname>log_parameter_max_length_on_error</varname> (<type>integer</type>)
+ <indexterm>
+ <primary><varname>log_parameter_max_length_on_error</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ If greater than zero, each bind parameter value reported in error messages
+ is trimmed to this many bytes. If this value is specified without units,
+ it is taken as bytes. Zero (the default) disables logging parameters on error.
+ <literal>-1</literal> causes parameters logged in full.
+
+ This setting only affects statements logged as a result of
+ <xref linkend="guc-log-min-error-statement"/>.
+ Non-zero values add some overhead, as
+ <productname>PostgreSQL</productname> will compute and store textual
+ representations of parameter values in memory for all statements,
+ even if they eventually do not get logged.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry id="guc-log-statement" xreflabel="log_statement">
<term><varname>log_statement</varname> (<type>enum</type>)
<indexterm>
diff --git a/src/backend/nodes/params.c b/src/backend/nodes/params.c
index a57f9eea76..77328e17ff 100644
--- a/src/backend/nodes/params.c
+++ b/src/backend/nodes/params.c
@@ -269,7 +269,7 @@ RestoreParamList(char **start_address)
* can contain NULLs for any unknown individual values. NULL can be given if
* no parameters are known.
*
- * If maxlen is not zero, that's the maximum number of bytes of any one
+ * If maxlen is not -1, that's the maximum number of bytes of any one
* parameter value to be printed; an ellipsis is added if the string is
* longer. (Added quotes are not considered in this calculation.)
*/
@@ -280,6 +280,7 @@ BuildParamLogString(ParamListInfo params, char **knownTextValues, int maxlen)
oldCxt;
StringInfoData buf;
+ Assert(maxlen == -1 || maxlen > 0);
/*
* NB: think not of returning params->paramValuesStr! It may have been
* generated with a different maxlen, and so be unsuitable. Besides that,
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 5b677863b9..f185935d0a 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1838,7 +1838,7 @@ exec_bind_message(StringInfo input_message)
*/
if (pstring)
{
- if (log_parameters_on_error)
+ if (log_parameter_max_length_on_error != 0)
{
MemoryContext oldcxt;
@@ -1846,13 +1846,24 @@ exec_bind_message(StringInfo input_message)
if (knownTextValues == NULL)
knownTextValues =
palloc0(numParams * sizeof(char *));
- /*
- * Note: must copy at least two more full characters
- * than BuildParamLogString wants to see; otherwise it
- * might fail to include the ellipsis.
- */
- knownTextValues[paramno] =
- pnstrdup(pstring, 64 + 2 * MAX_MULTIBYTE_CHAR_LEN);
+
+ if (log_parameter_max_length_on_error == -1)
+ 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)
@@ -1913,9 +1924,11 @@ exec_bind_message(StringInfo input_message)
* errors, if configured to do so. (This is saved in the portal, so
* that they'll appear when the query is executed later.)
*/
- if (log_parameters_on_error)
+ if (log_parameter_max_length_on_error != 0)
params->paramValuesStr =
- BuildParamLogString(params, knownTextValues, 64);
+ BuildParamLogString(params,
+ knownTextValues,
+ log_parameter_max_length_on_error);
}
else
params = NULL;
@@ -2400,11 +2413,11 @@ errdetail_execute(List *raw_parsetree_list)
static int
errdetail_params(ParamListInfo params)
{
- if (params && params->numParams > 0)
+ if (log_parameter_max_length != 0 && params && params->numParams > 0)
{
char *str;
- str = BuildParamLogString(params, NULL, 0);
+ str = BuildParamLogString(params, NULL, log_parameter_max_length);
if (str && str[0] != '\0')
errdetail("parameters: %s", str);
}
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 79bc7ac8ca..538d940895 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -515,7 +515,6 @@ extern const struct config_enum_entry dynamic_shared_memory_options[];
* GUC option variables that are exported from this module
*/
bool log_duration = false;
-bool log_parameters_on_error = false;
bool Debug_print_plan = false;
bool Debug_print_parse = false;
bool Debug_print_rewritten = false;
@@ -544,6 +543,8 @@ int log_min_messages = WARNING;
int client_min_messages = NOTICE;
int log_min_duration_sample = -1;
int log_min_duration_statement = -1;
+int log_parameter_max_length = 0;
+int log_parameter_max_length_on_error = 0;
int log_temp_files = -1;
double log_statement_sample_rate = 1.0;
double log_xact_sample_rate = 0;
@@ -1381,15 +1382,6 @@ static struct config_bool ConfigureNamesBool[] =
false,
NULL, NULL, NULL
},
- {
- {"log_parameters_on_error", PGC_SUSET, LOGGING_WHAT,
- gettext_noop("Logs bind parameters of the logged statements where possible."),
- NULL
- },
- &log_parameters_on_error,
- false,
- NULL, NULL, NULL
- },
{
{"debug_print_parse", PGC_USERSET, LOGGING_WHAT,
gettext_noop("Logs each query's parse tree."),
@@ -2855,6 +2847,28 @@ static struct config_int ConfigureNamesInt[] =
NULL, NULL, NULL
},
+ {
+ {"log_parameter_max_length", PGC_SUSET, LOGGING_WHAT,
+ gettext_noop("When logging statements, limit logged parameter values to first N bytes."),
+ gettext_noop("Zero to print values in full."),
+ GUC_UNIT_BYTE
+ },
+ &log_parameter_max_length,
+ -1, -1, INT_MAX / 2,
+ NULL, NULL, NULL
+ },
+
+ {
+ {"log_parameter_max_length_on_error", PGC_USERSET, LOGGING_WHAT,
+ gettext_noop("When reporting an error, limit logged parameter values to first N bytes."),
+ gettext_noop("Zero to print values in full."),
+ GUC_UNIT_BYTE
+ },
+ &log_parameter_max_length_on_error,
+ 0, -1, INT_MAX / 2,
+ NULL, NULL, NULL
+ },
+
{
{"bgwriter_delay", PGC_SIGHUP, RESOURCES_BGWRITER,
gettext_noop("Background writer sleep time between rounds."),
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index e9f8ca775d..8c26ac90d1 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -545,7 +545,12 @@
# e.g. '<%u%%%d> '
#log_lock_waits = off # log lock waits >= deadlock_timeout
#log_statement = 'none' # none, ddl, mod, all
-#log_parameters_on_error = off # on error log statements with bind parameters
+#log_parameter_max_length = -1 # when logging statements, limit logged
+ # parameter values to N bytes;
+ # -1 means print in full, 0 to disable
+#log_parameter_max_length_on_error = 0 # when logging an error, limit logged
+ # parameter values to N bytes;
+ # -1 means print in full, 0 to disable
#log_replication_commands = off
#log_temp_files = -1 # log temporary files equal or larger
# than the specified size in kilobytes;
diff --git a/src/bin/pgbench/t/001_pgbench_with_server.pl b/src/bin/pgbench/t/001_pgbench_with_server.pl
index 25ea17f7d1..b7eb37d65d 100644
--- a/src/bin/pgbench/t/001_pgbench_with_server.pl
+++ b/src/bin/pgbench/t/001_pgbench_with_server.pl
@@ -271,7 +271,35 @@ COMMIT;
});
# Verify server logging of parameters.
-$node->append_conf('postgresql.conf', "log_parameters_on_error = true");
+# 1. Logging neither with errors nor with statements
+$node->append_conf('postgresql.conf',
+ "log_min_duration_statement = 0\n" .
+ "log_parameter_max_length = 0\n" .
+ "log_parameter_max_length_on_error = 0");
+$node->reload;
+pgbench(
+ '-n -t1 -c1 -M prepared',
+ 2,
+ [],
+ [
+ qr{ERROR: invalid input syntax for type json},
+ qr{(?!extended query with parameters)}
+ ],
+ 'server parameter logging',
+ {
+ '001_param_1' => q[select '{ invalid ' as value \gset
+select $$'Valame Dios!' dijo Sancho; 'no le dije yo a vuestra merced que mirase bien lo que hacia?'$$ as long \gset
+select column1::jsonb from (values (:value), (:long)) as q;
+]
+ });
+my $log = TestLib::slurp_file($node->logfile);
+unlike($log, qr[DETAIL: parameters: \$1 = '\{ invalid ',], "no parameters logged");
+$log = undef;
+
+# 2. Logging truncated parameters on error, full with statements
+$node->append_conf('postgresql.conf',
+ "log_parameter_max_length = -1\n" .
+ "log_parameter_max_length_on_error = 64");
$node->reload;
pgbench(
'-n -t1 -c1 -M prepared',
@@ -283,11 +311,10 @@ pgbench(
],
'server parameter logging',
{
- '001_param_1' => q{select '1' as one \gset
+ '001_param_2' => q{select '1' as one \gset
SELECT 1 / (random() / 2)::int, :one::int, :two::int;
}
});
-
$node->append_conf('postgresql.conf', "log_min_duration_statement = 0");
$node->reload;
pgbench(
@@ -300,17 +327,64 @@ pgbench(
],
'server parameter logging',
{
- '001_param_2' => q[select '{ invalid ' as value \gset
+ '001_param_3' => q[select '{ invalid ' as value \gset
select $$'Valame Dios!' dijo Sancho; 'no le dije yo a vuestra merced que mirase bien lo que hacia?'$$ as long \gset
select column1::jsonb from (values (:value), (:long)) as q;
]
});
-my $log = TestLib::slurp_file($node->logfile);
+$log = TestLib::slurp_file($node->logfile);
like($log, qr[DETAIL: parameters: \$1 = '\{ invalid ', \$2 = '''Valame Dios!'' dijo Sancho; ''no le dije yo a vuestra merced que mirase bien lo que hacia\?'''],
"parameter report does not truncate");
$log = undef;
-$node->append_conf('postgresql.conf', "log_min_duration_statement = -1");
+# 3. Logging full parameters on error, truncated with statements
+$node->append_conf('postgresql.conf',
+ "log_min_duration_statement = -1\n" .
+ "log_parameter_max_length = 7\n" .
+ "log_parameter_max_length_on_error = -1");
+$node->reload;
+pgbench(
+ '-n -t1 -c1 -M prepared',
+ 2,
+ [],
+ [
+ qr{ERROR: division by zero},
+ qr{CONTEXT: extended query with parameters: \$1 = '1', \$2 = NULL}
+ ],
+ 'server parameter logging',
+ {
+ '001_param_4' => q{select '1' as one \gset
+SELECT 1 / (random() / 2)::int, :one::int, :two::int;
+}
+ });
+
+$node->append_conf('postgresql.conf', "log_min_duration_statement = 0");
+$node->reload;
+pgbench(
+ '-n -t1 -c1 -M prepared',
+ 2,
+ [],
+ [
+ qr{ERROR: invalid input syntax for type json},
+ qr[CONTEXT: JSON data, line 1: \{ invalid\.\.\.[\r\n]+extended query with parameters: \$1 = '\{ invalid ', \$2 = '''Valame Dios!'' dijo Sancho; ''no le dije yo a vuestra merced que mirase bien lo que hacia\?']m
+ ],
+ 'server parameter logging',
+ {
+ '001_param_5' => q[select '{ invalid ' as value \gset
+select $$'Valame Dios!' dijo Sancho; 'no le dije yo a vuestra merced que mirase bien lo que hacia?'$$ as long \gset
+select column1::jsonb from (values (:value), (:long)) as q;
+]
+ });
+$log = TestLib::slurp_file($node->logfile);
+like($log, qr[DETAIL: parameters: \$1 = '\{ inval\.\.\.', \$2 = '''Valame\.\.\.'],
+ "parameter report truncates");
+$log = undef;
+
+# 3. Restore config
+$node->append_conf('postgresql.conf',
+ "log_min_duration_statement = -1\n" .
+ "log_parameter_max_length_on_error = 0\n" .
+ "log_parameter_max_length = -1");
$node->reload;
# test expressions
diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h
index ce93ace76c..a375914440 100644
--- a/src/include/utils/guc.h
+++ b/src/include/utils/guc.h
@@ -234,7 +234,8 @@ typedef enum
/* GUC vars that are actually declared in guc.c, rather than elsewhere */
extern bool log_duration;
-extern bool log_parameters_on_error;
+extern int log_parameter_max_length;
+extern int log_parameter_max_length_on_error;
extern bool Debug_print_plan;
extern bool Debug_print_parse;
extern bool Debug_print_rewritten;
On 2020-Apr-02, Alexey Bashtanov wrote:
+ if (log_parameter_max_length_on_error > 0) + { + /* + * 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);The comment says we need at least 2 chars, but
log_parameter_max_length_on_error might be 1, so I think you can either add 64
byte fudge factor, like before, or do Max(log_parameter_max_length_on_error, 2).That's the code I reused without deep analysis TBH.
I think it's mostly for to allocate the space for the ellipsis in case it
needs to be added,
not to copy any actual characters, that's why we add.
More or less. If you don't add these chars, mbcliplen doesn't think
there's character there, so it ends up not adding the ellipsis. (I
don't remember why it has to be two chars rather than just one.)
--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Alvaro Herrera <alvherre@2ndquadrant.com> writes:
More or less. If you don't add these chars, mbcliplen doesn't think
there's character there, so it ends up not adding the ellipsis. (I
don't remember why it has to be two chars rather than just one.)
I think the idea is to be sure that there's a full multibyte character
after the truncation point; if the truncation point is within a multibyte
character, then you might have only a partial multibyte character after
that, which could cause problems. Doing it this way, mbcliplen will
never look at the last possibly-truncated character.
regards, tom lane
Alexey Bashtanov <bashtanov@imap.cc> writes:
Please see the new version attached.
Pushed with a bit of editorialization.
regards, tom lane