diff options
| author | kseleznyov <[email protected]> | 2026-07-08 22:57:00 +0300 |
|---|---|---|
| committer | GitHub <[email protected]> | 2026-07-08 22:57:00 +0300 |
| commit | da54c4c178a73e910ccdf2f38e99014e2267f537 (patch) | |
| tree | a9575c8cbc513f2baeebb2ec057a3a0de91681fd | |
| parent | af7af25a00bff4809add9fc4f994cdc9aaf6a32d (diff) | |
[YDB_LOG] Migrate ydb/core/tx/long_tx_service (#44656)
| -rw-r--r-- | ydb/core/tx/long_tx_service/acquire_snapshot_impl.cpp | 40 | ||||
| -rw-r--r-- | ydb/core/tx/long_tx_service/commit_impl.cpp | 82 | ||||
| -rw-r--r-- | ydb/core/tx/long_tx_service/long_tx_service_impl.cpp | 242 | ||||
| -rw-r--r-- | ydb/core/tx/long_tx_service/snapshots_exchange.cpp | 208 |
4 files changed, 381 insertions, 191 deletions
diff --git a/ydb/core/tx/long_tx_service/acquire_snapshot_impl.cpp b/ydb/core/tx/long_tx_service/acquire_snapshot_impl.cpp index 52558c3a5ab..4f7a1953d1b 100644 --- a/ydb/core/tx/long_tx_service/acquire_snapshot_impl.cpp +++ b/ydb/core/tx/long_tx_service/acquire_snapshot_impl.cpp @@ -8,11 +8,7 @@ #include <util/random/random.h> -#define TXLOG_LOG(priority, stream) \ - LOG_LOG_S(*TlsActivationContext, priority, NKikimrServices::LONG_TX_SERVICE, LogPrefix << stream) -#define TXLOG_DEBUG(stream) TXLOG_LOG(NActors::NLog::PRI_DEBUG, stream) -#define TXLOG_NOTICE(stream) TXLOG_LOG(NActors::NLog::PRI_NOTICE, stream) -#define TXLOG_ERROR(stream) TXLOG_LOG(NActors::NLog::PRI_ERROR, stream) +#define YDB_LOG_THIS_FILE_COMPONENT NKikimrServices::LONG_TX_SERVICE namespace NKikimr { namespace NLongTxService { @@ -45,7 +41,9 @@ namespace NLongTxService { private: void SendNavigateRequest() { - TXLOG_DEBUG("Sending navigate request for " << DatabaseName); + YDB_LOG_DEBUG("Sending navigate request", + {"logPrefix", LogPrefix}, + {"databaseName", DatabaseName}); auto request = MakeHolder<NSchemeCache::TSchemeCacheNavigate>(); request->DatabaseName = DatabaseName; auto& entry = request->ResultSet.emplace_back(); @@ -64,7 +62,9 @@ namespace NLongTxService { } void Handle(TEvents::TEvUndelivered::TPtr& ev) { - TXLOG_DEBUG("Received undelivered from " << ev->Sender); + YDB_LOG_DEBUG("Received undelivered", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}); ReplyError(Ydb::StatusIds::UNAVAILABLE, "An essential service is unavailable"); } @@ -72,7 +72,9 @@ namespace NLongTxService { NSchemeCache::TSchemeCacheNavigate* resp = ev->Get()->Request.Get(); const auto& entry = resp->ResultSet.at(0); - TXLOG_DEBUG("Received navigate response status " << entry.Status); + YDB_LOG_DEBUG("Received navigate response status", + {"logPrefix", LogPrefix}, + {"status", entry.Status}); switch (entry.Status) { case NSchemeCache::TSchemeCacheNavigate::EStatus::Ok: @@ -95,7 +97,7 @@ namespace NLongTxService { case NSchemeCache::TSchemeCacheNavigate::EStatus::RedirectLookupError: case NSchemeCache::TSchemeCacheNavigate::EStatus::LookupError: return ReplyError(Ydb::StatusIds::UNAVAILABLE, "Schema service unavailable"); - + case NSchemeCache::TSchemeCacheNavigate::EStatus::AccessDenied: return ReplyError(Ydb::StatusIds::UNAUTHORIZED, "Access denied"); } @@ -126,7 +128,9 @@ namespace NLongTxService { void SendAcquireStep(ui64 coordinator) { if (WaitingCoordinators.insert(coordinator).second) { - TXLOG_DEBUG("Sending acquire step to coordinator " << coordinator); + YDB_LOG_DEBUG("Sending acquire step to coordinator", + {"logPrefix", LogPrefix}, + {"coordinator", coordinator}); SendToTablet(coordinator, MakeHolder<TEvTxProxy::TEvAcquireReadStep>(coordinator)); } } @@ -143,9 +147,10 @@ namespace NLongTxService { const auto* msg = ev->Get(); const ui64 tabletId = msg->TabletId; - TXLOG_DEBUG("Delivery problem" - << " TabletId# " << tabletId - << " NotDelivered# " << msg->NotDelivered); + YDB_LOG_DEBUG("Delivery problem", + {"logPrefix", LogPrefix}, + {"tabletId", tabletId}, + {"notDelivered", msg->NotDelivered}); WaitingCoordinators.erase(tabletId); if (WaitingCoordinators.empty() && !BackupCoordinators.empty()) { @@ -162,7 +167,9 @@ namespace NLongTxService { void Handle(TEvTxProxy::TEvAcquireReadStepResult::TPtr& ev) { const auto* msg = ev->Get(); const ui64 step = msg->Record.GetStep(); - TXLOG_DEBUG("Received read step " << step); + YDB_LOG_DEBUG("Received read step", + {"logPrefix", LogPrefix}, + {"step", step}); ReplySuccess(TRowVersion(step, Max<ui64>())); } @@ -173,7 +180,10 @@ namespace NLongTxService { } void ReplyError(Ydb::StatusIds::StatusCode status, const TString& message) { - TXLOG_DEBUG("Replying with error " << status << ": " << message); + YDB_LOG_DEBUG("Replying with error", + {"logPrefix", LogPrefix}, + {"status", status}, + {"message", message}); NYql::TIssues issues; issues.AddIssue(message); Send(Parent, new TEvPrivate::TEvAcquireSnapshotFinished(status, std::move(issues)), 0, Cookie); diff --git a/ydb/core/tx/long_tx_service/commit_impl.cpp b/ydb/core/tx/long_tx_service/commit_impl.cpp index e8d3311b96e..baf4b604b1a 100644 --- a/ydb/core/tx/long_tx_service/commit_impl.cpp +++ b/ydb/core/tx/long_tx_service/commit_impl.cpp @@ -7,11 +7,7 @@ #include <ydb/library/actors/core/actor_bootstrapped.h> -#define TXLOG_LOG(priority, stream) \ - LOG_LOG_S(*TlsActivationContext, priority, NKikimrServices::LONG_TX_SERVICE, LogPrefix << stream) -#define TXLOG_DEBUG(stream) TXLOG_LOG(NActors::NLog::PRI_DEBUG, stream) -#define TXLOG_NOTICE(stream) TXLOG_LOG(NActors::NLog::PRI_NOTICE, stream) -#define TXLOG_ERROR(stream) TXLOG_LOG(NActors::NLog::PRI_ERROR, stream) +#define YDB_LOG_THIS_FILE_COMPONENT NKikimrServices::LONG_TX_SERVICE namespace NKikimr { namespace NLongTxService { @@ -65,7 +61,8 @@ namespace NLongTxService { } void SendAllocateTxId() { - TXLOG_DEBUG("Allocating TxId"); + YDB_LOG_DEBUG("Allocating TxId", + {"logPrefix", LogPrefix}); Send(MakeTxProxyID(), new TEvTxUserProxy::TEvAllocateTxId); Become(&TThis::StateAllocateTxId); } @@ -81,7 +78,8 @@ namespace NLongTxService { TxId = msg->TxId; Services = msg->Services; LogPrefix = TStringBuilder() << LogPrefix << " TxId# " << TxId << " "; - TXLOG_DEBUG("Allocated TxId"); + YDB_LOG_DEBUG("Allocated TxId", + {"logPrefix", LogPrefix}); PrepareTransaction(); } @@ -124,7 +122,10 @@ namespace NLongTxService { return true; } - TXLOG_DEBUG("Sending TEvProposeTransaction to ColumnShard# " << tabletId << " WriteId# " << data.GetWriteIdsStr()); + YDB_LOG_DEBUG("Sending TEvProposeTransaction", + {"logPrefix", LogPrefix}, + {"toColumnShard", tabletId}, + {"writeId", data.GetWriteIdsStr()}); SendToTablet(tabletId, MakeHolder<TEvColumnShard::TEvProposeTransaction>( NKikimrTxColumnShard::TX_KIND_COMMIT, @@ -149,15 +150,19 @@ namespace NLongTxService { if (!SelectedCoordinator) { SelectedCoordinator = privateCoordinator; - TXLOG_DEBUG("Selected coordinator " << SelectedCoordinator); + YDB_LOG_DEBUG("Selected coordinator", + {"logPrefix", LogPrefix}, + {"selectedCoordinator", SelectedCoordinator}); } if (!SelectedCoordinator || SelectedCoordinator != privateCoordinator) { TString error = "Unable to choose coordinator for all participants"; - TXLOG_ERROR(error - << ": previous coordinator " << SelectedCoordinator - << ", current coordinator " << privateCoordinator - << ", Tablet# " << tabletId); + YDB_LOG_ERROR("previous coordinator current coordinator", + {"logPrefix", LogPrefix}, + {"error", error}, + {"selectedCoordinator", SelectedCoordinator}, + {"privateCoordinator", privateCoordinator}, + {"tablet", tabletId}); NYql::TIssues issues; issues.AddIssue(MakeIssue(NKikimrIssues::TIssuesIds::TX_DECLINED_IMPLICIT_COORDINATOR, error)); FinishWithError(Ydb::StatusIds::INTERNAL_ERROR, std::move(issues)); @@ -172,9 +177,10 @@ namespace NLongTxService { const ui64 tabletId = msg->Record.GetOrigin(); const NKikimrTxColumnShard::EResultStatus status = msg->Record.GetStatus(); - TXLOG_DEBUG("Received TEvProposeTransactionResult from" - << " ColumnShard# " << tabletId - << " Status# " << NKikimrTxColumnShard::EResultStatus_Name(status)); + YDB_LOG_DEBUG("Received TEvProposeTransactionResult", + {"logPrefix", LogPrefix}, + {"columnShard", tabletId}, + {"status", NKikimrTxColumnShard::EResultStatus_Name(status)}); switch (status) { case NKikimrTxColumnShard::PREPARED: { @@ -215,9 +221,10 @@ namespace NLongTxService { const ui64 tabletId = msg->TabletId; Y_ABORT_UNLESS(tabletId != SelectedCoordinator); - TXLOG_DEBUG("Delivery problem" - << " TabletId# " << tabletId - << " NotDelivered# " << msg->NotDelivered); + YDB_LOG_DEBUG("Delivery problem", + {"logPrefix", LogPrefix}, + {"tabletId", tabletId}, + {"notDelivered", msg->NotDelivered}); if (!WaitingShards.count(tabletId)) { return; @@ -263,7 +270,9 @@ namespace NLongTxService { WaitingShards.emplace(tabletId, TRetryData{}); } - TXLOG_DEBUG("Sending TEvProposeTransaction to SelectedCoordinator# " << SelectedCoordinator); + YDB_LOG_DEBUG("Sending TEvProposeTransaction", + {"logPrefix", LogPrefix}, + {"toSelectedCoordinator", SelectedCoordinator}); SendToTablet(SelectedCoordinator, std::move(req)); Become(&TThis::StatePlan); } @@ -285,11 +294,15 @@ namespace NLongTxService { case TEvTxProxy::TEvProposeTransactionStatus::EStatus::StatusProcessed: case TEvTxProxy::TEvProposeTransactionStatus::EStatus::StatusConfirmed: // This is just an informational status - TXLOG_DEBUG("Received TEvProposeTransactionStatus from coordinator Status# " << msg->GetStatus()); + YDB_LOG_DEBUG("Received TEvProposeTransactionStatus from coordinator", + {"logPrefix", LogPrefix}, + {"status", msg->GetStatus()}); break; case TEvTxProxy::TEvProposeTransactionStatus::EStatus::StatusPlanned: - TXLOG_DEBUG("Received TEvProposeTransactionStatus from coordinator Status# " << msg->GetStatus()); + YDB_LOG_DEBUG("Received TEvProposeTransactionStatus from coordinator", + {"logPrefix", LogPrefix}, + {"status", msg->GetStatus()}); PlanStep = msg->Record.GetStepId(); break; @@ -303,7 +316,9 @@ namespace NLongTxService { [[fallthrough]]; default: { - TXLOG_ERROR("Received TEvProposeTransactionStatus from coordinator Status# " << msg->GetStatus()); + YDB_LOG_ERROR("Received TEvProposeTransactionStatus from coordinator", + {"logPrefix", LogPrefix}, + {"status", msg->GetStatus()}); NYql::TIssues issues; issues.AddIssue("Coordinator did not accept this transaction"); return FinishWithError(Ydb::StatusIds::UNAVAILABLE, std::move(issues)); @@ -316,9 +331,10 @@ namespace NLongTxService { const ui64 tabletId = msg->Record.GetOrigin(); const auto status = msg->Record.GetStatus(); - TXLOG_DEBUG("Received TEvProposeTransactionResult from" - << " ColumnShard# " << tabletId - << " Status# " << NKikimrTxColumnShard::EResultStatus_Name(status)); + YDB_LOG_DEBUG("Received TEvProposeTransactionResult", + {"logPrefix", LogPrefix}, + {"columnShard", tabletId}, + {"status", NKikimrTxColumnShard::EResultStatus_Name(status)}); if (!WaitingShards.contains(tabletId)) { // ignore unexpected messages @@ -359,9 +375,10 @@ namespace NLongTxService { const auto* msg = ev->Get(); const ui64 tabletId = msg->TabletId; - TXLOG_DEBUG("Delivery problem" - << " TabletId# " << tabletId - << " NotDelivered# " << msg->NotDelivered); + YDB_LOG_DEBUG("Delivery problem", + {"logPrefix", LogPrefix}, + {"tabletId", tabletId}, + {"notDelivered", msg->NotDelivered}); if (tabletId == SelectedCoordinator) { if (PlanStep) { @@ -426,8 +443,11 @@ namespace NLongTxService { return true; } - TXLOG_DEBUG("Ask TEvProposeTransactionResult from ColumnShard# " << tabletId - << " for PlanStep# " << PlanStep << " TxId# " << TxId); + YDB_LOG_DEBUG("Ask TEvProposeTransactionResult", + {"logPrefix", LogPrefix}, + {"fromColumnShard", tabletId}, + {"planStep", PlanStep}, + {"txId", TxId}); SendToTablet(tabletId, MakeHolder<TEvColumnShard::TEvCheckPlannedTransaction>( SelfId(), diff --git a/ydb/core/tx/long_tx_service/long_tx_service_impl.cpp b/ydb/core/tx/long_tx_service/long_tx_service_impl.cpp index 0aa7120be97..ac7ff42323a 100644 --- a/ydb/core/tx/long_tx_service/long_tx_service_impl.cpp +++ b/ydb/core/tx/long_tx_service/long_tx_service_impl.cpp @@ -14,12 +14,7 @@ #include <ydb/library/actors/core/log.h> #include <atomic> -#define TXLOG_LOG(priority, stream) \ - LOG_LOG_S(*TlsActivationContext, priority, NKikimrServices::LONG_TX_SERVICE, LogPrefix << stream) -#define TXLOG_DEBUG(stream) TXLOG_LOG(NActors::NLog::PRI_DEBUG, stream) -#define TXLOG_NOTICE(stream) TXLOG_LOG(NActors::NLog::PRI_NOTICE, stream) -#define TXLOG_WARN(stream) TXLOG_LOG(NActors::NLog::PRI_WARN, stream) -#define TXLOG_ERROR(stream) TXLOG_LOG(NActors::NLog::PRI_ERROR, stream) +#define YDB_LOG_THIS_FILE_COMPONENT NKikimrServices::LONG_TX_SERVICE LWTRACE_USING(LONG_TX_SERVICE_PROVIDER) @@ -45,7 +40,9 @@ void TLongTxServiceActor::Bootstrap() { false, TActivationContext::ActorSystem(), SelfId()); } - TXLOG_NOTICE("Started, SelfId: " << SelfId()); + YDB_LOG_NOTICE("Started,", + {"logPrefix", LogPrefix}, + {"selfId", SelfId()}); Become(&TThis::StateWork); } @@ -114,7 +111,9 @@ void TLongTxServiceActor::Handle(TEvLongTxService::TEvBeginTx::TPtr& ev) { const auto* msg = ev->Get(); const TString& databaseName = msg->Record.GetDatabaseName(); - TXLOG_DEBUG("Received TEvBeginTx from " << ev->Sender); + YDB_LOG_DEBUG("Received TEvBeginTx", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}); switch (msg->Record.GetMode()) { case NKikimrLongTxService::TEvBeginTx::MODE_READ_ONLY: @@ -143,7 +142,9 @@ void TLongTxServiceActor::Handle(TEvLongTxService::TEvBeginTx::TPtr& ev) { tx.TxId = txId; tx.DatabaseName = databaseName; tx.State = ETxState::Active; - TXLOG_DEBUG("Created new LongTxId# " << txId); + YDB_LOG_DEBUG("Created new", + {"logPrefix", LogPrefix}, + {"longTxId", txId}); Send(ev->Sender, new TEvLongTxService::TEvBeginTxResult(txId), 0, ev->Cookie); return; } @@ -159,7 +160,10 @@ void TLongTxServiceActor::Handle(TEvLongTxService::TEvBeginTx::TPtr& ev) { void TLongTxServiceActor::Handle(TEvLongTxService::TEvCommitTx::TPtr& ev) { const auto* msg = ev->Get(); - TXLOG_DEBUG("Received TEvCommitTx from " << ev->Sender << " LongTxId# " << msg->GetLongTxId()); + YDB_LOG_DEBUG("Received TEvCommitTx", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}, + {"longTxId", msg->GetLongTxId()}); TLongTxId txId = msg->GetLongTxId(); if (!txId.IsWritable()) { @@ -182,7 +186,9 @@ void TLongTxServiceActor::Handle(TEvLongTxService::TEvCommitTx::TPtr& ev) { if (tx.ColumnShardWrites.empty()) { // There's nothing to commit, so just reply with success Send(ev->Sender, new TEvLongTxService::TEvCommitTxResult(Ydb::StatusIds::SUCCESS), 0, ev->Cookie); - TXLOG_DEBUG("Committed LongTxId# " << txId << " without side-effects"); + YDB_LOG_DEBUG("Committed without side-effects", + {"logPrefix", LogPrefix}, + {"longTxId", txId}); Transactions.erase(it); return; } @@ -201,13 +207,18 @@ void TLongTxServiceActor::Handle(TEvLongTxService::TEvCommitTxResult::TPtr& ev) ui32 nodeId = ev->Sender.NodeId(); auto* node = ProxyNodes.FindPtr(nodeId); if (!node) { - TXLOG_DEBUG("Ignored unexpected TEvCommitTxResult from node " << nodeId); + YDB_LOG_DEBUG("Ignored unexpected TEvCommitTxResult from node", + {"logPrefix", LogPrefix}, + {"nodeId", nodeId}); return; } auto it = node->ActiveRequests.find(ev->Cookie); if (it == node->ActiveRequests.end() || it->second.Type != ERequestType::Commit) { - TXLOG_DEBUG("Ignored unexpected TEvCommitTxResult from node " << nodeId << " with cookie " << ev->Cookie); + YDB_LOG_DEBUG("Ignored unexpected TEvCommitTxResult from node with cookie", + {"logPrefix", LogPrefix}, + {"nodeId", nodeId}, + {"cookie", ev->Cookie}); return; } @@ -232,7 +243,10 @@ void TLongTxServiceActor::Handle(TEvPrivate::TEvCommitFinished::TPtr& ev) { void TLongTxServiceActor::Handle(TEvLongTxService::TEvRollbackTx::TPtr& ev) { const auto* msg = ev->Get(); - TXLOG_DEBUG("Received TEvRollbackTx from " << ev->Sender << " LongTxId# " << msg->GetLongTxId()); + YDB_LOG_DEBUG("Received TEvRollbackTx", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}, + {"longTxId", msg->GetLongTxId()}); TLongTxId txId = msg->GetLongTxId(); if (!txId.IsWritable()) { @@ -260,7 +274,9 @@ void TLongTxServiceActor::Handle(TEvLongTxService::TEvRollbackTx::TPtr& ev) { } Send(ev->Sender, new TEvLongTxService::TEvRollbackTxResult(Ydb::StatusIds::SUCCESS), 0, ev->Cookie); - TXLOG_DEBUG("Erased LongTxId# " << txId); + YDB_LOG_DEBUG("Erased", + {"logPrefix", LogPrefix}, + {"longTxId", txId}); Transactions.erase(it); } @@ -268,13 +284,18 @@ void TLongTxServiceActor::Handle(TEvLongTxService::TEvRollbackTxResult::TPtr& ev ui32 nodeId = ev->Sender.NodeId(); auto* node = ProxyNodes.FindPtr(nodeId); if (!node) { - TXLOG_DEBUG("Ignored unexpected TEvRollbackTxResult from node " << nodeId); + YDB_LOG_DEBUG("Ignored unexpected TEvRollbackTxResult from node", + {"logPrefix", LogPrefix}, + {"nodeId", nodeId}); return; } auto it = node->ActiveRequests.find(ev->Cookie); if (it == node->ActiveRequests.end() || it->second.Type != ERequestType::Rollback) { - TXLOG_DEBUG("Ignored unexpected TEvRollbackTxResult from node " << nodeId << " with cookie " << ev->Cookie); + YDB_LOG_DEBUG("Ignored unexpected TEvRollbackTxResult from node with cookie", + {"logPrefix", LogPrefix}, + {"nodeId", nodeId}, + {"cookie", ev->Cookie}); return; } @@ -285,7 +306,10 @@ void TLongTxServiceActor::Handle(TEvLongTxService::TEvRollbackTxResult::TPtr& ev void TLongTxServiceActor::Handle(TEvLongTxService::TEvAttachColumnShardWrites::TPtr& ev) { const auto* msg = ev->Get(); - TXLOG_DEBUG("Received TEvAttachColumnShardWrites from " << ev->Sender << " LongTxId# " << msg->GetLongTxId()); + YDB_LOG_DEBUG("Received TEvAttachColumnShardWrites", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}, + {"longTxId", msg->GetLongTxId()}); TLongTxId txId = msg->GetLongTxId(); if (!txId.IsWritable()) { @@ -327,13 +351,18 @@ void TLongTxServiceActor::Handle(TEvLongTxService::TEvAttachColumnShardWritesRes ui32 nodeId = ev->Sender.NodeId(); auto* node = ProxyNodes.FindPtr(nodeId); if (!node) { - TXLOG_DEBUG("Ignored unexpected TEvAttachColumnShardWritesResult from node " << nodeId); + YDB_LOG_DEBUG("Ignored unexpected TEvAttachColumnShardWritesResult from node", + {"logPrefix", LogPrefix}, + {"nodeId", nodeId}); return; } auto it = node->ActiveRequests.find(ev->Cookie); if (it == node->ActiveRequests.end() || it->second.Type != ERequestType::AttachColumnShardWrites) { - TXLOG_DEBUG("Ignored unexpected TEvAttachColumnShardWritesResult from node " << nodeId << " with cookie " << ev->Cookie); + YDB_LOG_DEBUG("Ignored unexpected TEvAttachColumnShardWritesResult from node with cookie", + {"logPrefix", LogPrefix}, + {"nodeId", nodeId}, + {"cookie", ev->Cookie}); return; } @@ -366,7 +395,10 @@ void TLongTxServiceActor::Handle(TEvLongTxService::TEvAcquireReadSnapshot::TPtr& auto* msg = ev->Get(); const TString& databaseName = GetDatabaseNameOrLegacyDefault(msg->DatabaseName); - TXLOG_DEBUG("Received TEvAcquireReadSnapshot from " << ev->Sender << " for database " << databaseName); + YDB_LOG_DEBUG("Received TEvAcquireReadSnapshot from for database", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}, + {"databaseName", databaseName}); LWTRACK(AcquireReadSnapshotRequest, msg->Orbit, databaseName); @@ -402,14 +434,18 @@ void TLongTxServiceActor::ScheduleAcquireSnapshot(const TString& databaseName, T return; } - TXLOG_DEBUG("Scheduling TEvAcquireSnapshotFlush for database " << databaseName); + YDB_LOG_DEBUG("Scheduling TEvAcquireSnapshotFlush for database", + {"logPrefix", LogPrefix}, + {"databaseName", databaseName}); Schedule(AcquireSnapshotBatchDelay, new TEvPrivate::TEvAcquireSnapshotFlush(databaseName)); state.FlushPending = true; } void TLongTxServiceActor::Handle(TEvPrivate::TEvAcquireSnapshotFlush::TPtr& ev) { const auto* msg = ev->Get(); - TXLOG_DEBUG("Received TEvAcquireSnapshotFlush for database " << msg->DatabaseName); + YDB_LOG_DEBUG("Received TEvAcquireSnapshotFlush for database", + {"logPrefix", LogPrefix}, + {"databaseName", msg->DatabaseName}); auto& state = DatabaseSnapshots[msg->DatabaseName]; Y_ABORT_UNLESS(state.FlushPending); @@ -421,7 +457,9 @@ void TLongTxServiceActor::Handle(TEvPrivate::TEvAcquireSnapshotFlush::TPtr& ev) void TLongTxServiceActor::Handle(TEvPrivate::TEvAcquireSnapshotFinished::TPtr& ev) { const auto* msg = ev->Get(); - TXLOG_DEBUG("Received TEvAcquireSnapshotFinished, cookie = " << ev->Cookie); + YDB_LOG_DEBUG("Received TEvAcquireSnapshotFinished,", + {"logPrefix", LogPrefix}, + {"cookie", ev->Cookie}); auto* req = AcquireSnapshotInFlight.FindPtr(ev->Cookie); Y_ABORT_UNLESS(req, "Unexpected reply for request that is not inflight"); @@ -443,7 +481,7 @@ void TLongTxServiceActor::Handle(TEvPrivate::TEvAcquireSnapshotFinished::TPtr& e return NKqp::TSnapshotHandle{}; } }(); - + LWTRACK(AcquireReadSnapshotSuccess, userReq.Orbit, msg->Snapshot.Step, msg->Snapshot.TxId); Send(userReq.Sender, new TEvLongTxService::TEvAcquireReadSnapshotResult(databaseName, msg->Snapshot, std::move(snapshotHandle), std::move(userReq.Orbit)), 0, userReq.Cookie); } @@ -456,9 +494,13 @@ void TLongTxServiceActor::Handle(TEvPrivate::TEvAcquireSnapshotFinished::TPtr& e tx.TxId = txId; tx.DatabaseName = databaseName; tx.State = ETxState::Active; - TXLOG_DEBUG("Created new read-write LongTxId# " << txId); + YDB_LOG_DEBUG("Created new read-write", + {"logPrefix", LogPrefix}, + {"longTxId", txId}); } else { - TXLOG_DEBUG("Created new read-only LongTxId# " << txId); + YDB_LOG_DEBUG("Created new read-only", + {"logPrefix", LogPrefix}, + {"longTxId", txId}); } Send(beginReq.Sender, new TEvLongTxService::TEvBeginTxResult(txId), 0, beginReq.Cookie); } @@ -502,7 +544,10 @@ void TLongTxServiceActor::Handle(TEvLongTxService::TEvRegisterLock::TPtr& ev) { auto* msg = ev->Get(); ui64 lockId = msg->LockId; TInstant lockTimestamp = msg->LockTimestamp; - TXLOG_DEBUG("Received TEvRegisterLock for LockId# " << lockId << " LockTimestamp# " << lockTimestamp); + YDB_LOG_DEBUG("Received TEvRegisterLock", + {"logPrefix", LogPrefix}, + {"lockId", lockId}, + {"lockTimestamp", lockTimestamp}); Y_ABORT_UNLESS(lockId, "Unexpected registration of a zero LockId"); @@ -516,7 +561,9 @@ void TLongTxServiceActor::Handle(TEvLongTxService::TEvRegisterLock::TPtr& ev) { void TLongTxServiceActor::Handle(TEvLongTxService::TEvUnregisterLock::TPtr& ev) { auto* msg = ev->Get(); ui64 lockId = msg->LockId; - TXLOG_DEBUG("Received TEvUnregisterLock for LockId# " << lockId); + YDB_LOG_DEBUG("Received TEvUnregisterLock", + {"logPrefix", LogPrefix}, + {"lockId", lockId}); auto it = Locks.find(lockId); if (it == Locks.end()) { @@ -591,7 +638,11 @@ void TLongTxServiceActor::Handle(TEvLongTxService::TEvSubscribeLock::TPtr& ev) { auto& record = ev->Get()->Record; ui64 lockId = record.GetLockId(); ui32 lockNode = record.GetLockNode(); - TXLOG_DEBUG("Received TEvSubscribeLock from " << ev->Sender << " for LockId# " << lockId << " LockNode# " << lockNode); + YDB_LOG_DEBUG("Received TEvSubscribeLock from", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}, + {"lockId", lockId}, + {"lockNode", lockNode}); if (!lockId) { SendViaSession( @@ -689,9 +740,13 @@ void TLongTxServiceActor::Handle(TEvLongTxService::TEvLockStatus::TPtr& ev) { ui32 lockNode = record.GetLockNode(); auto lockStatus = record.GetStatus(); auto lockTimestamp = msg->GetLockTimestamp(); - TXLOG_DEBUG("Received TEvLockStatus from " << ev->Sender - << " for LockId# " << lockId << " LockNode# " << lockNode - << " LockStatus# " << lockStatus << " LockTimestamp# " << lockTimestamp); + YDB_LOG_DEBUG("Received TEvLockStatus from", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}, + {"lockId", lockId}, + {"lockNode", lockNode}, + {"lockStatus", lockStatus}, + {"lockTimestamp", lockTimestamp}); auto* node = ProxyNodes.FindPtr(lockNode); if (!node || node->State != EProxyState::Connected) { @@ -779,7 +834,11 @@ void TLongTxServiceActor::Handle(TEvLongTxService::TEvUnsubscribeLock::TPtr& ev) auto& record = ev->Get()->Record; ui64 lockId = record.GetLockId(); ui32 lockNode = record.GetLockNode(); - TXLOG_DEBUG("Received TEvUnsubscribeLock from " << ev->Sender << " for LockId# " << lockId << " LockNode# " << lockNode); + YDB_LOG_DEBUG("Received TEvUnsubscribeLock from", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}, + {"lockId", lockId}, + {"lockNode", lockNode}); if (!lockId) { return; @@ -938,7 +997,10 @@ void TLongTxServiceActor::SendProxyRequest(ui32 nodeId, ERequestType type, THold void TLongTxServiceActor::Handle(TEvInterconnect::TEvNodeConnected::TPtr& ev) { const ui32 nodeId = ev->Get()->NodeId; - TXLOG_DEBUG("Received TEvNodeConnected for NodeId# " << nodeId << " from session " << ev->Sender); + YDB_LOG_DEBUG("Received TEvNodeConnected for from session", + {"logPrefix", LogPrefix}, + {"nodeId", nodeId}, + {"sender", ev->Sender}); auto itNode = ProxyNodes.find(nodeId); if (itNode == ProxyNodes.end()) { @@ -983,7 +1045,10 @@ void TLongTxServiceActor::Handle(TEvInterconnect::TEvNodeConnected::TPtr& ev) { void TLongTxServiceActor::Handle(TEvInterconnect::TEvNodeDisconnected::TPtr& ev) { const ui32 nodeId = ev->Get()->NodeId; - TXLOG_DEBUG("Received TEvNodeDisconnected for NodeId# " << nodeId << " from session " << ev->Sender); + YDB_LOG_DEBUG("Received TEvNodeDisconnected for from session", + {"logPrefix", LogPrefix}, + {"nodeId", nodeId}, + {"sender", ev->Sender}); OnNodeDisconnected(nodeId, ev->Sender); } @@ -1081,10 +1146,13 @@ void TLongTxServiceActor::Handle(TEvPrivate::TEvReconnect::TPtr& ev) { void TLongTxServiceActor::Handle(TEvents::TEvUndelivered::TPtr& ev) { auto* msg = ev->Get(); - TXLOG_DEBUG("Received TEvUndelivered from " << ev->Sender << " cookie " << ev->Cookie - << " type " << msg->SourceType - << " reason " << msg->Reason - << " session " << ev->InterconnectSession); + YDB_LOG_DEBUG("Received TEvUndelivered from cookie type reason session", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}, + {"cookie", ev->Cookie}, + {"sourceType", msg->SourceType}, + {"reason", msg->Reason}, + {"interconnectSession", ev->InterconnectSession}); if (msg->SourceType == TEvInterconnect::EvConnectNode) { return OnNodeDisconnected(ev->Cookie, ev->Sender); @@ -1177,20 +1245,26 @@ TLongTxServiceActor::TLockStateHandle TLongTxServiceActor::GetAwaiterHandle(cons if (awaiterInfo.LockNodeId == SelfId().NodeId()) { auto lockIt = Locks.find(awaiterInfo.LockId); if (lockIt == Locks.end()) { - TXLOG_WARN("Local awaiter id: " << awaiterInfo.LockId << " not found"); + YDB_LOG_WARN("Local awaiter not found", + {"logPrefix", LogPrefix}, + {"id", awaiterInfo.LockId}); return TLockStateHandle{}; } return TLockStateHandle(lockIt->second); } else { auto& node = ConnectProxyNode(awaiterInfo.LockNodeId); if (node.State == EProxyState::Disconnected) { - TXLOG_WARN("Proxy node for remote awaiter id: " << awaiterInfo << " not found"); + YDB_LOG_WARN("Proxy node for remote awaiter not found", + {"logPrefix", LogPrefix}, + {"id", awaiterInfo}); return TLockStateHandle{}; } auto lockIt = node.Locks.find(awaiterInfo.LockId); if (lockIt == node.Locks.end()) { - TXLOG_WARN("Proxy lock for remote awaiter id: " << awaiterInfo << " not found"); + YDB_LOG_WARN("Proxy lock for remote awaiter not found", + {"logPrefix", LogPrefix}, + {"id", awaiterInfo}); return TLockStateHandle{}; } return TLockStateHandle(lockIt->second); @@ -1209,9 +1283,11 @@ void TLongTxServiceActor::UpdateLockWaitEdges( auto existingIt = WaitEdges.find(addedEdge.Id); if (existingIt != WaitEdges.end()) { if (existingIt->second.Blocker.LockInfo(SelfId()) != addedEdge.Blocker) { - TXLOG_ERROR("Unexpected blocker: " << existingIt->second.Blocker.LockInfo(SelfId()) - << " for duplicate added edge id: " << addedEdge.Id - << ", expected: " << addedEdge.Blocker.LockId); + YDB_LOG_ERROR("Unexpected for duplicate added edge", + {"logPrefix", LogPrefix}, + {"blocker", existingIt->second.Blocker.LockInfo(SelfId())}, + {"id", addedEdge.Id}, + {"expected", addedEdge.Blocker.LockId}); } continue; } @@ -1285,9 +1361,11 @@ void TLongTxServiceActor::UpdateLockWaitEdges( } } - TXLOG_DEBUG("Added wait edge id: " << addedEdge.Id - << ", awaiter: " << awaiterInfo - << ", blocker: " << addedEdge.Blocker); + YDB_LOG_DEBUG("Added wait edge", + {"logPrefix", LogPrefix}, + {"id", addedEdge.Id}, + {"awaiter", awaiterInfo}, + {"blocker", addedEdge.Blocker}); } TVector<TWaitEdgeId> actuallyRemoved; @@ -1300,9 +1378,11 @@ void TLongTxServiceActor::UpdateLockWaitEdges( Y_ABORT_UNLESS(it->second.Blocker); if (it->second.Awaiter.Impl != awaiter.Impl) { - TXLOG_ERROR("Unexpected awaiter: " << awaiterInfo - << " for removed edge id: " << id - << ", expected: " << awaiter.LockInfo(SelfId())); + YDB_LOG_ERROR("Unexpected for removed edge", + {"logPrefix", LogPrefix}, + {"awaiter", awaiterInfo}, + {"id", id}, + {"expected", awaiter.LockInfo(SelfId())}); continue; } @@ -1311,9 +1391,11 @@ void TLongTxServiceActor::UpdateLockWaitEdges( WaitEdges.erase(it); actuallyRemoved.push_back(id); - TXLOG_DEBUG("Removed wait edge id: " << id - << ", awaiter: " << awaiterInfo - << ", blocker: " << blockerInfo); + YDB_LOG_DEBUG("Removed wait edge", + {"logPrefix", LogPrefix}, + {"id", id}, + {"awaiter", awaiterInfo}, + {"blocker", blockerInfo}); } // 2. Send notifications @@ -1462,9 +1544,11 @@ void TLongTxServiceActor::UnlinkWaitNode(TWaitNode& waitNode) { void TLongTxServiceActor::Handle(TEvLongTxService::TEvWaitingLockAdd::TPtr& ev) { auto edgeId = TWaitEdgeId(ev->Sender, ev->Get()->RequestId); - TXLOG_DEBUG("Received TEvWaitingLockAdd for awaiter: " << ev->Get()->Lock - << ", blocker: " << ev->Get()->OtherLock - << ", edge id: " << edgeId); + YDB_LOG_DEBUG("Received TEvWaitingLockAdd for edge", + {"logPrefix", LogPrefix}, + {"awaiter", ev->Get()->Lock}, + {"blocker", ev->Get()->OtherLock}, + {"id", edgeId}); auto awaiter = GetAwaiterHandle(ev->Get()->Lock); if (!awaiter) { @@ -1482,7 +1566,9 @@ void TLongTxServiceActor::Handle(TEvLongTxService::TEvWaitingLockAdd::TPtr& ev) void TLongTxServiceActor::Handle(TEvLongTxService::TEvWaitingLockRemove::TPtr& ev) { auto edgeId = TWaitEdgeId(ev->Sender, ev->Get()->RequestId); - TXLOG_DEBUG("Received TEvWaitingLockRemove for edge id: " << edgeId); + YDB_LOG_DEBUG("Received TEvWaitingLockRemove for edge", + {"logPrefix", LogPrefix}, + {"id", edgeId}); auto edgeIt = WaitEdges.find(edgeId); if (edgeIt == WaitEdges.end()) { @@ -1496,10 +1582,12 @@ void TLongTxServiceActor::Handle(TEvLongTxService::TEvUpdateLockWaitEdges::TPtr& const auto& record = ev->Get()->Record; TLockInfo awaiterInfo(record.GetLockId(), record.GetLockNode()); - TXLOG_DEBUG("Received TEvUpdateLockWaitEdges from " << ev->Sender - << " for awaiter: " << awaiterInfo - << ", added count: " << record.GetAdded().size() - << ", removed count: " << record.GetRemoved().size()); + YDB_LOG_DEBUG("Received TEvUpdateLockWaitEdges from for added removed", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}, + {"awaiter", awaiterInfo}, + {"addedCount", record.GetAdded().size()}, + {"removedCount", record.GetRemoved().size()}); if (Settings.Counters) { Settings.Counters->WaitGraphEdgesReceived->Add( @@ -1708,9 +1796,11 @@ void TLongTxServiceActor::Handle(TEvPrivate::TEvRunDeadlockDetection::TPtr& ev) continue; } - TXLOG_DEBUG("Breaking the wait edge id: " << edge.Id - << ", awaiter: " << edge.Awaiter.LockInfo(SelfId()) - << ", blocker: " << edge.Blocker.LockInfo(SelfId())); + YDB_LOG_DEBUG("Breaking the wait edge", + {"logPrefix", LogPrefix}, + {"id", edge.Id}, + {"awaiter", edge.Awaiter.LockInfo(SelfId())}, + {"blocker", edge.Blocker.LockInfo(SelfId())}); edge.Broken = true; Send(edge.Id.OwnerId, new TEvLongTxService::TEvWaitingLockDeadlock(edge.Id.RequestId)); if (Settings.Counters) { @@ -1731,16 +1821,18 @@ void TLongTxServiceActor::Handle(TEvPrivate::TEvRunDeadlockDetection::TPtr& ev) void TLongTxServiceActor::Handle(TEvPrivate::TEvSnapshotMaintenance::TPtr&) { UpdateImmutableSnapshotsRegistry(); - TXLOG_DEBUG("Scheduled next TEvSnapshotMaintenance event in " - << AppData()->LongTxServiceConfig.GetSnapshotsRegistryUpdateIntervalSeconds() << " seconds"); + YDB_LOG_DEBUG("Scheduled next TEvSnapshotMaintenance event in seconds", + {"logPrefix", LogPrefix}, + {"interval", AppData()->LongTxServiceConfig.GetSnapshotsRegistryUpdateIntervalSeconds()}); Schedule( TDuration::Seconds(AppData()->LongTxServiceConfig.GetSnapshotsRegistryUpdateIntervalSeconds()), new TEvPrivate::TEvSnapshotMaintenance()); } -void TLongTxServiceActor::UpdateImmutableSnapshotsRegistry() { +void TLongTxServiceActor::UpdateImmutableSnapshotsRegistry() { if (!AppData()->FeatureFlags.GetEnableSnapshotsLocking()) { - TXLOG_DEBUG("Snapshots locking is disabled, clearing local and remote snapshots storage"); + YDB_LOG_DEBUG("Snapshots locking is disabled, clearing local and remote snapshots storage", + {"logPrefix", LogPrefix}); LocalSnapshotsStorage->Clear(); RemoteSnapshotsStorage->Clear(); AppData()->SnapshotRegistryHolder->Set(nullptr); @@ -1768,7 +1860,8 @@ void TLongTxServiceActor::UpdateImmutableSnapshotsRegistry() { LocalSnapshotsStorage->CleanExpired(); if (!RemoteSnapshotsStorage->IsReady()) { - TXLOG_DEBUG("Remote snapshots storage is not ready, skipping update"); + YDB_LOG_DEBUG("Remote snapshots storage is not ready, skipping update", + {"logPrefix", LogPrefix}); return; } @@ -1795,9 +1888,10 @@ void TLongTxServiceActor::UpdateImmutableSnapshotsRegistry() { } AppData()->SnapshotRegistryHolder->Set(std::move(*registryBuilder).Build()); - TXLOG_DEBUG("Updated immutable snapshots registry. " - << "Local snapshots count: " << localSnapshotsCount - << ", Remote snapshots count: " << remoteSnapshotsCount); + YDB_LOG_DEBUG("Updated immutable snapshots registry", + {"logPrefix", LogPrefix}, + {"localCount", localSnapshotsCount}, + {"remoteCount", remoteSnapshotsCount}); } void TLongTxServiceActor::Handle(NMon::TEvHttpInfo::TPtr& ev) { diff --git a/ydb/core/tx/long_tx_service/snapshots_exchange.cpp b/ydb/core/tx/long_tx_service/snapshots_exchange.cpp index e0723b59e5f..e425e944161 100644 --- a/ydb/core/tx/long_tx_service/snapshots_exchange.cpp +++ b/ydb/core/tx/long_tx_service/snapshots_exchange.cpp @@ -15,11 +15,9 @@ #include <ydb/library/services/services.pb.h> #include <library/cpp/time_provider/time_provider.h> -#define TXLOG_LOG(priority, stream) \ - LOG_LOG_S(*TlsActivationContext, priority, NKikimrServices::LONG_TX_SERVICE, LogPrefix << stream) -#define TXLOG_DEBUG(stream) TXLOG_LOG(NActors::NLog::PRI_DEBUG, stream) -#define TXLOG_NOTICE(stream) TXLOG_LOG(NActors::NLog::PRI_NOTICE, stream) -#define TXLOG_ERROR(stream) TXLOG_LOG(NActors::NLog::PRI_ERROR, stream) +#define YDB_LOG_THIS_FILE_COMPONENT NKikimrServices::LONG_TX_SERVICE + +#define YDB_LOG_THIS_FILE_COMPONENT NKikimrServices::LONG_TX_SERVICE namespace NKikimr { namespace NLongTxService { @@ -103,7 +101,8 @@ namespace { void Bootstrap() { LogPrefix = TStringBuilder() << "TTreeNodeActor [Node " << TBase::SelfId().NodeId() << "] "; if (ChildToSubtree.empty()) { - TXLOG_DEBUG("Leaf node"); + YDB_LOG_DEBUG("Leaf node", + {"logPrefix", LogPrefix}); PassAway(); return; } @@ -128,9 +127,11 @@ namespace { void Handle(TParentEvent::TPtr& ev) { AFL_ENSURE(NodeIdToTreeNodeActorId.contains(ev->Sender.NodeId())); const auto childActorId = NodeIdToTreeNodeActorId.at(ev->Sender.NodeId()); - TXLOG_DEBUG("Handling TParentEvent from " << ev->Sender - << " (NodeId: " << ev->Sender.NodeId() - << ", ChildActorId: " << childActorId << ")"); + YDB_LOG_DEBUG("Handling TParentEvent", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}, + {"nodeId", ev->Sender.NodeId()}, + {"childActorId", childActorId}); if (!ChildToSubtree.contains(childActorId)) { return; } @@ -146,8 +147,10 @@ namespace { void Handle(TEvInterconnect::TEvNodeDisconnected::TPtr& ev) { AFL_ENSURE(NodeIdToTreeNodeActorId.contains(ev->Get()->NodeId)); const auto failedActorId = NodeIdToTreeNodeActorId.at(ev->Get()->NodeId); - TXLOG_DEBUG("Handling TEvNodeDisconnected for NodeId: " << ev->Get()->NodeId - << ". Failed actor ID: " << failedActorId); + YDB_LOG_DEBUG("Handling TEvNodeDisconnected for Failed actor", + {"logPrefix", LogPrefix}, + {"nodeId", ev->Get()->NodeId}, + {"ID", failedActorId}); if (!ChildToSubtree.contains(failedActorId)) { return; } @@ -162,7 +165,9 @@ namespace { void Handle(TEvents::TEvUndelivered::TPtr& ev) { AFL_ENSURE(NodeIdToTreeNodeActorId.contains(ev->Sender.NodeId())); const TActorId failedActorId = NodeIdToTreeNodeActorId.at(ev->Sender.NodeId()); - TXLOG_DEBUG("Handling TEvents::TEvUndelivered from " << ev->Sender << "."); + YDB_LOG_DEBUG("Handling TEvents::TEvUndelivered", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}); if (!ChildToSubtree.contains(failedActorId)) { return; } @@ -185,22 +190,27 @@ namespace { subtree.erase(newRoot); AFL_ENSURE(ChildToSubtree.emplace(newRoot, std::move(subtree)).second); - TXLOG_DEBUG("Retrying subtree for child actor " << childActorId - << ". New root for subtree: " << newRoot - << ". Subtree size: " << ChildToSubtree.at(newRoot).size() << "."); + YDB_LOG_DEBUG("Retrying subtree for child actor New root for Subtree", + {"logPrefix", LogPrefix}, + {"childActorId", childActorId}, + {"subtree", newRoot}, + {"size", ChildToSubtree.at(newRoot).size()}); SendChildEvent(newRoot, ChildToSubtree.at(newRoot)); return true; } void SendChildEvent(const TActorId actorId, const THashSet<TActorId>& childActorIds) { - TXLOG_DEBUG("Sending child event to actor " << actorId << " with " << childActorIds.size() << " children"); + YDB_LOG_DEBUG("Sending child event to actor with children", + {"logPrefix", LogPrefix}, + {"actorId", actorId}, + {"childActorIdsCount", childActorIds.size()}); auto event = GetChildEvent(); for (const auto& childActorId : childActorIds) { auto childActorIdProto = event->Record.MutableTree()->AddChildrenActorIds(); ActorIdToProto(childActorId, childActorIdProto); } - + TBase::Send( actorId, event.release(), @@ -208,7 +218,9 @@ namespace { } void PassAway() final { - TXLOG_DEBUG("Passing away, sending parent event to " << ParentActorId); + YDB_LOG_DEBUG("Passing away, sending parent event", + {"logPrefix", LogPrefix}, + {"parentActorId", ParentActorId}); auto event = GetParentEvent(); TBase::Send( ParentActorId, @@ -220,7 +232,7 @@ namespace { TSubtreeSplitter SubtreeSplitter; THashMap<TActorId, THashSet<TActorId>> ChildToSubtree; THashMap<ui32, TActorId> NodeIdToTreeNodeActorId; - + protected: TString LogPrefix; @@ -243,7 +255,10 @@ namespace { AddToCollectedSnapshots(remoteSnapshot); } - TXLOG_DEBUG("Finished creating TSnapshotCollectorActor, local collection time: " << LocalCollectionTime.MilliSeconds()); + + YDB_LOG_DEBUG("Finished creating TSnapshotCollectorActor", + {"logPrefix", LogPrefix}, + {"localCollectionTime", LocalCollectionTime.MilliSeconds()}); } std::unique_ptr<TEvLongTxService::TEvCollectSnapshots> GetChildEvent() override { @@ -251,9 +266,11 @@ namespace { } std::unique_ptr<TEvLongTxService::TEvCollectSnapshotsResult> GetParentEvent() override { - TXLOG_DEBUG("Creating TEvCollectSnapshotsResult event with " - << CollectedSnapshots.size() << " collected snapshots and border " - << SnapshotBorder.Step << ":" << SnapshotBorder.TxId); + YDB_LOG_DEBUG("Creating TEvCollectSnapshotsResult event with collected snapshots and border", + {"logPrefix", LogPrefix}, + {"collectedSnapshotsSize", CollectedSnapshots.size()}, + {"snapshotBorderStep", SnapshotBorder.Step}, + {"snapshotBorderTxId", SnapshotBorder.TxId}); auto event = std::make_unique<TEvLongTxService::TEvCollectSnapshotsResult>(); event->Record.MutableSnapshots()->SetBorderStep(SnapshotBorder.Step); event->Record.MutableSnapshots()->SetBorderTxId(SnapshotBorder.TxId); @@ -296,12 +313,12 @@ namespace { for (const auto& tableIdProto : snapshot.GetTableIds()) { tableIds.emplace_back(tableIdProto.GetOwnerId(), tableIdProto.GetTableId(), tableIdProto.GetSchemaVersion()); } - + TRemoteSnapshotInfo remoteSnapshot( TRowVersion(snapshot.GetSnapshotStep(), snapshot.GetSnapshotTxId()), sessionActorId, std::move(tableIds)); - + AddToCollectedSnapshots(remoteSnapshot); } @@ -312,9 +329,12 @@ namespace { }); } - TXLOG_DEBUG("Received TEvCollectSnapshotsResult from child with" << ev->Record.GetSnapshots().GetSnapshots().size() - << " snapshots. Nodes count: " << ev->Record.GetSnapshots().GetNodesCollectionInfo().size() - << ". Updated border to " << SnapshotBorder.Step << ":" << SnapshotBorder.TxId); + YDB_LOG_DEBUG("Received TEvCollectSnapshotsResult from child with snapshots. Nodes Updated border", + {"logPrefix", LogPrefix}, + {"snapshotsCount", ev->Record.GetSnapshots().GetSnapshots().size()}, + {"nodesCount", ev->Record.GetSnapshots().GetNodesCollectionInfo().size()}, + {"snapshotBorderStep", SnapshotBorder.Step}, + {"snapshotBorderTxId", SnapshotBorder.TxId}); } private: @@ -343,9 +363,11 @@ namespace { TSnapshotPropagatorActor(TActorId parentActorId, TEvLongTxService::TEvPropagateSnapshots* event, const TSubtreeSplitter& subtreeSplitter) : TTreeNodeActor(parentActorId, event, subtreeSplitter) { Snapshots_ = event->Record.GetSnapshots(); - TXLOG_DEBUG("Initialized propagator actor with " << Snapshots_.GetSnapshots().size() - << " snapshots and border " << Snapshots_.GetBorderStep() - << ":" << Snapshots_.GetBorderTxId()); + YDB_LOG_DEBUG("Initialized propagator actor with snapshots and border", + {"logPrefix", LogPrefix}, + {"snapshotsSize", Snapshots_.GetSnapshots().size()}, + {"borderStep", Snapshots_.GetBorderStep()}, + {"borderTxId", Snapshots_.GetBorderTxId()}); } std::unique_ptr<TEvLongTxService::TEvPropagateSnapshots> GetChildEvent() override { @@ -418,14 +440,17 @@ public: void Bootstrap() { LogPrefix = TStringBuilder() << "TSnapshotsExchangerActor [Node " << SelfId().NodeId() << "] "; - TXLOG_DEBUG("Creating TSnapshotsExchangerActor with board path: " << BoardPath); + YDB_LOG_DEBUG("Creating TSnapshotsExchangerActor with board", + {"logPrefix", LogPrefix}, + {"path", BoardPath}); UpdateBoardRetrySettings(); Send(GetNameserviceActorId(), new TEvInterconnect::TEvGetNode(SelfId().NodeId())); TBase::Become(&TThis::StatePrepare); } void PassAway() { - TXLOG_DEBUG("Passing away TSnapshotsExchangerActor"); + YDB_LOG_DEBUG("Passing away TSnapshotsExchangerActor", + {"logPrefix", LogPrefix}); if (Publisher) { Send(Publisher, new TEvents::TEvPoison); } @@ -440,7 +465,7 @@ public: } STFUNC(StatePrepare) { - switch (ev->GetTypeRewrite()) { + switch (ev->GetTypeRewrite()) { hFunc(TEvInterconnect::TEvNodeInfo, Handle); hFunc(TEvStateStorage::TEvBoardInfo, Handle); @@ -492,10 +517,13 @@ private: void Handle(TEvInterconnect::TEvNodeInfo::TPtr& ev) { if (const auto& node = ev->Get()->Node) { SelfDataCenterId = node->Location.GetDataCenterId(); - TXLOG_DEBUG("Self data center ID: " << SelfDataCenterId); + YDB_LOG_DEBUG("Self data center", + {"logPrefix", LogPrefix}, + {"ID", SelfDataCenterId}); } else { SelfDataCenterId = TString(); - TXLOG_DEBUG("No node info, setting empty data center ID"); + YDB_LOG_DEBUG("No node info, setting empty data center ID", + {"logPrefix", LogPrefix}); } NKikimrLongTxService::TSnapshotExchangeBoardNodeInfo info; @@ -598,12 +626,17 @@ private: } } AFL_ENSURE(PublisherIdToExchangeActorId.size() == ExchangeActorIdToDataCenterId.size()); - TXLOG_DEBUG("Finished updating nodes, now know " << ExchangeActorIdToDataCenterId.size() << " other exchange actors"); + YDB_LOG_DEBUG("Finished updating nodes, now know other exchange actors", + {"logPrefix", LogPrefix}, + {"exchangeActorIdToDataCenterIdSize", ExchangeActorIdToDataCenterId.size()}); } void Handle(TEvLongTxService::TEvCollectSnapshots::TPtr& ev) { - TXLOG_DEBUG("Handling TEvCollectSnapshots event from " << ev->Sender - << " with " << ev->Get()->Record.GetTree().GetChildrenActorIds().size() << " children"); + YDB_LOG_DEBUG("Handling TEvCollectSnapshots event with children", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}, + {"childrenActorIdsSize", ev->Get()->Record.GetTree().GetChildrenActorIds().size()}); + const auto now = AppData()->TimeProvider->Now(); auto* collectorActor = CreateSnapshotCollectorActor( LocalSnapshotsStorage->View(now), @@ -617,10 +650,12 @@ private: } void Handle(TEvLongTxService::TEvCollectSnapshotsResult::TPtr& ev) { - TXLOG_DEBUG("Handling TEvCollectSnapshotsResult event from " << ev->Sender - << " with " << ev->Get()->Record.GetSnapshots().GetSnapshots().size() << " snapshots" - << " and border " << ev->Get()->Record.GetSnapshots().GetBorderStep() - << ":" << ev->Get()->Record.GetSnapshots().GetBorderTxId()); + YDB_LOG_DEBUG("Handling TEvCollectSnapshotsResult event from with snapshots and border", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}, + {"snapshotsSize", ev->Get()->Record.GetSnapshots().GetSnapshots().size()}, + {"borderStep", ev->Get()->Record.GetSnapshots().GetBorderStep()}, + {"borderTxId", ev->Get()->Record.GetSnapshots().GetBorderTxId()}); // Finished collecting snapshots from cluster. AFL_ENSURE(UpdateInflight); AFL_ENSURE(ev->Sender.NodeId() == SelfId().NodeId()); @@ -639,12 +674,15 @@ private: } CollectionPropagationStarted = now; } else { - TXLOG_DEBUG("Snapshots locking is disabled, skipping propagation"); + YDB_LOG_DEBUG("Snapshots locking is disabled, skipping propagation", + {"logPrefix", LogPrefix}); } } void Handle(TEvLongTxService::TEvPropagateSnapshots::TPtr& ev) { - TXLOG_DEBUG("Handling TEvPropagateSnapshots event from " << ev->Sender); + YDB_LOG_DEBUG("Handling TEvPropagateSnapshots event", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}); if (AppData()->FeatureFlags.GetEnableSnapshotsLocking()) { // Update remote snapshots storage and continue propagation THashMap<ui32, TInstant> nodeIdToCollectionTime; @@ -658,7 +696,7 @@ private: for (const auto& tableIdProto : snapshot.GetTableIds()) { tableIds.emplace_back(tableIdProto.GetOwnerId(), tableIdProto.GetTableId(), tableIdProto.GetSchemaVersion()); } - + remoteSnapshots.emplace_back(TRemoteSnapshotInfo{ TRowVersion(snapshot.GetSnapshotStep(), snapshot.GetSnapshotTxId()), sessionActorId, @@ -673,9 +711,12 @@ private: } TRowVersion border(ev->Get()->Record.GetSnapshots().GetBorderStep(), ev->Get()->Record.GetSnapshots().GetBorderTxId()); - TXLOG_DEBUG("Updating remote snapshots storage with " << remoteSnapshots.size() - << " snapshots from " << nodeIdToCollectionTime.size() << "nodes." - << " Update border to " << border.Step << ":" << border.TxId); + YDB_LOG_DEBUG("Updating remote snapshots storage with snapshots from nodes. Update border", + {"logPrefix", LogPrefix}, + {"remoteSnapshotsSize", remoteSnapshots.size()}, + {"nodeIdToCollectionTimeSize", nodeIdToCollectionTime.size()}, + {"borderStep", border.Step}, + {"borderTxId", border.TxId}); RemoteSnapshotsStorage->UpdateBorder(border); std::sort(std::begin(remoteSnapshots), std::end(remoteSnapshots), TRemoteSnapshotInfo::TComparatorBySnapshotAndSessionId{}); @@ -686,7 +727,8 @@ private: Counters.TimeSinceLastRemoteSnapshotsUpdateMs->Set(0); } } else { - TXLOG_DEBUG("Snapshots locking is disabled, skipping remote snapshots update"); + YDB_LOG_DEBUG("Snapshots locking is disabled, skipping remote snapshots update", + {"logPrefix", LogPrefix}); } auto* propagatorActor = CreateSnapshotPropagatorActor( @@ -699,7 +741,8 @@ private: } void Handle(TEvLongTxService::TEvPropagateSnapshotsResult::TPtr&) { - TXLOG_DEBUG("Handling TEvPropagateSnapshotsResult event"); + YDB_LOG_DEBUG("Handling TEvPropagateSnapshotsResult event", + {"logPrefix", LogPrefix}); // Finished propagating snapshots to cluster. AFL_ENSURE(UpdateInflight); UpdateInflight = false; @@ -711,7 +754,9 @@ private: } void Handle(TEvLongTxService::TEvRemoteSnapshotsPrefill::TPtr& ev) { - TXLOG_DEBUG("Handling TEvRemoteSnapshotsPrefill from " << ev->Sender); + YDB_LOG_DEBUG("Handling TEvRemoteSnapshotsPrefill", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}); auto resultEvent = std::make_unique<TEvLongTxService::TEvRemoteSnapshotsPrefillResult>(); @@ -726,7 +771,7 @@ private: collectedSnapshots.erase(lastSnapshotIter); } }; - + for (const auto& remoteSnapshot : RemoteSnapshotsStorage->View()) { addToCollectedSnapshots(remoteSnapshot); } @@ -769,8 +814,10 @@ private: localNodeInfoProto->SetNodeId(SelfId().NodeId()); localNodeInfoProto->SetUpdateTime(now.Seconds()); - TXLOG_DEBUG("Sending TEvRemoteSnapshotsPrefillResult to " << ev->Sender - << " with " << resultEvent->Record.GetSnapshots().GetSnapshots().size() << " snapshots"); + YDB_LOG_DEBUG("Sending TEvRemoteSnapshotsPrefillResult to with snapshots", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}, + {"snapshotsSize", resultEvent->Record.GetSnapshots().GetSnapshots().size()}); Send(ev->Sender, resultEvent.release()); } @@ -781,7 +828,8 @@ private: const bool isLeader = IsLeader(); if (AppData()->FeatureFlags.GetEnableSnapshotsLocking() && isLeader && !UpdateInflight) { - TXLOG_DEBUG("Starting snapshot collection"); + YDB_LOG_DEBUG("Starting snapshot collection", + {"logPrefix", LogPrefix}); auto collectSnapshotsEvent = std::make_unique<TEvLongTxService::TEvCollectSnapshots>(); FillTreeExchangeActors(collectSnapshotsEvent->Record.MutableTree()); @@ -790,21 +838,25 @@ private: CollectionPropagationStarted = AppData()->TimeProvider->Now(); } else if (!AppData()->FeatureFlags.GetEnableSnapshotsLocking()) { - TXLOG_DEBUG("Snapshots locking is disabled, skipping snapshot collection"); + YDB_LOG_DEBUG("Snapshots locking is disabled, skipping snapshot collection", + {"logPrefix", LogPrefix}); } else if (!isLeader) { - TXLOG_DEBUG("Not a leader, skipping snapshot collection"); + YDB_LOG_DEBUG("Not a leader, skipping snapshot collection", + {"logPrefix", LogPrefix}); } else { AFL_ENSURE(UpdateInflight); - TXLOG_DEBUG("Update already in flight, skipping snapshot collection"); + YDB_LOG_DEBUG("Update already in flight, skipping snapshot collection", + {"logPrefix", LogPrefix}); } - TXLOG_DEBUG("Scheduling next TEvRemoteSnapshotsUpdate in " - << AppData()->LongTxServiceConfig.GetSnapshotsExchangeIntervalSeconds() << " seconds"); + YDB_LOG_DEBUG("Scheduling next TEvRemoteSnapshotsUpdate in seconds", + {"logPrefix", LogPrefix}, + {"interval", AppData()->LongTxServiceConfig.GetSnapshotsExchangeIntervalSeconds()}); Schedule( TDuration::Seconds(AppData()->LongTxServiceConfig.GetSnapshotsExchangeIntervalSeconds()), new TEvPrivate::TEvRemoteSnapshotsUpdate()); } - bool IsLeader() const { + bool IsLeader() const { return std::all_of(ExchangeActorIdToDataCenterId.begin(), ExchangeActorIdToDataCenterId.end(), [this](const std::pair<TActorId, TString>& actorIdAndDataCenterId) { return actorIdAndDataCenterId.first < SelfId(); }); @@ -815,7 +867,9 @@ private: auto actorIt = PublisherIdToExchangeActorId.begin(); std::advance(actorIt, RandomNumber<ui64>(PublisherIdToExchangeActorId.size())); PrefillTargetActor = actorIt->second; - TXLOG_DEBUG("Requesting prefill from random peer: " << PrefillTargetActor); + YDB_LOG_DEBUG("Requesting prefill from random", + {"logPrefix", LogPrefix}, + {"peer", PrefillTargetActor}); auto event = std::make_unique<TEvLongTxService::TEvRemoteSnapshotsPrefill>(); Send(PrefillTargetActor, event.release(), IEventHandle::FlagTrackDelivery); @@ -827,7 +881,9 @@ private: } void Handle(TEvLongTxService::TEvRemoteSnapshotsPrefillResult::TPtr& ev) { - TXLOG_DEBUG("Handling TEvRemoteSnapshotsPrefillResult from " << ev->Sender); + YDB_LOG_DEBUG("Handling TEvRemoteSnapshotsPrefillResult", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}); AFL_ENSURE(ev->Sender == PrefillTargetActor); const auto& snapshots = ev->Get()->Record.GetSnapshots(); @@ -860,8 +916,11 @@ private: } TRowVersion border(snapshots.GetBorderStep(), snapshots.GetBorderTxId()); - TXLOG_DEBUG("Applying prefill remote snapshots: " << remoteSnapshots.size() - << ", border " << border.Step << ":" << border.TxId); + YDB_LOG_DEBUG("Applying prefill remote border", + {"logPrefix", LogPrefix}, + {"snapshots", remoteSnapshots.size()}, + {"borderStep", border.Step}, + {"borderTxId", border.TxId}); RemoteSnapshotsStorage->UpdateBorder(border); std::sort(std::begin(remoteSnapshots), std::end(remoteSnapshots), @@ -873,19 +932,26 @@ private: } void HandlePrefill(TEvInterconnect::TEvNodeDisconnected::TPtr& ev) { - TXLOG_DEBUG("Handling TEvNodeDisconnected for NodeId: " << ev->Get()->NodeId); - TXLOG_DEBUG("Prefill target disconnected, proceeding without prefill"); + YDB_LOG_DEBUG("Handling TEvNodeDisconnected", + {"logPrefix", LogPrefix}, + {"nodeId", ev->Get()->NodeId}); + YDB_LOG_DEBUG("Prefill target disconnected, proceeding without prefill", + {"logPrefix", LogPrefix}); ProceedToPublish(); } void HandlePrefill(TEvents::TEvUndelivered::TPtr& ev) { - TXLOG_DEBUG("Handling TEvents::TEvUndelivered from " << ev->Sender); - TXLOG_DEBUG("Prefill request undelivered, proceeding without prefill"); + YDB_LOG_DEBUG("Handling TEvents::TEvUndelivered", + {"logPrefix", LogPrefix}, + {"sender", ev->Sender}); + YDB_LOG_DEBUG("Prefill request undelivered, proceeding without prefill", + {"logPrefix", LogPrefix}); ProceedToPublish(); } void HandlePrefill(TEvPrivate::TEvPrefillTimeout::TPtr&) { - TXLOG_DEBUG("Prefill timed out, proceeding without prefill"); + YDB_LOG_DEBUG("Prefill timed out, proceeding without prefill", + {"logPrefix", LogPrefix}); ProceedToPublish(); } |
