Skip to content
This repository was archived by the owner on Dec 18, 2018. It is now read-only.

Commit 7ebbdad

Browse files
davidfowldavidfowl
authored
Add support for connection scopes if logging is enabled (#1953)
* Add support for connection scopes if logging is enabled - Don't create a scope if logging isn't on - Copied the pattern we use in Hosting
1 parent fd1758f commit 7ebbdad

File tree

5 files changed

+165
-53
lines changed

5 files changed

+165
-53
lines changed

‎src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/ConnectionLogScope.cs‎

Lines changed: 63 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,63 @@
1+
// Copyright (c) .NET Foundation. All rights reserved.
2+
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
3+
4+
using System;
5+
using System.Collections;
6+
using System.Collections.Generic;
7+
using System.Globalization;
8+
9+
namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal
10+
{
11+
public class ConnectionLogScope : IReadOnlyList<KeyValuePair<string, object>>
12+
{
13+
private readonly string _connectionId;
14+
15+
private string _cachedToString;
16+
17+
public ConnectionLogScope(string connectionId)
18+
{
19+
_connectionId = connectionId;
20+
}
21+
22+
public KeyValuePair<string, object> this[int index]
23+
{
24+
get
25+
{
26+
if (index == 0)
27+
{
28+
return new KeyValuePair<string, object>("ConnectionId", _connectionId);
29+
}
30+
31+
throw new ArgumentOutOfRangeException(nameof(index));
32+
}
33+
}
34+
35+
public int Count => 1;
36+
37+
public IEnumerator<KeyValuePair<string, object>> GetEnumerator()
38+
{
39+
for (int i = 0; i < Count; ++i)
40+
{
41+
yield return this[i];
42+
}
43+
}
44+
45+
IEnumerator IEnumerable.GetEnumerator()
46+
{
47+
return GetEnumerator();
48+
}
49+
50+
public override string ToString()
51+
{
52+
if (_cachedToString == null)
53+
{
54+
_cachedToString = string.Format(
55+
CultureInfo.InvariantCulture,
56+
"ConnectionId:{0}",
57+
_connectionId);
58+
}
59+
60+
return _cachedToString;
61+
}
62+
}
63+
}

‎src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/FrameConnection.cs‎

Lines changed: 66 additions & 51 deletions
Original file line numberDiff line numberDiff line change
@@ -2,8 +2,10 @@
22
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
33

44
using System;
5+
using System.Collections;
56
using System.Collections.Generic;
67
using System.Diagnostics;
8+
using System.Globalization;
79
using System.IO;
810
using System.Threading;
911
using System.Threading.Tasks;
@@ -79,72 +81,75 @@ public FrameConnection(FrameConnectionContext context)
7981

8082
public void StartRequestProcessing<TContext>(IHttpApplication<TContext> application)
8183
{
82-
_lifetimeTask = ProcessRequestsAsync<TContext>(application);
84+
_lifetimeTask = ProcessRequestsAsync(application);
8385
}
8486

8587
private async Task ProcessRequestsAsync<TContext>(IHttpApplication<TContext> application)
8688
{
87-
try
89+
using (BeginConnectionScope())
8890
{
89-
Log.ConnectionStart(ConnectionId);
90-
KestrelEventSource.Log.ConnectionStart(this, _context.ConnectionInformation);
91-
92-
AdaptedPipeline adaptedPipeline = null;
93-
var adaptedPipelineTask = Task.CompletedTask;
94-
var input = _context.Input.Reader;
95-
var output = _context.Output;
96-
97-
if (_context.ConnectionAdapters.Count > 0)
91+
try
9892
{
99-
adaptedPipeline = new AdaptedPipeline(input,
100-
output,
101-
PipeFactory.Create(AdaptedInputPipeOptions),
102-
PipeFactory.Create(AdaptedOutputPipeOptions),
103-
Log);
104-
105-
input = adaptedPipeline.Input.Reader;
106-
output = adaptedPipeline.Output;
107-
}
93+
Log.ConnectionStart(ConnectionId);
94+
KestrelEventSource.Log.ConnectionStart(this, _context.ConnectionInformation);
10895

109-
// _frame must be initialized before adding the connection to the connection manager
110-
CreateFrame(application, input, output);
96+
AdaptedPipeline adaptedPipeline = null;
97+
var adaptedPipelineTask = Task.CompletedTask;
98+
var input = _context.Input.Reader;
99+
var output = _context.Output;
111100

112-
// Do this before the first await so we don't yield control to the transport until we've
113-
// added the connection to the connection manager
114-
_context.ServiceContext.ConnectionManager.AddConnection(_context.FrameConnectionId, this);
115-
_lastTimestamp = _context.ServiceContext.SystemClock.UtcNow.Ticks;
101+
if (_context.ConnectionAdapters.Count > 0)
102+
{
103+
adaptedPipeline = new AdaptedPipeline(input,
104+
output,
105+
PipeFactory.Create(AdaptedInputPipeOptions),
106+
PipeFactory.Create(AdaptedOutputPipeOptions),
107+
Log);
108+
109+
input = adaptedPipeline.Input.Reader;
110+
output = adaptedPipeline.Output;
111+
}
116112

117-
if (adaptedPipeline != null)
118-
{
119-
// Stream can be null here and run async will close the connection in that case
120-
var stream = await ApplyConnectionAdaptersAsync();
121-
adaptedPipelineTask = adaptedPipeline.RunAsync(stream);
122-
}
113+
// _frame must be initialized before adding the connection to the connection manager
114+
CreateFrame(application, input, output);
123115

124-
await _frame.ProcessRequestsAsync();
125-
await adaptedPipelineTask;
126-
await _socketClosedTcs.Task;
127-
}
128-
catch (Exception ex)
129-
{
130-
Log.LogError(0, ex, $"Unexpected exception in {nameof(FrameConnection)}.{nameof(ProcessRequestsAsync)}.");
131-
}
132-
finally
133-
{
134-
_context.ServiceContext.ConnectionManager.RemoveConnection(_context.FrameConnectionId);
135-
DisposeAdaptedConnections();
116+
// Do this before the first await so we don't yield control to the transport until we've
117+
// added the connection to the connection manager
118+
_context.ServiceContext.ConnectionManager.AddConnection(_context.FrameConnectionId, this);
119+
_lastTimestamp = _context.ServiceContext.SystemClock.UtcNow.Ticks;
136120

137-
if (_frame.WasUpgraded)
138-
{
139-
_context.ServiceContext.ConnectionManager.UpgradedConnectionCount.ReleaseOne();
121+
if (adaptedPipeline != null)
122+
{
123+
// Stream can be null here and run async will close the connection in that case
124+
var stream = await ApplyConnectionAdaptersAsync();
125+
adaptedPipelineTask = adaptedPipeline.RunAsync(stream);
126+
}
127+
128+
await _frame.ProcessRequestsAsync();
129+
await adaptedPipelineTask;
130+
await _socketClosedTcs.Task;
140131
}
141-
else
132+
catch (Exception ex)
142133
{
143-
_context.ServiceContext.ConnectionManager.NormalConnectionCount.ReleaseOne();
134+
Log.LogError(0, ex, $"Unexpected exception in {nameof(FrameConnection)}.{nameof(ProcessRequestsAsync)}.");
144135
}
136+
finally
137+
{
138+
_context.ServiceContext.ConnectionManager.RemoveConnection(_context.FrameConnectionId);
139+
DisposeAdaptedConnections();
140+
141+
if (_frame.WasUpgraded)
142+
{
143+
_context.ServiceContext.ConnectionManager.UpgradedConnectionCount.ReleaseOne();
144+
}
145+
else
146+
{
147+
_context.ServiceContext.ConnectionManager.NormalConnectionCount.ReleaseOne();
148+
}
145149

146-
Log.ConnectionStop(ConnectionId);
147-
KestrelEventSource.Log.ConnectionStop(this);
150+
Log.ConnectionStop(ConnectionId);
151+
KestrelEventSource.Log.ConnectionStop(this);
152+
}
148153
}
149154
}
150155

@@ -454,5 +459,15 @@ public void StopTimingWrite()
454459
_writeTimingWrites--;
455460
}
456461
}
462+
463+
private IDisposable BeginConnectionScope()
464+
{
465+
if (Log.IsEnabled(LogLevel.Critical))
466+
{
467+
return Log.BeginScope(new ConnectionLogScope(ConnectionId));
468+
}
469+
470+
return null;
471+
}
457472
}
458473
}

