Improve DQ actor failure logging for undelivered events and timeouts (#47247)

3 files changed, 60 insertions, 7 deletions

diff --git a/ydb/library/yql/providers/dq/actors/actor_helpers.h b/ydb/library/yql/providers/dq/actors/actor_helpers.h
index 67cdbbd2460..69eaee8cce7 100644
--- a/ydb/library/yql/providers/dq/actors/actor_helpers.h
+++ b/ydb/library/yql/providers/dq/actors/actor_helpers.h
@@ -10,6 +10,13 @@
 
 namespace NYql {
 
+enum class EActorFutureCallbackFailureReason {
+    None,
+    Undelivered,
+    NodeDisconnected,
+    Timeout,
+};
+
 enum EExecutorPoolType {
     Main,
     FullResultWriter,
@@ -25,17 +32,27 @@ struct TRichActorFutureCallback : public TRichActor<TRichActorFutureCallback<Eve
 
     static constexpr char ActorName[] = "YQL_DQ_ACTOR_FUTURE_CALLBACK";
 
-    TRichActorFutureCallback(TCallback&& callback, TFailure&& failure, TDuration timeout)
+    TRichActorFutureCallback(
+        TCallback&& callback,
+        TFailure&& failure,
+        TDuration timeout,
+        TString context = {},
+        NActors::TActorId targetActorId = {})
         : TBase(&TRichActorFutureCallback::StateWaitForEvent)
         , Callback(std::move(callback))
         , Failure(std::move(failure))
         , Timeout(timeout)
+        , Context(std::move(context))
+        , TargetActorId(targetActorId)
     { }
 
 private:
     const TCallback Callback;
     const TFailure Failure;
     const TDuration Timeout;
+    const TString Context;
+    const NActors::TActorId TargetActorId;
+    EActorFutureCallbackFailureReason FailureReason = EActorFutureCallbackFailureReason::None;
     bool TimerStarted = false;
     NActors::TSchedulerCookieHolder TimerCookieHolder;
 
@@ -47,11 +64,26 @@ private:
         })
         hFunc(NActors::TEvInterconnect::TEvNodeDisconnected, [this] (NActors::TEvInterconnect::TEvNodeDisconnected::TPtr& ev) mutable {
             this->Unsubscribe(ev->Get()->NodeId);
+            FailureReason = EActorFutureCallbackFailureReason::NodeDisconnected;
+            YQL_CLOG(DEBUG, ProviderDq) << "ActorFutureCallback failed: interconnect node disconnected"
+                << " context=" << Context
+                << " disconnectedNodeId=" << ev->Get()->NodeId
+                << " targetActorId=" << TargetActorId
+                << " callbackActorId=" << this->SelfId();
             TimerStarted = true;
             OnFailure();
         })
         hFunc(NActors::TEvents::TEvUndelivered, [this] (NActors::TEvents::TEvUndelivered::TPtr& ev) mutable {
+            const auto* undelivered = ev->Get();
             this->Unsubscribe(ev->Sender.NodeId());
+            FailureReason = EActorFutureCallbackFailureReason::Undelivered;
+            YQL_CLOG(DEBUG, ProviderDq) << "ActorFutureCallback failed: event undelivered (fast failure, not a timeout)"
+                << " context=" << Context
+                << " undeliveredReason=" << static_cast<int>(undelivered->Reason)
+                << " sourceEventType=" << undelivered->SourceType
+                << " unsure=" << undelivered->Unsure
+                << " targetActorId=" << TargetActorId
+                << " callbackActorId=" << this->SelfId();
             TimerStarted = true;
             OnFailure();
         })
@@ -69,6 +101,14 @@ private:
 
     void OnFailure() {
         if (TimerStarted) {
+            if (FailureReason == EActorFutureCallbackFailureReason::None) {
+                FailureReason = EActorFutureCallbackFailureReason::Timeout;
+                YQL_CLOG(DEBUG, ProviderDq) << "ActorFutureCallback failed: response timeout"
+                    << " context=" << Context
+                    << " timeout=" << Timeout
+                    << " targetActorId=" << TargetActorId
+                    << " callbackActorId=" << this->SelfId();
+            }
             Failure();
             this->PassAway();
         } else {
diff --git a/ydb/library/yql/providers/dq/actors/resource_allocator.cpp b/ydb/library/yql/providers/dq/actors/resource_allocator.cpp
index 8c143ec3dad..95c31712355 100644
--- a/ydb/library/yql/providers/dq/actors/resource_allocator.cpp
+++ b/ydb/library/yql/providers/dq/actors/resource_allocator.cpp
@@ -85,7 +85,10 @@ private:
             Fail((ui64)-1, "GWM Disconnected");
         })
         hFunc(TEvents::TEvUndelivered, [this](TEvents::TEvUndelivered::TPtr& ev) {
-            Fail(ev->Cookie, "Undelivered");
+            Fail(ev->Cookie, TStringBuilder()
+                << "Undelivered: sender: " << ev->Sender
+                << ", reason: " << ev->Get()->Reason
+                << ", source type: " << ev->Get()->SourceType);
         })
     })
 
