SetTransactionName not respected in RabbitMQ transactions after updating from 10.18.0 to 10.19.1

[tro2102]

Description After upgrading to 10.19.1, RabbitMQ consumer transactions as consumed by EventingBasicConsumer are no longer being reported as the name specified when calling NewRelic.Api.Agent.NewRelic.SetTransactionName(). Instead, they are reported as the default OtherTransaction/Message/RabbitMQ/Topic/Named/<routingKey>

Pinning the NR agent version to 10.18.0 resolves the behavior.

Expected Behavior Transactions respect the name specified in NewRelic.Api.Agent.NewRelic.SetTransactionName()

Your Environment Docker mcr.microsoft.com/dotnet/sdk:7.0

[workato-integration[bot]]

https://new-relic.atlassian.net/browse/NR-179041

[chynesNR]

Hello @tro2102 -- thanks for your report. I was able to use SetTransactionName() on a RabbitMQ transaction and it behaved as expected, so I'm not sure why you're seeing that behavior. The best way to troubleshoot would be to take a look at your Agent logs at Finest level, and the best way for you to share that with us securely would be to go through our Support channels. Please make sure to reference this issue so that we can link them.

[tro2102]

Thanks for the quick response, @chynesNR . I got some additional information today while running the agent locally. I've attached some stripped down logs here. The same exact application code was run to generate both logs.

Using NR agent 10.19.1:

