summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorepbugaev <[email protected]>2023-01-12 19:02:01 +0300
committerepbugaev <[email protected]>2023-01-12 19:02:01 +0300
commitb48a7948c3aec8c078a24714d4da420a6225d09f (patch)
treee3cd9639c37e68f37df5017a53563a907c0db6fd
parentd2fde6cc065110a9c8955e0e25c56c8c5e721460 (diff)
Write sessionId to logs
Write sessionId to logs
-rw-r--r--ydb/library/yql/core/facade/yql_facade.cpp18
-rw-r--r--ydb/library/yql/core/file_storage/file_storage.cpp2
-rw-r--r--ydb/library/yql/providers/dq/actors/executer_actor.cpp14
-rw-r--r--ydb/library/yql/providers/dq/actors/full_result_writer.cpp6
-rw-r--r--ydb/library/yql/providers/dq/actors/graph_execution_events_actor.cpp4
-rw-r--r--ydb/library/yql/providers/dq/actors/resource_allocator.cpp6
-rw-r--r--ydb/library/yql/providers/dq/actors/result_actor_base.h24
-rw-r--r--ydb/library/yql/providers/dq/actors/result_aggregator.cpp8
-rw-r--r--ydb/library/yql/providers/dq/actors/result_receiver.cpp4
-rw-r--r--ydb/library/yql/providers/dq/actors/task_controller.cpp12
-rw-r--r--ydb/library/yql/providers/dq/actors/worker_actor.cpp12
-rw-r--r--ydb/library/yql/providers/dq/provider/exec/yql_dq_exectransformer.cpp4
-rw-r--r--ydb/library/yql/providers/dq/provider/yql_dq_gateway.cpp8
-rw-r--r--ydb/library/yql/providers/dq/worker_manager/local_worker_manager.cpp2
-rw-r--r--ydb/library/yql/utils/log/context.cpp40
-rw-r--r--ydb/library/yql/utils/log/context.h70
-rw-r--r--ydb/library/yql/utils/log/log_ut.cpp156
-rw-r--r--ydb/library/yql/utils/log/profile.cpp4
-rw-r--r--ydb/library/yql/utils/log/profile.h4
19 files changed, 287 insertions, 111 deletions
diff --git a/ydb/library/yql/core/facade/yql_facade.cpp b/ydb/library/yql/core/facade/yql_facade.cpp
index 04bed4adb9a..255f53101d7 100644
--- a/ydb/library/yql/core/facade/yql_facade.cpp
+++ b/ydb/library/yql/core/facade/yql_facade.cpp
@@ -553,7 +553,7 @@ TProgram::TFutureStatus TProgram::DiscoverAsync(const TString& username) {
}
return openSession.Apply([this](const TFuture<void>& f) {
- YQL_LOG_CTX_ROOT_SCOPE(GetSessionId());
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(GetSessionId());
try {
f.GetValue();
} catch (const std::exception& e) {
@@ -608,7 +608,7 @@ TProgram::TFutureStatus TProgram::ValidateAsync(const TString& username, IOutput
SavedExprRoot_ = ExprRoot_;
return openSession.Apply([this](const TFuture<void>& f) {
- YQL_LOG_CTX_ROOT_SCOPE(GetSessionId());
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(GetSessionId());
try {
f.GetValue();
} catch (const std::exception& e) {
@@ -680,7 +680,7 @@ TProgram::TFutureStatus TProgram::OptimizeAsync(
return NThreading::MakeFuture<TStatus>(IGraphTransformer::TStatus::Error);
return openSession.Apply([this](const TFuture<void>& f) {
- YQL_LOG_CTX_ROOT_SCOPE(GetSessionId());
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(GetSessionId());
try {
f.GetValue();
} catch (const std::exception& e) {
@@ -751,7 +751,7 @@ TProgram::TFutureStatus TProgram::OptimizeAsyncWithConfig(
SavedExprRoot_ = ExprRoot_;
return openSession.Apply([this](const TFuture<void>& f) {
- YQL_LOG_CTX_ROOT_SCOPE(GetSessionId());
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(GetSessionId());
try {
f.GetValue();
} catch (const std::exception& e) {
@@ -833,7 +833,7 @@ TProgram::TFutureStatus TProgram::RunAsync(
SavedExprRoot_ = ExprRoot_;
return openSession.Apply([this](const TFuture<void>& f) {
- YQL_LOG_CTX_ROOT_SCOPE(GetSessionId());
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(GetSessionId());
try {
f.GetValue();
} catch (const std::exception& e) {
@@ -905,7 +905,7 @@ TProgram::TFutureStatus TProgram::RunAsyncWithConfig(
SavedExprRoot_ = ExprRoot_;
return openSession.Apply([this](const TFuture<void>& f) {
- YQL_LOG_CTX_ROOT_SCOPE(GetSessionId());
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(GetSessionId());
try {
f.GetValue();
} catch (const std::exception& e) {
@@ -1236,7 +1236,7 @@ TMaybe<TString> TProgram::GetDiscoveredData() {
}
TProgram::TFutureStatus TProgram::ContinueAsync() {
- YQL_LOG_CTX_ROOT_SCOPE(GetSessionId());
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(GetSessionId());
return AsyncTransformWithFallback(true);
}
@@ -1246,7 +1246,7 @@ void TProgram::Abort()
}
void TProgram::CleanupLastSession() {
- YQL_LOG_CTX_ROOT_SCOPE(GetSessionId());
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(GetSessionId());
TString sessionId = GetSessionId();
if (sessionId.empty()) {
@@ -1261,7 +1261,7 @@ void TProgram::CleanupLastSession() {
}
void TProgram::CloseLastSession() {
- YQL_LOG_CTX_ROOT_SCOPE(GetSessionId());
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(GetSessionId());
TString sessionId = TakeSessionId();
if (sessionId.empty()) {
diff --git a/ydb/library/yql/core/file_storage/file_storage.cpp b/ydb/library/yql/core/file_storage/file_storage.cpp
index a9a59c3c6e4..963c32aca73 100644
--- a/ydb/library/yql/core/file_storage/file_storage.cpp
+++ b/ydb/library/yql/core/file_storage/file_storage.cpp
@@ -328,7 +328,7 @@ private:
}
auto logCtx = NLog::CurrentLogContextPath();
return NThreading::Async([logCtx, fs = Inner_, action]() {
- YQL_LOG_CTX_ROOT_SCOPE(logCtx);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(logCtx);
return action(fs);
}, *MtpQueue);
}
diff --git a/ydb/library/yql/providers/dq/actors/executer_actor.cpp b/ydb/library/yql/providers/dq/actors/executer_actor.cpp
index a0f7855f1eb..753306b961b 100644
--- a/ydb/library/yql/providers/dq/actors/executer_actor.cpp
+++ b/ydb/library/yql/providers/dq/actors/executer_actor.cpp
@@ -82,7 +82,7 @@ private:
HFunc(TEvQueryResponse, OnQueryResponse);
// execution timeout
cFunc(TEvents::TEvBootstrap::EventType, [this]() {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << "Execution timeout";
auto issue = TIssue("Execution timeout");
issue.SetCode(TIssuesIds::DQ_GATEWAY_NEED_FALLBACK_ERROR, TSeverityIds::S_ERROR);
@@ -129,7 +129,7 @@ private:
}
void OnGraph(TEvGraphRequest::TPtr& ev, const NActors::TActorContext&) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
Y_VERIFY(!ControlId);
Y_VERIFY(!ResultId);
YQL_CLOG(DEBUG, ProviderDq) << "TDqExecuter::OnGraph";
@@ -264,7 +264,7 @@ private:
void OnFailure(TEvDqFailure::TPtr& ev, const NActors::TActorContext&) {
if (!Finished) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << __FUNCTION__
<< ", status=" << static_cast<int>(ev->Get()->Record.GetStatusCode())
<< ", issues size=" << ev->Get()->Record.IssuesSize()
@@ -282,7 +282,7 @@ private:
}
void OnGraphFinished(TEvGraphFinished::TPtr&, const NActors::TActorContext&) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << __FUNCTION__;
if (!Finished) {
try {
@@ -299,14 +299,14 @@ private:
// TBD: wait for PoisonTaken from CheckPointCoordinator before send TEvQueryResponse to PrinterId
void OnQueryResponse(TEvQueryResponse::TPtr& ev, const TActorContext&) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << __FUNCTION__ << " status=" << static_cast<int>(ev->Get()->Record.GetStatusCode()) << " issuses_size=" << ev->Get()->Record.IssuesSize();
Send(PrinterId, ev->Release().Release());
PassAway();
}
void OnDqStats(TEvDqStats::TPtr& ev) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << __FUNCTION__;
Send(PrinterId, ev->Release().Release());
}
@@ -316,7 +316,7 @@ private:
}
void OnAllocateWorkersResponse(TEvAllocateWorkersResponse::TPtr& ev, const NActors::TActorContext&) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << "TDqExecuter::TEvAllocateWorkersResponse";
AddCounters(ev->Get()->Record);
diff --git a/ydb/library/yql/providers/dq/actors/full_result_writer.cpp b/ydb/library/yql/providers/dq/actors/full_result_writer.cpp
index 06fc24e650a..0a16965215b 100644
--- a/ydb/library/yql/providers/dq/actors/full_result_writer.cpp
+++ b/ydb/library/yql/providers/dq/actors/full_result_writer.cpp
@@ -46,7 +46,7 @@ private:
})
void PassAway() override {
- YQL_LOG_CTX_ROOT_SCOPE(TraceID);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceID);
YQL_CLOG(DEBUG, ProviderDq) << __FUNCTION__;
try {
FullResultWriter->Abort();
@@ -62,7 +62,7 @@ private:
}
void OnStatusRequest(TEvFullResultWriterStatusRequest::TPtr&, const NActors::TActorContext&) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceID);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceID);
NDqProto::TFullResultWriterStatusResponse response;
response.SetBytesReceived(BytesReceived);
if (ErrorMessage) {
@@ -72,7 +72,7 @@ private:
}
void OnWriteRequest(TEvFullResultWriterWriteRequest::TPtr& ev, const NActors::TActorContext&) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceID);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceID);
auto& request = ev->Get()->Record;
if (request.GetFinish()) {
Finish();
diff --git a/ydb/library/yql/providers/dq/actors/graph_execution_events_actor.cpp b/ydb/library/yql/providers/dq/actors/graph_execution_events_actor.cpp
index 4ab306e9bf0..2e745c03d07 100644
--- a/ydb/library/yql/providers/dq/actors/graph_execution_events_actor.cpp
+++ b/ydb/library/yql/providers/dq/actors/graph_execution_events_actor.cpp
@@ -30,11 +30,11 @@ private:
})
void DoPassAway() override {
- YQL_LOG_CTX_ROOT_SCOPE(TraceID);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceID);
}
void OnEvent(NDqs::TEvGraphExecutionEvent::TPtr& ev, const NActors::TActorContext&) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceID);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceID);
YQL_CLOG(DEBUG, ProviderDq) << __FUNCTION__ << ' ' << NYql::NDqProto::EGraphExecutionEventType_Name(ev->Get()->Record.GetEventType());
try {
diff --git a/ydb/library/yql/providers/dq/actors/resource_allocator.cpp b/ydb/library/yql/providers/dq/actors/resource_allocator.cpp
index b6011d22e21..e9a2bdd518e 100644
--- a/ydb/library/yql/providers/dq/actors/resource_allocator.cpp
+++ b/ydb/library/yql/providers/dq/actors/resource_allocator.cpp
@@ -133,7 +133,7 @@ private:
void OnAllocateWorkersResponse(TEvAllocateWorkersResponse::TPtr& ev, const TActorContext& ctx)
{
- YQL_LOG_CTX_ROOT_SCOPE(TraceId, SelfId().ToString());
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId, SelfId().ToString());
Y_UNUSED(ctx);
YQL_CLOG(DEBUG, ProviderDq) << "TEvAllocateWorkersResponse " << ev->Sender.NodeId();
@@ -219,7 +219,7 @@ private:
void DoPassAway() override
{
- YQL_LOG_CTX_ROOT_SCOPE(TraceId, SelfId().ToString());
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId, SelfId().ToString());
for (const auto& group : AllocatedWorkers) {
for (const auto& actorIdProto : group.GetWorkerActor()) {
auto actorNode = NActors::ActorIdFromProto(actorIdProto).NodeId();
@@ -269,7 +269,7 @@ private:
}
void Fail(const ui64 cookie, const TString& reason) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId, SelfId().ToString());
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId, SelfId().ToString());
if (FailState) {
return;
}
diff --git a/ydb/library/yql/providers/dq/actors/result_actor_base.h b/ydb/library/yql/providers/dq/actors/result_actor_base.h
index 849d765ebdd..4863f018dcd 100644
--- a/ydb/library/yql/providers/dq/actors/result_actor_base.h
+++ b/ydb/library/yql/providers/dq/actors/result_actor_base.h
@@ -65,7 +65,7 @@ namespace NYql::NDqs::NExecutionHelpers {
}
void OnReceiveData(NYql::NDqProto::TData&& data, const TString& messageId = "", bool autoAck = false) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
if (data.GetRows() > 0 && !ResultBuilder) {
Issues.AddIssue(TIssue("Non empty rows: >=" + ToString(data.GetRows())).SetCode(0, TSeverityIds::S_WARNING));
@@ -162,7 +162,7 @@ namespace NYql::NDqs::NExecutionHelpers {
cFunc(NActors::TEvents::TEvGone::EventType, OnFullResultWriterShutdown);
cFunc(NActors::TEvents::TEvPoison::EventType, TBase::PassAway)
default:
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << "Unexpected event " << etype;
break;
}
@@ -176,7 +176,7 @@ namespace NYql::NDqs::NExecutionHelpers {
HFunc(TEvDqFailure, OnErrorInShutdownState);
HFunc(TEvFullResultWriterAck, OnFullResultWriterAck);
default:
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << "Unexpected event " << etype;
break;
}
@@ -184,7 +184,7 @@ namespace NYql::NDqs::NExecutionHelpers {
private:
void OnQueryResult(TEvQueryResponse::TPtr& ev, const NActors::TActorContext&) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_ENSURE(!ev->Get()->Record.HasResultSet() && ev->Get()->Record.GetYson().empty());
YQL_CLOG(DEBUG, ProviderDq) << "Shutting down TResultAggregator";
@@ -202,14 +202,14 @@ namespace NYql::NDqs::NExecutionHelpers {
}
void OnFullResultWriterShutdown() {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << "Got TEvGone";
FullResultWriterID = {};
}
void OnFullResultWriterResponse(NYql::NDqs::TEvDqFailure::TPtr& ev, const NActors::TActorContext&) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << __FUNCTION__;
if (ev->Get()->Record.IssuesSize() == 0) { // weird way used by writer to acknowledge it's death
DoFinish();
@@ -220,7 +220,7 @@ namespace NYql::NDqs::NExecutionHelpers {
}
void OnUndelivered(NActors::TEvents::TEvUndelivered::TPtr& ev) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
TString message = "Undelivered from " + ToString(ev->Sender) + " to " + ToString(TBase::SelfId())
+ " reason: " + ToString(ev->Get()->Reason) + " sourceType: " + ToString(ev->Get()->SourceType >> 16)
+ "." + ToString(ev->Get()->SourceType & 0xFFFF);
@@ -228,7 +228,7 @@ namespace NYql::NDqs::NExecutionHelpers {
}
void OnFullResultWriterAck(TEvFullResultWriterAck::TPtr& ev, const NActors::TActorContext&) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << __FUNCTION__;
Y_VERIFY(ev->Get()->Record.GetMessageId() == WriteQueue.front().MessageId);
if (!WriteQueue.front().SentProcessedEvent) { // messages, received before limits exceeded, are already been reported
@@ -252,7 +252,7 @@ namespace NYql::NDqs::NExecutionHelpers {
}
void OnShutdownQueryResult(NActors::TEvents::TEvGone::TPtr& ev, const NActors::TActorContext&) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
auto iter = BlockingActors.find(ev->Sender);
if (iter != BlockingActors.end()) {
BlockingActors.erase(iter);
@@ -282,7 +282,7 @@ namespace NYql::NDqs::NExecutionHelpers {
TBase::Send(GraphExecutionEventsId, new TEvGraphExecutionEvent(record));
TBase::template Synchronize<TEvGraphExecutionEvent>([this](TEvGraphExecutionEvent::TPtr& ev) {
Y_VERIFY(ev->Get()->Record.GetEventType() == NYql::NDqProto::EGraphExecutionEventType::SYNC);
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
if (auto msg = ev->Get()->Record.GetErrorMessage()) {
OnError(NYql::NDqProto::StatusIds::UNSUPPORTED, msg);
@@ -319,7 +319,7 @@ namespace NYql::NDqs::NExecutionHelpers {
}
void DoPassAway() override {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << __FUNCTION__;
}
@@ -332,7 +332,7 @@ namespace NYql::NDqs::NExecutionHelpers {
}
void UnsafeWriteToFullResultTable() {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << __FUNCTION__;
TBase::Send(FullResultWriterID, MakeHolder<TEvFullResultWriterWriteRequest>(std::move(WriteQueue.front().WriteRequest)));
}
diff --git a/ydb/library/yql/providers/dq/actors/result_aggregator.cpp b/ydb/library/yql/providers/dq/actors/result_aggregator.cpp
index ec49e909e58..c687b5bf3ea 100644
--- a/ydb/library/yql/providers/dq/actors/result_aggregator.cpp
+++ b/ydb/library/yql/providers/dq/actors/result_aggregator.cpp
@@ -101,7 +101,7 @@ private:
}
void OnWakeup() {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << __FUNCTION__;
auto now = TInstant::Now();
if (PullRequestTimeout && now - PullRequestStartTime > PullRequestTimeout) {
@@ -123,7 +123,7 @@ private:
}
void OnReadyState(TEvReadyState::TPtr& ev, const TActorContext&) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
AddCounters(ev->Get()->Record);
SourceID = NActors::ActorIdFromProto(ev->Get()->Record.GetSourceId());
@@ -138,7 +138,7 @@ private:
}
void OnPullResult(TEvPullResult::TPtr&, const TActorContext&) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
PullRequestStartTime = TInstant::Now();
Send(SourceID, MakeHolder<TEvPullDataRequest>(MAX_RESULT_BATCH), IEventHandle::FlagTrackDelivery);
}
@@ -148,7 +148,7 @@ private:
}
void OnPullResponse(TEvPullDataResponse::TPtr& ev, const TActorContext&) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
if (FinishCalled) {
// finalization has been begun, actor will not kill himself anymore, should ignore responses instead
diff --git a/ydb/library/yql/providers/dq/actors/result_receiver.cpp b/ydb/library/yql/providers/dq/actors/result_receiver.cpp
index f14c03fad50..bdb5bbd6af4 100644
--- a/ydb/library/yql/providers/dq/actors/result_receiver.cpp
+++ b/ydb/library/yql/providers/dq/actors/result_receiver.cpp
@@ -65,7 +65,7 @@ public:
private:
void OnChannelData(NDq::TEvDqCompute::TEvChannelData::TPtr& ev, const TActorContext&) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << __FUNCTION__;
bool finishRequested = ev->Get()->Record.GetChannelData().GetFinished();
@@ -85,7 +85,7 @@ private:
}
void OnMessageProcessed(TEvMessageProcessed::TPtr& ev) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << __FUNCTION__;
SendAck(ev->Get()->MessageId);
}
diff --git a/ydb/library/yql/providers/dq/actors/task_controller.cpp b/ydb/library/yql/providers/dq/actors/task_controller.cpp
index 021fd6ddae1..02178732b16 100644
--- a/ydb/library/yql/providers/dq/actors/task_controller.cpp
+++ b/ydb/library/yql/providers/dq/actors/task_controller.cpp
@@ -106,7 +106,7 @@ private:
}
void OnAbortExecution(NDq::TEvDq::TEvAbortExecution::TPtr& ev) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
auto statusCode = ev->Get()->Record.GetStatusCode();
TIssues issues = ev->Get()->GetIssues();
YQL_CLOG(DEBUG, ProviderDq) << "AbortExecution from " << ev->Sender << ":" << NYql::NDqProto::StatusIds_StatusCode_Name(statusCode) << " " << issues.ToOneLineString();
@@ -122,7 +122,7 @@ private:
TActorId computeActor = ev->Sender;
auto& state = ev->Get()->Record;
ui64 taskId = state.GetTaskId();
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(TRACE, ProviderDq)
<< SelfId()
<< " EvState TaskId: " << taskId
@@ -473,7 +473,7 @@ private:
}
void OnReadyState(TEvReadyState::TPtr& ev) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
TaskStat.AddCounters(ev->Get()->Record);
@@ -536,7 +536,7 @@ private:
void OnResultFailure(TEvDqFailure::TPtr& ev) {
if (Finished) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(WARN, ProviderDq) << "TEvDqFailure IGNORED when Finished from " << ev->Sender;
} else {
FinalStat().FlushCounters(ev->Get()->Record); // histograms will NOT be reported
@@ -546,10 +546,10 @@ private:
}
void OnError(NYql::NDqProto::StatusIds::StatusCode statusCode, const TIssues& issues) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << "OnError " << issues.ToOneLineString() << " " << NYql::NDqProto::StatusIds_StatusCode_Name(statusCode);
if (Finished) {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(WARN, ProviderDq) << "OnError IGNORED when Finished";
} else {
auto req = MakeHolder<TEvDqFailure>(statusCode, issues);
diff --git a/ydb/library/yql/providers/dq/actors/worker_actor.cpp b/ydb/library/yql/providers/dq/actors/worker_actor.cpp
index d1da68f1c96..2596701c45e 100644
--- a/ydb/library/yql/providers/dq/actors/worker_actor.cpp
+++ b/ydb/library/yql/providers/dq/actors/worker_actor.cpp
@@ -85,18 +85,18 @@ public:
, RuntimeData(runtimeData)
, TraceId(traceId)
{
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << "TDqWorker created ";
}
~TDqWorker()
{
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << "TDqWorker destroyed ";
}
void DoPassAway() override {
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
for (const auto& inputs : InputMap) {
Send(inputs.first, new NActors::TEvents::TEvPoison());
}
@@ -211,7 +211,7 @@ private:
void OnDqTask(TEvDqTask::TPtr& ev, const NActors::TActorContext& ctx) {
Y_UNUSED(ctx);
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(DEBUG, ProviderDq) << "TDqWorker::OnDqTask";
TFailureInjector::Reach("dq_task_failure", [] {::_exit(1); });
@@ -331,7 +331,7 @@ private:
void OnPullRequest(TEvPullDataRequest::TPtr& ev, const NActors::TActorContext& ctx) {
Y_UNUSED(ctx);
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(TRACE, ProviderDq) << "TDqWorker::OnPullRequest " << ev->Sender;
if (!TaskRunnerActor || !TaskRunnerPrepared) {
@@ -385,7 +385,7 @@ private:
void OnPullResponse(TEvPullDataResponse::TPtr& ev, const NActors::TActorContext& ctx) {
Y_UNUSED(ctx);
- YQL_LOG_CTX_ROOT_SCOPE(TraceId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(TraceId);
YQL_CLOG(TRACE, ProviderDq) << "TDqWorker::OnPullResponse";
Stat.AddCounters(ev->Get()->Record);
diff --git a/ydb/library/yql/providers/dq/provider/exec/yql_dq_exectransformer.cpp b/ydb/library/yql/providers/dq/provider/exec/yql_dq_exectransformer.cpp
index be96417a15f..04630c0994c 100644
--- a/ydb/library/yql/providers/dq/provider/exec/yql_dq_exectransformer.cpp
+++ b/ydb/library/yql/providers/dq/provider/exec/yql_dq_exectransformer.cpp
@@ -1516,7 +1516,7 @@ private:
YQL_CLOG(DEBUG, ProviderDq) << "Freezing files for " << input->Content();
if (filesRes.first.Level == TStatus::Async) {
filesRes.second.Subscribe([execState = ExecState, node = input.Get(), logCtx](const TAsyncTransformCallbackFuture& future) {
- YQL_LOG_CTX_ROOT_SCOPE(logCtx);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(logCtx);
YQL_ENSURE(!future.HasException());
YQL_CLOG(DEBUG, ProviderDq) << "Finishing freezing files";
CompleteNode(execState, node, future.GetValue());
@@ -1635,7 +1635,7 @@ private:
bool neverFallback = settings->FallbackPolicy.Get().GetOrElse("default") == "never";
future.Subscribe([publicIds, state = State, startTime, execState = ExecState, node = input.Get(), neverFallback, logCtx](const NThreading::TFuture<IDqGateway::TResult>& completedFuture) {
- YQL_LOG_CTX_ROOT_SCOPE(logCtx);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(logCtx);
YQL_ENSURE(!completedFuture.HasException());
const IDqGateway::TResult& res = completedFuture.GetValueSync();
diff --git a/ydb/library/yql/providers/dq/provider/yql_dq_gateway.cpp b/ydb/library/yql/providers/dq/provider/yql_dq_gateway.cpp
index 364808c3445..bd39e74fbbd 100644
--- a/ydb/library/yql/providers/dq/provider/yql_dq_gateway.cpp
+++ b/ydb/library/yql/providers/dq/provider/yql_dq_gateway.cpp
@@ -50,7 +50,7 @@ public:
template<typename RespType>
void OnResponse(TPromise<TResult> promise, TString sessionId, NGrpc::TGrpcStatus&& status, RespType&& resp, const THashMap<TString, TString>& modulesMapping, bool alwaysFallback = false)
{
- YQL_LOG_CTX_ROOT_SCOPE(sessionId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(sessionId);
YQL_CLOG(TRACE, ProviderDq) << "TDqGateway::callback";
TResult result;
@@ -238,7 +238,7 @@ public:
const TDqProgressWriter& progressWriter, const THashMap<TString, TString>& modulesMapping,
bool discard)
{
- YQL_LOG_CTX_ROOT_SCOPE(sessionId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(sessionId);
Yql::DqsProto::ExecuteGraphRequest queryPB;
for (const auto& task : plan.Tasks) {
@@ -311,7 +311,7 @@ public:
}
TFuture<void> OpenSession(const TString& sessionId, const TString& username) {
- YQL_LOG_CTX_ROOT_SCOPE(sessionId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(sessionId);
YQL_CLOG(INFO, ProviderDq) << "OpenSession";
Yql::DqsProto::OpenSessionRequest request;
request.SetSession(sessionId);
@@ -331,7 +331,7 @@ public:
auto self = weak_from_this();
auto callback = [self, promise, sessionId](NGrpc::TGrpcStatus&& status, Yql::DqsProto::OpenSessionResponse&& resp) mutable {
Y_UNUSED(resp);
- YQL_LOG_CTX_ROOT_SCOPE(sessionId);
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(sessionId);
auto this_ = self.lock();
if (!this_) {
YQL_CLOG(DEBUG, ProviderDq) << "Gateway was closed: " << sessionId;
diff --git a/ydb/library/yql/providers/dq/worker_manager/local_worker_manager.cpp b/ydb/library/yql/providers/dq/worker_manager/local_worker_manager.cpp
index 2731af67b6d..f39ba024ca7 100644
--- a/ydb/library/yql/providers/dq/worker_manager/local_worker_manager.cpp
+++ b/ydb/library/yql/providers/dq/worker_manager/local_worker_manager.cpp
@@ -207,7 +207,7 @@ private:
return;
}
- YQL_LOG_CTX_ROOT_SCOPE(ev->Get()->Record.GetTraceId());
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(ev->Get()->Record.GetTraceId());
YQL_CLOG(DEBUG, ProviderDq) << "TLocalWorkerManager::TEvAllocateWorkersRequest " << resourceId;
TFailureInjector::Reach("allocate_workers_failure", [] { ::_exit(1); });
diff --git a/ydb/library/yql/utils/log/context.cpp b/ydb/library/yql/utils/log/context.cpp
index b591c42a779..c8ad4604450 100644
--- a/ydb/library/yql/utils/log/context.cpp
+++ b/ydb/library/yql/utils/log/context.cpp
@@ -14,7 +14,7 @@ struct TThrowedLogContext {
} // namspace
-void OutputLogCtx(IOutputStream* out, bool withBraces) {
+void OutputLogCtx(IOutputStream* out, bool withBraces, bool skipSessionId) {
const NImpl::TLogContextListItem* ctxList = NImpl::GetLogContextList();
if (ctxList->HasNext()) {
@@ -25,22 +25,17 @@ void OutputLogCtx(IOutputStream* out, bool withBraces) {
// skip header stub element
NImpl::TLogContextListItem* ctxItem = ctxList->Next;
- { // special case for outputing the first element
- const TString* it = ctxItem->begin();
- const TString* end = ctxItem->end();
-
- (*out) << *it++;
- for (; it != end; ++it) {
- (*out) << '/' << *it;
- }
-
- ctxItem = ctxItem->Next;
- }
-
- // output remaining elements
+ bool isFirst = true;
while (ctxItem != ctxList) {
for (const TString& name: *ctxItem) {
- (*out) << '/' << name;
+ if (!skipSessionId && !name.empty()) {
+ if (!isFirst) {
+ (*out) << '/';
+ }
+ (*out) << name;
+ isFirst = false;
+ }
+ skipSessionId = false;
}
ctxItem = ctxItem->Next;
}
@@ -55,10 +50,18 @@ NImpl::TLogContextListItem* NImpl::GetLogContextList() {
return FastTlsSingleton<NImpl::TLogContextListItem>();
}
-TString CurrentLogContextPath() {
+std::pair<TString, TString> CurrentLogContextPath() {
+ TString sessionId;
+ const NImpl::TLogContextListItem* possibleRootLogCtx = NImpl::GetLogContextList()->Next;
+ if (auto rootLogCtx = dynamic_cast<const NImpl::TLogContextSessionItem*>(possibleRootLogCtx)) {
+ if (rootLogCtx->HasSessionId()) {
+ sessionId = (*rootLogCtx->begin());
+ }
+ }
+
TStringStream ss;
- OutputLogCtx(&ss, false);
- return ss.Str();
+ OutputLogCtx(&ss, false, !sessionId.empty());
+ return std::make_pair(sessionId, ss.Str());
}
TString ThrowedLogContextPath() {
@@ -66,6 +69,7 @@ TString ThrowedLogContextPath() {
return std::move(tlc->LocationWithLogContext);
}
+
TAutoPtr<TLogElement> TContextPreprocessor::Preprocess(
TAutoPtr<TLogElement> element)
{
diff --git a/ydb/library/yql/utils/log/context.h b/ydb/library/yql/utils/log/context.h
index ab6e9430e50..6ef0946c030 100644
--- a/ydb/library/yql/utils/log/context.h
+++ b/ydb/library/yql/utils/log/context.h
@@ -5,7 +5,7 @@
#include <util/stream/output.h>
#include <util/system/src_location.h>
#include <util/system/yassert.h>
-
+#include <array>
// continues existing contexts chain
@@ -22,8 +22,12 @@
// starts new contexts chain, after leaving current scope restores
// previous contexts chain
+#define YQL_LOG_CTX_ROOT_SESSION_SCOPE(sessionId, ...) \
+ auto Y_CAT(c, __LINE__) = ::NYql::NLog::MakeRootCtx(sessionId, ##__VA_ARGS__); \
+ Y_UNUSED(Y_CAT(c, __LINE__))
+
#define YQL_LOG_CTX_ROOT_SCOPE(...) \
- auto Y_CAT(c, __LINE__) = ::NYql::NLog::MakeRootCtx(__VA_ARGS__); \
+ auto Y_CAT(c, __LINE__) = ::NYql::NLog::MakeRootCtx("", __VA_ARGS__); \
Y_UNUSED(Y_CAT(c, __LINE__))
#define YQL_LOG_CTX_ROOT_BLOCK(...) \
@@ -45,21 +49,30 @@ namespace NImpl {
/**
* @brief Represents item of logging context list.
*/
-struct TLogContextListItem {
+class TLogContextListItem {
+public:
TLogContextListItem* Next;
TLogContextListItem* Prev;
size_t NamesCount;
- explicit TLogContextListItem(size_t namesCount = 0)
+ explicit TLogContextListItem(size_t namesCount = 0, size_t headerSize = 0)
: Next(this)
, Prev(this)
, NamesCount(namesCount)
+ , HeaderSize_(headerSize)
{
+ // initialize HeaderSize_ if child didn't
+ if (headerSize == 0) {
+ HeaderSize_ = sizeof(*this);
+ }
+ }
+
+ virtual ~TLogContextListItem() {
}
const TString* begin() const {
auto* ptr = reinterpret_cast<const ui8*>(this);
- return reinterpret_cast<const TString*>(ptr + sizeof(*this));
+ return reinterpret_cast<const TString*>(ptr + HeaderSize_);
}
const TString* end() const {
@@ -85,6 +98,10 @@ struct TLogContextListItem {
Next->Prev = Prev;
Next = Prev = this;
}
+
+private:
+ // Additional memory before Names_ used in child class
+ size_t HeaderSize_;
};
/**
@@ -92,6 +109,24 @@ struct TLogContextListItem {
*/
TLogContextListItem* GetLogContextList();
+/**
+ * @brief Context element with stored SessionId.
+*/
+class TLogContextSessionItem : public TLogContextListItem {
+public:
+ TLogContextSessionItem(size_t size, bool hasSessionId_)
+ : TLogContextListItem(size, sizeof(*this)) {
+ HasSessionId_ = hasSessionId_;
+ }
+
+ bool HasSessionId() const {
+ return HasSessionId_;
+ }
+
+private:
+ bool HasSessionId_;
+};
+
} // namspace NImpl
/**
@@ -125,12 +160,12 @@ private:
* list head by itself and restores previous one on destruction.
*/
template <size_t Size>
-class TRootLogContext: public NImpl::TLogContextListItem {
+class TRootLogContext: public NImpl::TLogContextSessionItem {
public:
template <typename... TArgs>
- TRootLogContext(TArgs... args)
- : TLogContextListItem(Size)
- , Names_{{ TString{std::forward<TArgs>(args)}... }}
+ TRootLogContext(const TString& sessionId, TArgs... args)
+ : TLogContextSessionItem(Size, !sessionId.empty())
+ , Names_{{ sessionId, TString{std::forward<TArgs>(args)}... }}
{
NImpl::TLogContextListItem* ctxList = NImpl::GetLogContextList();
PrevLogContextHead_.Prev = ctxList->Prev;
@@ -160,20 +195,25 @@ private:
* arguments list.
*/
template <typename... TArgs>
-auto MakeCtx(TArgs&&... args) -> TLogContext<sizeof...(args)> {
+inline auto MakeCtx(TArgs&&... args) -> TLogContext<sizeof...(args)> {
return TLogContext<sizeof...(args)>(std::forward<TArgs>(args)...);
}
template <typename... TArgs>
-auto MakeRootCtx(TArgs&&... args) -> TRootLogContext<sizeof...(args)> {
- return TRootLogContext<sizeof...(args)>(std::forward<TArgs>(args)...);
+inline auto MakeRootCtx(const TString& sessionId, TArgs&&... args) -> TRootLogContext<sizeof...(args) + 1> {
+ return TRootLogContext<sizeof...(args) + 1>(sessionId, std::forward<TArgs>(args)...);
+}
+
+inline auto MakeRootCtx(const std::pair<TString, TString>& ctx) -> TRootLogContext<2> {
+ return TRootLogContext<2>(ctx.first, ctx.second);
}
/**
- * @brief Returns current logger contexts path as string. Each element
+ * @brief Returns pair with sessionId and
+ * current logger contexts path as string. Each element
* is separated with '/'.
*/
-TString CurrentLogContextPath();
+std::pair<TString, TString> CurrentLogContextPath();
/**
* @brief If last throwing exception was performed with YQL_LOG_CTX_THROW
@@ -191,7 +231,7 @@ struct TContextPreprocessor {
/**
* @brief Outputs current logger context into stream
*/
-void OutputLogCtx(IOutputStream* out, bool withBraces);
+void OutputLogCtx(IOutputStream* out, bool withBraces, bool skipSessionId = false);
/**
* @brief Outputs current logger context into exception message.
diff --git a/ydb/library/yql/utils/log/log_ut.cpp b/ydb/library/yql/utils/log/log_ut.cpp
index bf8b71476c0..8f3dbe758d4 100644
--- a/ydb/library/yql/utils/log/log_ut.cpp
+++ b/ydb/library/yql/utils/log/log_ut.cpp
@@ -195,22 +195,22 @@ Y_UNIT_TEST_SUITE(TLogTest)
TStringStream out;
YqlLoggerScope logger(&out);
- UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath(), "");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "");
YQL_LOG(INFO) << "level0 - begin";
{
YQL_LOG_CTX_SCOPE("ctx1");
- UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath(), "ctx1");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx1");
YQL_LOG(INFO) << "level1 - begin";
YQL_LOG_CTX_BLOCK(TStringBuf("ctx2")) {
- UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath(), "ctx1/ctx2");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx1/ctx2");
YQL_LOG(WARN) << "level2";
}
- UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath(), "ctx1");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx1");
YQL_LOG(INFO) << "level1 - end";
}
- UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath(), "");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "");
YQL_LOG(INFO) << "level0 - end";
TString row1Str, row2Str, row3Str, row4Str, row5Str, _;
@@ -248,6 +248,138 @@ Y_UNIT_TEST_SUITE(TLogTest)
}
}
+ Y_UNIT_TEST(UnknownSessionContexts) {
+ TStringStream out;
+ YqlLoggerScope logger(&out);
+
+ {
+ YQL_LOG_CTX_ROOT_SCOPE("ctx");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().first, "");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx");
+ YQL_LOG(INFO) << "level0 - begin";
+
+ {
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(CurrentLogContextPath());
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().first, "");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx");
+
+ YQL_LOG(INFO) << "level1 - begin";
+ YQL_LOG_CTX_BLOCK("ctx1") {
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().first, "");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx/ctx1");
+
+ YQL_LOG(WARN) << "level2";
+ }
+
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().first, "");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx");
+ YQL_LOG(INFO) << "level1 - end";
+ }
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().first, "");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx");
+ YQL_LOG(INFO) << "level0 - end";
+ }
+
+ TString row1Str, row2Str, row3Str, row4Str, row5Str, _;
+ Split(out.Str(), '\n', row1Str, row2Str, row3Str, row4Str, row5Str, _);
+ {
+ TLogRow logRow = ParseLogRow(row1Str);
+ UNIT_ASSERT_EQUAL(logRow.Level, ELevel::INFO);
+ UNIT_ASSERT_EQUAL(logRow.Component, EComponent::Default);
+ UNIT_ASSERT_STRINGS_EQUAL(logRow.Message, "{ctx} level0 - begin");
+ }
+ {
+ TLogRow logRow = ParseLogRow(row2Str);
+ UNIT_ASSERT_EQUAL(logRow.Level, ELevel::INFO);
+ UNIT_ASSERT_EQUAL(logRow.Component, EComponent::Default);
+ UNIT_ASSERT_STRINGS_EQUAL(logRow.Message, "{ctx} level1 - begin");
+ }
+ {
+ TLogRow logRow = ParseLogRow(row3Str);
+ UNIT_ASSERT_EQUAL(logRow.Level, ELevel::WARN);
+ UNIT_ASSERT_EQUAL(logRow.Component, EComponent::Default);
+ UNIT_ASSERT_STRINGS_EQUAL(logRow.Message, "{ctx/ctx1} level2");
+ }
+ {
+ TLogRow logRow = ParseLogRow(row4Str);
+ UNIT_ASSERT_EQUAL(logRow.Level, ELevel::INFO);
+ UNIT_ASSERT_EQUAL(logRow.Component, EComponent::Default);
+ UNIT_ASSERT_STRINGS_EQUAL(logRow.Message, "{ctx} level1 - end");
+ }
+ {
+ TLogRow logRow = ParseLogRow(row5Str);
+ UNIT_ASSERT_EQUAL(logRow.Level, ELevel::INFO);
+ UNIT_ASSERT_EQUAL(logRow.Component, EComponent::Default);
+ UNIT_ASSERT_STRINGS_EQUAL(logRow.Message, "{ctx} level0 - end");
+ }
+ }
+
+ Y_UNIT_TEST(SessionContexts) {
+ TStringStream out;
+ YqlLoggerScope logger(&out);
+
+ {
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE("sessionId", "ctx");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().first, "sessionId");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx");
+ YQL_LOG(INFO) << "level0 - begin";
+
+ {
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(CurrentLogContextPath());
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().first, "sessionId");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx");
+
+ YQL_LOG(INFO) << "level1 - begin";
+ YQL_LOG_CTX_BLOCK("ctx1") {
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().first, "sessionId");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx/ctx1");
+
+ YQL_LOG(WARN) << "level2";
+ }
+
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().first, "sessionId");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx");
+ YQL_LOG(INFO) << "level1 - end";
+ }
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().first, "sessionId");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx");
+ YQL_LOG(INFO) << "level0 - end";
+ }
+
+ TString row1Str, row2Str, row3Str, row4Str, row5Str, _;
+ Split(out.Str(), '\n', row1Str, row2Str, row3Str, row4Str, row5Str, _);
+ {
+ TLogRow logRow = ParseLogRow(row1Str);
+ UNIT_ASSERT_EQUAL(logRow.Level, ELevel::INFO);
+ UNIT_ASSERT_EQUAL(logRow.Component, EComponent::Default);
+ UNIT_ASSERT_STRINGS_EQUAL(logRow.Message, "{sessionId/ctx} level0 - begin");
+ }
+ {
+ TLogRow logRow = ParseLogRow(row2Str);
+ UNIT_ASSERT_EQUAL(logRow.Level, ELevel::INFO);
+ UNIT_ASSERT_EQUAL(logRow.Component, EComponent::Default);
+ UNIT_ASSERT_STRINGS_EQUAL(logRow.Message, "{sessionId/ctx} level1 - begin");
+ }
+ {
+ TLogRow logRow = ParseLogRow(row3Str);
+ UNIT_ASSERT_EQUAL(logRow.Level, ELevel::WARN);
+ UNIT_ASSERT_EQUAL(logRow.Component, EComponent::Default);
+ UNIT_ASSERT_STRINGS_EQUAL(logRow.Message, "{sessionId/ctx/ctx1} level2");
+ }
+ {
+ TLogRow logRow = ParseLogRow(row4Str);
+ UNIT_ASSERT_EQUAL(logRow.Level, ELevel::INFO);
+ UNIT_ASSERT_EQUAL(logRow.Component, EComponent::Default);
+ UNIT_ASSERT_STRINGS_EQUAL(logRow.Message, "{sessionId/ctx} level1 - end");
+ }
+ {
+ TLogRow logRow = ParseLogRow(row5Str);
+ UNIT_ASSERT_EQUAL(logRow.Level, ELevel::INFO);
+ UNIT_ASSERT_EQUAL(logRow.Component, EComponent::Default);
+ UNIT_ASSERT_STRINGS_EQUAL(logRow.Message, "{sessionId/ctx} level0 - end");
+ }
+ }
+
Y_UNIT_TEST(ThrowWithContext) {
bool isThrown = false;
YQL_LOG_CTX_SCOPE("first");
@@ -284,30 +416,30 @@ Y_UNIT_TEST_SUITE(TLogTest)
TStringStream out;
YqlLoggerScope logger(&out);
- UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath(), "");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "");
{
YQL_LOG_CTX_SCOPE("ctx1");
- UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath(), "ctx1");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx1");
YQL_LOG(INFO) << "level1 - begin";
YQL_LOG_CTX_BLOCK(TStringBuf("ctx2")) {
- UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath(), "ctx1/ctx2");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx1/ctx2");
YQL_LOG(WARN) << "level2 - begin";
{
YQL_LOG_CTX_ROOT_SCOPE("ctx3");
- UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath(), "ctx3");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx3");
YQL_LOG(ERROR) << "level3";
}
- UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath(), "ctx1/ctx2");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx1/ctx2");
YQL_LOG(WARN) << "level2 - end";
}
- UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath(), "ctx1");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "ctx1");
YQL_LOG(INFO) << "level1 - end";
}
- UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath(), "");
+ UNIT_ASSERT_STRINGS_EQUAL(CurrentLogContextPath().second, "");
TString row1Str, row2Str, row3Str, row4Str, row5Str, _;
Split(out.Str(), '\n', row1Str, row2Str, row3Str, row4Str, row5Str, _);
diff --git a/ydb/library/yql/utils/log/profile.cpp b/ydb/library/yql/utils/log/profile.cpp
index ba9556498fd..4dd412b8f63 100644
--- a/ydb/library/yql/utils/log/profile.cpp
+++ b/ydb/library/yql/utils/log/profile.cpp
@@ -33,8 +33,8 @@ TProfilingScope::~TProfilingScope() {
<< TStringBuf("] took ") << Prec(elapsed, 3) << unit;
};
- if (!LogCtxPath_.empty()) {
- YQL_LOG_CTX_ROOT_SCOPE(LogCtxPath_);
+ if (!LogCtxPath_.first.empty() || !LogCtxPath_.second.empty()) {
+ YQL_LOG_CTX_ROOT_SESSION_SCOPE(LogCtxPath_);
doLog();
} else {
doLog();
diff --git a/ydb/library/yql/utils/log/profile.h b/ydb/library/yql/utils/log/profile.h
index 656dd550880..dda7e03f9d2 100644
--- a/ydb/library/yql/utils/log/profile.h
+++ b/ydb/library/yql/utils/log/profile.h
@@ -45,7 +45,7 @@ namespace NLog {
class TProfilingScope {
public:
TProfilingScope(const char* name, ELevel level, const char* file, int line,
- TString logCtxPath = TString())
+ std::pair<TString, TString> logCtxPath = std::make_pair(TString(), TString()))
: Name_(name)
, Level_(level)
, File_(file)
@@ -67,7 +67,7 @@ private:
const char* File_;
int Line_;
ui64 StartedAt_;
- TString LogCtxPath_;
+ std::pair<TString, TString> LogCtxPath_;
};
} // namspace NLog