Date: Wed, 27 Feb 2019 12:06:53 -0600
From: Justin Pryzby <pryzby@telsasoft.com>
To: pgsql-hackers@postgresql.org
Subject: Re: query logging of prepared statements
Message-ID: <20190227180653.GF28750@telsasoft.com>
References: <20190208132953.GF29720@telsasoft.com>
 <20190215145704.GW30291@telsasoft.com>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="r7U+bLA8boMOj+mD"
Content-Disposition: inline
In-Reply-To: <20190215145704.GW30291@telsasoft.com>
User-Agent: Mutt/1.5.23 (2014-03-12)
Precedence: bulk


--r7U+bLA8boMOj+mD
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

On Fri, Feb 15, 2019 at 08:57:04AM -0600, Justin Pryzby wrote:
> I propose that the prepared statement associated with an EXECUTE should be
> included in log "DETAIL" only when log_error_verbosity=VERBOSE, for both SQL
> EXECUTE and PQexecPrepared (if at all).  I'd like to be able to continue
> logging DETAIL (including bind parameters), so want like to avoid setting
> "TERSE" just to avoid redundant messages.  (It occurs to me that the GUC should
> probably stick to its existing documented behavior rather than be extended,
> which suggests that the duplicitive portions of the logs should simply be
> removed, rather than conditionalized.  Let me know what you think).

I'm attaching a v2 patch which avoids repeated logging of PREPARE, rather than
making such logs conditional on log_error_verbosity=VERBOSE, since
log_error_verbosity is documented to control whether these are output:
DETAIL/HINT/QUERY/CONTEXT/SQLSTATE.

For SQL EXECUTE, excluding "detail" seems reasonable (perhaps for
log_error_verbosity<VERBOSE).  But for PQexecPrepared, the
v1 patch made log_error_verbosity also control the "message" output, which is
outside the scope of its documented behavior.

|message                | execute qq: PREPARE qq AS SELECT $1
|detail                 | parameters: $1 = '3'

https://www.postgresql.org/docs/current/runtime-config-logging.html
|Controls the amount of detail written in the server log for each message that
|is logged. Valid values are TERSE, DEFAULT, and VERBOSE, each adding more
|fields to displayed messages. TERSE excludes the logging of DETAIL, HINT,
|QUERY, and CONTEXT error information. VERBOSE output includes the SQLSTATE
|error code (see also Appendix A) and the source code file name, function name,
|and line number that generated the error. Only superusers can change this
|setting.

As I mentioned in my original message, it seems odd that for SQL EXECUTE, the
PREPARE is shown in "detail", but for the library call, it's shown in
"message".  This patch resolves that inconsistency by showing it in neither.

--r7U+bLA8boMOj+mD
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="v2-0001-Avoid-repetitive-log-of-PREPARE-during-EXECUTE-of.patch"

From d60957d9cd1108f389dde0125fadee71a96b4229 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <justin@telsasoft.com>
Date: Sat, 9 Feb 2019 19:20:43 -0500
Subject: [PATCH v2] Avoid repetitive log of PREPARE during EXECUTE of prepared
 statements

---
 src/backend/tcop/postgres.c | 13 +++++--------
 1 file changed, 5 insertions(+), 8 deletions(-)

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 8b4d94c9a1..dac5362c81 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1041,8 +1041,7 @@ exec_simple_query(const char *query_string)
 	{
 		ereport(LOG,
 				(errmsg("statement: %s", query_string),
-				 errhidestmt(true),
-				 errdetail_execute(parsetree_list)));
+				 errhidestmt(true)));
 		was_logged = true;
 	}
 
@@ -2062,14 +2061,13 @@ exec_execute_message(const char *portal_name, long max_rows)
 	if (check_log_statement(portal->stmts))
 	{
 		ereport(LOG,
-				(errmsg("%s %s%s%s: %s",
+				(errmsg("%s %s%s%s",
 						execute_is_fetch ?
 						_("execute fetch from") :
 						_("execute"),
 						prepStmtName,
 						*portal_name ? "/" : "",
-						*portal_name ? portal_name : "",
-						sourceText),
+						*portal_name ? portal_name : ""),
 				 errhidestmt(true),
 				 errdetail_params(portalParams)));
 		was_logged = true;
@@ -2150,15 +2148,14 @@ exec_execute_message(const char *portal_name, long max_rows)
 			break;
 		case 2:
 			ereport(LOG,
-					(errmsg("duration: %s ms  %s %s%s%s: %s",
+					(errmsg("duration: %s ms  %s %s%s%s",
 							msec_str,
 							execute_is_fetch ?
 							_("execute fetch from") :
 							_("execute"),
 							prepStmtName,
 							*portal_name ? "/" : "",
-							*portal_name ? portal_name : "",
-							sourceText),
+							*portal_name ? portal_name : ""),
 					 errhidestmt(true),
 					 errdetail_params(portalParams)));
 			break;
-- 
2.12.2


--r7U+bLA8boMOj+mD--