aws / aws/aws-dotnet-messaging

DefaultMessageManager outcome logs are emitted outside the telemetry Activity scope (no trace correlation)

Open
#337 1 comment 0 reactions 0 assignees View on GitHub
bug p2 queued
Dominant language
C#
Stars
143
Forks
27
Avg merge
1d 18h
Merged PRs (30d)
4

Description

### Description

Three `LogError` calls in `DefaultMessageManager.InvokeHandler` are emitted **after** the telemetry `Activity` opened by `HandlerInvoker.InvokeAsync` has already been disposed. As a result, those log records carry no trace context: in any observability platform that ingests logs via OTLP (Datadog, etc.), `SpanId` and `TraceId` are zeroed out, and operators cannot click from the log to the corresponding handler trace.

### Steps to reproduce

1. Register an SQS poller and a handler with `AddAWSMessageBus`.
2. Wire OpenTelemetry tracing via `AWS.Messaging.Telemetry.OpenTelemetry` (`tracing.AddAWSMessagingInstrumentation()`), and ship logs through an OTLP exporter.
3. Have the handler return `MessageProcessStatus.Failed()` for a message (or throw an exception that escapes `HandlerInvoker`, or fault its `Task`).
4. Observe the `"Message handling completed unsuccessfully for message ID {MessageId}"` (or sibling) log record in the log backend.

### Expected behavior

The outcome log records should sit inside the same `Activity` that wraps the handler invocation, so they share `TraceId` / `SpanId` with the handler span and can be correlated with it.

### Actual behavior

The records have `SpanId: "0000000000000000"` and `TraceFlags: "None"`. Example (sanitized) record from a Datadog log ingested via OTLP:

```json
{
"Attributes": {
"MessageId": "",
"{OriginalFormat}": "Message handling completed unsuccessfully for message ID {MessageId}"
},
"CategoryName": "AWS.Messaging.Services.DefaultMessageManager",
"SeverityText": "Error",
"SpanId": "0000000000000000",
"TraceFlags": "None"
}
```

The `MessageId` attribute is the only correlator available; nothing ties the record to the handler trace.

### Root cause

The Activity is opened inside `HandlerInvoker.InvokeAsync` and ends when its `using` block exits:

[`HandlerInvoker.cs#L45`](https://github.com/aws/aws-dotnet-messaging/blob/main/src/AWS.Messaging/Services/HandlerInvoker.cs#L45)
```csharp
using (var trace = _telemetryFactory.Trace("Processing message", messageEnvelope))
{
// ... handler invocation ...
}
```

`DefaultMessageManager.InvokeHandler` calls that method, awaits the returned task, and **then** decides whether to log the outcome:

[`DefaultMessageManager.cs#L167-L208`](https://github.com/aws/aws-dotnet-messaging/blob/main/src/AWS.Messaging/Services/DefaultMessageManager.cs#L167-L208)
```csharp
private async Task InvokeHandler(MessageEnvelope messageEnvelope, SubscriberMapping subscriberMapping, CancellationToken cancelToken)
{
var isSuccessful = false;
var handlerTask = _handlerInvoker.InvokeAsync(messageEnvelope, subscriberMapping, cancelToken);
try
{
await handlerTask;
}
catch (InvalidMessageHandlerSignatureException) { throw; }
catch (AWSMessagingException) { /* swallowed */ }
catch (Exception ex)
{
_logger.LogError(ex, "An exception has been thrown from handler '{HandlerType}' ...", ...); // L185
}

_inFlightMessageMetadata.Remove(messageEnvelope, out _);

if (handlerTask.IsCompletedSuccessfully)
{
if (handlerTask.Result.IsSuccess) { /* delete */ }
else
{
_logger.LogError("Message handling completed unsuccessfully for message ID {MessageId}", ...); // L200
await _sqsMessageCommunication.ReportMessageFailureAsync(messageEnvelope);
}
}
else if (handlerTask.IsFaulted)
{
_logger.LogError(handlerTask.Exception, "An exception has been thrown from handler '{HandlerType}' ...", ...); // L206
await _sqsMessageCommunication.ReportMessageFailureAsync(messageEnvelope);
}

return isSuccessful;
}
```

By the time any of `L185`, `L200`, or `L206` execute, `HandlerInvoker.InvokeAsync` has returned and the `Activity` has been disposed, so `Activity.Current` is no longer the handler activity (it is `null` or the poller's parent activity).

The same problem applies to all three call sites:

- `DefaultMessageManager.cs:185` — handler exception that escapes `HandlerInvoker` and is not `InvalidMessageHandlerSignatureException` or `AWSMessagingException`.
- `DefaultMessageManager.cs:200` — handler returned `MessageProcessStatus.Failed()`.
- `DefaultMessageManager.cs:206` — `handlerTask.IsFaulted` branch.

### Impact

- Outcome / failure logs cannot be correlated with the handler trace in any platform.
- For users who rely on click-through from log to trace as their primary debugging workflow, the most operationally interesting records (failures, faulted tasks) are exactly the ones with no trace context.
- The `MessageId` attribute is the only correlator, which forces a manual second query to find the related trace.

### Environment

- `AWS.Messaging` version: 1.3.0
- `AWS.Messaging.Telemetry.OpenTelemetry` version: 1.0.0
- .NET 10
- Logs and traces exported via OTLP (Datadog backend in our case, but the issue is in the producer side and is platform-independent).

Contributor guide

Open the contributing guide

Research direction

Start with HandlerInvoker.cs at the telemetry Activity opened in InvokeAsync, then trace the awaited outcome handling in DefaultMessageManager.cs within InvokeHandler, especially the logging calls around lines 185, 200, and 206. Reproduce a failed or faulted handler with OpenTelemetry enabled and verify that each outcome log retains the handler Activity's TraceId and SpanId.

Written by the indexing model from the issue text.

Assessment

Tech stack
aws, csharp
Domain
backend, observability-sre
Issue type
Bug
Difficulty
3/5
Estimated time
1-2 days
Activity status
Quiet
Clarity
Clearly specified
Newbie friendliness
55/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.