From c4558f91eb5729c1401015def9e09698d88906ea Mon Sep 17 00:00:00 2001 From: Kam Cheung Ting Date: Mon, 17 Aug 2026 08:57:56 +0000 Subject: [PATCH 1/2] 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/test/transaction_test.cc | 85 ++++++++++++++++++++++++++++ src/iceberg/transaction.cc | 26 ++++++++- 2 files changed, 110 insertions(+), 1 deletion(-) diff --git a/src/iceberg/test/transaction_test.cc b/src/iceberg/test/transaction_test.cc index 3a13b7bc5d..46a645bd2e 100644 --- a/src/iceberg/test/transaction_test.cc +++ b/src/iceberg/test/transaction_test.cc @@ -21,7 +21,9 @@ #include "iceberg/expression/expressions.h" #include "iceberg/expression/term.h" +#include "iceberg/logging/log_level.h" #include "iceberg/sort_order.h" +#include "iceberg/test/logging_test_helpers.h" #include "iceberg/test/matchers.h" #include "iceberg/test/mock_catalog.h" #include "iceberg/test/update_test_base.h" @@ -173,6 +175,89 @@ TEST_F(TransactionRetryTest, CommitRetryExhausted) { EXPECT_EQ(update_call_count, 5); } +namespace { +// True if any captured record has the given level and a message containing `needle`. +bool HasRecord(const std::vector& records, LogLevel level, + std::string_view needle) { + for (const auto& record : records) { + if (record.level == level && record.message.find(needle) != std::string::npos) { + return true; + } + } + return false; +} +} // namespace + +// A commit that succeeds after one retryable conflict emits a WARN for the retry +// (carrying the prior error) and an INFO for the eventual success. +TEST_F(TransactionRetryTest, CommitRetryEmitsRetryAndSuccessLogs) { + auto capturing = std::make_shared(); + capturing->SetLevel(LogLevel::kTrace); + ScopedDefaultLogger guard(capturing); + + int update_call_count = 0; + ON_CALL(*mock_catalog_, UpdateTable(::testing::_, ::testing::_, ::testing::_)) + .WillByDefault([this, &update_call_count]( + const TableIdentifier&, + const std::vector>&, + const std::vector>&) + -> Result> { + ++update_call_count; + if (update_call_count == 1) { + return CommitFailed("conflict on first attempt"); + } + return Table::Make(mock_table_->name(), mock_table_->metadata(), + std::string(mock_table_->metadata_file_location()), + mock_table_->io(), mock_catalog_); + }); + + ICEBERG_UNWRAP_OR_FAIL(auto txn, mock_table_->NewTransaction()); + ICEBERG_UNWRAP_OR_FAIL(auto update, txn->NewUpdateProperties()); + update->Set("retry.test", "value"); + EXPECT_THAT(update->Commit(), IsOk()); + EXPECT_THAT(txn->Commit(), IsOk()); + + auto records = capturing->records(); + EXPECT_TRUE( + HasRecord(records, LogLevel::kWarn, "Retrying transaction commit (attempt 2)")) + << "expected a retry WARN"; + EXPECT_TRUE(HasRecord(records, LogLevel::kWarn, "conflict on first attempt")) + << "retry WARN should carry the prior error"; + EXPECT_TRUE(HasRecord(records, LogLevel::kInfo, "succeeded after 2 attempts")) + << "expected a success INFO"; +} + +// A commit that exhausts its retries emits an ERROR with the attempt count and the +// final error. +TEST_F(TransactionRetryTest, CommitRetryExhaustedEmitsErrorLog) { + auto capturing = std::make_shared(); + capturing->SetLevel(LogLevel::kTrace); + ScopedDefaultLogger guard(capturing); + + ON_CALL(*mock_catalog_, UpdateTable(::testing::_, ::testing::_, ::testing::_)) + .WillByDefault([](const TableIdentifier&, + const std::vector>&, + const std::vector>&) + -> Result> { + return CommitFailed("always conflicts"); + }); + + ICEBERG_UNWRAP_OR_FAIL(auto txn, mock_table_->NewTransaction()); + ICEBERG_UNWRAP_OR_FAIL(auto update, txn->NewUpdateProperties()); + update->Set("retry.test", "value"); + EXPECT_THAT(update->Commit(), IsOk()); + EXPECT_THAT(txn->Commit(), IsError(ErrorKind::kCommitFailed)); + + auto records = capturing->records(); + EXPECT_TRUE(HasRecord(records, LogLevel::kError, "failed after 5 attempt(s)")) + << "expected a final ERROR with the attempt count"; + EXPECT_TRUE(HasRecord(records, LogLevel::kError, "always conflicts")) + << "final ERROR should carry the last error"; + // Retries 2..5 each log a WARN. + EXPECT_TRUE( + HasRecord(records, LogLevel::kWarn, "Retrying transaction commit (attempt 5)")); +} + TEST_F(TransactionRetryTest, CommitNonRetryableErrorStopsImmediately) { int update_call_count = 0; ON_CALL(*mock_catalog_, UpdateTable(::testing::_, ::testing::_, ::testing::_)) diff --git a/src/iceberg/transaction.cc b/src/iceberg/transaction.cc index 80d39c8a89..f617ce3947 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" @@ -376,14 +378,36 @@ Result> Transaction::Commit() { int32_t total_timeout_ms = props.Get(TableProperties::kCommitTotalRetryTimeMs); bool is_first_attempt = true; + int32_t attempt = 0; + std::string last_error; auto commit_result = MakeCommitRetryRunner(num_retries, min_wait_ms, max_wait_ms, total_timeout_ms) - .Run([this, &is_first_attempt]() -> Result> { + .Run([this, &is_first_attempt, &attempt, + &last_error]() -> Result> { + ++attempt; + // The runner only re-invokes this task when it has decided to retry, so + // attempt > 1 here means a genuine retry after a retryable failure. + 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.has_value()) { + last_error = result.error().message; + } return result; }); + if (commit_result.has_value()) { + 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); + } + Result finalize_result = commit_result.has_value() ? Result(commit_result.value()->metadata().get()) From eb6235874070cf3e1af222ffa501ed231fd76da0 Mon Sep 17 00:00:00 2001 From: Kam Cheung Ting Date: Mon, 17 Aug 2026 09:09:21 +0000 Subject: [PATCH 2/2] 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 ++ .../test/table_metadata_builder_test.cc | 25 ++++++++++++++++ src/iceberg/test/transaction_test.cc | 30 +++++++++++++++++++ src/iceberg/transaction.cc | 20 ++++++++++++- 4 files changed, 77 insertions(+), 1 deletion(-) diff --git a/src/iceberg/table_metadata.cc b/src/iceberg/table_metadata.cc index 94a154501b..40922cc129 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" @@ -1099,6 +1100,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/test/table_metadata_builder_test.cc b/src/iceberg/test/table_metadata_builder_test.cc index 0d10722bb1..9ebbfc327b 100644 --- a/src/iceberg/test/table_metadata_builder_test.cc +++ b/src/iceberg/test/table_metadata_builder_test.cc @@ -24,6 +24,7 @@ #include #include +#include "iceberg/logging/log_level.h" #include "iceberg/partition_spec.h" #include "iceberg/result.h" #include "iceberg/schema.h" @@ -33,6 +34,7 @@ #include "iceberg/table_metadata.h" #include "iceberg/table_properties.h" #include "iceberg/table_update.h" +#include "iceberg/test/logging_test_helpers.h" #include "iceberg/test/matchers.h" #include "iceberg/transform.h" #include "iceberg/type.h" @@ -1185,6 +1187,29 @@ TEST(TableMetadataBuilderTest, RemoveSchemasAfterSchemaChange) { ASSERT_THAT(builder->Build(), HasErrorMessage("Cannot remove current schema: 1")); } +// Adding a snapshot to the builder emits a DEBUG record naming the snapshot. +TEST(TableMetadataBuilderTest, AddSnapshotEmitsDebugLog) { + auto capturing = std::make_shared(); + capturing->SetLevel(LogLevel::kTrace); + ScopedDefaultLogger guard(capturing); + + auto base = CreateBaseMetadata(); + auto builder = TableMetadataBuilder::BuildFrom(base.get()); + builder->AddSnapshot( + std::make_shared(Snapshot{.snapshot_id = 42, .sequence_number = 7})); + ICEBERG_UNWRAP_OR_FAIL(auto metadata, builder->Build()); + + bool found = false; + for (const auto& record : capturing->records()) { + if (record.level == LogLevel::kDebug && + record.message.find("Added snapshot 42") != std::string::npos) { + found = true; + break; + } + } + EXPECT_TRUE(found) << "expected a DEBUG record naming the added snapshot"; +} + TEST(TableMetadataBuilderTest, RemoveSnapshotRef) { auto base = CreateBaseMetadata(); auto builder = TableMetadataBuilder::BuildFrom(base.get()); diff --git a/src/iceberg/test/transaction_test.cc b/src/iceberg/test/transaction_test.cc index 46a645bd2e..5da46a8a63 100644 --- a/src/iceberg/test/transaction_test.cc +++ b/src/iceberg/test/transaction_test.cc @@ -258,6 +258,36 @@ TEST_F(TransactionRetryTest, CommitRetryExhaustedEmitsErrorLog) { HasRecord(records, LogLevel::kWarn, "Retrying transaction commit (attempt 5)")); } +// A commit that succeeds on the first attempt emits a plain success INFO (no +// "after N attempts"). This is the single-attempt case that was previously silent. +TEST_F(TransactionRetryTest, CommitSuccessEmitsInfoLog) { + auto capturing = std::make_shared(); + capturing->SetLevel(LogLevel::kTrace); + ScopedDefaultLogger guard(capturing); + + ON_CALL(*mock_catalog_, UpdateTable(::testing::_, ::testing::_, ::testing::_)) + .WillByDefault([this](const TableIdentifier&, + const std::vector>&, + const std::vector>&) + -> Result> { + return Table::Make(mock_table_->name(), mock_table_->metadata(), + std::string(mock_table_->metadata_file_location()), + mock_table_->io(), mock_catalog_); + }); + + ICEBERG_UNWRAP_OR_FAIL(auto txn, mock_table_->NewTransaction()); + ICEBERG_UNWRAP_OR_FAIL(auto update, txn->NewUpdateProperties()); + update->Set("retry.test", "value"); + EXPECT_THAT(update->Commit(), IsOk()); + EXPECT_THAT(txn->Commit(), IsOk()); + + auto records = capturing->records(); + EXPECT_TRUE(HasRecord(records, LogLevel::kInfo, "Transaction commit succeeded")) + << "expected a success INFO on a single-attempt commit"; + // No retry happened, so there must be no retry WARN. + EXPECT_FALSE(HasRecord(records, LogLevel::kWarn, "Retrying transaction commit")); +} + TEST_F(TransactionRetryTest, CommitNonRetryableErrorStopsImmediately) { int update_call_count = 0; ON_CALL(*mock_catalog_, UpdateTable(::testing::_, ::testing::_, ::testing::_)) diff --git a/src/iceberg/transaction.cc b/src/iceberg/transaction.cc index f617ce3947..df978908b4 100644 --- a/src/iceberg/transaction.cc +++ b/src/iceberg/transaction.cc @@ -377,6 +377,9 @@ Result> Transaction::Commit() { int32_t max_wait_ms = props.Get(TableProperties::kCommitMaxRetryWaitMs); int32_t total_timeout_ms = props.Get(TableProperties::kCommitTotalRetryTimeMs); + // 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; bool is_first_attempt = true; int32_t attempt = 0; std::string last_error; @@ -400,8 +403,23 @@ Result> Transaction::Commit() { }); if (commit_result.has_value()) { + // 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,