Enable ServiceBus dependency and request collection #1797

lmolkova · 2018-07-06T00:06:56Z

This change enables ServicBus calls tracking
ApplicaitonInsights listens to ServiceBus SDK events and tracks requests automatically, enriching them with ServiceBus specific properties such as endpoint, queue name, function called (Send/Process)

Such events are translated to telemetry so that 'Send' is tracked as dependency and 'Process' is a request.
ServiceBus SDK also ensures that is there is a trace context in the message, it will be used.

There is a small caveat with request tracking: AppInsights SDK tracks request from SB automatically and therefore Request tracked by webjobs SDK, in this case, is not needed.
Based on the presence of Activity.Current, we can say whether someone tracks request already and avoid double-tracking.

We've had an offline conversation with @brettsam about HTTP requests, and we've decided that 'outer', 'automagical' request should be tracked: it contains specific info (such as SB message Id or queue name, or in case of HTTP request URL and response code).
'Outer' request will have a bit bigger duration than a pure function call; for now, actual function duration is added into the telemetry properties.

Request operation name still is set to function name as portal UI depends on it.

ServiceBus package was updated to the latest stable version 3.0.2 because of NullReferenceException bug in diagnostics code Azure/azure-service-bus-dotnet#459

lmolkova · 2018-07-06T00:07:45Z

@brettsam @fabiocav please review when you have time

brettsam

Had a couple of initial comments.

brettsam · 2018-07-06T13:13:30Z

src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Constants/LogConstants.cs

@@ -143,5 +143,10 @@ public static class LogConstants
        /// Gets the name of the key used to store a metric sum.
        /// </summary>
        public const string MetricValueKey = "Value";
+
+        /// <summary>
+        /// Gets the name of they key used to store function execution time in the ApplicationInsights RequestTelemetry properties.


nit: "they" -> "the"

brettsam · 2018-07-06T13:14:39Z

...rosoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsHostBuilderExtensions.cs

                    return dependencyCollector;
                });
                services.AddSingleton<ITelemetryModule, AppServicesHeartbeatTelemetryModule>();

-                ServerTelemetryChannel serverChannel = new ServerTelemetryChannel();
-                services.AddSingleton<ITelemetryChannel>(serverChannel);
+                services.AddSingleton<ITelemetryChannel, ServerTelemetryChannel>();


Was this the other Disposal issue that you'd mentioned?

brettsam · 2018-07-06T13:21:35Z

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLogger.cs

        }

-        private static void ApplyFunctionResultProperties(RequestTelemetry requestTelemetry, IEnumerable<KeyValuePair<string, object>> stateValues)
+        private static void ApplyFunctionResultActivityTags(IEnumerable<KeyValuePair<string, object>> state, IDictionary<string, object> scope)


Can you add a comment as to what's happening here? We're adding these to the Activity Tags... and then they'll be used elsewhere by App Insights?

brettsam · 2018-07-06T13:24:13Z

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLogger.cs

-            // Set ip address to zeroes. If we find HttpRequest details below, we will update this
-            requestTelemetry.Context.Location.Ip = LoggingConstants.ZeroIpAddress;
+                // Set ip address to zeroes. If we find HttpRequest details below, we will update this
+                //requestTelemetry.Context.Location.Ip = LoggingConstants.ZeroIpAddress;


Remove this commented out line? Looks like you do this elsewhere now.

brettsam · 2018-07-06T14:27:20Z

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/WebJobsTelemetryInitializer.cs

-            if (telemetry is ISupportProperties telemetryProps)
+            // this could be telemetry tracked in scope of function call - then we should apply the logger scope
+            // or RequestTelemetry tracked by the WebJobs SDK or AppInsight SDK - then we should apply Activity.Tags
+            if (request == null && scopeProps.Any())


How are you determining whether the RequestTelemetry is part of a function call here? Shouldn't RequestTelemetry not be null in that case?

RequestTelemetry is never null (initializer runs on tracked telemetry item). The question is: who reported RequestTelemetry: functions in LogFunctionResult or AppInsights SDK automagically

brettsam · 2018-07-06T14:31:06Z

...Jobs.Host.EndToEndTests/ApplicationInsights/ServiceBusRequestAndDependencyCollectionTests.cs

+                _functionWaitHandle.WaitOne();
+
+                //TODO : clean me
+                await Task.Delay(5000);


