Adding HTTP pipeline logging for all controllers

mathewc · mathewc · commit 870e7e9223e7 · 2017-03-15T09:50:32.000-07:00
diff --git a/src/WebJobs.Script.WebHost/App_Start/WebApiConfig.cs b/src/WebJobs.Script.WebHost/App_Start/WebApiConfig.cs
@@ -9,6 +9,7 @@
 using Autofac.Integration.WebApi;
 using Microsoft.Azure.WebJobs.Script.Config;
 using Microsoft.Azure.WebJobs.Script.WebHost.Controllers;
+using Microsoft.Azure.WebJobs.Script.WebHost.Filters;
 using Microsoft.Azure.WebJobs.Script.WebHost.Handlers;
 
 namespace Microsoft.Azure.WebJobs.Script.WebHost
@@ -48,7 +49,7 @@ public static void Register(HttpConfiguration config, ScriptSettingsManager sett
             var container = builder.Build();
             config.DependencyResolver = new AutofacWebApiDependencyResolver(container);
             config.Formatters.Add(new PlaintextMediaTypeFormatter());
-            config.MessageHandlers.Add(new WebScriptHostHandler(config));
+            AddMessageHandlers(config);
 
             // Web API configuration and services
 
@@ -81,5 +82,11 @@ public static void Register(HttpConfiguration config, ScriptSettingsManager sett
             config.InitializeReceiveGitHubWebHooks();
             config.InitializeReceiveSalesforceWebHooks();
         }
+
+        private static void AddMessageHandlers(HttpConfiguration config)
+        {
+            config.MessageHandlers.Add(new WebScriptHostHandler(config));
+            config.MessageHandlers.Add(new SystemTraceHandler(config));
+        }
     }
 }
diff --git a/src/WebJobs.Script.WebHost/Controllers/AdminController.cs b/src/WebJobs.Script.WebHost/Controllers/AdminController.cs
@@ -11,10 +11,11 @@
 using System.Threading.Tasks;
 using System.Web.Http;
 using System.Web.Http.Controllers;
-using Microsoft.Azure.WebJobs.Script.Config;
+using Microsoft.Azure.WebJobs.Host;
 using Microsoft.Azure.WebJobs.Script.Description;
 using Microsoft.Azure.WebJobs.Script.WebHost.Filters;
 using Microsoft.Azure.WebJobs.Script.WebHost.Models;
+using Newtonsoft.Json;
 
 namespace Microsoft.Azure.WebJobs.Script.WebHost.Controllers
 {
@@ -27,11 +28,13 @@ public class AdminController : ApiController
     {
         private readonly WebScriptHostManager _scriptHostManager;
         private readonly WebHostSettings _webHostSettings;
+        private readonly TraceWriter _traceWriter;
 
-        public AdminController(WebScriptHostManager scriptHostManager, WebHostSettings webHostSettings)
+        public AdminController(WebScriptHostManager scriptHostManager, WebHostSettings webHostSettings, TraceWriter traceWriter)
         {
             _scriptHostManager = scriptHostManager;
             _webHostSettings = webHostSettings;
+            _traceWriter = traceWriter.WithSource($"{ScriptConstants.TraceSourceHostAdmin}.Api");
         }
 
         [HttpPost]
@@ -90,8 +93,6 @@ public FunctionStatus GetFunctionStatus(string name)
         [AllowAnonymous]
         public IHttpActionResult GetHostStatus()
         {
-            // based on the authorization level we determine
-            // the level of detail to return
             var authorizationLevel = Request.GetAuthorizationLevel();
             if (authorizationLevel == AuthorizationLevel.Admin ||
                 Request.IsAntaresInternalRequest())
@@ -120,15 +121,24 @@ public IHttpActionResult GetHostStatus()
                     };
                 }
 
+                _traceWriter.Info($"Host Status: {JsonConvert.SerializeObject(status, Formatting.Indented)}");
+
                 return Ok(status);
             }
             else
             {
-                // for Anonymous requests, we don't return any info
-                return Ok();
+                return Unauthorized();
             }
         }
 
+        [HttpPost]
+        [Route("admin/host/ping")]
+        [AllowAnonymous]
+        public IHttpActionResult Ping()
+        {
+            return Ok();
+        }
+
         [HttpPost]
         [Route("admin/host/debug")]
         public HttpResponseMessage LaunchDebugger()
