Skip to content
This repository has been archived by the owner on Jan 23, 2023. It is now read-only.
/ corefx Public archive

Refactor DiagnosticSource logging (correlation part1) #15971

Merged
merged 4 commits into from
Feb 10, 2017
Merged

Refactor DiagnosticSource logging (correlation part1) #15971

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
a672fef
Refactor DiagnosticSource logging, prepare for Activity support
Feb 8, 2017
7bc01f3
fix uap and unix builds
Feb 9, 2017
d9f4f54
review comments
Feb 9, 2017
6216583
review
Feb 10, 2017
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
89 changes: 0 additions & 89 deletions src/Common/src/System/Net/Http/HttpHandlerDiagnosticListenerExtensions.cs
View file
Open in desktop

This file was deleted.

2 changes: 0 additions & 2 deletions src/System.Net.Http.WinHttpHandler/src/System.Net.Http.WinHttpHandler.msbuild
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -21,8 +21,6 @@
<CompileItem Include="$(CommonPath)\System\Net\UriScheme.cs" />
<CompileItem Include="$(CommonPath)\System\Net\SecurityProtocol.cs" />
<CompileItem Include="$(CommonPath)\System\Net\Http\HttpHandlerDefaults.cs" />
<CompileItem Include="$(CommonPath)\System\Net\Http\HttpHandlerDiagnosticListenerExtensions.cs" />
<CompileItem Include="$(CommonPath)\System\Net\Http\HttpHandlerLoggingStrings.cs" />
<CompileItem Include="$(CommonPath)\System\Net\Http\NoWriteNoSeekStreamContent.cs" />
<CompileItem Include="$(CommonPath)\System\Net\Http\WinHttpException.cs" />
<CompileItem Include="$(CommonPath)\System\Threading\Tasks\RendezvousAwaitable.cs" />
Expand Down
5 changes: 0 additions & 5 deletions src/System.Net.Http.WinHttpHandler/src/System/Net/Http/WinHttpHandler.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -94,7 +94,6 @@ private Func<
private volatile bool _disposed;
private SafeWinHttpHandle _sessionHandle;
private WinHttpAuthHelper _authHelper = new WinHttpAuthHelper();
private static readonly DiagnosticListener s_diagnosticListener = new DiagnosticListener(HttpHandlerLoggingStrings.DiagnosticListenerName);

