Add sampled logging when workflow query task times out (temporalio#5521)

gow · web-flow · commit 3b6a2dcad549 · 2024-03-15T00:42:16.000Z
## What changed?
Adding a sampled logging when a workflow query task times out.

## Why?
Need this to be able to debug issues in the future when workflow queries
timeout.

## How did you test it?
&lt;!-- How have you verified this change? Tested locally? Added a unit
test? Checked in staging env? --&gt;

## Potential risks
&lt;!-- Assuming the worst case, what can be broken when deploying this
change to production? --&gt;

## Documentation
&lt;!-- Have you made sure this change doesn't falsify anything currently
stated in `docs/`? If significant
new behavior is added, have you described that in `docs/`? --&gt;

## Is hotfix candidate?
&lt;!-- Is this PR a hotfix candidate or does it require a notification to
be sent to the broader community? (Yes/No) --&gt;
diff --git a/common/dynamicconfig/constants.go b/common/dynamicconfig/constants.go
@@ -480,6 +480,9 @@ const (
 	// MatchingMembershipUnloadDelay is how long to wait to re-confirm loss of ownership before unloading a task queue.
 	// Set to zero to disable proactive unload.
 	MatchingMembershipUnloadDelay = "matching.membershipUnloadDelay"
+	// MatchingQueryWorkflowTaskTimeoutLogRate defines the sampling rate for logs when a query workflow task times out. Since
+	// these log lines can be noisy, we want to be able to turn on and sample selectively for each affected namespace.
+	MatchingQueryWorkflowTaskTimeoutLogRate = "matching.queryWorkflowTaskTimeoutLogRate"
 
 	// for matching testing only:
 
diff --git a/config/dynamicconfig/development-cass.yaml b/config/dynamicconfig/development-cass.yaml
@@ -46,3 +46,5 @@ frontend.adminDeleteAccessHistoryFraction:
   - value: 1.0
 frontend.enableNexusHTTPHandler:
   - value: true
+matching.queryWorkflowTaskTimeoutLogRate:
+  - value: 1.0
diff --git a/config/dynamicconfig/development-sql.yaml b/config/dynamicconfig/development-sql.yaml
@@ -49,3 +49,5 @@ frontend.adminDeleteAccessHistoryFraction:
   - value: 1.0
 frontend.enableNexusHTTPHandler:
   - value: true
+matching.queryWorkflowTaskTimeoutLogRate:
+  - value: 1.0
diff --git a/service/matching/config.go b/service/matching/config.go
@@ -72,6 +72,7 @@ type (
 		BacklogNegligibleAge              dynamicconfig.DurationPropertyFnWithTaskQueueInfoFilters
 		MaxWaitForPollerBeforeFwd         dynamicconfig.DurationPropertyFnWithTaskQueueInfoFilters
 		QueryPollerUnavailableWindow      dynamicconfig.DurationPropertyFn
+		QueryWorkflowTaskTimeoutLogRate   dynamicconfig.FloatPropertyFnWithTaskQueueInfoFilters
 		MembershipUnloadDelay             dynamicconfig.DurationPropertyFn
 
 		// Time to hold a poll request before returning an empty response if there are no tasks
@@ -205,6 +206,7 @@ func NewConfig(
 		BacklogNegligibleAge:                  dc.GetDurationPropertyFilteredByTaskQueueInfo(dynamicconfig.MatchingBacklogNegligibleAge, 24*365*10*time.Hour),
 		MaxWaitForPollerBeforeFwd:             dc.GetDurationPropertyFilteredByTaskQueueInfo(dynamicconfig.MatchingMaxWaitForPollerBeforeFwd, 200*time.Millisecond),
 		QueryPollerUnavailableWindow:          dc.GetDurationProperty(dynamicconfig.QueryPollerUnavailableWindow, 20*time.Second),
+		QueryWorkflowTaskTimeoutLogRate:       dc.GetFloatPropertyFilteredByTaskQueueInfo(dynamicconfig.MatchingQueryWorkflowTaskTimeoutLogRate, 0.0),
 		MembershipUnloadDelay:                 dc.GetDurationProperty(dynamicconfig.MatchingMembershipUnloadDelay, 500*time.Millisecond),
 
 		AdminNamespaceToPartitionDispatchRate:          dc.GetFloatPropertyFilteredByNamespace(dynamicconfig.AdminMatchingNamespaceToPartitionDispatchRate, 10000),
diff --git a/service/matching/matching_engine.go b/service/matching/matching_engine.go
@@ -30,6 +30,7 @@ import (
 	"errors"
 	"fmt"
 	"math"
+	"math/rand"
 	"sync"
 	"sync/atomic"
 	"time"
@@ -864,6 +865,24 @@ func (e *matchingEngineImpl) QueryWorkflow(
 			return nil, serviceerror.NewInternal("unknown query completed type")
 		}
 	case <-ctx.Done():
+		// task timed out. log (optionally) and return the timeout error
+		ns, err := e.namespaceRegistry.GetNamespaceByID(namespaceID)
+		if err != nil {
+			e.logger.Error("Failed to get the namespace by ID",
+				tag.WorkflowNamespaceID(string(namespaceID)),
+				tag.Error(err))
+		} else {
+			sampleRate := e.config.QueryWorkflowTaskTimeoutLogRate(ns.Name().String(), taskQueueName, enumspb.TASK_QUEUE_TYPE_WORKFLOW)
+			if rand.Float64() < sampleRate {
+				e.logger.Info("Workflow Query Task timed out",
+					tag.WorkflowNamespaceID(ns.ID().String()),
+					tag.WorkflowNamespace(ns.Name().String()),
+					tag.WorkflowID(queryRequest.GetQueryRequest().GetExecution().GetWorkflowId()),
+					tag.WorkflowRunID(queryRequest.GetQueryRequest().GetExecution().GetRunId()),
+					tag.WorkflowTaskRequestId(taskID),
+					tag.WorkflowTaskQueueName(taskQueueName))
+			}
+		}
 		return nil, ctx.Err()
 	}
 }
