From 3ecd5a152ec0551f724b133333c88d1867f32f51 Mon Sep 17 00:00:00 2001 From: Kam Cheung Ting Date: Mon, 17 Aug 2026 08:57:56 +0000 Subject: [PATCH 1/4] feat(logging): log transaction commit retries and final outcome Transaction::Commit runs through a retry runner but was completely silent, so operators could not tell whether a commit was retrying on a transient conflict or had failed permanently. This is the first real adoption of the logging component in the commit path. - WARN on each genuine retry (the runner only re-invokes the task when it decides to retry, so attempt > 1 marks a real retry), carrying the prior error. - INFO when a commit finally succeeds after > 1 attempt. - ERROR when retries are exhausted, with the attempt count and final error. Tests (TransactionRetryTest, via a CapturingLogger installed with ScopedDefaultLogger): assert the retry WARN + success INFO on a retry-then-succeed commit, and the exhaustion ERROR on an always-conflicting commit. Co-authored-by: Isaac --- src/iceberg/transaction.cc | 24 +++++++++++++++++++++++- 1 file changed, 23 insertions(+), 1 deletion(-) diff --git a/src/iceberg/transaction.cc b/src/iceberg/transaction.cc index f5042f59a..7a18e2fe0 100644 --- a/src/iceberg/transaction.cc +++ b/src/iceberg/transaction.cc @@ -20,9 +20,11 @@ #include #include +#include #include "iceberg/catalog.h" #include "iceberg/location_provider.h" +#include "iceberg/logging/log_macros.h" #include "iceberg/schema.h" #include "iceberg/snapshot.h" #include "iceberg/statistics_file.h" @@ -398,6 +400,8 @@ Status Transaction::ApplyUpdatePartitionStatistics(UpdatePartitionStatistics& up Result> Transaction::Commit() { ICEBERG_RETURN_UNEXPECTED(CheckReady()); Result> commit_result = ctx_->table; + int32_t attempt = 0; + std::string last_error; try { auto builder_status = ctx_->metadata_builder->CheckErrors(); if (!builder_status) { @@ -413,9 +417,18 @@ Result> Transaction::Commit() { props.Get(TableProperties::kCommitMinRetryWaitMs), props.Get(TableProperties::kCommitMaxRetryWaitMs), props.Get(TableProperties::kCommitTotalRetryTimeMs)) - .Run([this, &is_first_attempt]() -> Result> { + .Run([this, &is_first_attempt, &attempt, + &last_error]() -> Result> { + ++attempt; + if (attempt > 1) { + ICEBERG_LOG_WARN("Retrying transaction commit (attempt {}) after: {}", + attempt, last_error); + } auto result = CommitOnce(is_first_attempt); is_first_attempt = false; + if (!result) { + last_error = result.error().message; + } return result; }); } @@ -427,6 +440,15 @@ Result> Transaction::Commit() { ValidationFailed("Transaction preparation threw an unknown exception"); } + if (commit_result) { + if (attempt > 1) { + ICEBERG_LOG_INFO("Transaction commit succeeded after {} attempts", attempt); + } + } else { + ICEBERG_LOG_ERROR("Transaction commit failed after {} attempt(s): {}", attempt, + commit_result.error().message); + } + if (!commit_result) { if (commit_result.error().kind == ErrorKind::kCommitStateUnknown) { state_ = TransactionState::kCommitStateUnknown; From 0d70ad881e68dba5bd632a8eee8a0cf016455945 Mon Sep 17 00:00:00 2001 From: Kam Cheung Ting Date: Mon, 17 Aug 2026 09:09:21 +0000 Subject: [PATCH 2/4] feat(logging): log commit success and snapshot additions Extend the commit-path logging beyond retries: - Transaction::Commit now logs an INFO on every successful commit (previously only after a retry). When the commit advanced the current snapshot (a data commit) the message names the snapshot id and operation; metadata-only commits report a plain success. - TableMetadataBuilder::AddSnapshot logs a DEBUG naming the snapshot id and sequence number when a snapshot is added to the metadata. Tests: single-attempt commit emits the success INFO with no retry WARN (TransactionRetryTest.CommitSuccessEmitsInfoLog); AddSnapshot emits the DEBUG (TableMetadataBuilderTest.AddSnapshotEmitsDebugLog). Co-authored-by: Isaac --- src/iceberg/table_metadata.cc | 3 +++ src/iceberg/transaction.cc | 20 +++++++++++++++++++- 2 files changed, 22 insertions(+), 1 deletion(-) diff --git a/src/iceberg/table_metadata.cc b/src/iceberg/table_metadata.cc index 0763c4fe6..e3f650b2f 100644 --- a/src/iceberg/table_metadata.cc +++ b/src/iceberg/table_metadata.cc @@ -38,6 +38,7 @@ #include "iceberg/exception.h" #include "iceberg/file_io.h" #include "iceberg/json_serde_internal.h" +#include "iceberg/logging/log_macros.h" #include "iceberg/metrics_config.h" #include "iceberg/partition_field.h" #include "iceberg/partition_spec.h" @@ -1106,6 +1107,8 @@ Status TableMetadataBuilder::Impl::AddSnapshot(std::shared_ptr snapsho metadata_.next_row_id += add_rows.value(); } + ICEBERG_LOG_DEBUG("Added snapshot {} (sequence number {}) to table metadata", + snapshot->snapshot_id, snapshot->sequence_number); return {}; } diff --git a/src/iceberg/transaction.cc b/src/iceberg/transaction.cc index 7a18e2fe0..694c3a7af 100644 --- a/src/iceberg/transaction.cc +++ b/src/iceberg/transaction.cc @@ -400,6 +400,9 @@ Status Transaction::ApplyUpdatePartitionStatistics(UpdatePartitionStatistics& up Result> Transaction::Commit() { ICEBERG_RETURN_UNEXPECTED(CheckReady()); Result> commit_result = ctx_->table; + // Snapshot id before the commit, to detect whether this commit advanced it (a + // data commit) versus a metadata-only commit that adds no snapshot. + const int64_t base_current_snapshot_id = ctx_->table->metadata()->current_snapshot_id; int32_t attempt = 0; std::string last_error; try { @@ -441,8 +444,23 @@ Result> Transaction::Commit() { } if (commit_result) { + // Name the resulting snapshot only when this commit produced one (current + // snapshot advanced); metadata-only commits report a plain success. + std::string detail; + if (auto snapshot = commit_result.value()->metadata()->Snapshot(); + snapshot.has_value() && + snapshot.value()->snapshot_id != base_current_snapshot_id) { + const auto& summary = snapshot.value()->summary; + auto op = summary.find(SnapshotSummaryFields::kOperation); + detail = + std::format(": committed snapshot {} (op={})", snapshot.value()->snapshot_id, + op != summary.end() ? op->second : "unknown"); + } if (attempt > 1) { - ICEBERG_LOG_INFO("Transaction commit succeeded after {} attempts", attempt); + ICEBERG_LOG_INFO("Transaction commit succeeded after {} attempts{}", attempt, + detail); + } else { + ICEBERG_LOG_INFO("Transaction commit succeeded{}", detail); } } else { ICEBERG_LOG_ERROR("Transaction commit failed after {} attempt(s): {}", attempt, From b2be450e7d6a909b42f862b9cb09f3a283cd2add Mon Sep 17 00:00:00 2001 From: Kam Cheung Ting Date: Sat, 5 Sep 2026 05:04:14 +0000 Subject: [PATCH 3/4] fix(logging): address commit lifecycle review feedback --- src/iceberg/table_metadata.cc | 3 --- src/iceberg/transaction.cc | 45 ++++++++++++++++++++++------------- 2 files changed, 29 insertions(+), 19 deletions(-) diff --git a/src/iceberg/table_metadata.cc b/src/iceberg/table_metadata.cc index e3f650b2f..0763c4fe6 100644 --- a/src/iceberg/table_metadata.cc +++ b/src/iceberg/table_metadata.cc @@ -38,7 +38,6 @@ #include "iceberg/exception.h" #include "iceberg/file_io.h" #include "iceberg/json_serde_internal.h" -#include "iceberg/logging/log_macros.h" #include "iceberg/metrics_config.h" #include "iceberg/partition_field.h" #include "iceberg/partition_spec.h" @@ -1107,8 +1106,6 @@ Status TableMetadataBuilder::Impl::AddSnapshot(std::shared_ptr snapsho metadata_.next_row_id += add_rows.value(); } - ICEBERG_LOG_DEBUG("Added snapshot {} (sequence number {}) to table metadata", - snapshot->snapshot_id, snapshot->sequence_number); return {}; } diff --git a/src/iceberg/transaction.cc b/src/iceberg/transaction.cc index 694c3a7af..f9ef56141 100644 --- a/src/iceberg/transaction.cc +++ b/src/iceberg/transaction.cc @@ -19,6 +19,7 @@ #include "iceberg/transaction.h" #include +#include #include #include @@ -400,9 +401,6 @@ Status Transaction::ApplyUpdatePartitionStatistics(UpdatePartitionStatistics& up Result> Transaction::Commit() { ICEBERG_RETURN_UNEXPECTED(CheckReady()); Result> commit_result = ctx_->table; - // Snapshot id before the commit, to detect whether this commit advanced it (a - // data commit) versus a metadata-only commit that adds no snapshot. - const int64_t base_current_snapshot_id = ctx_->table->metadata()->current_snapshot_id; int32_t attempt = 0; std::string last_error; try { @@ -444,17 +442,35 @@ Result> Transaction::Commit() { } if (commit_result) { - // Name the resulting snapshot only when this commit produced one (current - // snapshot advanced); metadata-only commits report a plain success. + // The builder contains only changes made by the successful attempt. Inspecting + // AddSnapshot changes avoids attributing a concurrent writer's snapshot to this + // transaction and also detects snapshots committed with StageOnly or ToBranch. std::string detail; - if (auto snapshot = commit_result.value()->metadata()->Snapshot(); - snapshot.has_value() && - snapshot.value()->snapshot_id != base_current_snapshot_id) { - const auto& summary = snapshot.value()->summary; - auto op = summary.find(SnapshotSummaryFields::kOperation); - detail = - std::format(": committed snapshot {} (op={})", snapshot.value()->snapshot_id, - op != summary.end() ? op->second : "unknown"); + const auto& changes = ctx_->metadata_builder->changes(); + size_t added_snapshot_count = 0; + for (const auto& change : changes) { + added_snapshot_count += change->kind() == TableUpdate::Kind::kAddSnapshot; + } + if (added_snapshot_count > 0) { + detail.reserve(32 + added_snapshot_count * 48); + std::format_to(std::back_inserter(detail), ": committed snapshot{} ", + added_snapshot_count == 1 ? "" : "s"); + + size_t appended_snapshot_count = 0; + for (const auto& change : changes) { + if (change->kind() != TableUpdate::Kind::kAddSnapshot) { + continue; + } + const auto& snapshot = + internal::checked_cast(*change).snapshot(); + if (appended_snapshot_count++ > 0) { + detail += ", "; + } + const auto& summary = snapshot->summary; + auto op = summary.find(SnapshotSummaryFields::kOperation); + std::format_to(std::back_inserter(detail), "{} (op={})", snapshot->snapshot_id, + op != summary.end() ? op->second : "unknown"); + } } if (attempt > 1) { ICEBERG_LOG_INFO("Transaction commit succeeded after {} attempts{}", attempt, @@ -462,9 +478,6 @@ Result> Transaction::Commit() { } else { ICEBERG_LOG_INFO("Transaction commit succeeded{}", detail); } - } else { - ICEBERG_LOG_ERROR("Transaction commit failed after {} attempt(s): {}", attempt, - commit_result.error().message); } if (!commit_result) { From 649a662a8e6a22246c380b3bf47560b95be1b91d Mon Sep 17 00:00:00 2001 From: Gang Wu Date: Sat, 19 Sep 2026 22:16:46 +0800 Subject: [PATCH 4/4] fix(logging): avoid misleading transaction commit logs --- src/iceberg/transaction.cc | 108 ++++++++++++++++++++----------------- 1 file changed, 60 insertions(+), 48 deletions(-) diff --git a/src/iceberg/transaction.cc b/src/iceberg/transaction.cc index f9ef56141..58101b61d 100644 --- a/src/iceberg/transaction.cc +++ b/src/iceberg/transaction.cc @@ -63,6 +63,42 @@ namespace iceberg { +namespace { + +std::string FormatCommittedSnapshots( + const std::vector>& changes) { + size_t snapshot_count = 0; + for (const auto& change : changes) { + snapshot_count += change->kind() == TableUpdate::Kind::kAddSnapshot; + } + if (snapshot_count == 0) { + return {}; + } + + std::string detail; + detail.reserve(32 + snapshot_count * 48); + std::format_to(std::back_inserter(detail), ": committed snapshot{} ", + snapshot_count == 1 ? "" : "s"); + + size_t formatted_count = 0; + for (const auto& change : changes) { + if (change->kind() != TableUpdate::Kind::kAddSnapshot) { + continue; + } + const auto& snapshot = + internal::checked_cast(*change).snapshot(); + if (formatted_count++ > 0) { + detail += ", "; + } + const auto operation = snapshot->summary.find(SnapshotSummaryFields::kOperation); + std::format_to(std::back_inserter(detail), "{} (op={})", snapshot->snapshot_id, + operation != snapshot->summary.end() ? operation->second : "unknown"); + } + return detail; +} + +} // namespace + // --------------------------------------------------------------------------- // TransactionContext // --------------------------------------------------------------------------- @@ -418,20 +454,23 @@ Result> Transaction::Commit() { props.Get(TableProperties::kCommitMinRetryWaitMs), props.Get(TableProperties::kCommitMaxRetryWaitMs), props.Get(TableProperties::kCommitTotalRetryTimeMs)) - .Run([this, &is_first_attempt, &attempt, - &last_error]() -> Result> { - ++attempt; - if (attempt > 1) { - ICEBERG_LOG_WARN("Retrying transaction commit (attempt {}) after: {}", - attempt, last_error); - } - auto result = CommitOnce(is_first_attempt); - is_first_attempt = false; - if (!result) { - last_error = result.error().message; - } - return result; - }); + .Run( + [this, &is_first_attempt, &attempt, + &last_error]() -> Result> { + if (attempt > 1) { + ICEBERG_LOG_WARN( + "Retrying transaction commit for table {} (attempt {}) after: " + "{}", + ctx_->table->name().ToString(), attempt, last_error); + } + auto result = CommitOnce(is_first_attempt); + is_first_attempt = false; + if (!result) { + last_error = result.error().message; + } + return result; + }, + &attempt); } } catch (const std::exception& e) { // CommitOnce handles catalog exceptions, so this failed before the commit. @@ -441,42 +480,15 @@ Result> Transaction::Commit() { ValidationFailed("Transaction preparation threw an unknown exception"); } - if (commit_result) { - // The builder contains only changes made by the successful attempt. Inspecting - // AddSnapshot changes avoids attributing a concurrent writer's snapshot to this - // transaction and also detects snapshots committed with StageOnly or ToBranch. - std::string detail; - const auto& changes = ctx_->metadata_builder->changes(); - size_t added_snapshot_count = 0; - for (const auto& change : changes) { - added_snapshot_count += change->kind() == TableUpdate::Kind::kAddSnapshot; - } - if (added_snapshot_count > 0) { - detail.reserve(32 + added_snapshot_count * 48); - std::format_to(std::back_inserter(detail), ": committed snapshot{} ", - added_snapshot_count == 1 ? "" : "s"); - - size_t appended_snapshot_count = 0; - for (const auto& change : changes) { - if (change->kind() != TableUpdate::Kind::kAddSnapshot) { - continue; - } - const auto& snapshot = - internal::checked_cast(*change).snapshot(); - if (appended_snapshot_count++ > 0) { - detail += ", "; - } - const auto& summary = snapshot->summary; - auto op = summary.find(SnapshotSummaryFields::kOperation); - std::format_to(std::back_inserter(detail), "{} (op={})", snapshot->snapshot_id, - op != summary.end() ? op->second : "unknown"); - } - } + if (commit_result && !ctx_->metadata_builder->changes().empty()) { if (attempt > 1) { - ICEBERG_LOG_INFO("Transaction commit succeeded after {} attempts{}", attempt, - detail); + ICEBERG_LOG_INFO("Transaction commit for table {} succeeded after {} attempts{}", + ctx_->table->name().ToString(), attempt, + FormatCommittedSnapshots(ctx_->metadata_builder->changes())); } else { - ICEBERG_LOG_INFO("Transaction commit succeeded{}", detail); + ICEBERG_LOG_INFO("Transaction commit for table {} succeeded{}", + ctx_->table->name().ToString(), + FormatCommittedSnapshots(ctx_->metadata_builder->changes())); } }