public WinHttpHandler()
{
Expand Down Expand Up @@ -533,8 +532,6 @@ protected override Task<HttpResponseMessage> SendAsync(

CheckDisposed();

Guid loggingRequestId = s_diagnosticListener.LogHttpRequest(request);

SetOperationStarted();

TaskCompletionSource<HttpResponseMessage> tcs = new TaskCompletionSource<HttpResponseMessage>();
Expand Down Expand Up @@ -563,8 +560,6 @@ protected override Task<HttpResponseMessage> SendAsync(
TaskCreationOptions.DenyChildAttach,
TaskScheduler.Default);

s_diagnosticListener.LogHttpResponse(tcs.Task, loggingRequestId);

return tcs.Task;
}

Expand Down
6 changes: 0 additions & 6 deletions ....Net.Http.WinHttpHandler/tests/UnitTests/System.Net.Http.WinHttpHandler.Unit.Tests.csproj
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -64,12 +64,6 @@
<Compile Include="$(CommonPath)\System\Net\Http\HttpHandlerDefaults.cs">
<Link>Common\System\Net\Http\HttpHandlerDefaults.cs</Link>
</Compile>
<Compile Include="$(CommonPath)\System\Net\Http\HttpHandlerDiagnosticListenerExtensions.cs">
<Link>Common\System\Net\Http\HttpHandlerDiagnosticListenerExtensions.cs</Link>
</Compile>
<Compile Include="$(CommonPath)\System\Net\Http\HttpHandlerLoggingStrings.cs">
<Link>Common\System\Net\Http\HttpHandlerLoggingStrings.cs</Link>
</Compile>
<Compile Include="$(CommonPath)\System\Net\Http\NoWriteNoSeekStreamContent.cs">
<Link>Common\System\Net\Http\NoWriteNoSeekStreamContent.cs</Link>
</Compile>
Expand Down
15 changes: 2 additions & 13 deletions src/System.Net.Http/src/System.Net.Http.csproj
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -116,6 +116,8 @@
</ItemGroup>
<!-- Common, except for Windows net46 build -->
<ItemGroup Condition="'$(TargetGroup)' != 'net46' And '$(TargetGroup)' != 'netfx'">
<Compile Include="System\Net\Http\DiagnosticsHandler.cs" />
<Compile Include="System\Net\Http\DiagnosticsHandlerLoggingStrings.cs"/>
<Compile Include="$(CommonPath)\System\Net\Mail\DomainLiteralReader.cs">
<Link>Common\System\Net\Mail\DomainLiteralReader.cs</Link>
</Compile>
Expand Down Expand Up @@ -267,12 +269,6 @@
<Compile Include="$(CommonPath)\System\Net\Http\HttpHandlerDefaults.cs">
<Link>Common\System\Net\Http\HttpHandlerDefaults.cs</Link>
</Compile>
<Compile Include="$(CommonPath)\System\Net\Http\HttpHandlerDiagnosticListenerExtensions.cs">
<Link>Common\System\Net\Http\HttpHandlerDiagnosticListenerExtensions.cs</Link>
</Compile>
<Compile Include="$(CommonPath)\System\Net\Http\HttpHandlerLoggingStrings.cs">
<Link>Common\System\Net\Http\HttpHandlerLoggingStrings.cs</Link>
</Compile>
<Compile Include="$(CommonPath)\System\Net\Http\NoWriteNoSeekStreamContent.cs">
<Link>Common\System\Net\Http\NoWriteNoSeekStreamContent.cs</Link>
</Compile>
Expand Down Expand Up @@ -351,13 +347,6 @@
<Compile Include="$(CommonPath)\System\NotImplemented.cs">
<Link>Common\System\NotImplemented.cs</Link>
</Compile>
<!-- TODO: reconcile with Open\src\Common, see issue #5525 -->
<Compile Include="$(CommonPath)\System\Net\Http\HttpHandlerDiagnosticListenerExtensions.cs">
<Link>Common\System\Net\Http\HttpHandlerDiagnosticListenerExtensions.cs</Link>
</Compile>
<Compile Include="$(CommonPath)\System\Net\Http\HttpHandlerLoggingStrings.cs">
<Link>Common\System\Net\Http\HttpHandlerLoggingStrings.cs</Link>
</Compile>
<Compile Include="$(CommonPath)\System\Net\HttpKnownHeaderNames.cs">
<Link>Common\System\Net\HttpKnownHeaderNames.cs</Link>
</Compile>
Expand Down
117 changes: 117 additions & 0 deletions src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,117 @@
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.
// See the LICENSE file in the project root for more information.

using System.Diagnostics;
using System.Threading;
using System.Threading.Tasks;

namespace System.Net.Http
{
/// <summary>
/// DiagnosticHandler notifies DiagnosticSource subscribers about outgoing Http requests
/// </summary>
internal sealed class DiagnosticsHandler : DelegatingHandler
{
/// <summary>
/// DiagnosticHandler constructor
/// </summary>
/// <param name="innerHandler">Inner handler: Windows or Unix implementation of HttpMessageHandler.
/// Note that DiagnosticHandler is the latest in the pipeline </param>
public DiagnosticsHandler(HttpMessageHandler innerHandler) : base(innerHandler)
{
}

protected internal override Task<HttpResponseMessage> SendAsync(HttpRequestMessage request,
CancellationToken cancellationToken)
{
//do not write to diagnostic source if request is invalid or cancelled,
//let inner handler decide what to do with it
if (request == null || cancellationToken.IsCancellationRequested)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why are these checks here? Seems like if we're really leaving it up to the implementation what to do with these, the implementation could very well choose to execute a request (e.g. ignore cancellation), in which case it seems you'd still want to do pre/post logging of whatever you can. I'd suggest just removing these checks and just dealing below with the possibility that request is null in LogHttpRequest.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Apparently HttpClient checks request in SendAsync before calling HttpMessageHandler, so request never could be null here anyway.

{
return base.SendAsync(request, cancellationToken);
}

Guid loggingRequestId = LogHttpRequest(request);
Task<HttpResponseMessage> responseTask = base.SendAsync(request, cancellationToken);
LogHttpResponse(responseTask, loggingRequestId);
return responseTask;
}

#region private

private static readonly DiagnosticListener s_diagnosticListener =
new DiagnosticListener(DiagnosticsHandlerLoggingStrings.DiagnosticListenerName);

private static Guid LogHttpRequest(HttpRequestMessage request)
{
return s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.RequestWriteName) ?
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Rather than doing this more detailed check in both LogHttpRequest and LogHttpResponse, how about just doing it once in SendAsync and only calling LogHttpRequest and LogHttpResponse if it was set.

LogHttpRequestCore(request) :
Guid.Empty;
}

private static void LogHttpResponse(Task<HttpResponseMessage> responseTask, Guid loggingRequestId)
{
if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ResponseWriteName))
{
ScheduleLogResponse(responseTask, loggingRequestId);
}
}

