Add spock.log_verbosity and spock.apply_change_logging GUCs

docs/configuring.md

@@ -57,6 +57,29 @@ functions adhere to the same rule previously described for
 added into the `default` replication set; alternatively, they will be added
 to the `default_insert_only` replication set.
 
+### `spock.apply_change_logging`
+
+`spock.apply_change_logging` controls per-change JSON logging by the apply
+worker. After each change is successfully applied locally, a single JSON
+object is written to the PostgreSQL server log (at `LOG` level) so that
+operators can correlate replayed changes with their origin and commit
+timestamp. This is intended for debugging and auditing; it adds log volume
+proportional to the apply workload, so leave it at the default in normal
+operation.
+
+The following values are possible:
+
+- `none` (the default) - no per-change logging.
+- `key_only` - for each `INSERT`/`UPDATE`/`DELETE`, log the action,
+  schema-qualified table, primary-key values, origin, and commit timestamp.
+- `verbose` - all of the above, plus the old and new row data for each
+  change.
+
+Replicated DDL is logged (with its SQL text) in both `key_only` and
+`verbose` modes. This option can be set by a superuser via `SET`, or
+reloaded with the `SIGHUP` mechanism (for example,
+`SELECT pg_reload_conf()`); a server restart is not required.
+
 ### `spock.channel_counters`
 
 `spock.channel_counters` is a boolean value (the default is `true`) that
@@ -385,6 +408,29 @@ The following configuration values are possible:
   row that was previously from another publisher or updated it locally, but
   only since the time when the subscription was created.
 
+### `spock.log_verbosity`
+
+`spock.log_verbosity` controls the verbosity of Spock's own debug log
+output. Spock emits internal `DEBUG1`/`DEBUG2` messages that are normally
+silent, because PostgreSQL's `log_min_messages` typically defaults to
+`warning`. Lowering `log_min_messages` globally would surface those
+messages, but it would also flood the log with unrelated PostgreSQL debug
+output.
+
+Instead, this setting *promotes* Spock's own debug messages to `LOG` level
+(which is written to the server log under any normal `log_min_messages`
+setting), without changing `log_min_messages`. The value controls how much
+detail is promoted:
+
+- `normal` (the default) - promote nothing; Spock's `DEBUG1`/`DEBUG2`
+  messages keep their native (normally silent) levels.
+- `debug1` - promote Spock's `DEBUG1` messages to `LOG`.
+- `debug2` - promote both Spock's `DEBUG1` and `DEBUG2` messages to `LOG`.
+
+This option can be set by a superuser via `SET`, or reloaded with the
+`SIGHUP` mechanism (for example, `SELECT pg_reload_conf()`); a server
+restart is not required.
+
 ### `spock.save_resolutions`
 
 `spock.save_resolutions` is a boolean value (the default is `false`) that

include/spock.h

@@ -55,6 +55,61 @@ extern bool check_all_uc_indexes;
 extern bool	spock_enable_quiet_mode;
 extern int	log_origin_change;
 extern int	spock_apply_idle_timeout;