diff --git a/src/WebJobs.Script.WebHost/Controllers/FunctionsController.cs b/src/WebJobs.Script.WebHost/Controllers/FunctionsController.cs
@@ -47,6 +47,7 @@ public override async Task<HttpResponseMessage> ExecuteAsync(HttpControllerConte
             var authorizationLevel = settings.IsAuthDisabled
                 ? AuthorizationLevel.Admin
                 : await AuthorizationLevelAttribute.GetAuthorizationLevelAsync(request, secretManager, functionName: function.Name);
+            request.SetAuthorizationLevel(authorizationLevel);
 
             if (function.Metadata.IsExcluded ||
                 (function.Metadata.IsDisabled && authorizationLevel != AuthorizationLevel.Admin))
diff --git a/src/WebJobs.Script.WebHost/Filters/AuthorizationLevelAttribute.cs b/src/WebJobs.Script.WebHost/Filters/AuthorizationLevelAttribute.cs
@@ -38,7 +38,7 @@ public async override Task OnAuthorizationAsync(HttpActionContext actionContext,
             var secretManager = actionContext.ControllerContext.Configuration.DependencyResolver.GetService<ISecretManager>();
             var settings = actionContext.ControllerContext.Configuration.DependencyResolver.GetService<WebHostSettings>();
             var requestAuthorizationLevel = await GetAuthorizationLevelAsync(actionContext.Request, secretManager, EvaluateKeyMatch);
-            actionContext.Request.Properties[ScriptConstants.AzureFunctionsHttpRequestAuthorizationLevel] = requestAuthorizationLevel;
+            actionContext.Request.SetAuthorizationLevel(requestAuthorizationLevel);
 
             if (settings.IsAuthDisabled || 
                 SkipAuthorization(actionContext) ||
diff --git a/src/WebJobs.Script.WebHost/Handlers/SystemTraceHandler.cs b/src/WebJobs.Script.WebHost/Handlers/SystemTraceHandler.cs
@@ -0,0 +1,54 @@
+﻿// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+using System.Net.Http;
+using System.Threading;
+using System.Threading.Tasks;
+using System.Web.Http;
+using Microsoft.Azure.WebJobs.Host;
+using Newtonsoft.Json.Linq;
+
+namespace Microsoft.Azure.WebJobs.Script.WebHost.Handlers
+{
+    public class SystemTraceHandler : DelegatingHandler
+    {
+        private readonly HttpConfiguration _config;
+
+        public SystemTraceHandler(HttpConfiguration config)
+        {
+            _config = config;
+        }
+
+        protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
+        {
+            var traceWriter = _config.DependencyResolver.GetService<TraceWriter>();
+            var details = new JObject
+            {
+                { "id", request.GetRequestId() },
+                { "method", request.Method.ToString() },
+                { "uri", request.RequestUri.LocalPath.ToString() }
+            };
+            traceWriter.Info($"Executing HTTP request: {details}");
+
+            var response = await base.SendAsync(request, cancellationToken);
+
+            details = new JObject
+            {
+                { "id", request.GetRequestId() },
+                { "method", request.Method.ToString() },
+                { "uri", request.RequestUri.LocalPath.ToString() },
+                { "authorizationLevel", request.GetAuthorizationLevel().ToString() }
+            };
+            traceWriter.Info($"Executed HTTP request: {details}");
+
+            details = new JObject
+            {
+                { "id", request.GetRequestId() },
+                { "status", response.StatusCode.ToString() }
+            };
+            traceWriter.Info($"Response details: {details}");
+
+            return response;
+        }
+    }
+}
diff --git a/src/WebJobs.Script.WebHost/Handlers/WebScriptHostHandler.cs b/src/WebJobs.Script.WebHost/Handlers/WebScriptHostHandler.cs
@@ -33,6 +33,8 @@ protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage
         {
             var scriptHostManager = _config.DependencyResolver.GetService<WebScriptHostManager>();
 
+            SetRequestId(request);
+
             // some routes do not require the host to be running (most do)
             // in standby mode, we don't want to wait for host start
             bool bypassHostCheck = request.RequestUri.LocalPath.Trim('/').ToLowerInvariant().EndsWith("admin/host/status") ||
@@ -69,5 +71,11 @@ protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage
 
             return await base.SendAsync(request, cancellationToken);
         }
+
+        internal static void SetRequestId(HttpRequestMessage request)
+        {
+            string requestID = request.GetHeaderValueOrDefault(ScriptConstants.AntaresLogIdHeaderName) ?? Guid.NewGuid().ToString();
+            request.Properties[ScriptConstants.AzureFunctionsRequestIdKey] = requestID;
+        }
     }
 }
diff --git a/src/WebJobs.Script.WebHost/WebJobs.Script.WebHost.csproj b/src/WebJobs.Script.WebHost/WebJobs.Script.WebHost.csproj
@@ -423,6 +423,7 @@
       <DependentUpon>Global.asax</DependentUpon>
     </Compile>
     <Compile Include="GlobalSuppressions.cs" />
+    <Compile Include="Handlers\SystemTraceHandler.cs" />
     <Compile Include="Handlers\WebScriptHostHandler.cs" />
     <Compile Include="Models\ApiModel.cs" />
     <Compile Include="Models\ApiModelUtility.cs" />
diff --git a/src/WebJobs.Script/Extensions/HttpRequestMessageExtensions.cs b/src/WebJobs.Script/Extensions/HttpRequestMessageExtensions.cs
@@ -13,7 +13,17 @@ public static class HttpRequestMessageExtensions
     {
         public static AuthorizationLevel GetAuthorizationLevel(this HttpRequestMessage request)
         {
-            return request.GetRequestPropertyOrDefault<AuthorizationLevel>(ScriptConstants.AzureFunctionsHttpRequestAuthorizationLevel);
+            return request.GetRequestPropertyOrDefault<AuthorizationLevel>(ScriptConstants.AzureFunctionsHttpRequestAuthorizationLevelKey);
+        }
+
+        public static string GetRequestId(this HttpRequestMessage request)
+        {
+            return request.GetRequestPropertyOrDefault<string>(ScriptConstants.AzureFunctionsRequestIdKey);
+        }
+
+        public static void SetAuthorizationLevel(this HttpRequestMessage request, AuthorizationLevel authorizationLevel)
+        {
+            request.Properties[ScriptConstants.AzureFunctionsHttpRequestAuthorizationLevelKey] = authorizationLevel;
         }
 
         public static bool IsAntaresInternalRequest(this HttpRequestMessage request)
@@ -26,7 +36,17 @@ public static bool IsAntaresInternalRequest(this HttpRequestMessage request)
             // this header will *always* be present on requests originating externally (i.e. going
             // through the Anatares front end). For requests originating internally it will NOT be
             // present.
-            return !request.Headers.Contains(ScriptConstants.AntaresExternalRequestHeaderName);
+            return !request.Headers.Contains(ScriptConstants.AntaresLogIdHeaderName);
+        }
+
+        public static string GetHeaderValueOrDefault(this HttpRequestMessage request, string headerName)
+        {
+            IEnumerable<string> values = null;
+            if (request.Headers.TryGetValues(headerName, out values))
+            {
+                return values.First();
+            }
+            return null;
         }
 
         public static TValue GetRequestPropertyOrDefault<TValue>(this HttpRequestMessage request, string key)
diff --git a/src/WebJobs.Script/ScriptConstants.cs b/src/WebJobs.Script/ScriptConstants.cs
@@ -11,7 +11,8 @@ public static class ScriptConstants
         public const string AzureFunctionsWebHookDataKey = "MS_AzureFunctionsWebHookData";
         public const string AzureFunctionsHttpResponseKey = "MS_AzureFunctionsHttpResponse";
         public const string AzureFunctionsHttpRouteDataKey = "MS_AzureFunctionsHttpRouteData";
-        public const string AzureFunctionsHttpRequestAuthorizationLevel = "MS_AzureFunctionsAuthorizationLevel";
+        public const string AzureFunctionsHttpRequestAuthorizationLevelKey = "MS_AzureFunctionsAuthorizationLevel";
+        public const string AzureFunctionsRequestIdKey = "MS_AzureFunctionsRequestID";
 
         public const string TracePropertyPrimaryHostKey = "MS_PrimaryHost";
         public const string TracePropertyFunctionNameKey = "MS_FunctionName";
@@ -21,6 +22,7 @@ public static class ScriptConstants
         public const string TracePropertyIsSystemTraceKey = "MS_IsSystemTrace";
 
         public const string TraceSourceSecretManagement = "SecretManagement";
+        public const string TraceSourceHostAdmin = "HostAdmin";
         public const string TraceSourceFileWatcher = "FileWatcher";
 
         // Define all system parameters we inject with a prefix to avoid collisions
@@ -39,7 +41,7 @@ public static class ScriptConstants
         public const string DefaultMasterKeyName = "master";
         public const string DefaultFunctionKeyName = "default";
 
-        public const string AntaresExternalRequestHeaderName = "X-ARR-LOG-ID";
+        public const string AntaresLogIdHeaderName = "X-ARR-LOG-ID";
         public const string CheckLoadQueryParameterName = "checkLoad";
         public const string DynamicSku = "Dynamic";
 
diff --git a/test/WebJobs.Script.Tests.Integration/Host/StandbyModeTests.cs b/test/WebJobs.Script.Tests.Integration/Host/StandbyModeTests.cs
@@ -63,6 +63,12 @@ public void GetWebHookReceiverManager_ReturnsExpectedValue()
             TestGetter(_webHostResolver.GetWebHookReceiverManager);
         }
 