private static void ScheduleLogResponse(
Task<HttpResponseMessage> responseTask, Guid loggingRequestId)
{
responseTask.ContinueWith(
t =>
{
if (!t.IsCanceled)
{
LogHttpResponseCore(t.IsFaulted ? null : t.Result, t.Exception, loggingRequestId);
}
},
TaskScheduler.Default);
Copy link
Member

@stephentoub stephentoub Feb 9, 2017 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A few things:

  • Why are we not logging a response if the operation was canceled? Seems like that'd still be interesting to know, as otherwise someone looking at a log doesn't know whether the operation is still in flight or whether it was canceled.
  • If the intent really is though to not log anything if it's canceled, that's more efficiently achieved by passing TaskContinuationOptions.NotOnCanceled to the ContinueWith call.
  • The lambda is also closing over loggingRequestId, which allocates both a closure and a delegate to a method on that closure object. It'd be more efficient to pass the needed state in through the continuation's object state; since the state in this case is a Guid, it'll still be boxed, but that's better than the two larger allocations for the delegate and closure. Something like:
responseTask.ContinueWith((t,s) => LogHttpResponseCore(t.IsFaulted ? null : t.Result, t.Exception, (Guid)s),
    loggingRequestId, CancellationToken.None, TaskContinuationOptions.NotOnCanceled, TaskScheduler.Default);

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree that logging cancelled requests is a good idea. It also requires passing TaskStatus to Write event, so user's won't need to guess what happened to the request

}

private static Guid LogHttpRequestCore(HttpRequestMessage request)
{
Guid loggingRequestId = Guid.NewGuid();
long timestamp = Stopwatch.GetTimestamp();

s_diagnosticListener.Write(
DiagnosticsHandlerLoggingStrings.RequestWriteName,
new
{
Request = request,
LoggingRequestId = loggingRequestId,
Timestamp = timestamp
}
);

return loggingRequestId;
}

private static void LogHttpResponseCore(HttpResponseMessage response, Exception exception,
Guid loggingRequestId)
{
// An empty loggingRequestId signifies that the request was not logged, so do
// not attempt to log response.
if (loggingRequestId != Guid.Empty)
{
long timestamp = Stopwatch.GetTimestamp();

s_diagnosticListener.Write(
DiagnosticsHandlerLoggingStrings.ResponseWriteName,
new
{
Response = response,
LoggingRequestId = loggingRequestId,
TimeStamp = timestamp,
Exception = exception
}
);
}
}

