[CF 5272] V6 - Truncate logs by max_log_size

This branch was automatically generated by a robot using patches from an
email thread registered at:

https://commitfest.postgresql.org/patch/5272

The branch will be overwritten each time a new patch version is posted to
the thread, and also periodically to check for bitrot caused by changes
on the master branch.

Patch(es): https://www.postgresql.org/message-id/CA+E0NR7XD3wpts2GEFpZpO-M8kj9f8pTrhnAKvq5n4xjtLgLKg@mail.gmail.com
Author(s): Kirill Gavrilov

Author: Commitfest Bot

doc/src/sgml/config.sgml

@@ -8140,6 +8140,22 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
       </listitem>
      </varlistentry>
 
+     <varlistentry id="guc-max-log-size" xreflabel="max_log_size">
+      <term><varname>max_log_size</varname> (<type>integer</type>)
+      <indexterm>
+       <primary><varname>max_log_size</varname> configuration parameter</primary>
+      </indexterm>
+      </term>
+      <listitem>
+       <para>
+        If greater than zero, each query logged is truncated to this many bytes.
+        Zero disables the setting.
+        If this value is specified without units, it is taken as bytes.
+        This feature is disabled by default.
+       </para>
+      </listitem>
+     </varlistentry>
+
      </variablelist>
     </sect2>
      <sect2 id="runtime-config-logging-csvlog">

src/backend/tcop/postgres.c

@@ -71,6 +71,7 @@
 #include "tcop/pquery.h"
 #include "tcop/tcopprot.h"
 #include "tcop/utility.h"
+#include "utils/elog.h"
 #include "utils/guc_hooks.h"
 #include "utils/injection_point.h"
 #include "utils/lsyscache.h"
@@ -1019,11 +1020,22 @@ exec_simple_query(const char *query_string)
 	bool		was_logged = false;
 	bool		use_implicit_block;
 	char		msec_str[32];
+	char* 		truncated_query = NULL;
+	const char*	query_log;
 
 	/*
 	 * Report query to various monitoring facilities.
 	 */
 	debug_query_string = query_string;
+	if (need_truncate_query_log(query_string))
+	{
+		truncated_query = truncate_query_log(query_string);
+		query_log = truncated_query;
+	}
+	else
+	{
+		query_log = query_string;
+	}
 
 	pgstat_report_activity(STATE_RUNNING, query_string);
 
@@ -1068,7 +1080,7 @@ exec_simple_query(const char *query_string)
 	if (check_log_statement(parsetree_list))
 	{
 		ereport(LOG,
-				(errmsg("statement: %s", query_string),
+				(errmsg("statement: %s", query_log),
 				 errhidestmt(true),
 				 errdetail_execute(parsetree_list)));
 		was_logged = true;
@@ -1367,7 +1379,7 @@ exec_simple_query(const char *query_string)
 		case 2:
 			ereport(LOG,
 					(errmsg("duration: %s ms  statement: %s",
-							msec_str, query_string),
+							msec_str, query_log),
 					 errhidestmt(true),
 					 errdetail_execute(parsetree_list)));
 			break;
@@ -1378,6 +1390,8 @@ exec_simple_query(const char *query_string)
 
 	TRACE_POSTGRESQL_QUERY_DONE(query_string);
 
+	if (truncated_query)
+		pfree(truncated_query);
 	debug_query_string = NULL;
 }
 

src/backend/utils/error/elog.c

@@ -112,6 +112,7 @@ int			Log_destination = LOG_DESTINATION_STDERR;
 char	   *Log_destination_string = NULL;
 bool		syslog_sequence_numbers = true;
 bool		syslog_split_messages = true;
+int			max_log_size = 0;
 
 /* Processed form of backtrace_functions GUC */
 static char *backtrace_function_list;