+        [Fact]
+        public void GetPerformanceManager_ReturnsExpectedValue()
+        {
+            TestGetter(_webHostResolver.GetPerformanceManager);
+        }
+
         [Fact]
         public void GetWebScriptHostManager_ReturnsExpectedValue()
         {
diff --git a/test/WebJobs.Script.Tests.Integration/SamplesEndToEndTests.cs b/test/WebJobs.Script.Tests.Integration/SamplesEndToEndTests.cs
@@ -907,6 +907,15 @@ public async Task ServiceBusTopicTrigger_ManualInvoke_Succeeds()
             Assert.Equal(value, result.Trim());
         }
 
+        [Fact]
+        public async Task HostPing_Succeeds()
+        {
+            string uri = "admin/host/ping";
+            HttpRequestMessage request = new HttpRequestMessage(HttpMethod.Post, uri);
+            HttpResponseMessage response = await this._fixture.HttpClient.SendAsync(request);
+            Assert.Equal(HttpStatusCode.OK, response.StatusCode);
+        }
+
         [Fact]
         public async Task HostStatus_AdminLevel_Succeeds()
         {
@@ -983,32 +992,12 @@ public async Task HostStatus_AnonymousAntaresInteral_CheckLoad_Succeeds()
         }
 
         [Fact]