+extern int	spock_log_verbosity;
+extern int	spock_apply_change_logging;
+
+/*
+ * spock.log_verbosity - controls the verbosity of spock-specific log output.
+ *
+ * Spock's own DEBUG1/DEBUG2 messages are silent by default because PostgreSQL's
+ * log_min_messages typically defaults to WARNING or NOTICE.  Customer Success
+ * needs to crank up spock detail when debugging an issue without flipping
+ * log_min_messages globally (which floods the logs with non-spock output).
+ *
+ * PostgreSQL has only a single, global log threshold (log_min_messages), so we
+ * cannot give spock a lower "minimum level" of its own: a DEBUG1/DEBUG2 message
+ * emitted below log_min_messages is discarded by errstart() before it is ever
+ * built.  Instead this GUC *promotes* spock's own debug messages up to LOG,
+ * which is always written to the server log under any normal log_min_messages
+ * setting.  The level controls how much detail is promoted:
+ *
+ *   normal - no promotion; DEBUG1/DEBUG2 keep their native (silent) levels.
+ *   debug1 - promote SPOCK_DEBUG1 messages to LOG (DEBUG2 stays silent).
+ *   debug2 - promote both SPOCK_DEBUG1 and SPOCK_DEBUG2 messages to LOG.
+ */
+typedef enum SpockLogVerbosity
+{
+	SPOCK_LOG_VERBOSITY_NORMAL = 0,
+	SPOCK_LOG_VERBOSITY_DEBUG1,
+	SPOCK_LOG_VERBOSITY_DEBUG2
+} SpockLogVerbosity;
+
+/*
+ * spock.apply_change_logging - controls JSON change logging by the apply worker.
+ *
+ *   none     - default; no extra logging.
+ *   key_only - log {action, schema, table, primary_key, origin, commit_ts}
+ *              for each DML change.  DDL is also logged with its SQL text.
+ *   verbose  - all of the above, plus old/new row data for DML.
+ */
+typedef enum SpockApplyChangeLogging
+{
+	SPOCK_APPLY_CHANGE_LOG_NONE = 0,
+	SPOCK_APPLY_CHANGE_LOG_KEY_ONLY,
+	SPOCK_APPLY_CHANGE_LOG_VERBOSE
+} SpockApplyChangeLogging;
+
+/*
+ * Route every spock-specific DEBUG1/DEBUG2 ereport through these macros so
+ * spock.log_verbosity can promote them to LOG without recompiling.  Each macro
+ * promotes to LOG only once spock.log_verbosity is at or above that message's
+ * tier; otherwise the message keeps its native (and normally silent) level.
+ * Used as `ereport(SPOCK_DEBUG1, (errmsg("...")));`
+ */
+#define SPOCK_DEBUG1 \
+	((spock_log_verbosity >= SPOCK_LOG_VERBOSITY_DEBUG1) ? LOG : DEBUG1)
+#define SPOCK_DEBUG2 \
+	((spock_log_verbosity >= SPOCK_LOG_VERBOSITY_DEBUG2) ? LOG : DEBUG2)
 
 extern char *shorten_hash(const char *str, int maxlen);
 extern void gen_slot_name(Name slot_name, char *dbname,

include/spock_change_log.h

@@ -0,0 +1,30 @@
+/*-------------------------------------------------------------------------
+ *
+ * spock_change_log.h
+ *      Public surface for spock.apply_change_logging output.
+ *
+ *-------------------------------------------------------------------------
+ */
+#ifndef SPOCK_CHANGE_LOG_H
+#define SPOCK_CHANGE_LOG_H
+
+/*
+ * Forward declarations only.  spock_change_log.h is included from
+ * spock_apply.c right next to other spock_*.h headers, and pulling in
+ * spock_proto_native.h / spock_relcache.h would also drag in
+ * spock_compat.h via spock_output_plugin.h - the resulting macro
+ * redefinitions then collide with commands/trigger.h declarations
+ * pulled in further down the include chain (spock_common.h).
+ */
+struct SpockRelation;
+struct SpockTupleData;
+
+extern void spock_log_apply_change(const char *action,
+								   struct SpockRelation *rel,
+								   struct SpockTupleData *oldtup,
+								   struct SpockTupleData *newtup,
+								   const char *origin_name);
+
+extern void spock_log_apply_ddl(const char *sql, const char *origin_name);
+
+#endif							/* SPOCK_CHANGE_LOG_H */

src/spock.c

@@ -139,6 +139,20 @@ static const struct config_enum_entry readonly_options[] = {
 	{NULL, 0, false}
 };
 
+static const struct config_enum_entry log_verbosity_options[] = {
+	{"normal", SPOCK_LOG_VERBOSITY_NORMAL, false},
+	{"debug1", SPOCK_LOG_VERBOSITY_DEBUG1, false},
+	{"debug2", SPOCK_LOG_VERBOSITY_DEBUG2, false},
+	{NULL, 0, false}
+};
+
+static const struct config_enum_entry apply_change_logging_options[] = {
+	{"none", SPOCK_APPLY_CHANGE_LOG_NONE, false},
+	{"key_only", SPOCK_APPLY_CHANGE_LOG_KEY_ONLY, false},
+	{"verbose", SPOCK_APPLY_CHANGE_LOG_VERBOSE, false},
+	{NULL, 0, false}
+};
+
 bool		spock_synchronous_commit = false;
 char	   *spock_temp_directory = "";
 static char *spock_temp_directory_config;
@@ -157,6 +171,8 @@ bool		check_all_uc_indexes = false;
 bool		spock_enable_quiet_mode = false;
 int			log_origin_change = SPOCK_ORIGIN_NONE;
 int			spock_apply_idle_timeout = 300;
+int			spock_log_verbosity = SPOCK_LOG_VERBOSITY_NORMAL;
+int			spock_apply_change_logging = SPOCK_APPLY_CHANGE_LOG_NONE;
 
 static emit_log_hook_type prev_emit_log_hook = NULL;
 
@@ -1066,6 +1082,31 @@ _PG_init(void)
 							 0,
 							 NULL, NULL, NULL);
 
