Skip to content
This repository was archived by the owner on Jan 23, 2023. It is now read-only.

Overhaul System.Net library logging #13134

Merged
stephentoub merged 4 commits into from
Oct 29, 2016
Merged

Overhaul System.Net library logging #13134

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
92fd5c0
Overhaul System.Net library logging
stephentoub Oct 28, 2016
3b251eb
Address PR feedback
stephentoub Oct 29, 2016
2284f73
Add additional System.Net tracing tests
stephentoub Oct 29, 2016
3070c9d
Fix build for versions without Assembly.Location
stephentoub Oct 29, 2016
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
26 changes: 15 additions & 11 deletions Documentation/debugging/windows-instructions.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -89,11 +89,10 @@ Logs are going to be placed in %SYSTEMDRIVE%\sockets.etl.

#### Trace multiple providers

1. Create a new file containing all the GUIDs. Create a file called providers.txt:
1. Create a file called providers.txt with the following contents:

```
"{e03c0352-f9c9-56ff-0ea7-b94ba8cabc6b}"
"{501a994a-eb63-5415-9af1-1b031260f16c}"
"{066c0e27-a02d-5a98-9a4d-078cc3b1a896}"
"{bdd9a83e-1929-5482-0d73-2fe5e1c0e16d}"
```
Expand Down Expand Up @@ -138,31 +137,36 @@ Logs are going to be placed in %SYSTEMDRIVE%\sockets.etl.

### Built-in EventSource tracing

The following EventSources are built-in CoreFX. The ones that are not marked as [__TestCode__] or [__FEATURE_TRACING__] can be enabled in production scenarios for log collection.
The following EventSources are built-in to CoreFX. The ones that are not marked as [__TestCode__] can be enabled in production scenarios for log collection.

#### Global
* `*System.Diagnostics.Eventing.FrameworkEventSource {8E9F5090-2D75-4d03-8A81-E5AFBF85DAF1}`: Global EventSource used by multiple namespaces.

#### System.Collections
* `*System.Collections.Concurrent.ConcurrentCollectionsEventSource {35167F8E-49B2-4b96-AB86-435B59336B5E}`: [__FEATURE_TRACING__] Provides an event source for tracing Coordination Data Structure collection information.
* `*System.Collections.Concurrent.ConcurrentCollectionsEventSource {35167F8E-49B2-4b96-AB86-435B59336B5E}`: Provides an event source for tracing Coordination Data Structure collection information.

#### System.Linq
* `*System.Linq.Parallel.PlinqEventSource {159eeeec-4a14-4418-a8fe-faabcd987887}`: Provides an event source for tracing PLINQ information.

#### System.Net namespaces

* `*Microsoft-System-Net-Debug {99e4576b-9d7e-585f-8b32-0ac3082f2282}`: Highly verbose, low-level debugging traces in production code.
* `*Microsoft-System-Net-Http {bdd9a83e-1929-5482-0d73-2fe5e1c0e16d}`: HTTP-related traces.
* `*Microsoft-System-Net-Mail {42c8027b-f048-58d2-537d-a4a9d5ee7038}`: SMTP-related traces.
* `*Microsoft-System-Net-NameResolution {5f302add-3825-520e-8fa0-627b206e2e7e}`: DNS-related traces.
* `*Microsoft-System-Net-NetworkInformation {b8e42167-0eb2-5e39-97b5-acaca593d3a2}`: Network configuration-related traces.
* `*Microsoft-System-Net-Ping {a771ec4a-7260-59ce-0475-db257437ed8c}`: Ping-related traces.
* `*Microsoft-System-Net-Primitives {a9f9e4e1-0cf5-5005-b530-3d37959d5e84}`: Traces related to core networking-related types.
* `*Microsoft-System-Net-Requests {3763dc7e-7046-5576-9041-5616e21cc2cf}`: WebRequest-related traces.
* `*Microsoft-System-Net-Sockets {e03c0352-f9c9-56ff-0ea7-b94ba8cabc6b}`: Sockets-related traces.
* `*Microsoft-System-Net-Security {066c0e27-a02d-5a98-9a4d-078cc3b1a896}`: Security-related traces.
* `*Microsoft-System-Net-WebHeaderCollection {fd36452f-9f2b-5850-d212-6c436231e3dc}`: WebHeaderCollection-related traces.
* `*Microsoft-System-Net-WebSockets-Client {71cddde3-cf58-52d5-094f-927828a09337}`: ClientWebSocket-related traces.
* `*Microsoft-System-Net-TestLogging {18579866-5c03-5954-91ff-bdc63681458c}`: [__TestCode__] Test-code tracing (I/O async completions, performance test reporting).
* `*Microsoft-System-Net {501a994a-eb63-5415-9af1-1b031260f16c}`: Common tracing shared by System.Net components.
* `*Microsoft-System-Net-Sockets {e03c0352-f9c9-56ff-0ea7-b94ba8cabc6b}`: Sockets specific traces.
* `*Microsoft-System-Net-Security {066c0e27-a02d-5a98-9a4d-078cc3b1a896}`: Security specific traces.
* `*Microsoft-System-Net-Http {bdd9a83e-1929-5482-0d73-2fe5e1c0e16d}`: Http specific traces.