-        public async Task HostStatus_FunctionLevelRequest_Succeeds()
-        {
-            string uri = "admin/host/status";
-            var request = new HttpRequestMessage(HttpMethod.Get, uri);
-            request.Headers.Add("x-functions-key", "zlnu496ve212kk1p84ncrtdvmtpembduqp25ajjc");
-            var response = await this._fixture.HttpClient.SendAsync(request);
-            Assert.Equal(HttpStatusCode.OK, response.StatusCode);
-            Assert.Null(response.Content);
-        }
-
-        [Fact]
-        public async Task HostStatus_AnonymousLevelRequest_Succeeds()
+        public async Task HostStatus_AnonymousLevelRequest_Fails()
         {
             string uri = "admin/host/status";
             var request = new HttpRequestMessage(HttpMethod.Get, uri);
             var response = await this._fixture.HttpClient.SendAsync(request);
-            Assert.Equal(HttpStatusCode.OK, response.StatusCode);
-            Assert.Null(response.Content);
-
-            // issue the request again, specifying a load check - expect
-            // this to not return load details
-            uri = "admin/host/status?checkLoad=1";
-            request = new HttpRequestMessage(HttpMethod.Get, uri);
-            response = await this._fixture.HttpClient.SendAsync(request);
-            Assert.Equal(HttpStatusCode.OK, response.StatusCode);
-            Assert.Null(response.Content);
+            Assert.Equal(HttpStatusCode.Unauthorized, response.StatusCode);
         }
 
         [Fact]
diff --git a/test/WebJobs.Script.Tests.Shared/TestHandler.cs b/test/WebJobs.Script.Tests.Shared/TestHandler.cs
@@ -0,0 +1,18 @@
+﻿// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+using System.Net;
+using System.Net.Http;
+using System.Threading;
+using System.Threading.Tasks;
+
+namespace Microsoft.WebJobs.Script.Tests
+{
+    public class TestHandler : DelegatingHandler
+    {
+        protected override Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
+        {
+            return Task.Factory.StartNew(() => new HttpResponseMessage(HttpStatusCode.OK), cancellationToken);
+        }
+    }
+}
diff --git a/test/WebJobs.Script.Tests.Shared/WebJobs.Script.Tests.Shared.projitems b/test/WebJobs.Script.Tests.Shared/WebJobs.Script.Tests.Shared.projitems
@@ -11,6 +11,7 @@
   <ItemGroup>
     <Compile Include="$(MSBuildThisFileDirectory)SingleThreadedSynchronizationContext.cs" />
     <Compile Include="$(MSBuildThisFileDirectory)TempDirectory.cs" />