@@ -299,7 +302,8 @@ private:
                 QueryStat.GetCounterName("Actor", {{"ClusterName", maybeRequestInfo->second.ClusterName}}, "CreateFailTimeUs"),
                 delta);
         }
-        TString message = "Disconnected from worker: `" + workerInfo + "', reason: " + reason;
+        TString message = TStringBuilder()
+            << "Disconnected from worker: `" << workerInfo << "`, reason: " << reason;
         YQL_CLOG(ERROR, ProviderDq) << message;
         auto response = MakeHolder<TEvAllocateWorkersResponse>(message, NYql::NDqProto::StatusIds::UNAVAILABLE);
         QueryStat.FlushCounters(response->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 6216abea8ad..6f3b24cddca 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
@@ -979,7 +979,8 @@ private:
                 return true;
             });
             IDqGateway::TDqProgressWriter progressWriter = MakeDqProgressWriter(publicIds);
-            bool enableFullResultWrite = settings->EnableFullResultWrite.Get().GetOrElse(false);
+            const bool initialFullResultWrite = settings->EnableFullResultWrite.Get().GetOrElse(false);
+            bool enableFullResultWrite = initialFullResultWrite;
             if (enableFullResultWrite) {
                 const auto type = result.Input().Ref().GetTypeAnn();
                 const auto integration = GetDqIntegrationForFullResTable(State);
@@ -991,6 +992,11 @@ private:
                     && integration->PrepareFullResultTableParams(result.Ref(), ctx, graphParams, secureParams, TColumnOrder(columns));
                 settings->EnableFullResultWrite = enableFullResultWrite;
             }
+            YQL_CLOG(INFO, ProviderDq) << "FullResultWrite decision: initial=" << initialFullResultWrite
+                << " effective=" << enableFullResultWrite
+                << " discard=" << fillSettings.Discard
+                << " hasDqGateway=" << (bool)State->DqGateway
+                << " hasYtFullResultParam=" << graphParams.contains("yt.full_result_table");
 
             TString lambda;
             bool untrustedUdfFlag;
@@ -1086,10 +1092,13 @@ private:
             }
 
             return WrapFutureCallback<false>(future, [localRun, startTime, type, rowSpec, skiffType, fillSettings, level, settings, enableFullResultWrite, columns, graphParams, state = State, skiffConverter = SkiffConverter](const IDqGateway::TResult& res, const TExprNode::TPtr& input, TExprNode::TPtr& output, TExprContext& ctx) {
-                YQL_CLOG(DEBUG, ProviderDq) << state->SessionId <<  " WrapFutureCallback";
-
                 auto duration = TInstant::Now() - startTime;
-                YQL_CLOG(INFO, ProviderDq) << "Execution Result complete, duration: " << duration;
+                YQL_CLOG(INFO, ProviderDq) << state->SessionId << " Execution Result complete, duration: " << duration
+                    << " localRun=" << localRun
+                    << " enableFullResultWrite=" << enableFullResultWrite
+                    << " truncated=" << res.Truncated
+                    << " rowsCount=" << res.RowsCount
+                    << " dataBytes=" << res.Data.size();
                 if (state->Metrics) {
                     state->Metrics->SetCounter("dq", "TotalExecutionTime", duration.MilliSeconds());
                     state->Metrics->SetCounter(