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 | 