‎test/Microsoft.AspNetCore.Server.Kestrel.Core.Tests/FrameConnectionTests.cs‎

Lines changed: 22 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@
33

44
using System;
55
using System.Collections.Generic;
6+
using System.Linq;
67
using System.Threading;
78
using System.Threading.Tasks;
89
using Microsoft.AspNetCore.Server.Kestrel.Core.Adapter.Internal;
@@ -529,5 +530,26 @@ public void WriteTimingTimeoutPushedOnConcurrentWrite()
529530
Assert.True(_frameConnection.TimedOut);
530531
Assert.True(aborted.Wait(TimeSpan.FromSeconds(10)));
531532
}
533+
534+
[Fact]
535+
public async Task StartRequestProcessingCreatesLogScopeWithConnectionId()
536+
{
537+
_frameConnection.StartRequestProcessing(new DummyApplication());
538+
539+
_frameConnection.OnConnectionClosed(ex: null);
540+
541+
await _frameConnection.StopAsync().TimeoutAfter(TimeSpan.FromSeconds(5));
542+
543+
var scopeObjects = ((TestKestrelTrace)_frameConnectionContext.ServiceContext.Log)
544+
.Logger
545+
.Scopes
546+
.OfType<IReadOnlyList<KeyValuePair<string, object>>>()
547+
.ToList();
548+
549+
Assert.Equal(1, scopeObjects.Count);
550+
var pairs = scopeObjects[0].ToDictionary(p => p.Key, p => p.Value);
551+
Assert.True(pairs.ContainsKey("ConnectionId"));
552+
Assert.Equal(_frameConnection.ConnectionId, pairs["ConnectionId"]);
553+
}
532554
}
533555
}

