DistributedEventBus: Log messages always added with empty TraceId though amqp message with correlation_id was received

[a-herbst]

Is there an existing issue for this?

• I have searched the existing issues

Description

DistributedEventBusModules (e.g. like the RabbitMqDistributedEventBusModule) do not cause TraceId to be set in System.Diagnostics.Activity.CurrentActivity. Serilog messages are never logged with a TraceId because of that

• ... when a DistributedEventHandler adds a log message
• ... when an event failed to be deserialized by the DistributedEventBusModule
• ... when a DistributedEventHandler throws an exception

See

• RabbitMqDistributedEventBus only sets the correlationId in ICorrelationIdProvider
  but never via Activity.SetParentId
• Serilog reads TraceId from System.Diagnostics.Activity.CurrentActivity - see Logger.cs#L443

Reproduction Steps

0. (Skip to step 7. when checking out repository https://github.com/a-herbst/AbpIssueRabbitMqTraceIdNotLogged)

1. Initialize solution

   mkdir AbpIssueRabbitMqTraceIdNotLogged
   cd AbpIssueRabbitMqTraceIdNotLogged
   abp new AbpIssueRabbitMqTraceIdNotLogged -t app-nolayers -u no-ui --skip-migration --skip-migrator
   cd AbpIssueRabbitMqTraceIdNotLogged
   abp add-package Volo.Abp.EventBus.RabbitMQ

2. confiugre appsettings.json

   appsettings.json

   {
     ...,
   
     "RabbitMQ": {
       "EventBus": {
         "ClientName": "AbpIssueRabbitMqTraceIdNotLogged",
         "ExchangeName": "AbpIssueRabbitMqTraceIdNotLoggedExchange"
       }
     }
   }
   

3. configure log message template to contain a {TraceId} place holder

   Program.cs

   .WriteTo.Async(c =>
       c.File(
           "Logs/logs.txt",
           outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}]  (TraceId/CorrelationId: {TraceId}) {Message:lj}{NewLine}{Exception}"
       )
   )
   .WriteTo.Async(c =>
       c.Console(
           outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] (TraceId/CorrelationId:  {TraceId}) {Message:lj}{NewLine}{Exception}"
       )
   )

4. add Eto classes

   • CannotBeHandledEto.cs

     using Volo.Abp.Domain.Entities.Events.Distributed;
     using Volo.Abp.EventBus;
     
     namespace AbpIssueRabbitMqTraceIdNotLogged.Services.Etos
     {
         /// <summary>
         /// A sample ETO that causes a business exception when processed.
         /// </summary>
         [EventName("CannotBeHandledEto")]
         public class CannotBeHandledEto : EtoBase
         {
             public required string Data { get; set; }
         }
     }

   • NotDeserializableEto.cs

     using Volo.Abp.Domain.Entities.Events.Distributed;
     using Volo.Abp.EventBus;
     
     namespace AbpIssueRabbitMqTraceIdNotLogged.Services.Etos
     {
         /// <summary>
         /// A sample ETO that causes deserialization to fail.
         /// </summary>
         [EventName("NotDeserializableEto")]
         public class NotDeserializableEto : EtoBase
         {
             [JsonConstructor]
             public NotDeserializableEto()
             {
                 throw new InvalidOperationException("This ETO cannot be deserialized.");
             }
     
             public NotDeserializableEto(bool dummy) { }
     
             public required string Data { get; set; }
         }
     }