#endregion
}
}
2 changes: 1 addition & 1 deletion ...tem/Net/Http/HttpHandlerLoggingStrings.cs → .../Http/DiagnosticsHandlerLoggingStrings.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,7 +7,7 @@ namespace System.Net.Http
/// <summary>
/// Defines names of DiagnosticListener and Write events for WinHttpHandler, CurlHandler, and HttpHandlerToFilter.
/// </summary>
internal static class HttpHandlerLoggingStrings
internal static class DiagnosticsHandlerLoggingStrings
{
public const string DiagnosticListenerName = "HttpHandlerDiagnosticListener";
public const string RequestWriteName = "System.Net.Http.Request";
Expand Down
4 changes: 3 additions & 1 deletion src/System.Net.Http/src/System/Net/Http/HttpClientHandler.Unix.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -143,6 +143,7 @@ public IDictionary<String, object> Properties
public HttpClientHandler()
{
_curlHandler = new CurlHandler();
_curlHandlerPipeline = new DiagnosticsHandler(_curlHandler);
}

protected override void Dispose(bool disposing)
Expand All @@ -160,14 +161,15 @@ protected override void Dispose(bool disposing)

protected internal override Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
{
return _curlHandler.SendAsync(request, cancellationToken);
return _curlHandlerPipeline.SendAsync(request, cancellationToken);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would like to avoid all checks for whether logging is currently enabled except for one upfront, e.g. make this line something like:

return s_diagnosticListener.IsEnabled() ?
    _curlHandlerPipeline.SendAsync(request, cancellationToken) :
    _curlHandler.SendAsync(request, cancellationToken);

such that we only have the one additional static field read / bool check upfront, and then if logging wasn't enabled, we don't have to incur any of the additional costs, such as extra branches, extra function calls, extra virtual calls, etc. We then don't have to worry quite as much about what happens in the DiagnosticHandler in subsequent PRs with regards to perf overheads.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I suggest that DiagnosticsHandler should own the logic to define if it's enabled or not at cost of one non-virtual static function
In the part 2, it will start to send other events, so having this logic spread across all handlers would be quite hard to maintain.

}

#endregion Request Execution

#region Private

private readonly CurlHandler _curlHandler;
private readonly HttpMessageHandler _curlHandlerPipeline;

#endregion Private
}
Expand Down
4 changes: 3 additions & 1 deletion src/System.Net.Http/src/System/Net/Http/HttpClientHandler.Windows.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -194,6 +194,7 @@ public IDictionary<String, object> Properties
public HttpClientHandler()
{
_winHttpHandler = new WinHttpHandler();
_winHttpHandlerPipeline = new DiagnosticsHandler(_winHttpHandler);

// Adjust defaults to match current .NET Desktop HttpClientHandler (based on HWR stack).
AllowAutoRedirect = true;
Expand Down Expand Up @@ -265,14 +266,15 @@ protected internal override Task<HttpResponseMessage> SendAsync(HttpRequestMessa
}
}

return _winHttpHandler.SendAsync(request, cancellationToken);
return _winHttpHandlerPipeline.SendAsync(request, cancellationToken);
}

#endregion Request Execution

#region Private

private WinHttpHandler _winHttpHandler;
private readonly HttpMessageHandler _winHttpHandlerPipeline;
private bool _useProxy;
private volatile bool _disposed;
#endregion Private
Expand Down
6 changes: 0 additions & 6 deletions src/System.Net.Http/src/System/Net/Http/Unix/CurlHandler.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -127,8 +127,6 @@ internal partial class CurlHandler : HttpMessageHandler
private static string s_curlVersionDescription;
private static string s_curlSslVersionDescription;

private static readonly DiagnosticListener s_diagnosticListener = new DiagnosticListener(HttpHandlerLoggingStrings.DiagnosticListenerName);

private readonly MultiAgent _agent;
private volatile bool _anyOperationStarted;
private volatile bool _disposed;
Expand Down Expand Up @@ -460,8 +458,6 @@ protected internal override Task<HttpResponseMessage> SendAsync(
return Task.FromCanceled<HttpResponseMessage>(cancellationToken);
}

Guid loggingRequestId = s_diagnosticListener.LogHttpRequest(request);

// Create the easy request. This associates the easy request with this handler and configures
// it based on the settings configured for the handler.
var easy = new EasyRequest(this, request, cancellationToken);
Expand All @@ -475,8 +471,6 @@ protected internal override Task<HttpResponseMessage> SendAsync(
easy.CleanupAndFailRequest(exc);
}

s_diagnosticListener.LogHttpResponse(easy.Task, loggingRequestId);

return easy.Task;
}

Expand Down
Loading