#### System.Threading
* `*System.Threading.SynchronizationEventSource {EC631D38-466B-4290-9306-834971BA0217}`: Provides an event source for tracing Coordination Data Structure synchronization information.
* `*System.Threading.Tasks.TplEventSource {2e5dba47-a3d2-4d16-8ee0-6671ffdcd7b5}`: Provides an event source for tracing TPL information.
* `*System.Threading.Tasks.Parallel.EventSource`: Provides an event source for tracing TPL information.
* `*System.Threading.Tasks.Dataflow.DataflowEventSource {16F53577-E41D-43D4-B47E-C17025BF4025}`: [__FEATURE_TRACING__] Provides an event source for tracing Dataflow information.
* `*System.Threading.Tasks.Dataflow.DataflowEventSource {16F53577-E41D-43D4-B47E-C17025BF4025}`: Provides an event source for tracing Dataflow information.

## Notes
* You can find the test invocation command-line by looking at the logs generated after the `msbuild /t:rebuild,test` within the test folder.
7 changes: 1 addition & 6 deletions src/Common/src/Interop/Windows/SChannel/SecPkgContext_ConnectionInfo.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -38,12 +38,7 @@ internal unsafe SecPkgContext_ConnectionInfo(byte[] nativeBuffer)
}
catch (OverflowException)
{
if (GlobalLog.IsEnabled)
{
GlobalLog.Assert("SslConnectionInfo::.ctor", "Negative size.");
}

Debug.Fail("SslConnectionInfo::.ctor", "Negative size.");
NetEventSource.Fail(this, "Negative size");
throw;
}
}
Expand Down
7 changes: 1 addition & 6 deletions src/Common/src/Interop/Windows/SChannel/UnmanagedCertificateContext.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -38,12 +38,7 @@ internal static X509Certificate2Collection GetRemoteCertificatesFromStoreContext
}

var cert = new X509Certificate2(new IntPtr(next));
if (GlobalLog.IsEnabled)
{
GlobalLog.Print(
"UnmanagedCertificateContext::GetRemoteCertificatesFromStoreContext " +
"adding remote certificate:" + cert.Subject + cert.Thumbprint);
}
if (NetEventSource.IsEnabled) NetEventSource.Info(certContext, $"Adding remote certificate:{cert}");
Copy link
Contributor

@Priya91 Priya91 Oct 28, 2016 •
edited
Loading

Choose a reason for hiding this comment

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

IsEnabled is checked in NetEventSource.Info no? There at other places as well.

Copy link
Member Author

@stephentoub stephentoub Oct 28, 2016

Choose a reason for hiding this comment

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

Yes, but the call site is using string interpolation, and will end up allocating a FormattableString along with an object[] to hold the arguments (cert). The IsEnabled check guards those costs.


result.Add(cert);
last = next;
Expand Down
15 changes: 3 additions & 12 deletions src/Common/src/Interop/Windows/Winsock/SafeNativeOverlapped.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,10 +15,7 @@ internal sealed class SafeNativeOverlapped : SafeHandle
private SafeNativeOverlapped()
: this(IntPtr.Zero)
{
if (GlobalLog.IsEnabled)
{
GlobalLog.Print("SafeNativeOverlapped#" + LoggingHash.HashString(this) + "::ctor(null)");
}
if (NetEventSource.IsEnabled) NetEventSource.Info(this);
}