5. add DistributedEventHandler

   MyDistributedEventHandler.cs

   using System.Diagnostics;
   using AbpIssueRabbitMqTraceIdNotLogged.Services.Etos;
   using Volo.Abp;
   using Volo.Abp.DependencyInjection;
   using Volo.Abp.EventBus;
   using Volo.Abp.EventBus.Distributed;
   using Volo.Abp.Tracing;
   
   namespace AbpIssueRabbitMqTraceIdNotLogged.Services
   {
       public class MyDistributedEventHandler(
           ICorrelationIdProvider correlationIdProvider,
           ILogger<MyDistributedEventHandler> logger
       )
           : IDistributedEventHandler<CannotBeHandledEto>,
               IDistributedEventHandler<NotDeserializableEto>,
               IScopedDependency
       {
           public static bool WasCannotBeHandledEtoReceivedBefore = false;
   
           public Task HandleEventAsync(NotDeserializableEto eventData)
           {
               logger.LogInformation(
                   "{type} event received: {EventData}",
                   EventNameAttribute.GetNameOrDefault(eventData.GetType()),
                   eventData
               );
   
               logger.LogInformation(
                   "{type} event successfully handled: {EventData}",
                   EventNameAttribute.GetNameOrDefault(eventData.GetType()),
                   eventData
               );
   
               // the event handler will succeed - but the Eto will fail to  deserialize so this method will never be actually called
               return Task.CompletedTask;
           }
   
           public Task HandleEventAsync(CannotBeHandledEto eventData)
           {
               logger.LogInformation(
                   "{type} event received: {EventData}",
                   EventNameAttribute.GetNameOrDefault(eventData.GetType()),
                   eventData
               );
   
               // throw business exception when event is handled for the first time
               if (!WasCannotBeHandledEtoReceivedBefore)
               {
                   WasCannotBeHandledEtoReceivedBefore = true;
                   throw new BusinessException("Insert magic reason here");
               }
   
               logger.LogInformation(
                   "{type} event successfully handled: {EventData}",
                   EventNameAttribute.GetNameOrDefault(eventData.GetType()),
                   eventData
               );
   
               WasCannotBeHandledEtoReceivedBefore = true;
               return Task.CompletedTask;
           }
       }
   }

6. add a HostedService publishing those messages

   MyHostedService.cs

   using AbpIssueRabbitMqTraceIdNotLogged.Services.Etos;
   using Volo.Abp.DependencyInjection;
   using Volo.Abp.EventBus.Distributed;
   using Volo.Abp.Tracing;
   
   namespace AbpIssueRabbitMqTraceIdNotLogged.Services
   {
       public class MyHostedService(
           IServiceProvider serviceProvider,
           IHostApplicationLifetime hostApplicationLifetime
       ) : IHostedService, ITransientDependency
       {
           public Task StartAsync(CancellationToken cancellationToken)
           {
               using var serviceScope = serviceProvider.CreateAsyncScope();
               var correlationIdProvider =
                   serviceScope.ServiceProvider. GetRequiredService<ICorrelationIdProvider>();
               var distributedEventBus =
                   serviceScope.ServiceProvider. GetRequiredService<IDistributedEventBus>();
   
               // ensure to have a correlationId set
               string correlationId = Guid.Parse ("DEADBEEF-DEAD-BEEF-DEAD-DEADBEEFDEAD")
                   .ToString("N")
                   .ToLower();
               using var _ = correlationIdProvider.Change(correlationId);
   
               // publish event that will cause a BusinessException in EventHandler
               distributedEventBus.PublishAsync(new CannotBeHandledEto() { Data =  "42" });
   
               // publish another event that will cause an Exception while being  deserialized
               distributedEventBus.PublishAsync(new NotDeserializableEto(true) { Data  = "23" });
   
               Task.Delay(5000, cancellationToken)
                   .ContinueWith(_ =>
                   {
                       Console.WriteLine("Hosted Service is running. Stopping  application...");
                       hostApplicationLifetime.StopApplication();
                   });
               return Task.CompletedTask;
           }
   
           public Task StopAsync(CancellationToken cancellationToken)
           {
               return Task.CompletedTask;
           }
       }
   }

7. launch RabbitMq on localhost, i.e.

   docker run -it --rm --name rabbitmq -p 5672:5672 -p 15672:15672 rabbitmq:4-management

