diff options
| author | epbugaev <[email protected]> | 2023-01-12 19:02:01 +0300 |
|---|---|---|
| committer | epbugaev <[email protected]> | 2023-01-12 19:02:01 +0300 |
| commit | b48a7948c3aec8c078a24714d4da420a6225d09f (patch) | |
| tree | e3cd9639c37e68f37df5017a53563a907c0db6fd | |
| parent | d2fde6cc065110a9c8955e0e25c56c8c5e721460 (diff) | |
Write sessionId to logs
Write sessionId to logs
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 |