private SafeNativeOverlapped(IntPtr handle)
Expand All @@ -32,10 +29,7 @@ public unsafe SafeNativeOverlapped(SafeCloseSocket socketHandle, NativeOverlappe
{
SocketHandle = socketHandle;

if (GlobalLog.IsEnabled)
{
GlobalLog.Print("SafeNativeOverlapped#" + LoggingHash.HashString(this) + "::ctor(socket#" + LoggingHash.HashString(socketHandle) + ")");
}
if (NetEventSource.IsEnabled) NetEventSource.Info(this, $"socketHandle:{socketHandle}");

#if DEBUG
SocketHandle.AddRef();
Expand All @@ -57,10 +51,7 @@ public override bool IsInvalid

protected override bool ReleaseHandle()
{
if (GlobalLog.IsEnabled)
{
GlobalLog.Print("SafeNativeOverlapped#" + LoggingHash.HashString(this) + "::ReleaseHandle()");
}
if (NetEventSource.IsEnabled) NetEventSource.Info(this);

FreeNativeOverlapped();

Expand Down
15 changes: 3 additions & 12 deletions src/Common/src/Interop/Windows/sspicli/NegotiationInfoClass.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,18 +16,12 @@ internal NegotiationInfoClass(SafeHandle safeHandle, int negotiationState)
{
if (safeHandle.IsInvalid)
{
if (GlobalLog.IsEnabled)
{
GlobalLog.Print("NegotiationInfoClass::.ctor() the handle is invalid:" + (safeHandle.DangerousGetHandle()).ToString("x"));
}
if (NetEventSource.IsEnabled) NetEventSource.Info(this, $"Invalid handle:{safeHandle}");
return;
}

IntPtr packageInfo = safeHandle.DangerousGetHandle();
if (GlobalLog.IsEnabled)
{
GlobalLog.Print("NegotiationInfoClass::.ctor() packageInfo:" + packageInfo.ToString("x8") + " negotiationState:" + negotiationState.ToString("x8"));
}
if (NetEventSource.IsEnabled) NetEventSource.Info(this, $"packageInfo:{packageInfo} negotiationState:{negotiationState:x}");

if (negotiationState == Interop.SspiCli.SECPKG_NEGOTIATION_COMPLETE
|| negotiationState == Interop.SspiCli.SECPKG_NEGOTIATION_OPTIMISTIC)
Expand All @@ -39,10 +33,7 @@ internal NegotiationInfoClass(SafeHandle safeHandle, int negotiationState)
name = Marshal.PtrToStringUni(unmanagedString);
}

if (GlobalLog.IsEnabled)
{
GlobalLog.Print("NegotiationInfoClass::.ctor() packageInfo:" + packageInfo.ToString("x8") + " negotiationState:" + negotiationState.ToString("x8") + " name:" + LoggingHash.ObjectToString(name));
}
if (NetEventSource.IsEnabled) NetEventSource.Info(this, $"packageInfo:{packageInfo} negotiationState:{negotiationState:x} name:{name}");

// An optimization for future string comparisons.
if (string.Compare(name, Kerberos, StringComparison.OrdinalIgnoreCase) == 0)
Expand Down
13 changes: 2 additions & 11 deletions src/Common/src/Interop/Windows/sspicli/SSPIAuthType.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -28,10 +28,7 @@ public SecurityPackageInfoClass[] SecurityPackages

public int EnumerateSecurityPackages(out int pkgnum, out SafeFreeContextBuffer pkgArray)
{
if (GlobalLog.IsEnabled)
{
GlobalLog.Print("SSPIAuthType::EnumerateSecurityPackages()");
}
if (NetEventSource.IsEnabled) NetEventSource.Info(this);
return SafeFreeContextBuffer.EnumeratePackages(out pkgnum, out pkgArray);
}

Expand Down Expand Up @@ -108,16 +105,10 @@ public unsafe int DecryptMessage(SafeDeleteContext context, Interop.SspiCli.SecB

if (status == 0 && qop == Interop.SspiCli.SECQOP_WRAP_NO_ENCRYPT)
{
if (GlobalLog.IsEnabled)
{
GlobalLog.Assert("SspiCli.DecryptMessage", "Expected qop = 0, returned value = " + qop.ToString("x", CultureInfo.InvariantCulture));
}

Debug.Fail("SspiCli.DecryptMessage", "Expected qop = 0, returned value = " + qop.ToString("x", CultureInfo.InvariantCulture));
NetEventSource.Fail(this, $"Expected qop = 0, returned value = {qop}");
throw new InvalidOperationException(SR.net_auth_message_not_encrypted);
}


return status;
}

Expand Down
5 changes: 1 addition & 4 deletions src/Common/src/Interop/Windows/sspicli/SSPISecureChannelType.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,10 +26,7 @@ public SecurityPackageInfoClass[] SecurityPackages

public int EnumerateSecurityPackages(out int pkgnum, out SafeFreeContextBuffer pkgArray)
{
if (GlobalLog.IsEnabled)
{
GlobalLog.Print("SSPISecureChannelType::EnumerateSecurityPackages()");
}
if (NetEventSource.IsEnabled) NetEventSource.Info(this);
return SafeFreeContextBuffer.EnumeratePackages(out pkgnum, out pkgArray);
}

Expand Down
Loading