Skip to content

Commit 041fc38

Browse files
mathewcmathewc
committed
Adding http trace logging (#2272)
1 parent 71d607d commit 041fc38

File tree

7 files changed

+197
-93
lines changed

7 files changed

+197
-93
lines changed

‎src/WebJobs.Script.WebHost/Middleware/FunctionInvocationMiddleware.cs‎

Lines changed: 1 addition & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
// Copyright (c) .NET Foundation. All rights reserved.
22
// Licensed under the MIT License. See License.txt in the project root for license information.
3+
34
using System;
45
using System.Collections.Generic;
56
using System.Diagnostics;
@@ -42,7 +43,6 @@ public async Task Invoke(HttpContext context)
4243
// // downstream middleware and filters rely on this
4344
// context.Items[ScriptConstants.AzureFunctionsHostKey] = scriptHost;
4445
//}
45-
SetRequestId(context.Request);
4646

4747
if (_next != null)
4848
{
@@ -204,11 +204,5 @@ private async Task<bool> AuthenticateAndAuthorizeAsync(HttpContext context, Func
204204
return true;
205205
}
206206
}
207-
208-
internal static void SetRequestId(HttpRequest request)
209-
{
210-
string requestID = request.GetHeaderValueOrDefault(ScriptConstants.AntaresLogIdHeaderName) ?? Guid.NewGuid().ToString();
211-
request.HttpContext.Items[ScriptConstants.AzureFunctionsRequestIdKey] = requestID;
212-
}
213207
}
214208
}

‎src/WebJobs.Script.WebHost/Middleware/SystemTraceMiddleware.cs‎

Lines changed: 84 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,84 @@
1+
// Copyright (c) .NET Foundation. All rights reserved.
2+
// Licensed under the MIT License. See License.txt in the project root for license information.
3+
4+
using System;
5+
using System.Collections.Generic;
6+
using System.Diagnostics;
7+
using System.Linq;
8+
using System.Threading.Tasks;
9+
using Microsoft.AspNetCore.Http;
10+
using Microsoft.Azure.WebJobs.Script.Extensions;
11+
using Microsoft.Azure.WebJobs.Script.WebHost.Security.Authentication;
12+
using Microsoft.Extensions.Logging;
13+
using Newtonsoft.Json.Linq;
14+
15+
namespace Microsoft.Azure.WebJobs.Script.WebHost.Middleware
16+
{
17+
internal class SystemTraceMiddleware
18+
{
19+
private readonly ILogger _logger;
20+
private readonly RequestDelegate _next;
21+
22+
public SystemTraceMiddleware(RequestDelegate next, ILogger<SystemTraceMiddleware> logger)
23+
{
24+
_logger = logger;
25+
_next = next;
26+
}
27+
28+
public async Task Invoke(HttpContext context)
29+
{
30+
SetRequestId(context.Request);
31+
32+
var sw = new Stopwatch();
33+
sw.Start();
34+
var request = context.Request;
35+
var details = new JObject
36+
{
37+
{ "requestId", request.GetRequestId() },
38+
{ "method", request.Method.ToString() },
39+
{ "uri", request.Path.ToString() }
40+
};
41+
var logData = new Dictionary<string, object>
42+
{
43+
[ScriptConstants.LogPropertyActivityIdKey] = request.GetRequestId()
44+
};
45+
_logger.Log(LogLevel.Information, 0, logData, null, (s, e) => $"Executing HTTP request: {details}");
46+
47+
await _next.Invoke(context);
48+
49+
sw.Stop();
50+
details["identities"] = GetIdentities(context);
51+
details["status"] = context.Response.StatusCode;
52+
details["duration"] = sw.ElapsedMilliseconds;
53+
_logger.Log(LogLevel.Information, 0, logData, null, (s, e) => $"Executed HTTP request: {details}");
54+
}
55+
56+
internal static void SetRequestId(HttpRequest request)
57+
{
58+
string requestID = request.GetHeaderValueOrDefault(ScriptConstants.AntaresLogIdHeaderName) ?? Guid.NewGuid().ToString();
59+
request.HttpContext.Items[ScriptConstants.AzureFunctionsRequestIdKey] = requestID;
60+
}
61+
62+
private static JArray GetIdentities(HttpContext context)
63+
{
64+
JArray identities = new JArray();
65+
foreach (var identity in context.User.Identities.Where(p => p.IsAuthenticated))
66+
{
67+
var formattedIdentity = new JObject
68+
{
69+
{ "type", identity.AuthenticationType }
70+
};
71+
72+
var claim = identity.Claims.FirstOrDefault(p => p.Type == SecurityConstants.AuthLevelClaimType);
73+
if (claim != null)
74+
{
75+
formattedIdentity.Add("level", claim.Value);
76+
}
77+
78+
identities.Add(formattedIdentity);
79+
}
80+
81+
return identities;
82+
}
83+
}
84+
}