2023-11-10 19:33:17,496 NewRelic  DEBUG: [pid: 7, tid: 17] Wrapper "NewRelic.Providers.Wrapper.RabbitMq.HandleBasicDeliverWrapper" will be used for instrumented method "RabbitMQ.Client.Impl.ModelBase.HandleBasicDeliver"
2023-11-10 19:33:17,498 NewRelic FINEST: [pid: 7, tid: 17] Trx Noop: Attempting to execute NewRelic.Providers.Wrapper.RabbitMq.HandleBasicDeliverWrapper found from InstrumentedMethodInfo: Method: RabbitMQ.Client.Impl.ModelBase, RabbitMQ.Client, Version=6.0.0.0, Culture=neutral, PublicKeyToken=89e7d7c5feba84ce:HandleBasicDeliver(System.String,System.UInt64,System.Boolean,System.String,System.String,RabbitMQ.Client.IBasicProperties,System.ReadOnlyMemory`1[System.Byte]), RequestedWrapperName: HandleBasicDeliverWrapper, IsAsync: False, RequestedMetricName: , RequestedTransactionNamePriority: , StartWebTransaction: False
2023-11-10 19:33:17,527 NewRelic FINEST: [pid: 7, tid: 17] Trx 0ec33431d7e72511: Created transaction on NewRelic.Agent.Extensions.Providers.ThreadLocalStorage`1[NewRelic.Agent.Core.Transactions.IInternalTransaction]

...

2023-11-10 19:33:17,566 NewRelic FINEST: [pid: 7, tid: 17] Trx 0ec33431d7e72511: Response time captured.
2023-11-10 19:33:17,575 NewRelic   INFO: [pid: 7, tid: 7] Initializing the Agent API
2023-11-10 19:33:17,580 NewRelic   WARN: [pid: 7, tid: 7] Agent API Error: An error occurred invoking API method "SetTransactionName" - "System.InvalidOperationException: The API method called is only valid from within a transaction. This error can occur if you call the API method from a thread other than the one the transaction started on.
   at NewRelic.Agent.Core.Api.AgentApiImplementation.GetCurrentInternalTransaction()
   at NewRelic.Agent.Core.Api.AgentApiImplementation.SetTransactionName(String category, String name)
   at NewRelic.Agent.Core.AgentApi.TryInvoke(Action action, String methodName, ApiMethod apiMethod)"

And 10:18.0:

2023-11-10 18:40:54,445 NewRelic  DEBUG: [pid: 7, tid: 5] Wrapper "NewRelic.Providers.Wrapper.RabbitMq.HandleBasicDeliverWrapper" will be used for instrumented method "RabbitMQ.Client.Events.EventingBasicConsumer.HandleBasicDeliver"
2023-11-10 18:40:54,445 NewRelic FINEST: [pid: 7, tid: 5] Trx Noop: Attempting to execute NewRelic.Providers.Wrapper.RabbitMq.HandleBasicDeliverWrapper found from InstrumentedMethodInfo: Method: RabbitMQ.Client.Events.EventingBasicConsumer, RabbitMQ.Client, Version=6.0.0.0, Culture=neutral, PublicKeyToken=89e7d7c5feba84ce:HandleBasicDeliver(System.String,System.UInt64,System.Boolean,System.String,System.String,RabbitMQ.Client.IBasicProperties,System.ReadOnlyMemory`1[System.Byte]), RequestedWrapperName: HandleBasicDeliverWrapper, IsAsync: False, RequestedMetricName: , RequestedTransactionNamePriority: , StartWebTransaction: False
2023-11-10 18:40:54,472 NewRelic FINEST: [pid: 7, tid: 5] Trx 41623dfc6b9c9ec2: Created transaction on NewRelic.Agent.Extensions.Providers.ThreadLocalStorage`1[NewRelic.Agent.Core.Transactions.IInternalTransaction]

...

2023-11-10 18:40:54,523 NewRelic   INFO: [pid: 7, tid: 5] Initializing the Agent API
2023-11-10 18:40:54,526 NewRelic FINEST: [pid: 7, tid: 5] Trx 41623dfc6b9c9ec2: Retrieved from NewRelic.Agent.Extensions.Providers.ThreadLocalStorage`1[NewRelic.Agent.Core.Transactions.IInternalTransaction]
2023-11-10 18:40:54,562 NewRelic FINEST: [pid: 7, tid: 5] Trx 41623dfc6b9c9ec2: Setting transaction name to TransactionName{"IsWeb":false,"Category":"<removed>","Name":"<removed>","UnprefixedName":"<removed>"} (priority 2147483647, UserTransactionName) from TransactionName{"IsWeb":false,"Category":"<removed>","Name":"<removed>","UnprefixedName":"<removed>"} (priority 0, 0)

The exception isn't present in the logs on 10.18.0, and there is far more log content in 10.18.0 after the included lines. It appears the transaction ends in 10.19.1 before we attempt SetTransactionName().

[chynesNR]

Thanks @tro2102 -- that's exactly the information I was looking for! We did change one of the instrumentation points for RabbitMQ recently to a lower-level function, as we found cases where we might have been missing work that was being done. It's possible that changed the timing a little, especially if that function is the final call in the transaction. Would you be able to try moving the SetTransactionName() call earlier to see if that fixes it?

[tro2102]

We can absolutely try to test that next week, @chynesNR. In the meantime, here's a simplified overview of how we're using it - we call SetTransactionName() pretty early in the consumer process... pretty much as soon as we can, based on the transaction name we're trying to use.

var consumer = new EventingBasicConsumer(_channel);
consumer.Received += MessageHandler(_channel);

_channel.BasicConsume(
    queue: _topology.QueueName,
    autoAck: false,
    consumer: consumer
);

private EventHandler<BasicDeliverEventArgs> MessageHandler(IModel channel)
{
    return (_, ea) =>
    {
        try
        {
            var body = ea.Body.ToArray();
            var message = Encoding.UTF8.GetString(body);
            var messageType = GetMessageType(ea);
            NewRelic.Api.Agent.NewRelic.SetTransactionName("Consume", messageType);
            DoBusinessLogic(messageType, message);
            channel.BasicAck(ea.DeliveryTag, false);
        }
        catch (Exception e)
        {
            channel.BasicReject(ea.DeliveryTag, false);
        }
    };
}

The call happens before pretty much any non-Rabbit-specific functionality.

[chynesNR]

Hi @tro2102 -- Thanks for the code snippet. I was able to reproduce the issue you describe. We did change one of the RabbitMQ instrumentation points, which was intended to catch more usage edge cases, but if that's the only work being done in the Transaction, it is ending sooner than it should. I'll see if we can find a better way to handle it. In the meantime, if you don't want to roll back the Agent, you should be able to edit your NewRelic.Providers.Wrapper.RabbitMq.Instrumentation.xml to use the old instrumentation point: Current:

  <tracerFactory name="HandleBasicDeliverWrapper">
        <match assemblyName="RabbitMQ.Client" className="RabbitMQ.Client.Impl.ModelBase">
            <exactMethodMatcher methodName="HandleBasicDeliver" />
        </match>
  </tracerFactory>

Previous (change yours back to this):

  <tracerFactory name="HandleBasicDeliverWrapper">
        <match assemblyName="RabbitMQ.Client" className="RabbitMQ.Client.Events.EventingBasicConsumer">
            <exactMethodMatcher methodName="HandleBasicDeliver" />
        </match>
  </tracerFactory>