Distributed tracing: ASP.NET MVC & Web API (DataDog#276)

* add missing logging, using exception filters where possible

* refactor AspNetMvcIntegration a little to follow patterns of newer integrations

* read distributed tracing values from http headers

* make it public like other integrations

* fix operation name

* ensure span is always disposed, log exceptions, using filters where possible

* fix comments

* add project dependency so sample app is built when running integration test

* revert parameters types to dynamic because it breaks dynamic method invocation; fix xml doc comments

* don't trace the http request made by the integration test itself

* don't try to run IIS tests at the same time

* move `OperationName` and `ServiceName` to where they are used

Author: lucaspimentel

Datadog.Trace.sln

@@ -83,6 +83,7 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Samples.ExampleLibraryTrace
 EndProject
 Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Datadog.Trace.ClrProfiler.IntegrationTests", "test\Datadog.Trace.ClrProfiler.IntegrationTests\Datadog.Trace.ClrProfiler.IntegrationTests.csproj", "{0D546118-B70A-44D0-B675-39EDB99FCEEE}"
 	ProjectSection(ProjectDependencies) = postProject
+		{3C6DD42E-9214-4747-92BA-78DE29AACE59} = {3C6DD42E-9214-4747-92BA-78DE29AACE59}
 		{9951A03A-AD1B-48D8-A96D-B85532BEDADD} = {9951A03A-AD1B-48D8-A96D-B85532BEDADD}
 		{3493346B-44F6-4F50-8FB4-51D0090DF544} = {3493346B-44F6-4F50-8FB4-51D0090DF544}
 		{C0C8D381-D6B9-4C76-9428-F40F2FA93A9A} = {C0C8D381-D6B9-4C76-9428-F40F2FA93A9A}

src/Datadog.Trace.ClrProfiler.Managed/Integrations/AspNetMvcIntegration.cs

@@ -5,55 +5,51 @@
 using System.Web;
 using System.Web.Routing;
 using Datadog.Trace.ExtensionMethods;
+using Datadog.Trace.Logging;
 
 namespace Datadog.Trace.ClrProfiler.Integrations
 {
     /// <summary>
     /// The ASP.NET MVC integration.
     /// </summary>
-    public sealed class AspNetMvcIntegration : IDisposable
+    public static class AspNetMvcIntegration
     {
         internal const string OperationName = "aspnet-mvc.request";
         private const string HttpContextKey = "__Datadog.Trace.ClrProfiler.Integrations.AspNetMvcIntegration";
 
         private static readonly Type ControllerContextType = Type.GetType("System.Web.Mvc.ControllerContext, System.Web.Mvc", throwOnError: false);
         private static readonly Type RouteCollectionRouteType = Type.GetType("System.Web.Mvc.Routing.RouteCollectionRoute, System.Web.Mvc", throwOnError: false);
-
-        private readonly HttpContextBase _httpContext;
-        private readonly Scope _scope;
+        private static readonly ILog Log = LogProvider.GetLogger(typeof(AspNetMvcIntegration));
 
         /// <summary>
-        /// Initializes a new instance of the <see cref="AspNetMvcIntegration"/> class.
+        /// Creates a scope used to instrument an MVC action and populates some common details.
         /// </summary>
-        /// <param name="controllerContextObj">The System.Web.Mvc.ControllerContext that was passed as an argument to the instrumented method.</param>
-        public AspNetMvcIntegration(object controllerContextObj)
+        /// <param name="controllerContext">The System.Web.Mvc.ControllerContext that was passed as an argument to the instrumented method.</param>
+        /// <returns>A new scope used to instrument an MVC action.</returns>
+        public static Scope CreateScope(dynamic controllerContext)
         {
-            if (controllerContextObj == null || ControllerContextType == null)
+            if (ControllerContextType == null ||
+                controllerContext == null ||
+                ((object)controllerContext)?.GetType() != ControllerContextType)
             {
                 // bail out early
-                return;
+                return null;
             }
 
+            Scope scope = null;
+
             try
             {
-                if (controllerContextObj.GetType() != ControllerContextType)
-                {
-                    return;
-                }
-
-                // access the controller context without referencing System.Web.Mvc directly
-                dynamic controllerContext = controllerContextObj;
+                var httpContext = controllerContext.HttpContext as HttpContextBase;
 
-                _httpContext = controllerContext.HttpContext;
-
-                if (_httpContext == null)
+                if (httpContext == null)
                 {
-                    return;
+                    return null;
                 }
 
-                string host = _httpContext.Request.Headers.Get("Host");
-                string httpMethod = _httpContext.Request.HttpMethod.ToUpperInvariant();
-                string url = _httpContext.Request.RawUrl.ToLowerInvariant();
+                string host = httpContext.Request.Headers.Get("Host");
+                string httpMethod = httpContext.Request.HttpMethod.ToUpperInvariant();
+                string url = httpContext.Request.RawUrl.ToLowerInvariant();
 
                 RouteData routeData = controllerContext.RouteData as RouteData;
                 Route route = routeData?.Route as Route;
@@ -76,8 +72,11 @@ public AspNetMvcIntegration(object controllerContextObj)
                 string actionName = (routeValues?.GetValueOrDefault("action") as string)?.ToLowerInvariant();
                 string resourceName = $"{httpMethod} {controllerName}.{actionName}";
 
-                _scope = Tracer.Instance.StartActive(OperationName);
-                Span span = _scope.Span;
+                // extract distributed tracing values
+                var spanContext = httpContext.Request.Headers.Extract();
+
+                scope = Tracer.Instance.StartActive(OperationName, spanContext);
+                Span span = scope.Span;
                 span.Type = SpanTypes.Web;
                 span.ResourceName = resourceName;
                 span.SetTag(Tags.HttpRequestHeadersHost, host);
@@ -87,16 +86,18 @@ public AspNetMvcIntegration(object controllerContextObj)
                 span.SetTag(Tags.AspNetController, controllerName);
                 span.SetTag(Tags.AspNetAction, actionName);
             }
-            catch
+            catch (Exception ex)
             {
-                // TODO: logging
+                Log.ErrorException("Error creating or populating scope.", ex);
             }
+
+            return scope;
         }
 
         /// <summary>
-        /// Wrapper method used to instrument System.Web.Mvc.Async.AsyncControllerActionInvoker.BeginInvokeAction().
+        /// Wrapper method used to instrument System.Web.Mvc.Async.IAsyncActionInvoker.BeginInvokeAction().
         /// </summary>
-        /// <param name="asyncControllerActionInvoker">The AsyncControllerActionInvoker instance.</param>
+        /// <param name="asyncControllerActionInvoker">The IAsyncActionInvoker instance.</param>
         /// <param name="controllerContext">The ControllerContext for the current request.</param>
         /// <param name="actionName">The name of the controller action.</param>
         /// <param name="callback">An <see cref="AsyncCallback"/> delegate.</param>
@@ -113,37 +114,37 @@ public static object BeginInvokeAction(
             dynamic callback,
             dynamic state)
         {
-            AspNetMvcIntegration integration = null;
+            Scope scope = null;
 
             try
             {
                 if (HttpContext.Current != null)
                 {
-                    integration = new AspNetMvcIntegration((object)controllerContext);
-                    HttpContext.Current.Items[HttpContextKey] = integration;
+                    scope = CreateScope(controllerContext);
+                    HttpContext.Current.Items[HttpContextKey] = scope;
                 }
             }
-            catch
+            catch (Exception ex)
             {
-                // TODO: log this as an instrumentation error, but continue calling instrumented method
+                Log.ErrorException("Error instrumenting method {0}", ex, "System.Web.Mvc.Async.IAsyncActionInvoker.BeginInvokeAction()");
             }
 
             try
             {
-                // call the original method, catching and rethrowing any unhandled exceptions
+                // call the original method, inspecting (but not catching) any unhandled exceptions
                 return asyncControllerActionInvoker.BeginInvokeAction(controllerContext, actionName, callback, state);
             }
-            catch (Exception ex)
+            catch (Exception ex) when (scope?.Span.SetExceptionForFilter(ex) ?? false)
             {
-                integration?.SetException(ex);
+                // unreachable code
                 throw;
             }
         }
 
         /// <summary>
-        /// Wrapper method used to instrument System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeAction().
+        /// Wrapper method used to instrument System.Web.Mvc.Async.IAsyncActionInvoker.EndInvokeAction().
         /// </summary>
-        /// <param name="asyncControllerActionInvoker">The AsyncControllerActionInvoker instance.</param>
+        /// <param name="asyncControllerActionInvoker">The IAsyncActionInvoker instance.</param>
         /// <param name="asyncResult">The <see cref="IAsyncResult"/> returned by <see cref="BeginInvokeAction"/>.</param>
         /// <returns>Returns the <see cref="bool"/> returned by the original EndInvokeAction().</returns>
         [InterceptMethod(
@@ -152,66 +153,31 @@ public static object BeginInvokeAction(
             TargetType = "System.Web.Mvc.Async.IAsyncActionInvoker")]
         public static bool EndInvokeAction(dynamic asyncControllerActionInvoker, dynamic asyncResult)
         {
-            AspNetMvcIntegration integration = null;
+            Scope scope = null;
+            var httpContext = HttpContext.Current;
 
             try
             {
-                if (HttpContext.Current != null)
-                {
-                    integration = HttpContext.Current?.Items[HttpContextKey] as AspNetMvcIntegration;
-                }
+                scope = httpContext?.Items[HttpContextKey] as Scope;
             }
-            catch
+            catch (Exception ex)
             {
-                // TODO: log this as an instrumentation error, but continue calling instrumented method
+                Log.ErrorException("Error instrumenting method {0}", ex, "System.Web.Mvc.Async.IAsyncActionInvoker.EndInvokeAction()");
             }
 
             try
             {
-                // call the original method, catching and rethrowing any unhandled exceptions
-                return asyncControllerActionInvoker.EndInvokeAction(asyncResult);
+                // call the original method, inspecting (but not catching) any unhandled exceptions
+                return (bool)asyncControllerActionInvoker.EndInvokeAction(asyncResult);
             }
-            catch (Exception ex)
+            catch (Exception ex) when (scope?.Span.SetExceptionForFilter(ex) ?? false)
             {
-                integration?.SetException(ex);
+                // unreachable code
                 throw;
             }
             finally
             {
-                integration?.Dispose();
-            }
-        }
-
-        /// <summary>
-        /// Tags the current span as an error. Called when an unhandled exception is thrown in the instrumented method.
-        /// </summary>
-        /// <param name="ex">The exception that was thrown and not handled in the instrumented method.</param>
-        public void SetException(Exception ex)
-        {
-            _scope?.Span?.SetException(ex);
-        }
-
-        /// <summary>
-        /// Performs application-defined tasks associated with freeing, releasing, or resetting unmanaged resources.
-        /// </summary>
-        public void Dispose()
-        {
-            try
-            {
-                // sometimes, if an exception was unhandled in user code, status code is set to 500 later in the pipeline,
-                // so it is still 200 here. if there was an unhandled exception, always set status code to 500.
-                if (_scope?.Span?.Error == true)
-                {
-                    _scope?.Span?.SetTag(Tags.HttpStatusCode, "500");
-                }
-                else if (_httpContext != null)
-                {
-                    _scope?.Span?.SetTag(Tags.HttpStatusCode, _httpContext.Response.StatusCode.ToString());
-                }
-            }
-            finally
-            {
-                _scope?.Dispose();
+                scope?.Dispose();
             }
         }
     }