Skip to content

SPOC-551: add spock.log_verbosity and spock.apply_change_logging GUCs #477

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
ibrarahmad wants to merge 1 commit into
base: main
Choose a base branch
from
Open

SPOC-551: add spock.log_verbosity and spock.apply_change_logging GUCs #477

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
45 changes: 45 additions & 0 deletions include/spock.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -55,6 +55,51 @@ 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).
*
* When spock_log_verbosity = SPOCK_LOG_VERBOSITY_VERBOSE every spock-emitted
* DEBUG message routed through SPOCK_DEBUG1 / SPOCK_DEBUG2 is promoted to
* LOG level so it appears in standard server logs.
*/
typedef enum SpockLogVerbosity
{
SPOCK_LOG_VERBOSITY_NORMAL = 0,
SPOCK_LOG_VERBOSITY_VERBOSE
} 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 = 'verbose' can promote them to LOG without recompiling.
* Used as `ereport(SPOCK_DEBUG1, (errmsg("...")));`
*/
#define SPOCK_LOG_DEBUG_LEVEL(orig_level) \
((spock_log_verbosity == SPOCK_LOG_VERBOSITY_VERBOSE) ? LOG : (orig_level))
#define SPOCK_DEBUG1 SPOCK_LOG_DEBUG_LEVEL(DEBUG1)
#define SPOCK_DEBUG2 SPOCK_LOG_DEBUG_LEVEL(DEBUG2)

extern char *shorten_hash(const char *str, int maxlen);
extern void gen_slot_name(Name slot_name, char *dbname,
Expand Down
30 changes: 30 additions & 0 deletions include/spock_change_log.h
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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 */
39 changes: 39 additions & 0 deletions src/spock.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -139,6 +139,19 @@ 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},
{"verbose", SPOCK_LOG_VERBOSITY_VERBOSE, 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;
Expand All @@ -156,6 +169,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;

Expand Down Expand Up @@ -1085,6 +1100,30 @@ _PG_init(void)
0,
NULL, NULL, NULL);

DefineCustomEnumVariable("spock.log_verbosity",
gettext_noop("Sets the verbosity of spock-specific log output."),
gettext_noop("When 'verbose', spock's own DEBUG1 and DEBUG2 messages are "
"promoted to LOG level so they appear in standard server logs "
"without changing log_min_messages globally."),
&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."),
Comment on lines +1103 to +1115
Copy link
Copy Markdown
Member

@rasifr rasifr May 21, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think we need both spock.log_verbosity and spock.apply_change_logging. A single spock.debug_log_level using the stock server_message_level_options enum should be sufficient: increasing the DEBUG level increases verbosity exactly like Postgres itself.

That also removes the need for the new SPOCK_DEBUG1/SPOCK_DEBUG2 macros — every existing ereport(DEBUG1/2, …) is already gated by log_min_messages, so the GUC simply controls the level at which spock's own debug output is emitted.

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,
Expand Down
22 changes: 22 additions & 0 deletions src/spock_apply.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -1410,6 +1411,10 @@ handle_insert(StringInfo s)
spock_apply_heap_insert(rel, &newtup);
}

if (!failed)
spock_log_apply_change("INSERT", rel, NULL, &newtup,
remote_origin_name);
Comment on lines +1414 to +1416
Copy link
Copy Markdown

@coderabbitai coderabbitai Bot May 20, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Potential issue | 🟠 Major | ⚡ Quick win

Prevent false “applied change” logs for skipped DML in exception replay modes.

In TRANSDISCARD/SUB_DISABLE, DML is intentionally skipped but failed remains false, so these blocks still emit spock_log_apply_change(...). That produces incorrect apply-change logs for operations never applied.

Proposed fix 
-	if (!failed)
+	if (!failed &&
+		!(MyApplyWorker->use_try_block &&
+		  (exception_behaviour == TRANSDISCARD ||
+		   exception_behaviour == SUB_DISABLE)))
 		spock_log_apply_change("INSERT", rel, NULL, &newtup,
 							   remote_origin_name);
-	if (!failed)
+	if (!failed &&
+		!(MyApplyWorker->use_try_block &&
+		  (exception_behaviour == TRANSDISCARD ||
+		   exception_behaviour == SUB_DISABLE)))
 		spock_log_apply_change("UPDATE", rel,
 							   hasoldtup ? &oldtup : NULL, &newtup,
 							   remote_origin_name);
-	if (!failed)
+	if (!failed &&
+		!(MyApplyWorker->use_try_block &&
+		  (exception_behaviour == TRANSDISCARD ||
+		   exception_behaviour == SUB_DISABLE)))
 		spock_log_apply_change("DELETE", rel, &oldtup, NULL,
 							   remote_origin_name);

Also applies to: 1584-1587, 1716-1718

🤖 Prompt for AI Agents 
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

In `@src/spock_apply.c` around lines 1414 - 1416, The apply-change log is emitted
even when DML was intentionally skipped under exception-replay modes
TRANSDISCARD/SUB_DISABLE; update the three spots that call
spock_log_apply_change (the INSERT block with newtup, the UPDATE block with
oldtup/newtup, and the DELETE block with oldtup) to only call
spock_log_apply_change when the operation both did not fail and was actually
applied — i.e., change the guard from if (!failed) to if (!failed &&
!<skip-dml-flag>), where <skip-dml-flag> checks the current exception replay
mode (TRANSDISCARD or SUB_DISABLE) or otherwise detects that DML was skipped;
use the existing symbols for those modes so the check reflects the code’s
exception replay state and ensures no “applied change” log is produced for
skipped operations.


/*
* DML operation is finished. Be paranoid and check memory context before
* switching out and cleaning the per-operation memory context
Expand Down Expand Up @@ -1576,6 +1581,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,
Comment on lines +1584 to +1586
Copy link
Copy Markdown
Member

@rasifr rasifr May 21, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should the change-log record really be gated by !failed? When user turns this on they almost certainly want to see the conflict and exception cases — those are the interesting ones. As written, it silently drops exactly the records you'd enable it to capture. I'd either always emit (with "incoming"|"applied"|"conflict"|"skipped" field, can be a generic string) or hook into spock_report_conflict()/log_insert_exception.

Same comment applies to the DDL path in handle_sql — it logs before execution, so a failed DDL still produces an "action":"DDL" line that looks applied.

remote_origin_name);

spock_relation_close(rel, NoLock);

end_replication_step();
Expand Down Expand Up @@ -1703,6 +1713,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();
Expand Down Expand Up @@ -2337,6 +2351,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);
}
Expand Down
Loading