diff --git a/components/nexusoperations/executors.go b/components/nexusoperations/executors.go index cfc4acd514..184d5ad77b 100644 --- a/components/nexusoperations/executors.go +++ b/components/nexusoperations/executors.go @@ -270,6 +270,19 @@ func (e taskExecutor) executeInvocationTask(ctx context.Context, env hsm.Environ Links: []nexus.Link{args.nexusLink}, } + traceCtx := invocationTraceContext{ + operationTag: "StartOperation", + namespaceName: ns.Name().String(), + targetNamespaceID: endpoint.GetEndpoint().GetSpec().GetTarget().GetWorker().GetNamespaceId(), + requestID: args.requestID, + operation: args.operation, + endpointName: args.endpointName, + workflowID: ref.WorkflowKey.WorkflowID, + runID: ref.WorkflowKey.RunID, + attemptStart: time.Now().UTC(), + attempt: task.Attempt, + } + var result *nexusrpc.ClientStartOperationResponse[*commonpb.Payload] var callErr error var startTime time.Time @@ -291,18 +304,8 @@ func (e taskExecutor) executeInvocationTask(ctx context.Context, env hsm.Environ } if e.HTTPTraceProvider != nil { - traceLogger := log.With(e.Logger, - tag.Operation("StartOperation"), - tag.WorkflowNamespace(ns.Name().String()), - tag.RequestID(args.requestID), - tag.NexusOperation(args.operation), - tag.Endpoint(args.endpointName), - tag.WorkflowID(ref.WorkflowKey.WorkflowID), - tag.WorkflowRunID(ref.WorkflowKey.RunID), - tag.AttemptStart(time.Now().UTC()), - tag.Attempt(task.Attempt), - ) - if trace := e.HTTPTraceProvider.NewTrace(task.Attempt, traceLogger); trace != nil { + traceLogger := log.With(e.Logger, traceCtx.tags()...) + if trace := e.HTTPTraceProvider.NewTrace(traceCtx.attempt, traceLogger); trace != nil { callCtx = httptrace.WithClientTrace(callCtx, trace) } } @@ -333,13 +336,7 @@ func (e taskExecutor) executeInvocationTask(ctx context.Context, env hsm.Environ chasmnexus.OutboundRequestCounter.With(e.MetricsHandler).Record(1, namespaceTag, destTag, methodTag, outcomeTag, failureSourceTag) chasmnexus.OutboundRequestLatency.With(e.MetricsHandler).Record(time.Since(startTime), namespaceTag, destTag, methodTag, outcomeTag, failureSourceTag) - if callErr != nil { - if failureSource == commonnexus.FailureSourceWorker || errors.As(callErr, new(*operationTimeoutBelowMinError)) { - e.Logger.Debug("Nexus StartOperation request failed", tag.Error(callErr)) - } else { - e.Logger.Error("Nexus StartOperation request failed", tag.Error(callErr)) - } - } + e.logCallFailure(traceCtx, callErr, failureSource) err = e.saveResult(ctx, env, ref, result, callErr) @@ -734,6 +731,19 @@ func (e taskExecutor) executeCancelationTask(ctx context.Context, env hsm.Enviro // Set this value on the parent context so that our custom HTTP caller can mutate it since we cannot access response headers directly. callCtx = context.WithValue(callCtx, commonnexus.FailureSourceContextKey, &atomic.Value{}) + traceCtx := invocationTraceContext{ + operationTag: "CancelOperation", + namespaceName: ns.Name().String(), + targetNamespaceID: endpoint.GetEndpoint().GetSpec().GetTarget().GetWorker().GetNamespaceId(), + requestID: args.requestID, + operation: args.operation, + endpointName: args.endpointName, + workflowID: ref.WorkflowKey.WorkflowID, + runID: ref.WorkflowKey.RunID, + attemptStart: time.Now().UTC(), + attempt: task.Attempt, + } + var callErr error var startTime time.Time if callTimeout < e.Config.MinRequestTimeout(ns.Name().String()) { @@ -758,18 +768,8 @@ func (e taskExecutor) executeCancelationTask(ctx context.Context, env hsm.Enviro } if e.HTTPTraceProvider != nil { - traceLogger := log.With(e.Logger, - tag.Operation("CancelOperation"), - tag.WorkflowNamespace(ns.Name().String()), - tag.RequestID(args.requestID), - tag.NexusOperation(args.operation), - tag.Endpoint(args.endpointName), - tag.WorkflowID(ref.WorkflowKey.WorkflowID), - tag.WorkflowRunID(ref.WorkflowKey.RunID), - tag.AttemptStart(time.Now().UTC()), - tag.Attempt(task.Attempt), - ) - if trace := e.HTTPTraceProvider.NewTrace(task.Attempt, traceLogger); trace != nil { + traceLogger := log.With(e.Logger, traceCtx.tags()...) + if trace := e.HTTPTraceProvider.NewTrace(traceCtx.attempt, traceLogger); trace != nil { callCtx = httptrace.WithClientTrace(callCtx, trace) } } @@ -791,13 +791,7 @@ func (e taskExecutor) executeCancelationTask(ctx context.Context, env hsm.Enviro chasmnexus.OutboundRequestCounter.With(e.MetricsHandler).Record(1, namespaceTag, destTag, methodTag, statusCodeTag, failureSourceTag) chasmnexus.OutboundRequestLatency.With(e.MetricsHandler).Record(time.Since(startTime), namespaceTag, destTag, methodTag, statusCodeTag, failureSourceTag) - if callErr != nil { - if failureSource == commonnexus.FailureSourceWorker || errors.As(callErr, new(*operationTimeoutBelowMinError)) { - e.Logger.Debug("Nexus CancelOperation request failed", tag.Error(callErr)) - } else { - e.Logger.Error("Nexus CancelOperation request failed", tag.Error(callErr)) - } - } + e.logCallFailure(traceCtx, callErr, failureSource) err = e.saveCancelationResult(ctx, env, ref, callErr, args.scheduledEventID) @@ -1025,6 +1019,51 @@ func cancelCallOutcomeTag(callCtx context.Context, callErr error) string { return "successful" } +// invocationTraceContext captures per-call contextual information used for HTTP tracing and failure logging. +type invocationTraceContext struct { + operationTag string // "StartOperation" or "CancelOperation" + namespaceName string // source (caller) namespace + targetNamespaceID string + requestID string + operation string + endpointName string + workflowID string + runID string + attemptStart time.Time + attempt int32 +} + +// tags returns the structured log tags describing the call. +func (c invocationTraceContext) tags() []tag.Tag { + return []tag.Tag{ + tag.Operation(c.operationTag), + tag.WorkflowNamespace(c.namespaceName), + tag.NexusEndpointTargetNamespaceID(c.targetNamespaceID), + tag.RequestID(c.requestID), + tag.NexusOperation(c.operation), + tag.Endpoint(c.endpointName), + tag.WorkflowID(c.workflowID), + tag.WorkflowRunID(c.runID), + tag.AttemptStart(c.attemptStart), + tag.Attempt(c.attempt), + } +} + +// logCallFailure logs a failed outbound Nexus call. +func (e taskExecutor) logCallFailure(traceCtx invocationTraceContext, callErr error, failureSource string) { + if callErr == nil { + return + } + tags := append(traceCtx.tags(), tag.Error(callErr)) + msg := fmt.Sprintf("Nexus %s request failed", traceCtx.operationTag) + _, isTimeoutBelowMin := errors.AsType[*operationTimeoutBelowMinError](callErr) + if failureSource == commonnexus.FailureSourceWorker || isTimeoutBelowMin { + e.Logger.Debug(msg, tags...) + } else { + e.Logger.Error(msg, tags...) + } +} + func isDestinationDown(err error) bool { var serviceErr serviceerror.ServiceError // For the system endpoint, we don't even consider the destination down since it's internal.