@@ -1696,11 +1697,18 @@ EmitErrorReport(void)
 {
 	ErrorData  *edata = &errordata[errordata_stack_depth];
 	MemoryContext oldcontext;
+	char* truncated_query = NULL;
 
 	recursion_depth++;
 	CHECK_STACK_DEPTH();
 	oldcontext = MemoryContextSwitchTo(edata->assoc_context);
 
+	if (need_truncate_query_log(debug_query_string))
+	{
+		truncated_query = truncate_query_log(debug_query_string);
+		debug_query_string = truncated_query;
+	}
+
 	/*
 	 * Reset the formatted timestamp fields before emitting any logs.  This
 	 * includes all the log destinations and emit_log_hook, as the latter
@@ -1741,6 +1749,9 @@ EmitErrorReport(void)
 
 	MemoryContextSwitchTo(oldcontext);
 	recursion_depth--;
+
+	if (truncated_query)
+		pfree(truncated_query);
 }
 
 /*
@@ -3817,3 +3828,39 @@ write_stderr(const char *fmt,...)
 #endif
 	va_end(ap);
 }
+
+/*
+ *	Apply truncation to build query that will be logged.
+ *
+ *	If query needs to be truncated, copied will be set to true
+ *	and returned string must be freed
+*/
+char*
+truncate_query_log(const char* query)
+{
+	size_t truncated_query_len;
+	char* truncatd_query;
+	size_t query_len;
+
+	if (!query)
+		return NULL;
+
+	query_len = strlen(query);
+	truncated_query_len = pg_mbcliplen(query, query_len, max_log_size);
+	truncatd_query = (char *) palloc(truncated_query_len+1);
+	memcpy(truncatd_query, query, truncated_query_len);
+	truncatd_query[truncated_query_len] = '\0';
+	return truncatd_query;
+}
+
+/*
+ *	Checks if query should be truncated
+ *	according to max_log_size
+*/
+bool
+need_truncate_query_log(const char* query)
+{
+	if (!query)
+		return false;
+	return !(max_log_size == 0 || strlen(query) < max_log_size);
+}

src/backend/utils/misc/guc_tables.c

@@ -3860,6 +3860,18 @@ struct config_int ConfigureNamesInt[] =
 		NULL, NULL, NULL
 	},
 
+	{
+		{"max_log_size", PGC_SUSET, LOGGING_WHAT,
+			gettext_noop("Sets max size in bytes of logged statement."),
+			NULL,
+			GUC_UNIT_BYTE
+		},
+		&max_log_size,
+		0,
+		0, INT_MAX,
+		NULL, NULL, NULL
+	},
+
 	/* End-of-list marker */
 	{
 		{NULL, 0, 0, NULL, NULL}, NULL, 0, 0, 0, NULL, NULL, NULL

src/backend/utils/misc/postgresql.conf.sample

@@ -634,6 +634,8 @@
 					# bind-parameter values to N bytes;
 					# -1 means print in full, 0 disables
 #log_statement = 'none'			# none, ddl, mod, all
+#max_log_size = 0 	# max size of logged statement
+				    # 0 disables the feature
 #log_replication_commands = off
 #log_temp_files = -1			# log temporary files equal or larger
 					# than the specified size in kilobytes;

src/bin/pg_ctl/t/004_logrotate.pl

@@ -69,6 +69,7 @@ sub check_log_pattern
 # these ensure stability of test results:
 log_rotation_age = 0
 lc_messages = 'C'
+max_log_size = 32
 ));
 
 $node->start();
@@ -135,6 +136,20 @@ sub check_log_pattern
 check_log_pattern('csvlog', $new_current_logfiles, 'syntax error', $node);
 check_log_pattern('jsonlog', $new_current_logfiles, 'syntax error', $node);
 
+$node->psql('postgres', 'INSERT INTO SOME_NON_EXISTANT_TABLE VALUES (TEST)');
+for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
+{
+	eval {
+		$current_logfiles = slurp_file($node->data_dir . '/current_logfiles');
+	};
+	last unless $@;
+	usleep(100_000);
+}
+die $@ if $@;
+check_log_pattern('stderr',  $current_logfiles, 'INSERT INTO SOME_NON_EXISTANT_TA(?!(BLE VALUES \(TEST\)))', $node);
+check_log_pattern('csvlog',  $current_logfiles, 'INSERT INTO SOME_NON_EXISTANT_TA(?!(BLE VALUES \(TEST\)))', $node);
+check_log_pattern('jsonlog', $current_logfiles, 'INSERT INTO SOME_NON_EXISTANT_TA(?!(BLE VALUES \(TEST\)))', $node);
+
 $node->stop();
 
 done_testing();

src/include/utils/elog.h

@@ -493,6 +493,7 @@ extern PGDLLIMPORT int Log_destination;
 extern PGDLLIMPORT char *Log_destination_string;
 extern PGDLLIMPORT bool syslog_sequence_numbers;
 extern PGDLLIMPORT bool syslog_split_messages;
+extern PGDLLIMPORT int max_log_size;
 
 /* Log destination bitmap */
 #define LOG_DESTINATION_STDERR	 1
@@ -508,6 +509,9 @@ extern void DebugFileOpen(void);
 extern char *unpack_sql_state(int sql_state);
 extern bool in_error_recursion_trouble(void);
 
+extern bool need_truncate_query_log(const char* query);
+extern char* truncate_query_log(const char* query);
+
 /* Common functions shared across destinations */
 extern void reset_formatted_start_time(void);
 extern char *get_formatted_start_time(void);