‎test/shared/TestApplicationErrorLogger.cs‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,8 @@ public class TestApplicationErrorLogger : ILogger
1919

2020
public ConcurrentBag<LogMessage> Messages { get; } = new ConcurrentBag<LogMessage>();
2121

22+
public ConcurrentBag<object> Scopes { get; } = new ConcurrentBag<object>();
23+
2224
public int TotalErrorsLogged => Messages.Count(message => message.LogLevel == LogLevel.Error);
2325

2426
public int CriticalErrorsLogged => Messages.Count(message => message.LogLevel == LogLevel.Critical);
@@ -27,6 +29,7 @@ public class TestApplicationErrorLogger : ILogger
2729

2830
public IDisposable BeginScope<TState>(TState state)
2931
{
32+
Scopes.Add(state);
3033
return new Disposable(() => { });
3134
}
3235

‎test/shared/TestServiceContext.cs‎

Lines changed: 11 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -13,8 +13,12 @@ namespace Microsoft.AspNetCore.Testing
1313
public class TestServiceContext : ServiceContext
1414
{
1515
public TestServiceContext()
16-
: this(new LoggerFactory(new[] { new KestrelTestLoggerProvider() }))
1716
{
17+
var logger = new TestApplicationErrorLogger();
18+
var kestrelTrace = new TestKestrelTrace(logger);
19+
var loggerFactory = new LoggerFactory(new[] { new KestrelTestLoggerProvider(logger) });
20+
21+
Initialize(loggerFactory, kestrelTrace);
1822
}
1923

2024
public TestServiceContext(ILoggerFactory loggerFactory)
@@ -23,6 +27,11 @@ public TestServiceContext(ILoggerFactory loggerFactory)
2327
}
2428

2529
public TestServiceContext(ILoggerFactory loggerFactory, IKestrelTrace kestrelTrace)
30+
{
31+
Initialize(loggerFactory, kestrelTrace);
32+
}
33+
34+
private void Initialize(ILoggerFactory loggerFactory, IKestrelTrace kestrelTrace)
2635
{
2736
LoggerFactory = loggerFactory;
2837
Log = kestrelTrace;
@@ -37,7 +46,7 @@ public TestServiceContext(ILoggerFactory loggerFactory, IKestrelTrace kestrelTra
3746
};
3847
}
3948

40-
public ILoggerFactory LoggerFactory { get; }
49+
public ILoggerFactory LoggerFactory { get; set; }
4150

4251
public string DateHeaderValue => DateHeaderValueManager.GetDateHeaderValues().String;
4352
}

0 commit comments

Comments
 (0)