-> TraceId in log messages from EventHandler not set

2026-01-28 08:16:38.120 +01:00 [INF] (TraceId/CorrelationId: ) CannotBeHandledEto event received: AbpIssueRabbitMqTraceIdNotLogged.Services.Etos.CannotBeHandledEto
2026-01-28 08:16:38.350 +01:00 [WRN] (TraceId/CorrelationId: ) Exception of type 'Volo.Abp.BusinessException' was thrown.
Volo.Abp.BusinessException: Exception of type 'Volo.Abp.BusinessException' was thrown.
   at AbpIssueRabbitMqTraceIdNotLogged.Services.MyDistributedEventHandler.HandleEventAsync(CannotBeHandledEto eventData) in C:\Users\ANH\source\repos\CSFiddle\AbpIssueRabbitMqTraceIdNotLogged\AbpIssueRabbitMqTraceIdNotLogged\Services\MyDistributedEventHandler.cs:line 69
   at Volo.Abp.EventBus.DistributedEventHandlerMethodExecutor`1.<>c.<get_ExecutorAsync>b__1_0(IEventHandler target, Object parameter)
   at Volo.Abp.EventBus.EventHandlerInvoker.InvokeAsync(IEventHandler eventHandler, Object eventData, Type eventType)
   at Volo.Abp.EventBus.EventBusBase.TriggerHandlerAsync(IEventHandlerFactory asyncHandlerFactory, Type eventType, Object eventData, List`1 exceptions, InboxConfig inboxConfig)
   at System.AbpExceptionExtensions.ReThrow(Exception exception)
   at Volo.Abp.EventBus.EventBusBase.ThrowOriginalExceptions(Type eventType, List`1 exceptions)
   at Volo.Abp.EventBus.EventBusBase.TriggerHandlersAsync(Type eventType, Object eventData)
   at Volo.Abp.EventBus.Distributed.DistributedEventBusBase.TriggerHandlersDirectAsync(Type eventType, Object eventData)
   at Volo.Abp.EventBus.RabbitMq.RabbitMqDistributedEventBus.ProcessEventAsync(IChannel channel, BasicDeliverEventArgs ea)
   at Volo.Abp.RabbitMQ.RabbitMqMessageConsumer.HandleIncomingMessageAsync(Object sender, BasicDeliverEventArgs basicDeliverEventArgs)
2026-01-28 08:16:38.351 +01:00 [WRN] (TraceId/CorrelationId: ) Code:Insert magic reason here
2026-01-28 08:16:38.459 +01:00 [ERR] (TraceId/CorrelationId: ) This ETO cannot be deserialized.
System.InvalidOperationException: This ETO cannot be deserialized.
   at AbpIssueRabbitMqTraceIdNotLogged.Services.Etos.NotDeserializableEto..ctor() in C:\Users\ANH\source\repos\CSFiddle\AbpIssueRabbitMqTraceIdNotLogged\AbpIssueRabbitMqTraceIdNotLogged\Services\Etos\NotDeserializableEto.cs:line 16
   at .ctor()
   at System.Text.Json.Serialization.Converters.ObjectDefaultConverter`1.OnTryRead(Utf8JsonReader& reader, Type typeToConvert, JsonSerializerOptions options, ReadStack& state, T& value)
   at System.Text.Json.Serialization.JsonConverter`1.TryRead(Utf8JsonReader& reader, Type typeToConvert, JsonSerializerOptions options, ReadStack& state, T& value, Boolean& isPopulatedValue)
   at System.Text.Json.Serialization.JsonConverter`1.ReadCore(Utf8JsonReader& reader, T& value, JsonSerializerOptions options, ReadStack& state)
   at System.Text.Json.Serialization.Metadata.JsonTypeInfo`1.Deserialize(Utf8JsonReader& reader, ReadStack& state)
   at System.Text.Json.Serialization.Metadata.JsonTypeInfo`1.DeserializeAsObject(Utf8JsonReader& reader, ReadStack& state)
   at System.Text.Json.JsonSerializer.ReadFromSpanAsObject(ReadOnlySpan`1 utf8Json, JsonTypeInfo jsonTypeInfo, Nullable`1 actualByteCount)
   at System.Text.Json.JsonSerializer.ReadFromSpanAsObject(ReadOnlySpan`1 json, JsonTypeInfo jsonTypeInfo)
   at System.Text.Json.JsonSerializer.Deserialize(String json, Type returnType, JsonSerializerOptions options)
   at Volo.Abp.Json.SystemTextJson.AbpSystemTextJsonSerializer.Deserialize(Type type, String jsonString, Boolean camelCase)
   at Volo.Abp.RabbitMQ.Utf8JsonRabbitMqSerializer.Deserialize(Byte[] value, Type type)
   at Volo.Abp.EventBus.RabbitMq.RabbitMqDistributedEventBus.ProcessEventAsync(IChannel channel, BasicDeliverEventArgs ea)
   at Volo.Abp.RabbitMQ.RabbitMqMessageConsumer.HandleIncomingMessageAsync(Object sender, BasicDeliverEventArgs basicDeliverEventArgs)

Expected behavior

1. Log messages template strings containing a {TraceId} placeholder should produce log entries where this placeholder is replaced with the correlation_id value received from the amqp message
   • ... when an IDistributedEventHandler logs a message

     2026-01-28 08:16:38.120 +01:00 [INF] (TraceId/CorrelationId: deadbeefdeadbeefdeaddeadbeefdead) CannotBeHandledEto event received: AbpIssueRabbitMqTraceIdNotLogged.Services.Etos.CannotBeHandledEto
     

   • ... when an event failes to be deserialized

     2026-01-28 08:16:38.459 +01:00 [ERR] (TraceId/CorrelationId: deadbeefdeadbeefdeaddeadbeefdead) This ETO cannot be deserialized.
     System.InvalidOperationException: This ETO cannot be deserialized.
     ...
     

   • ... when a Exception is thrown within a IDistributedEventHandler

     2026-01-28 08:16:38.350 +01:00 [WRN] (TraceId/CorrelationId: deadbeefdeadbeefdeaddeadbeefdead) Exception of type 'Volo.Abp.BusinessException' was thrown.
     Volo.Abp.BusinessException: Exception of type 'Volo.Abp.BusinessException' was thrown.
     ...
     

Actual behavior

1. {TraceId} placeholder of the log message template string is always empty - even when the amqp message contained a correlation_id property
   • ... when an IDistributedEventHandler logs a message

     2026-01-28 08:16:38.120 +01:00 [INF] (TraceId/CorrelationId: ) CannotBeHandledEto event received: AbpIssueRabbitMqTraceIdNotLogged.Services.Etos.CannotBeHandledEto
     

   • ... when an event failes to be deserialized

     2026-01-28 08:16:38.459 +01:00 [ERR] (TraceId/CorrelationId: ) This ETO cannot be deserialized.
     System.InvalidOperationException: This ETO cannot be deserialized.
     ...
     

   • ... when a Exception is thrown within a IDistributedEventHandler

     2026-01-28 08:16:38.350 +01:00 [WRN] (TraceId/CorrelationId: ) Exception of type 'Volo.Abp.BusinessException' was thrown.
     Volo.Abp.BusinessException: Exception of type 'Volo.Abp.BusinessException' was thrown.
     ...
     

Regression?

No response

Known Workarounds

• No workaround known to log Exceptions that happen during deserialization of an event
• IDistributedEventHandler implementations can set System.Diagnostics.Activity.TraceId before logging messages:

  Guid correlationId = Guid.Parse(correlationIdProvider.Get());
  
  var activity = new Activity("RabbitMqDistributedEventBus");
  activity.SetParentId(
    traceId: ActivityTraceId.CreateFromString(correlationId.ToString("N").ToLower()),
    spanId: Activity.Current?.SpanId ?? ActivitySpanId.CreateRandom()
  );
  using var _ = activity.Start();

Version

10.0

User Interface

Common (Default)

Database Provider

None/Others

Tiered or separate authentication server

None (Default)

Operation System

Windows (Default)

Other information

No response

[maliming]

hi

You can try to add a custom ILogEventEnricher.

using System;
using Serilog.Core;
using Serilog.Events;
using Volo.Abp.Tracing;

namespace MyCompanyName.MyProjectName.Web;

public class AbpCorrelationIdLogEventEnricher : ILogEventEnricher
{
    private readonly ICorrelationIdProvider _correlationIdProvider;

    public AbpCorrelationIdLogEventEnricher(ICorrelationIdProvider correlationIdProvider)
    {
        _correlationIdProvider = correlationIdProvider;
    }

    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        var correlationId = _correlationIdProvider.Get();
        if (correlationId.IsNullOrWhiteSpace())
        {
            return;
        }

        if (logEvent.Properties.ContainsKey("CorrelationId"))
        {
            return;
        }

        logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty("CorrelationId", correlationId));
    }
}

Log.Information("Starting web host.");
var builder = WebApplication.CreateBuilder(args);
builder.Host.AddAppSettingsSecretsJson()
    .UseAutofac()
    .UseSerilog((context, services, configuration) =>
    {
        configuration.MinimumLevel.Debug()
            .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
            .MinimumLevel.Override("Microsoft.EntityFrameworkCore", LogEventLevel.Warning)
            .Enrich.FromLogContext()
            .WriteTo.Async(c => c.File("Logs/logs.txt"))
            .WriteTo.Async(c =>
                c.Console(
                    outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] (TraceId/CorrelationId:  {CorrelationId}) {Message:lj}{NewLine}{Exception}"
                )
            )
            .Enrich.With(new AbpCorrelationIdLogEventEnricher(services.GetRequiredService<ICorrelationIdProvider>()));
    });
await builder.AddApplicationAsync<MyProjectNameWebModule>();

[a-herbst]

Enriching the LogContext only unfortunately will not be enough since this only supplies a property to the full-text produced by the log message template. But once you configure a serilog sink like

• https://github.com/serilog-contrib/serilog-sinks-applicationinsights
• or https://github.com/serilog/serilog-sinks-opentelemetry

... for using OpenTelemetry or ApplicationInsights you want to be able to filter and join for logs / traces / exceptions belonging to the same operation. For this to work it is important that the CorrelationId is transported to ApplicationInsights Operation_Id or to OpenTelemetry's LogRecord.TraceId.

LogEvent.TraceId is automatically filled by Serilog by reading the Activity.Current.TraceId. AspNetCore does this for you when an endpoint in a Controller gets called.

But when the DistributedEventBus is processing an event the DistributedEventBus module itself must take care of reading the correlation_id from AMQP and setting up an System.Diagnostics.Acitivity with it by doing something like I described in the workaround:

string correlationId = ...; // get current or create correlationId

var activity = new Activity("RabbitMqDistributedEventBus");
activity.SetParentId(
  traceId: ActivityTraceId.CreateFromString(correlationId.ToLower()),
  spanId: Activity.Current?.SpanId ?? ActivitySpanId.CreateRandom()
);
using var _ = activity.Start();

[maliming]

hi

AspNetCore does this for you when an endpoint in a Controller gets called.

Can you share the details of this behavior?

Thanks.

[a-herbst]

This behiavour should come from the default ActivityTrackingOptions that are configured by the HostBuilders in AspNetCore:

• https://learn.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-10.0#specify-the-trace-context-for-logging-scopes
• https://github.com/search?q=repo%3Adotnet%2Faspnetcore%20ActivityTrackingOptions&type=code