+	DefineCustomEnumVariable("spock.log_verbosity",
+							 gettext_noop("Sets the verbosity of spock-specific log output."),
+							 gettext_noop("Promotes spock's own debug messages to LOG so they appear in "
+										  "standard server logs without changing log_min_messages globally. "
+										  "'normal' (default) promotes nothing; 'debug1' promotes spock's "
+										  "DEBUG1 messages; 'debug2' promotes both DEBUG1 and DEBUG2."),
+							 &spock_log_verbosity,
+							 SPOCK_LOG_VERBOSITY_NORMAL,
+							 log_verbosity_options,
+							 PGC_SUSET, 0,
+							 NULL, NULL, NULL);
+
+	DefineCustomEnumVariable("spock.apply_change_logging",
+							 gettext_noop("Controls JSON logging of changes applied by the apply worker."),
+							 gettext_noop("'none' (default) disables. 'key_only' logs the action, "
+										  "schema-qualified relation, primary-key values, origin and "
+										  "commit timestamp for each DML change in JSON. 'verbose' "
+										  "additionally logs old/new row data. DDL is logged in both "
+										  "'key_only' and 'verbose' modes."),
+							 &spock_apply_change_logging,
+							 SPOCK_APPLY_CHANGE_LOG_NONE,
+							 apply_change_logging_options,
+							 PGC_SUSET, 0,
+							 NULL, NULL, NULL);
+
 	DefineCustomBoolVariable("spock.synchronous_commit",
 							 "spock specific synchronous commit value",
 							 NULL,

src/spock_apply.c

@@ -67,6 +67,7 @@
 #include "replication/walsender_private.h"
 
 #include "spock_autoddl.h"
+#include "spock_change_log.h"
 #include "spock_common.h"
 #include "spock_conflict.h"
 #include "spock_executor.h"
@@ -1475,6 +1476,10 @@ handle_insert(StringInfo s)
 		spock_apply_heap_insert(rel, &newtup);
 	}
 
+	if (!failed)
+		spock_log_apply_change("INSERT", rel, NULL, &newtup,
+							   remote_origin_name);
+
 	/*
 	 * DML operation is finished. Be paranoid and check memory context before
 	 * switching out and cleaning the per-operation memory context
@@ -1641,6 +1646,11 @@ handle_update(StringInfo s)
 		spock_apply_heap_update(rel, hasoldtup ? &oldtup : &newtup, &newtup);
 	}
 
+	if (!failed)
+		spock_log_apply_change("UPDATE", rel,
+							   hasoldtup ? &oldtup : NULL, &newtup,
+							   remote_origin_name);
+
 	spock_relation_close(rel, NoLock);
 
 	end_replication_step();
@@ -1768,6 +1778,10 @@ handle_delete(StringInfo s)
 		spock_apply_heap_delete(rel, &oldtup);
 	}
 
+	if (!failed)
+		spock_log_apply_change("DELETE", rel, &oldtup, NULL,
+							   remote_origin_name);
+
 	spock_relation_close(rel, NoLock);
 
 	end_replication_step();
@@ -2402,6 +2416,14 @@ handle_sql(QueuedMessage *queued_message, bool tx_just_started, char **sql)
 			 "item type %d expected %d",
 			 MySubscription->name, r, WJB_DONE);
 
+	/*
+	 * Emit the DDL change-log record (in both 'key_only' and 'verbose'
+	 * modes) BEFORE execution.  Logging at this point means the operator
+	 * always sees what SQL was about to run, even if the execution itself
+	 * later errors out.
+	 */
+	spock_log_apply_ddl(*sql, remote_origin_name);
+
 	/* Run the extracted SQL. */
 	spock_execute_sql_command(*sql, queued_message->role, tx_just_started);
 }