‎src/WebJobs.Script.WebHost/WebJobsApplicationBuilderExtension.cs‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,7 @@ public static IApplicationBuilder UseWebJobsScriptHost(this IApplicationBuilder
2323
{
2424
IEnvironment environment = builder.ApplicationServices.GetService<IEnvironment>() ?? SystemEnvironment.Instance;
2525

26+
builder.UseMiddleware<SystemTraceMiddleware>();
2627
builder.UseMiddleware<EnvironmentReadyCheckMiddleware>();
2728

2829
if (environment.IsPlaceholderModeEnabled())

‎src/WebJobs.Script/Extensions/HttpRequestExtensions.cs‎

Lines changed: 0 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -17,11 +17,6 @@ public static bool IsAdminRequest(this HttpRequest request)
1717
return request.Path.StartsWithSegments("/admin");
1818
}
1919

20-
public static AuthorizationLevel GetAuthorizationLevel(this HttpRequest request)
21-
{
22-
return request.GetRequestPropertyOrDefault<AuthorizationLevel>(ScriptConstants.AzureFunctionsHttpRequestAuthorizationLevelKey);
23-
}
24-
2520
public static TValue GetRequestPropertyOrDefault<TValue>(this HttpRequest request, string key)
2621
{
2722
if (request.HttpContext != null &&

‎src/WebJobs.Script/ScriptConstants.cs‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -7,13 +7,12 @@ namespace Microsoft.Azure.WebJobs.Script
77
{
88
public static class ScriptConstants
99
{
10-
public const string AzureFunctionsWebHookContextKey = "MS_AzureFunctionsWebHookContext";
1110
public const string AzureFunctionsHttpResponseKey = "MS_AzureFunctionsHttpResponse";
12-
public const string AzureFunctionsHttpRequestAuthorizationLevelKey = "MS_AzureFunctionsAuthorizationLevel";
1311
public const string AzureFunctionsHttpRequestKeyNameKey = "MS_AzureFunctionsKeyId";
1412
public const string AzureFunctionsHttpRequestAuthorizationDisabledKey = "MS_AzureFunctionsAuthorizationDisabled";
1513
public const string AzureFunctionsRequestIdKey = "MS_AzureFunctionsRequestID";
1614
public const string AzureFunctionsColdStartKey = "MS_AzureFunctionsColdStart";
15+
public const string AzureFunctionsRequestTimer = "MS_AzureFunctionsRequestTimer";
1716
public const string AzureFunctionsHttpRequestKey = "MS_AzureFunctionsHttpRequest";
1817
public const string AzureProxyFunctionExecutorKey = "MS_AzureProxyFunctionExecutor";
1918
public const string AzureFunctionsHostKey = "MS_AzureFunctionsHost";

‎test/WebJobs.Script.Tests/Handlers/SystemTraceHandlerTests.cs‎

Lines changed: 0 additions & 79 deletions
This file was deleted.

‎test/WebJobs.Script.Tests/Middleware/SystemTraceMiddlewareTests.cs‎

Lines changed: 110 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,110 @@
1+
// Copyright (c) .NET Foundation. All rights reserved.
2+
// Licensed under the MIT License. See License.txt in the project root for license information.
3+
4+
using System;
5+
using System.Collections.Generic;
6+
using System.Linq;
7+
using System.Security.Claims;
8+
using System.Threading.Tasks;
9+
using Microsoft.AspNetCore.Http;
10+
using Microsoft.AspNetCore.Http.Features;
11+
using Microsoft.Azure.WebJobs.Extensions.Http;
12+
using Microsoft.Azure.WebJobs.Script.WebHost.Authentication;
13+
using Microsoft.Azure.WebJobs.Script.WebHost.Middleware;
14+
using Microsoft.Azure.WebJobs.Script.WebHost.Security.Authentication;
15+
using Microsoft.Extensions.Logging;
16+
using Microsoft.Extensions.Primitives;
17+
using Microsoft.WebJobs.Script.Tests;
18+
using Newtonsoft.Json.Linq;
19+
using Xunit;
20+
21+
namespace Microsoft.Azure.WebJobs.Script.Tests.Handlers
22+
{
23+
public class SystemTraceMiddlewareTests
24+
{
25+
private readonly TestLoggerProvider _loggerProvider;
26+
private readonly SystemTraceMiddleware _middleware;
27+
28+
public SystemTraceMiddlewareTests()
29+
{
30+
_loggerProvider = new TestLoggerProvider();
31+
var loggerFactory = new LoggerFactory();
32+
loggerFactory.AddProvider(_loggerProvider);
33+
34+
RequestDelegate requestDelegate = async (HttpContext context) =>
35+
{
36+
await Task.Delay(25);
37+
};
38+
39+
var logger = loggerFactory.CreateLogger<SystemTraceMiddleware>();
40+
_middleware = new SystemTraceMiddleware(requestDelegate, logger);
41+
}
42+
43+
[Fact]
44+
public async Task SendAsync_WritesExpectedTraces()
45+
{
46+
string requestId = Guid.NewGuid().ToString();
47+
var context = new DefaultHttpContext();
48+
Uri uri = new Uri("http://functions.com/api/testfunc?code=123");
49+
var requestFeature = context.Request.HttpContext.Features.Get<IHttpRequestFeature>();
50+
requestFeature.Method = "GET";
51+
requestFeature.Scheme = uri.Scheme;
52+
requestFeature.Path = uri.GetComponents(UriComponents.KeepDelimiter | UriComponents.Path, UriFormat.Unescaped);
53+
requestFeature.PathBase = string.Empty;
54+
requestFeature.QueryString = uri.GetComponents(UriComponents.KeepDelimiter | UriComponents.Query, UriFormat.Unescaped);
55+
56+
var headers = new HeaderDictionary();
57+
headers.Add(ScriptConstants.AntaresLogIdHeaderName, new StringValues(requestId));
58+
requestFeature.Headers = headers;
59+
60+
var claims = new List<Claim>
61+
{
62+
new Claim(SecurityConstants.AuthLevelClaimType, AuthorizationLevel.Function.ToString())
63+
};
64+
var identity = new ClaimsIdentity(claims, AuthLevelAuthenticationDefaults.AuthenticationScheme);
65+
context.User = new ClaimsPrincipal(identity);
66+
67+
await _middleware.Invoke(context);
68+
69+
var logs = _loggerProvider.GetAllLogMessages().ToArray();
70+
Assert.Equal(2, logs.Length);
71+
72+
// validate executing trace
73+
var log = logs[0];
74+
Assert.Equal(typeof(SystemTraceMiddleware).FullName, log.Category);
75+
Assert.Equal(LogLevel.Information, log.Level);
76+
var idx = log.FormattedMessage.IndexOf(':');
77+
var message = log.FormattedMessage.Substring(0, idx).Trim();
78+
Assert.Equal("Executing HTTP request", message);
79+
var details = log.FormattedMessage.Substring(idx + 1).Trim();
80+
var jo = JObject.Parse(details);
81+
Assert.Equal(3, jo.Count);
82+
Assert.Equal(requestId, jo["requestId"]);
83+
Assert.Equal("GET", jo["method"]);
84+
Assert.Equal("/api/testfunc", jo["uri"]);
85+
86+
// validate executed trace
87+
log = logs[1];
88+
Assert.Equal(typeof(SystemTraceMiddleware).FullName, log.Category);
89+
Assert.Equal(LogLevel.Information, log.Level);
90+
idx = log.FormattedMessage.IndexOf(':');
91+
message = log.FormattedMessage.Substring(0, idx).Trim();
92+
Assert.Equal("Executed HTTP request", message);
93+
details = log.FormattedMessage.Substring(idx + 1).Trim();
94+
jo = JObject.Parse(details);
95+
Assert.Equal(6, jo.Count);
96+
Assert.Equal(requestId, jo["requestId"]);
97+
Assert.Equal("GET", jo["method"]);
98+
Assert.Equal("/api/testfunc", jo["uri"]);
99+
Assert.Equal(200, jo["status"]);
100+
var duration = (long)jo["duration"];
101+
Assert.True(duration > 0);
102+
103+
var authentication = (JArray)jo["identities"];
104+
Assert.Equal(1, authentication.Count);
105+
var keyIdentity = authentication.Single();
106+
Assert.Equal(AuthLevelAuthenticationDefaults.AuthenticationScheme, keyIdentity["type"]);
107+
Assert.Equal("Function", keyIdentity["level"]);
108+
}
109+
}
110+
}

0 commit comments

Comments
 (0)