+    <Compile Include="$(MSBuildThisFileDirectory)TestHandler.cs" />
     <Compile Include="$(MSBuildThisFileDirectory)TestHelpers.cs" />
     <Compile Include="$(MSBuildThisFileDirectory)TestInvoker.cs" />
     <Compile Include="$(MSBuildThisFileDirectory)TestScopedEnvironmentVariable.cs" />
diff --git a/test/WebJobs.Script.Tests/Controllers/Admin/AdminControllerTests.cs b/test/WebJobs.Script.Tests/Controllers/Admin/AdminControllerTests.cs
@@ -4,6 +4,7 @@
 using System;
 using System.Collections.Generic;
 using System.Collections.ObjectModel;
+using System.Diagnostics;
 using System.Net;
 using System.Net.Http;
 using System.Reflection;
@@ -46,7 +47,7 @@ public AdminControllerTests()
             managerMock = new Mock<WebScriptHostManager>(MockBehavior.Strict, new object[] { config, new TestSecretManagerFactory(), _settingsManager, settings });
             managerMock.SetupGet(p => p.Instance).Returns(hostMock.Object);
 
-            testController = new AdminController(managerMock.Object, settings);
+            testController = new AdminController(managerMock.Object, settings, new TestTraceWriter(TraceLevel.Verbose));
         }
 
         [Fact]
diff --git a/test/WebJobs.Script.Tests/Extensions/HttpRequestMessageExtensions.cs b/test/WebJobs.Script.Tests/Extensions/HttpRequestMessageExtensions.cs
diff --git a/test/WebJobs.Script.Tests/Handlers/SystemTraceHandlerTests.cs b/test/WebJobs.Script.Tests/Handlers/SystemTraceHandlerTests.cs
diff --git a/test/WebJobs.Script.Tests/Handlers/WebScriptHostHandlerTests.cs b/test/WebJobs.Script.Tests/Handlers/WebScriptHostHandlerTests.cs
diff --git a/test/WebJobs.Script.Tests/WebJobs.Script.Tests.csproj b/test/WebJobs.Script.Tests/WebJobs.Script.Tests.csproj

Original file line number	Diff line number	Diff line change
`@@ -33,6 +33,8 @@ protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage`
`33`	`33`	`{`
`34`	`34`	`var scriptHostManager = _config.DependencyResolver.GetService<WebScriptHostManager>();`
`35`	`35`
	`36`	`+ SetRequestId(request);`
	`37`	`+`
`36`	`38`	`// some routes do not require the host to be running (most do)`
`37`	`39`	`// in standby mode, we don't want to wait for host start`
`38`	`40`	`bool bypassHostCheck = request.RequestUri.LocalPath.Trim('/').ToLowerInvariant().EndsWith("admin/host/status") \|\|`
`@@ -69,5 +71,11 @@ protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage`
`69`	`71`
`70`	`72`	`return await base.SendAsync(request, cancellationToken);`
`71`	`73`	`}`
	`74`	`+`
	`75`	`+ internal static void SetRequestId(HttpRequestMessage request)`
	`76`	`+ {`
	`77`	`+ string requestID = request.GetHeaderValueOrDefault(ScriptConstants.AntaresLogIdHeaderName) ?? Guid.NewGuid().ToString();`
	`78`	`+ request.Properties[ScriptConstants.AzureFunctionsRequestIdKey] = requestID;`
	`79`	`+ }`
`72`	`80`	`}`
`73`	`81`	`}`
Original file line number	Diff line number	Diff line change
`@@ -63,6 +63,12 @@ public void GetWebHookReceiverManager_ReturnsExpectedValue()`
`63`	`63`	`TestGetter(_webHostResolver.GetWebHookReceiverManager);`
`64`	`64`	`}`
`65`	`65`
	`66`	`+ [Fact]`
	`67`	`+ public void GetPerformanceManager_ReturnsExpectedValue()`
	`68`	`+ {`
	`69`	`+ TestGetter(_webHostResolver.GetPerformanceManager);`
	`70`	`+ }`
	`71`	`+`
`66`	`72`	`[Fact]`
`67`	`73`	`public void GetWebScriptHostManager_ReturnsExpectedValue()`
`68`	`74`	`{`