Feature Idea: Add Support for NServiceBus Version 6

We recently had a question regarding New Relic support for NServiceBus version 6 https://groups.google.com/forum/#!topic/particularsoftware/i1lLjwslIo0

I was wondering if I could provide any help with getting the two to play nicely together.

New Relic edit

We take feature ideas seriously and our product managers review every one when plotting their roadmaps. However, there is no guarantee this feature will be implemented. This post ensures the idea is put on the table and discussed though. So please vote and share your extra details with our team.

Here’s the NServiceBus definition included with New Relic .NET agent. I think it only works with NServiceBus 5:

<?xml version="1.0" encoding="utf-8"?>
<extension xmlns="urn:newrelic-extension">
	<instrumentation>
		<tracerFactory name="NewRelic.Agent.Core.Tracer.Factories.BackgroundThreadTracerFactory">
			<match assemblyName="NServiceBus.Core" className="NServiceBus.Pipeline.MessageHandler">
				<exactMethodMatcher methodName="Invoke" parameters="object,NServiceBus.IMessageHandlerContext" />
			</match>
			<match assemblyName="GCC.MeasureAndInstall.Jobs.NServiceBus.Host" className="GCC.MeasureAndInstall.Jobs.NServiceBus.Host.Program">
				<exactMethodMatcher methodName="TestCall"/>
			</match>
		</tracerFactory>
	</instrumentation>
</extension>

Edit: Removed a debug tracerfactory I had accidentally included.

My current attempt to at least instrument message handling, based off a recomendation from the Particular Google Group.

<?xml version="1.0" encoding="utf-8"?>
<extension xmlns="urn:newrelic-extension">
	<instrumentation>
		<tracerFactory>
			<match assemblyName="NServiceBus.Core" className="NServiceBus.InvokeHandlerTerminator">
				<exactMethodMatcher methodName="Terminate" parameters="NServiceBus.Pipeline.IInvokeHandlerContext" />
			</match>
	</tracerFactory></instrumentation>
</extension>

I have set the logging level to “Debug” in my agent’s config. In the logging for the particular application I can see the following mentioned:

  {
    "name": "DotNet\/NServiceBus.InvokeHandlerTerminator\/Terminate"
  },
  [
    2,
    0.0842691,
    0.0842691,
    0.0003661,
    0.083903,
    0.00703984732
  ]
]

But I still do not see it showing up in the new relic transactions list on the site. Can anyone point me at what I might be missing?

I’ve updated my instrumentation with another wild stab based off some documentation:

<?xml version="1.0" encoding="utf-8"?>
<extension xmlns="urn:newrelic-extension">
	<instrumentation>
		<tracerFactory name="NewRelic.Agent.Core.Tracer.Factories.BackgroundThreadTracerFactory" metricName="NServiceBus/Handler">
			<match assemblyName="NServiceBus.Core" className="NServiceBus.InvokeHandlerTerminator">
				<exactMethodMatcher methodName="Terminate" parameters="NServiceBus.Pipeline.IInvokeHandlerContext" />
			</match>
		</tracerFactory>
	</instrumentation>
</extension>

I’m actually seeing the transaction appear in New Relic now, which is a big win. But in NServiceBus5 we would see the actual individual message handlers as different transactions. Here, they are all showing as NServiceBus.InvokeHandlerTerminator/Terminate. I don’t see in the old XML file how this was accomplished.

Can someone please help me understand how this worked before and what I need to do to get this working better for NServiceBus 6?

@Jake_Stevenson -

There actually has been no testing of the agent against NServiceBus 6. It’s unknown if the current instrumentation which was developed for v 5.0 works with v 6.0. You can see the current instrumentation in the file: C:\ProgramData\New Relic\.NET Agent\Extensions\NewRelic.Providers.Wrapper.NServiceBus.Instrumentation.xml. It could be NServiceBus 6.0 has changed things just enough to invalidate that instrumentation. If that’s the case then your current approach would be the recommended one.

Also @Jake_Stevenson - you are amazing for both trying to make this work and documenting your progress. THANK YOU for sharing all those detail here. You are a hero!

At this point I’ve determined New Relic wrote a little “magic” as a plugin that is smart enough to intercept NServiceBus 5 calls and interpret them differently. That magic is contained in the NewRelic.Providers.Wrapper.NServiceBus.dll distributed with the .NET agent.

The magic is pretty simple, if the call is from an expected NServiceBus method, it will do some examination of the arguments to determine the Queue and use that for the naming of the transaction in New Relic. Unfortunately, this DOES require code and doesn’t appear to be possible purely through the XML custom instrumentation.

NServicebus has changed it’s pipeline pretty dramatically for version 6, but it shouldn’t be too difficult to write a new plugin that will perform the same functionality

It doesn’t look like these plugins are open-source on the new relic github account. Would it be possible to open it up?