Note -- one thing I've been doing lately to remove these delays is to instead use TestHelpers.Await() and wait for the telemetries to appear. It'll auto-timeout if it takes too long, and that way the test is more deterministic.

brettsam · 2018-07-06T14:47:59Z

FYI -- I'll do another pass through when it's all ready to merge for a final review

lmolkova · 2018-07-07T00:03:59Z

FYI -- I'll do another pass through when it's all ready to merge for a final review

thanks, I'm debugging the new test that always passes locally, I'll fix it and go through your comments.

I'll let you know when I'm done, please ignore all debugging commits for now...

lmolkova · 2018-07-07T04:13:55Z

@brettsam
I've done with my changes, but I found the issue in ApplicaitonInsights SDK that seems to affect tests only: microsoft/ApplicationInsights-dotnet-server#948.

The test fails because other service bus tests might run before it and it affects magical auto-collection :(

We are fixing the issue in the next ApplicaitonInsights release (stable in a 1-2 weeks) and I'll update the version and enable the test.

Please advise whether it's ok to merge like that.

lmolkova · 2018-08-08T18:27:53Z

@brettsam could you please have a look? There was an issue with ServiceBus dependency collection that we've fixed in AppInsights 2.7, so if you're ok with this, it is ready to merge

lmolkova · 2018-08-08T21:10:31Z

Still blocked because of microsoft/ApplicationInsights-dotnet-server#970

lmolkova · 2018-08-11T02:29:15Z

Finally ready. All issues fixed and tests passed

lmolkova · 2018-08-13T20:34:46Z

quick pulse tests still seem to be unstable. But this change is ready for merge.
@brettsam

lmolkova · 2018-08-14T17:03:57Z

@brettsam could you please merge it if you don't have other concerns

brettsam · 2018-08-14T17:30:07Z

Taking another look now... I've kicked off another test run to make sure that it's just flakiness with that QuickPulse test. I made some improvements to it in v2.x but I need to port those over to dev.

brettsam

Looks good. Just one really minor comment (on a comment). If you can get that spelling fixed (and squash down to a single commit), I'll double-check that moving the SB nuget forward is okay. Then I'll go ahead and merge.

brettsam · 2018-08-14T17:32:51Z

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLogger.cs

-            // are added to the Properties bag.
-            foreach (KeyValuePair<string, object> prop in stateValues)
+            // Activity carries tracing context. It is managed by instrumented library (e.g. ServiceBus or Asp.Net Core)
+            // and consumed by ApplicaitonInsigts.


nit: spelling

brettsam · 2018-08-14T17:59:56Z

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLogger.cs

+
+                if (scope.TryGetValue(LogConstants.LogLevelKey, out object logLevel))
+                {
+                    currentActivity.AddTag(LogConstants.LogLevelKey, logLevel.ToString());
                }


Note: I'll need to set the FunctionInvocationId here as well, right? (as part of my PR that's out for review).

It seems I've found a simpler way to set invocation id on all telemetry in WebJobsTelemetryInitializer

azure-webjobs-sdk/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/WebJobsTelemetryInitializer.cs

Line 77 in 4ee8b1c

string invocationId = scopeProps.GetValueOrDefault<string>(ScopeKeys.FunctionInvocationId);

It will be stamped on all telemetry even dependencies that do not come through the ApplicationInsightsLogger.

But your PR still does some nice refactoring and better tests. Could you merge it and I'll rebase this one after that?

Sure, thanks! Merging now.

brettsam · 2018-08-14T18:05:52Z

src/Microsoft.Azure.WebJobs.ServiceBus/WebJobs.ServiceBus.csproj

@@ -9,8 +9,8 @@
  </PropertyGroup>

  <ItemGroup>
-    <PackageReference Include="Microsoft.Azure.ServiceBus" Version="2.0.0" />
-    <PackageReference Include="StyleCop.Analyzers" Version="1.1.0-beta004">
+    <PackageReference Include="Microsoft.Azure.ServiceBus" Version="3.0.2" />


@mathewc / @fabiocav -- this change is bumping our ServiceBus dependency. Do we have any concerns with that? I know we wanted to do it anyway, but wanted to make sure it was clear that it was happening here.

Chatted with Mathew and Fabio -- this should be fine (and we needed to do it anyway).

brettsam · 2018-08-14T18:27:28Z

It looks like we're seeing an additional trace with those QuickPulse tests. Do you see that locally?

lmolkova · 2018-08-15T16:50:24Z

