summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorkseleznyov <[email protected]>2026-07-08 22:57:00 +0300
committerGitHub <[email protected]>2026-07-08 22:57:00 +0300
commitda54c4c178a73e910ccdf2f38e99014e2267f537 (patch)
treea9575c8cbc513f2baeebb2ec057a3a0de91681fd
parentaf7af25a00bff4809add9fc4f994cdc9aaf6a32d (diff)
[YDB_LOG] Migrate ydb/core/tx/long_tx_service (#44656)
-rw-r--r--ydb/core/tx/long_tx_service/acquire_snapshot_impl.cpp40
-rw-r--r--ydb/core/tx/long_tx_service/commit_impl.cpp82
-rw-r--r--ydb/core/tx/long_tx_service/long_tx_service_impl.cpp242
-rw-r--r--ydb/core/tx/long_tx_service/snapshots_exchange.cpp208
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();
}