Agreed. that would be great

I’ve started writing my own plugin for New Relic 6. With my plugin and custom instrumentation XML file I was able to see this in my agent log:

2016-12-08 15:40:12,226 NewRelic DEBUG: Invoking "analytic_event_data" with : ["165735028082617915",[[{"type":"Transaction","timestamp":1481211562.8379924,"name":"OtherTransaction/Message/NServiceBus/Queue/Named/My.NServiceBus.CommandNam","duration":0.24966229999999998,"totalTime":0.2069011,"nr.apdexPerfZone":"S","webDuration":0.24966229999999998,"databaseDuration":0.0968438},{},{}],[{"type":"Transaction","timestamp":1481211565.5173988,"name":"OtherTransaction/Message/NServiceBus/Queue/Named/GCC.MeasureAndInstall.Jobs.NServiceBus.Contracts.Events.v1.IJobBooked","duration":0.0028574,"totalTime":0.0013585,"nr.apdexPerfZone":"S","webDuration":0.0028574},{},{}]]]

Success!

So now I see the transaction statistics appearing in new relic, but I don’t see traces for individual transactions. I’m hoping it’s just because the transactions are too fast.

Hi there - and thanks for the follow up on this. I wanted to check in and make sure we’re on the same page. The NServiceBus features are written into the .NET agent, which is not something we would make available open source. The agent is fundamentally different from plugins.

Or are you referencing a plugin in addition to the agent?

Thanks for helping me sort that.

Holly

I apologize, I think I got New Relic’s concept of extensions mixed up with plugins.

It’s an extension to the .NET Agent which I am working with.

Jake. is this open source? can i contribute?

Hey @Jake.Stevenson and @simon.cropp - thanks for your patience while I did a little digging. I can definitely understand the confusion. The NServiceBus code is in a file called /extensions in the agent. However, it is not really a standalone extension. It’s definitely part of the agent itself and can not be separated.

So - My earlier note still stands. We’re not able to make the agent open source, so the Feature Request is our best course of action. Sorry to be the bearer of not great news.

@Tjd https://docs.newrelic.com/docs/agents/net-agent/getting-started/compatibility-requirements-net-agent#messaging states “NServiceBus 5.0 or higher: Puts and takes on messages and cross application tracing”. Could you change this to “NServiceBus 5.x” until v6 is supported? It was unexpected to us that transactions stopped reporting after we upgraded to v6.

Before the agent got built-in support for NServiceBus 5, we were able to track individual messages as transactions by adding custom instrumentation like this:

    <tracerFactory name="NewRelic.Agent.Core.Tracer.Factories.BackgroundThreadTracerFactory" metricName="MessageHandlers/BazCommandHandler">
        <match assemblyName="Foo.Bar" className="Foo.Bar.MessageHandlers.BazCommandHandler">
            <exactMethodMatcher methodName="Handle" />
        </match>
    </tracerFactory>

Since the Handle method is async in v6, I’ve tried replacing the above definition with the following:

    <tracerFactory name="NewRelic.Providers.Wrapper.CustomInstrumentationAsync.OtherTransactionWrapperAsync​​" metricName="MessageHandlers/BazCommandHandler">
        <match assemblyName="Foo.Bar" className="Foo.Bar.MessageHandlers.BazCommandHandler">
            <exactMethodMatcher methodName="Handle" />
        </match>
    </tracerFactory>

But we’re not seeing any reports. The profiler log indicates that the Handle method is being instrumented, though.

@Jake.Stevenson Would be awesome if you could share your extension.

@hross Is there any way to push it forward? We have more people asking for this.

@khansen can you please contact me on < redacted email address >? We’d like to learn more about your problem.

I gave this a quick spike today

It works I’ve currently only implemented the message receive part and not the outgoing operations. I left it compliant with what the extension previously did, although I think we could provide better ways of reporting.

Pasted image2645x1494 355 KB

@weronika.labaj - I don’t have any updates from engineering, but did you see @daniel.marbach 's workaround? Curious to see if this works for others…

@daniel.marbach Cool, works for us, too.
The transactions time looks off, though; most transactions are reporting as ~1ms. Our command handlers make async calls to a web api, and the average response time from this api is ~150ms. Those calls are showing up with expected response times under “External services”. Any way to make the transactions time reflect this?

104318042017.png811x225 14.6 KB

@khansen I would suspect it is because of the Task returning APIs. I tried to dig a bit more the code of the NewRelic agent, especially the broker segment part. I have a hunch the API call is marked as finished as soon as the code reaches the first await statement. Maybe it is also my improper usage of their APIs. I do think this is a thing for the NewRelic support though. From Particular Software Standpoint we are happy to help out but unfortunately we cannot own this code since it is highly new relic specific and requires API knowledge that arguably new relic already has