It looks like we're seeing an additional trace with those QuickPulse tests. Do you see that locally?

I'm not able to repo it locally. On the build server, if the new test introduced in this PR is enabled, it causes some strange side effects on quick pulse test.

I'm investigating this and it seems to take a while...

brettsam · 2018-08-15T17:03:08Z

Okay -- don't worry too much about that if it doesn't happen locally. I'll port over my improvements from the other branch and maybe that'll make things better. If everything else is ready and passing but that test is still failing sometimes, we can still get this in. I'll take care of improving it.

brettsam · 2018-08-15T20:21:59Z

Can you do one more rebase on dev? I just checked in those QuickPulse improvements, which add some additional logging so maybe we can capture what's failing (assuming it still fails).

lmolkova changed the title ~~Enable ServiceBus dependency and request collection~~ [DO NOT MERGE] Enable ServiceBus dependency and request collection Jul 6, 2018

brettsam reviewed Jul 6, 2018

View reviewed changes

lmolkova force-pushed the lmolkova/ServieBusTracking branch from ed4687a to 22a9ec6 Compare July 7, 2018 04:10

lmolkova changed the title ~~[DO NOT MERGE] Enable ServiceBus dependency and request collection~~ Enable ServiceBus dependency and request collection Jul 7, 2018

lmolkova force-pushed the lmolkova/ServieBusTracking branch from 1e66458 to 4132a51 Compare August 8, 2018 18:26

lmolkova force-pushed the lmolkova/ServieBusTracking branch 2 times, most recently from 6fbd04d to b662a3d Compare August 13, 2018 20:10

brettsam approved these changes Aug 14, 2018

View reviewed changes

lmolkova force-pushed the lmolkova/ServieBusTracking branch 5 times, most recently from b7d0a6e to f31da7a Compare August 15, 2018 04:07

lmolkova force-pushed the lmolkova/ServieBusTracking branch from 4e99d23 to 10027f9 Compare August 15, 2018 18:52

Enable ServiceBus dependency collection

ca8f61c

lmolkova force-pushed the lmolkova/ServieBusTracking branch from 10027f9 to ca8f61c Compare August 15, 2018 20:42

brettsam merged commit 3403636 into Azure:dev Aug 15, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Enable ServiceBus dependency and request collection #1797

Enable ServiceBus dependency and request collection #1797

lmolkova commented Jul 6, 2018

lmolkova commented Jul 6, 2018

brettsam left a comment

brettsam Jul 6, 2018

brettsam Jul 6, 2018

lmolkova Jul 6, 2018

brettsam Jul 6, 2018

brettsam Jul 6, 2018

brettsam Jul 6, 2018

lmolkova Jul 7, 2018

brettsam Jul 6, 2018

brettsam commented Jul 6, 2018

lmolkova commented Jul 7, 2018 •

edited

Loading

lmolkova commented Jul 7, 2018

lmolkova commented Aug 8, 2018

lmolkova commented Aug 8, 2018

lmolkova commented Aug 11, 2018

lmolkova commented Aug 13, 2018

lmolkova commented Aug 14, 2018

brettsam commented Aug 14, 2018

brettsam left a comment

brettsam Aug 14, 2018

brettsam Aug 14, 2018

lmolkova Aug 15, 2018

brettsam Aug 15, 2018

brettsam Aug 14, 2018

brettsam Aug 14, 2018

brettsam commented Aug 14, 2018

lmolkova commented Aug 15, 2018

brettsam commented Aug 15, 2018

brettsam commented Aug 15, 2018

Enable ServiceBus dependency and request collection #1797

Enable ServiceBus dependency and request collection #1797

Conversation

lmolkova commented Jul 6, 2018

lmolkova commented Jul 6, 2018

brettsam left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

brettsam commented Jul 6, 2018

lmolkova commented Jul 7, 2018 • edited Loading

lmolkova commented Jul 7, 2018

lmolkova commented Aug 8, 2018

lmolkova commented Aug 8, 2018

lmolkova commented Aug 11, 2018

lmolkova commented Aug 13, 2018

lmolkova commented Aug 14, 2018

brettsam commented Aug 14, 2018

brettsam left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

brettsam commented Aug 14, 2018

lmolkova commented Aug 15, 2018

brettsam commented Aug 15, 2018

brettsam commented Aug 15, 2018

lmolkova commented Jul 7, 2018 •

edited

Loading