From 4e72e437a918d60c1d52e77a4a7a363326573f01 Mon Sep 17 00:00:00 2001 From: Wraith Date: Thu, 29 Jul 2021 00:49:59 +0100 Subject: [PATCH] Tracing improvements in Managed SNI (#1187) --- .../Data/SqlClient/SNI/LocalDB.Windows.cs | 35 ++-- .../Microsoft/Data/SqlClient/SNI/SNICommon.cs | 27 ++- .../Data/SqlClient/SNI/SNIMarsHandle.cs | 167 ++++++------------ .../Data/SqlClient/SNI/SNINpHandle.cs | 122 ++++--------- .../Microsoft/Data/SqlClient/SNI/SNIPacket.cs | 25 ++- .../Data/SqlClient/SNI/SNITcpHandle.cs | 98 +++++----- .../src/Microsoft/Data/SqlClient/SNI/SSRP.cs | 28 +-- .../SNI/SslOverTdsStream.NetCoreApp.cs | 28 +-- .../SNI/SslOverTdsStream.NetStandard.cs | 28 +-- .../Data/SqlClient/SNI/SslOverTdsStream.cs | 5 +- 10 files changed, 184 insertions(+), 379 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/LocalDB.Windows.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/LocalDB.Windows.cs index 6e1f0e19e8..68eaa25486 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/LocalDB.Windows.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/LocalDB.Windows.cs @@ -13,7 +13,6 @@ namespace Microsoft.Data.SqlClient.SNI internal sealed class LocalDB { private static readonly LocalDB Instance = new LocalDB(); - private const string s_className = nameof(LocalDB); //HKEY_LOCAL_MACHINE private const string LocalDBInstalledVersionRegistryKey = "SOFTWARE\\Microsoft\\Microsoft SQL Server Local DB\\Installed Versions\\"; @@ -103,8 +102,7 @@ internal static string MapLocalDBErrorStateToErrorMessage(LocalDBErrorState erro /// private bool LoadUserInstanceDll() { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(LocalDB))) { // Check in a non thread-safe way if the handle is already set for performance. if (_sqlUserInstanceLibraryHandle != null) @@ -128,7 +126,7 @@ private bool LoadUserInstanceDll() if (dllPath == null) { SNILoadHandle.SingletonInstance.LastError = new SNIError(SNIProviders.INVALID_PROV, 0, MapLocalDBErrorStateToCode(registryQueryErrorState), MapLocalDBErrorStateToErrorMessage(registryQueryErrorState)); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "User instance DLL path is null."); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(LocalDB), EventType.ERR, "User instance DLL path is null."); return false; } @@ -136,7 +134,7 @@ private bool LoadUserInstanceDll() if (string.IsNullOrWhiteSpace(dllPath)) { SNILoadHandle.SingletonInstance.LastError = new SNIError(SNIProviders.INVALID_PROV, 0, SNICommon.LocalDBInvalidSqlUserInstanceDllPath, Strings.SNI_ERROR_55); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "User instance DLL path is invalid. DLL path = {0}", dllPath); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(LocalDB), EventType.ERR, "User instance DLL path is invalid. DLL path = {0}", dllPath); return false; } @@ -146,7 +144,7 @@ private bool LoadUserInstanceDll() if (libraryHandle.IsInvalid) { SNILoadHandle.SingletonInstance.LastError = new SNIError(SNIProviders.INVALID_PROV, 0, SNICommon.LocalDBFailedToLoadDll, Strings.SNI_ERROR_56); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Library Handle is invalid. Could not load the dll."); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(LocalDB), EventType.ERR, "Library Handle is invalid. Could not load the dll."); libraryHandle.Dispose(); return false; } @@ -157,7 +155,7 @@ private bool LoadUserInstanceDll() if (_startInstanceHandle == IntPtr.Zero) { SNILoadHandle.SingletonInstance.LastError = new SNIError(SNIProviders.INVALID_PROV, 0, SNICommon.LocalDBBadRuntime, Strings.SNI_ERROR_57); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Was not able to load the PROC from DLL. Bad Runtime."); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(LocalDB), EventType.ERR, "Was not able to load the PROC from DLL. Bad Runtime."); libraryHandle.Dispose(); return false; } @@ -174,14 +172,10 @@ private bool LoadUserInstanceDll() } _sqlUserInstanceLibraryHandle = libraryHandle; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "User Instance DLL was loaded successfully."); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(LocalDB), EventType.INFO, "User Instance DLL was loaded successfully."); return true; } } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } /// @@ -191,8 +185,7 @@ private bool LoadUserInstanceDll() /// private string GetUserInstanceDllPath(out LocalDBErrorState errorState) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(LocalDB))) { string dllPath = null; using (RegistryKey key = Registry.LocalMachine.OpenSubKey(LocalDBInstalledVersionRegistryKey)) @@ -200,7 +193,7 @@ private string GetUserInstanceDllPath(out LocalDBErrorState errorState) if (key == null) { errorState = LocalDBErrorState.NO_INSTALLATION; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "No installation found."); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(LocalDB), EventType.ERR, "No installation found."); return null; } @@ -215,7 +208,7 @@ private string GetUserInstanceDllPath(out LocalDBErrorState errorState) if (!Version.TryParse(subKey, out currentKeyVersion)) { errorState = LocalDBErrorState.INVALID_CONFIG; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Invalid Configuration."); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(LocalDB), EventType.ERR, "Invalid Configuration."); return null; } @@ -229,7 +222,7 @@ private string GetUserInstanceDllPath(out LocalDBErrorState errorState) if (latestVersion.Equals(zeroVersion)) { errorState = LocalDBErrorState.INVALID_CONFIG; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Invalid Configuration."); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(LocalDB), EventType.ERR, "Invalid Configuration."); return null; } @@ -242,7 +235,7 @@ private string GetUserInstanceDllPath(out LocalDBErrorState errorState) if (instanceAPIPathRegistryObject == null) { errorState = LocalDBErrorState.NO_SQLUSERINSTANCEDLL_PATH; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "No SQL user instance DLL. Instance API Path Registry Object Error."); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(LocalDB), EventType.ERR, "No SQL user instance DLL. Instance API Path Registry Object Error."); return null; } @@ -251,7 +244,7 @@ private string GetUserInstanceDllPath(out LocalDBErrorState errorState) if (valueKind != RegistryValueKind.String) { errorState = LocalDBErrorState.INVALID_SQLUSERINSTANCEDLL_PATH; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Invalid SQL user instance DLL path. Registry value kind mismatch."); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(LocalDB), EventType.ERR, "Invalid SQL user instance DLL path. Registry value kind mismatch."); return null; } @@ -262,10 +255,6 @@ private string GetUserInstanceDllPath(out LocalDBErrorState errorState) } } } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } } } diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNICommon.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNICommon.cs index af370030ee..50d8ea239c 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNICommon.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNICommon.cs @@ -132,8 +132,6 @@ internal enum SNISMUXFlags : uint internal class SNICommon { - private const string s_className = nameof(SNICommon); - // Each error number maps to SNI_ERROR_* in String.resx internal const int ConnTerminatedError = 2; internal const int InvalidParameterError = 5; @@ -169,12 +167,11 @@ internal class SNICommon /// True if certificate is valid internal static bool ValidateSslServerCertificate(string targetServerName, X509Certificate cert, SslPolicyErrors policyErrors) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SNICommon.ValidateSslServerCertificate | SNI | SCOPE | INFO | Entering Scope {0} "); - try + using (TrySNIEventScope.Create("SNICommon.ValidateSslServerCertificate | SNI | SCOPE | INFO | Entering Scope {0} ")) { if (policyErrors == SslPolicyErrors.None) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "targetServerName {0}, SSL Server certificate not validated as PolicyErrors set to None.", args0: targetServerName); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNICommon), EventType.INFO, "targetServerName {0}, SSL Server certificate not validated as PolicyErrors set to None.", args0: targetServerName); return true; } @@ -185,7 +182,7 @@ internal static bool ValidateSslServerCertificate(string targetServerName, X509C // Verify that target server name matches subject in the certificate if (targetServerName.Length > certServerName.Length) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "targetServerName {0}, Target Server name is of greater length than Subject in Certificate.", args0: targetServerName); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNICommon), EventType.ERR, "targetServerName {0}, Target Server name is of greater length than Subject in Certificate.", args0: targetServerName); return false; } else if (targetServerName.Length == certServerName.Length) @@ -193,7 +190,7 @@ internal static bool ValidateSslServerCertificate(string targetServerName, X509C // Both strings have the same length, so targetServerName must be a FQDN if (!targetServerName.Equals(certServerName, StringComparison.OrdinalIgnoreCase)) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "targetServerName {0}, Target Server name does not match Subject in Certificate.", args0: targetServerName); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNICommon), EventType.ERR, "targetServerName {0}, Target Server name does not match Subject in Certificate.", args0: targetServerName); return false; } } @@ -201,7 +198,7 @@ internal static bool ValidateSslServerCertificate(string targetServerName, X509C { if (string.Compare(targetServerName, 0, certServerName, 0, targetServerName.Length, StringComparison.OrdinalIgnoreCase) != 0) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "targetServerName {0}, Target Server name does not match Subject in Certificate.", args0: targetServerName); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNICommon), EventType.ERR, "targetServerName {0}, Target Server name does not match Subject in Certificate.", args0: targetServerName); return false; } @@ -211,7 +208,7 @@ internal static bool ValidateSslServerCertificate(string targetServerName, X509C // (Names have different lengths, so the target server can't be a FQDN.) if (certServerName[targetServerName.Length] != '.') { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "targetServerName {0}, Target Server name does not match Subject in Certificate.", args0: targetServerName); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNICommon), EventType.ERR, "targetServerName {0}, Target Server name does not match Subject in Certificate.", args0: targetServerName); return false; } } @@ -219,16 +216,12 @@ internal static bool ValidateSslServerCertificate(string targetServerName, X509C else { // Fail all other SslPolicy cases besides RemoteCertificateNameMismatch - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "targetServerName {0}, SslPolicyError {1}, SSL Policy invalidated certificate.", args0: targetServerName, args1: policyErrors); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNICommon), EventType.ERR, "targetServerName {0}, SslPolicyError {1}, SSL Policy invalidated certificate.", args0: targetServerName, args1: policyErrors); return false; } - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "targetServerName {0}, Client certificate validated successfully.", args0: targetServerName); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNICommon), EventType.INFO, "targetServerName {0}, Client certificate validated successfully.", args0: targetServerName); return true; } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } /// @@ -241,7 +234,7 @@ internal static bool ValidateSslServerCertificate(string targetServerName, X509C /// internal static uint ReportSNIError(SNIProviders provider, uint nativeError, uint sniError, string errorMessage) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Provider = {0}, native Error = {1}, SNI Error = {2}, Error Message = {3}", args0: provider, args1: nativeError, args2: sniError, args3: errorMessage); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNICommon), EventType.ERR, "Provider = {0}, native Error = {1}, SNI Error = {2}, Error Message = {3}", args0: provider, args1: nativeError, args2: sniError, args3: errorMessage); return ReportSNIError(new SNIError(provider, nativeError, sniError, errorMessage)); } @@ -255,7 +248,7 @@ internal static uint ReportSNIError(SNIProviders provider, uint nativeError, uin /// internal static uint ReportSNIError(SNIProviders provider, uint sniError, Exception sniException, uint nativeErrorCode = 0) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Provider = {0}, SNI Error = {1}, Exception = {2}", args0: provider, args1: sniError, args2: sniException?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNICommon), EventType.ERR, "Provider = {0}, SNI Error = {1}, Exception = {2}", args0: provider, args1: sniError, args2: sniException?.Message); return ReportSNIError(new SNIError(provider, sniError, sniException, nativeErrorCode)); } diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIMarsHandle.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIMarsHandle.cs index 353c5240b4..798624e594 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIMarsHandle.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIMarsHandle.cs @@ -15,7 +15,6 @@ namespace Microsoft.Data.SqlClient.SNI internal sealed class SNIMarsHandle : SNIHandle { private const uint ACK_THRESHOLD = 2; - private const string s_className = nameof(SNIMarsHandle); private readonly SNIMarsConnection _connection; private readonly uint _status = TdsEnums.SNI_UNINITIALIZED; @@ -57,20 +56,18 @@ public override void Dispose() { // SendControlPacket will lock so make sure that it cannot deadlock by failing to enter the DemuxerLock Debug.Assert(_connection != null && Monitor.IsEntered(_connection.DemuxerSync), "SNIMarsHandle.HandleRecieveComplete should be called while holding the SNIMarsConnection.DemuxerSync because it can cause deadlocks"); - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SNIMarsHandle))) { - SendControlPacket(SNISMUXFlags.SMUX_FIN); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, Sent SMUX_FIN packet to terminate session.", args0: ConnectionId); - } - catch (Exception e) - { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "MARS Session Id {0}, Internal exception error = {1}, Member Name={2}", args0: ConnectionId, args1: e?.Message, args2: e?.GetType()?.Name); - SNICommon.ReportSNIError(SNIProviders.SMUX_PROV, SNICommon.InternalExceptionError, e); - } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); + try + { + SendControlPacket(SNISMUXFlags.SMUX_FIN); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, Sent SMUX_FIN packet to terminate session.", args0: ConnectionId); + } + catch (Exception e) + { + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.ERR, "MARS Session Id {0}, Internal exception error = {1}, Member Name={2}", args0: ConnectionId, args1: e?.Message, args2: e?.GetType()?.Name); + SNICommon.ReportSNIError(SNIProviders.SMUX_PROV, SNICommon.InternalExceptionError, e); + } } } @@ -89,7 +86,7 @@ public SNIMarsHandle(SNIMarsConnection connection, ushort sessionId, object call _callbackObject = callbackObject; _handleSendCompleteCallback = HandleSendComplete; SendControlPacket(SNISMUXFlags.SMUX_SYN); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, Sent SMUX_SYN packet to start a new session, session Id {1}", args0: ConnectionId, args1: _sessionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, Sent SMUX_SYN packet to start a new session, session Id {1}", args0: ConnectionId, args1: _sessionId); _status = TdsEnums.SNI_SUCCESS; } @@ -99,12 +96,11 @@ public SNIMarsHandle(SNIMarsConnection connection, ushort sessionId, object call /// SMUX header flags private void SendControlPacket(SNISMUXFlags flags) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SNIMarsHandle.SendControlPacket | SNI | INFO | SCOPE | Entering Scope {0}"); - try + using (TrySNIEventScope.Create("SNIMarsHandle.SendControlPacket | SNI | INFO | SCOPE | Entering Scope {0}")) { SNIPacket packet = RentPacket(headerSize: SNISMUXHeader.HEADER_LENGTH, dataSize: 0); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, Packet rented {1}, packet dataLeft {2}", args0: ConnectionId, args1: packet?._id, args2: packet?.DataLeft); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, Packet rented {1}, packet dataLeft {2}", args0: ConnectionId, args1: packet?._id, args2: packet?.DataLeft); #endif lock (this) { @@ -116,14 +112,10 @@ private void SendControlPacket(SNISMUXFlags flags) _connection.Send(packet); ReturnPacket(packet); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, Packet returned {1}, packet dataLeft {2}", args0: ConnectionId, args1: packet?._id, args2: packet?.DataLeft); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, Packet returned {1}, packet dataLeft {2}", args0: ConnectionId, args1: packet?._id, args2: packet?.DataLeft); ; #endif } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } private SNISMUXHeader SetupSMUXHeader(int length, SNISMUXFlags flags) @@ -158,7 +150,7 @@ private SNIPacket SetPacketSMUXHeader(SNIPacket packet) header.Write(packet.GetHeaderBuffer(SNISMUXHeader.HEADER_LENGTH)); packet.SetHeaderActive(); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, Setting SMUX_DATA header in current header for packet {1}", args0: ConnectionId, args1: packet?._id); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, Setting SMUX_DATA header in current header for packet {1}", args0: ConnectionId, args1: packet?._id); #endif return packet; } @@ -171,8 +163,7 @@ private SNIPacket SetPacketSMUXHeader(SNIPacket packet) public override uint Send(SNIPacket packet) { Debug.Assert(packet.ReservedHeaderSize == SNISMUXHeader.HEADER_LENGTH, "mars handle attempting to send muxed packet without smux reservation in Send"); - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SNIMarsHandle))) { while (true) { @@ -184,12 +175,12 @@ public override uint Send(SNIPacket packet) } } - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, Waiting for Acknowledgment event.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, Waiting for Acknowledgment event.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); _ackEvent.Wait(); lock (this) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _sendPacketQueue count found {1}, Acknowledgment event Reset", args0: ConnectionId, args1: _sendPacketQueue?.Count); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _sendPacketQueue count found {1}, Acknowledgment event Reset", args0: ConnectionId, args1: _sendPacketQueue?.Count); _ackEvent.Reset(); } } @@ -199,13 +190,9 @@ public override uint Send(SNIPacket packet) { muxedPacket = SetPacketSMUXHeader(packet); } - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, SMUX Packet is going to be sent.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, SMUX Packet is going to be sent.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); return _connection.Send(muxedPacket); } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } /// @@ -217,27 +204,22 @@ public override uint Send(SNIPacket packet) private uint InternalSendAsync(SNIPacket packet, SNIAsyncCallback callback) { Debug.Assert(packet.ReservedHeaderSize == SNISMUXHeader.HEADER_LENGTH, "mars handle attempting to send muxed packet without smux reservation in InternalSendAsync"); - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SNIMarsHandle.InternalSendAsync | SNI | INFO | SCOPE | Entering Scope {0}"); - try + using (TrySNIEventScope.Create("SNIMarsHandle.InternalSendAsync | SNI | INFO | SCOPE | Entering Scope {0}")) { lock (this) { if (_sequenceNumber >= _sendHighwater) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, SNI Queue is full", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, SNI Queue is full", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); return TdsEnums.SNI_QUEUE_FULL; } SNIPacket muxedPacket = SetPacketSMUXHeader(packet); muxedPacket.SetCompletionCallback(callback ?? HandleSendComplete); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, Sending packet", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, Sending packet", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); return _connection.SendAsync(muxedPacket, callback); } } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } /// @@ -246,10 +228,10 @@ private uint InternalSendAsync(SNIPacket packet, SNIAsyncCallback callback) /// SNI error code private uint SendPendingPackets() { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - SNIMarsQueuedPacket packet = null; - try + using (TrySNIEventScope.Create(nameof(SNIMarsHandle))) { + SNIMarsQueuedPacket packet = null; + while (true) { lock (this) @@ -263,18 +245,18 @@ private uint SendPendingPackets() if (result != TdsEnums.SNI_SUCCESS && result != TdsEnums.SNI_SUCCESS_IO_PENDING) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "MARS Session Id {0}, InternalSendAsync result is not SNI_SUCCESS and is not SNI_SUCCESS_IO_PENDING", args0: ConnectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.ERR, "MARS Session Id {0}, InternalSendAsync result is not SNI_SUCCESS and is not SNI_SUCCESS_IO_PENDING", args0: ConnectionId); return result; } _sendPacketQueue.Dequeue(); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _sendPacketQueue dequeued, count {1}", args0: ConnectionId, args1: _sendPacketQueue?.Count); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _sendPacketQueue dequeued, count {1}", args0: ConnectionId, args1: _sendPacketQueue?.Count); continue; } else { _ackEvent.Set(); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _sendPacketQueue count found {1}, acknowledgment set", args0: ConnectionId, args1: _sendPacketQueue?.Count); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _sendPacketQueue count found {1}, acknowledgment set", args0: ConnectionId, args1: _sendPacketQueue?.Count); } } @@ -284,10 +266,6 @@ private uint SendPendingPackets() return TdsEnums.SNI_SUCCESS; } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } /// @@ -299,8 +277,7 @@ private uint SendPendingPackets() public override uint SendAsync(SNIPacket packet, SNIAsyncCallback callback = null) { Debug.Assert(_connection != null && Monitor.IsEntered(_connection.DemuxerSync), "SNIMarsHandle.HandleRecieveComplete should be called while holding the SNIMarsConnection.DemuxerSync because it can cause deadlocks"); - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SNIMarsHandle))) { lock (this) { @@ -308,14 +285,10 @@ public override uint SendAsync(SNIPacket packet, SNIAsyncCallback callback = nul } SendPendingPackets(); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _sendPacketQueue enqueued, count {1}", args0: ConnectionId, args1: _sendPacketQueue?.Count); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _sendPacketQueue enqueued, count {1}", args0: ConnectionId, args1: _sendPacketQueue?.Count); return TdsEnums.SNI_SUCCESS_IO_PENDING; } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } /// @@ -325,8 +298,7 @@ public override uint SendAsync(SNIPacket packet, SNIAsyncCallback callback = nul /// SNI error code public override uint ReceiveAsync(ref SNIPacket packet) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SNIMarsHandle))) { lock (_receivedPacketQueue) { @@ -334,14 +306,14 @@ public override uint ReceiveAsync(ref SNIPacket packet) if (_connectionError != null) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "MARS Session Id {0}, _asyncReceives {1}, _receiveHighwater {2}, _sendHighwater {3}, _receiveHighwaterLastAck {4}, _connectionError {5}", args0: ConnectionId, args1: _asyncReceives, args2: _receiveHighwater, args3: _sendHighwater, args4: _receiveHighwaterLastAck, args5: _connectionError); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.ERR, "MARS Session Id {0}, _asyncReceives {1}, _receiveHighwater {2}, _sendHighwater {3}, _receiveHighwaterLastAck {4}, _connectionError {5}", args0: ConnectionId, args1: _asyncReceives, args2: _receiveHighwater, args3: _sendHighwater, args4: _receiveHighwaterLastAck, args5: _connectionError); return SNICommon.ReportSNIError(_connectionError); } if (queueCount == 0) { _asyncReceives++; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, queueCount 0, _asyncReceives {1}, _receiveHighwater {2}, _sendHighwater {3}, _receiveHighwaterLastAck {4}", args0: ConnectionId, args1: _asyncReceives, args2: _receiveHighwater, args3: _sendHighwater, args4: _receiveHighwaterLastAck); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, queueCount 0, _asyncReceives {1}, _receiveHighwater {2}, _sendHighwater {3}, _receiveHighwaterLastAck {4}", args0: ConnectionId, args1: _asyncReceives, args2: _receiveHighwater, args3: _sendHighwater, args4: _receiveHighwaterLastAck); return TdsEnums.SNI_SUCCESS_IO_PENDING; } @@ -351,7 +323,7 @@ public override uint ReceiveAsync(ref SNIPacket packet) if (queueCount == 1) { #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, packet dequeued {1}, packet Owner {2}, packet refCount {3}, received Packet Queue count {4}", args0: ConnectionId, args1: packet?._id, args2: packet?._owner, args3: packet?._refCount, args4: _receivedPacketQueue?.Count); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, packet dequeued {1}, packet Owner {2}, packet refCount {3}, received Packet Queue count {4}", args0: ConnectionId, args1: packet?._id, args2: packet?._owner, args3: packet?._refCount, args4: _receivedPacketQueue?.Count); #endif _packetEvent.Reset(); } @@ -362,14 +334,10 @@ public override uint ReceiveAsync(ref SNIPacket packet) _receiveHighwater++; } - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _asyncReceives {1}, _receiveHighwater {2}, _sendHighwater {3}, _receiveHighwaterLastAck {4}, queueCount {5}", args0: ConnectionId, args1: _asyncReceives, args2: _receiveHighwater, args3: _sendHighwater, args4: _receiveHighwaterLastAck, args5: _receivedPacketQueue?.Count); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _asyncReceives {1}, _receiveHighwater {2}, _sendHighwater {3}, _receiveHighwaterLastAck {4}, queueCount {5}", args0: ConnectionId, args1: _asyncReceives, args2: _receiveHighwater, args3: _sendHighwater, args4: _receiveHighwaterLastAck, args5: _receivedPacketQueue?.Count); SendAckIfNecessary(); return TdsEnums.SNI_SUCCESS; } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } /// @@ -377,8 +345,7 @@ public override uint ReceiveAsync(ref SNIPacket packet) /// public void HandleReceiveError(SNIPacket packet) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SNIMarsHandle))) { // SNIMarsHandle should only receive calls to this function from the SNIMarsConnection aggregator class // which should handle ownership of the packet because the individual mars handles are not aware of @@ -387,16 +354,12 @@ public void HandleReceiveError(SNIPacket packet) lock (_receivedPacketQueue) { _connectionError = SNILoadHandle.SingletonInstance.LastError; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "MARS Session Id {0}, _connectionError to be handled: {1}", args0: ConnectionId, args1: _connectionError); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.ERR, "MARS Session Id {0}, _connectionError to be handled: {1}", args0: ConnectionId, args1: _connectionError); _packetEvent.Set(); } ((TdsParserStateObject)_callbackObject).ReadAsyncCallback(PacketHandle.FromManagedPacket(packet), 1); } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } /// @@ -406,8 +369,7 @@ public void HandleReceiveError(SNIPacket packet) /// SNI error code public void HandleSendComplete(SNIPacket packet, uint sniErrorCode) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SNIMarsHandle))) { lock (this) { @@ -417,13 +379,9 @@ public void HandleSendComplete(SNIPacket packet, uint sniErrorCode) } _connection.ReturnPacket(packet); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, Returned Packet: {1}", args0: ConnectionId, args1: packet?._id); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, Returned Packet: {1}", args0: ConnectionId, args1: packet?._id); #endif } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } /// @@ -433,23 +391,18 @@ public void HandleSendComplete(SNIPacket packet, uint sniErrorCode) public void HandleAck(uint highwater) { Debug.Assert(_connection != null && Monitor.IsEntered(_connection.DemuxerSync), "SNIMarsHandle.HandleRecieveComplete should be called while holding the SNIMarsConnection.DemuxerSync because it can cause deadlocks"); - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SNIMarsHandle))) { lock (this) { if (_sendHighwater != highwater) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, Setting _sendHighwater {1} to highwater {2} and send pending packets.", args0: ConnectionId, args1: _sendHighwater, args2: highwater); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, Setting _sendHighwater {1} to highwater {2} and send pending packets.", args0: ConnectionId, args1: _sendHighwater, args2: highwater); _sendHighwater = highwater; SendPendingPackets(); } } } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } /// @@ -460,14 +413,13 @@ public void HandleAck(uint highwater) public void HandleReceiveComplete(SNIPacket packet, SNISMUXHeader header) { Debug.Assert(_connection != null && Monitor.IsEntered(_connection.DemuxerSync), "SNIMarsHandle.HandleRecieveComplete should be called while holding the SNIMarsConnection.DemuxerSync because it can cause deadlocks"); - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SNIMarsHandle))) { lock (this) { if (_sendHighwater != header.Highwater) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, header.highwater {1}, _sendHighwater {2}, Handle Ack with header.highwater", args0: ConnectionId, args1: header.Highwater, args2: _sendHighwater); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, header.highwater {1}, _sendHighwater {2}, Handle Ack with header.highwater", args0: ConnectionId, args1: header.Highwater, args2: _sendHighwater); HandleAck(header.Highwater); } @@ -477,13 +429,13 @@ public void HandleReceiveComplete(SNIPacket packet, SNISMUXHeader header) { _receivedPacketQueue.Enqueue(packet); _packetEvent.Set(); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, _receivedPacketQueue count {3}, packet event set", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater, args3: _receivedPacketQueue?.Count); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, _receivedPacketQueue count {3}, packet event set", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater, args3: _receivedPacketQueue?.Count); return; } _asyncReceives--; Debug.Assert(_callbackObject != null); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, _asyncReceives {3}", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater, args3: _asyncReceives); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, _asyncReceives {3}", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater, args3: _asyncReceives); ((TdsParserStateObject)_callbackObject).ReadAsyncCallback(PacketHandle.FromManagedPacket(packet), 0); } @@ -495,13 +447,9 @@ public void HandleReceiveComplete(SNIPacket packet, SNISMUXHeader header) { _receiveHighwater++; } - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _asyncReceives {1}, _receiveHighwater {2}, _sendHighwater {3}, _receiveHighwaterLastAck {4}", args0: ConnectionId, args1: _asyncReceives, args2: _receiveHighwater, args3: _sendHighwater, args4: _receiveHighwaterLastAck); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _asyncReceives {1}, _receiveHighwater {2}, _sendHighwater {3}, _receiveHighwaterLastAck {4}", args0: ConnectionId, args1: _asyncReceives, args2: _receiveHighwater, args3: _sendHighwater, args4: _receiveHighwaterLastAck); SendAckIfNecessary(); } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } /// @@ -521,7 +469,7 @@ private void SendAckIfNecessary() if (receiveHighwater - receiveHighwaterLastAck > ACK_THRESHOLD) { SendControlPacket(SNISMUXFlags.SMUX_ACK); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _asyncReceives {1}, _receiveHighwater {2}, _sendHighwater {3}, _receiveHighwaterLastAck {4} Sending acknowledgment ACK_THRESHOLD {5}", args0: ConnectionId, args1: _asyncReceives, args2: _receiveHighwater, args3: _sendHighwater, args4: _receiveHighwaterLastAck, args5: ACK_THRESHOLD); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _asyncReceives {1}, _receiveHighwater {2}, _sendHighwater {3}, _receiveHighwaterLastAck {4} Sending acknowledgment ACK_THRESHOLD {5}", args0: ConnectionId, args1: _asyncReceives, args2: _receiveHighwater, args3: _sendHighwater, args4: _receiveHighwaterLastAck, args5: ACK_THRESHOLD); } } @@ -533,8 +481,7 @@ private void SendAckIfNecessary() /// SNI error code public override uint Receive(out SNIPacket packet, int timeoutInMilliseconds) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SNIMarsHandle))) { packet = null; int queueCount; @@ -546,12 +493,12 @@ public override uint Receive(out SNIPacket packet, int timeoutInMilliseconds) { if (_connectionError != null) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, _connectionError found: {3}.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater, args3: _connectionError); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.ERR, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, _connectionError found: {3}.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater, args3: _connectionError); return SNICommon.ReportSNIError(_connectionError); } queueCount = _receivedPacketQueue.Count; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, W_receivedPacketQueue count {3}.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater, args3: queueCount); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, W_receivedPacketQueue count {3}.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater, args3: queueCount); if (queueCount > 0) { @@ -560,7 +507,7 @@ public override uint Receive(out SNIPacket packet, int timeoutInMilliseconds) if (queueCount == 1) { _packetEvent.Reset(); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, packet event reset, _receivedPacketQueue count 1.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, packet event reset, _receivedPacketQueue count 1.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); } result = TdsEnums.SNI_SUCCESS; @@ -575,23 +522,19 @@ public override uint Receive(out SNIPacket packet, int timeoutInMilliseconds) } SendAckIfNecessary(); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, returning with result {3}.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater, args3: result); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, returning with result {3}.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater, args3: result); return result; } - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, Waiting for packet event.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, Waiting for packet event.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); if (!_packetEvent.Wait(timeoutInMilliseconds)) { SNILoadHandle.SingletonInstance.LastError = new SNIError(SNIProviders.SMUX_PROV, 0, SNICommon.ConnTimeoutError, Strings.SNI_ERROR_11); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, _packetEvent wait timed out.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIMarsHandle), EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, _packetEvent wait timed out.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); return TdsEnums.SNI_WAIT_TIMEOUT; } } } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } /// diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNINpHandle.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNINpHandle.cs index a11779870b..887966ac0c 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNINpHandle.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNINpHandle.cs @@ -18,7 +18,6 @@ namespace Microsoft.Data.SqlClient.SNI /// internal sealed class SNINpHandle : SNIPhysicalHandle { - private const string s_className = nameof(SNINpHandle); internal const string DefaultPipePath = @"sql\query"; // e.g. \\HOSTNAME\pipe\sql\query // private const int MAX_PIPE_INSTANCES = 255; // TODO: Investigate pipe instance limit. @@ -40,10 +39,10 @@ internal sealed class SNINpHandle : SNIPhysicalHandle public SNINpHandle(string serverName, string pipeName, long timerExpire) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Setting server name = {1}, pipe name = {2}", args0: _connectionId, args1: serverName, args2: pipeName); - try + using (TrySNIEventScope.Create(nameof(SNINpHandle))) { + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.INFO, "Connection Id {0}, Setting server name = {1}, pipe name = {2}", args0: _connectionId, args1: serverName, args2: pipeName); + _sendSync = new object(); _targetServer = serverName; @@ -72,14 +71,14 @@ public SNINpHandle(string serverName, string pipeName, long timerExpire) { SNICommon.ReportSNIError(SNIProviders.NP_PROV, SNICommon.ConnOpenFailedError, te); _status = TdsEnums.SNI_ERROR; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, Connection Timed out. Error Code 1 Exception = {1}", args0: _connectionId, args1: te?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.ERR, "Connection Id {0}, Connection Timed out. Error Code 1 Exception = {1}", args0: _connectionId, args1: te?.Message); return; } catch (IOException ioe) { SNICommon.ReportSNIError(SNIProviders.NP_PROV, SNICommon.ConnOpenFailedError, ioe); _status = TdsEnums.SNI_ERROR; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, IO Exception occurred. Error Code 1 Exception = {1}", args0: _connectionId, args1: ioe?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.ERR, "Connection Id {0}, IO Exception occurred. Error Code 1 Exception = {1}", args0: _connectionId, args1: ioe?.Message); return; } @@ -87,7 +86,7 @@ public SNINpHandle(string serverName, string pipeName, long timerExpire) { SNICommon.ReportSNIError(SNIProviders.NP_PROV, 0, SNICommon.ConnOpenFailedError, Strings.SNI_ERROR_40); _status = TdsEnums.SNI_ERROR; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, Pipe Stream not operational. Error Code 1 Exception = {1}", args0: _connectionId, args1: Strings.SNI_ERROR_1); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.ERR, "Connection Id {0}, Pipe Stream not operational. Error Code 1 Exception = {1}", args0: _connectionId, args1: Strings.SNI_ERROR_1); return; } @@ -97,27 +96,11 @@ public SNINpHandle(string serverName, string pipeName, long timerExpire) _stream = _pipeStream; _status = TdsEnums.SNI_SUCCESS; } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } - public override Guid ConnectionId - { - get - { - return _connectionId; - } - } + public override Guid ConnectionId => _connectionId; - public override uint Status - { - get - { - return _status; - } - } + public override uint Status => _status; public override int ProtocolVersion { @@ -136,24 +119,19 @@ public override int ProtocolVersion public override uint CheckConnection() { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SNINpHandle))) { if (!_stream.CanWrite || !_stream.CanRead) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, Cannot write or read to/from the stream", args0: _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.ERR, "Connection Id {0}, Cannot write or read to/from the stream", args0: _connectionId); return TdsEnums.SNI_ERROR; } else { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Can read and write to/from stream.", args0: _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.INFO, "Connection Id {0}, Can read and write to/from stream.", args0: _connectionId); return TdsEnums.SNI_SUCCESS; } } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } public override void Dispose() @@ -180,14 +158,13 @@ public override void Dispose() //Release any references held by _stream. _stream = null; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, All streams disposed and references cleared.", args0: _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.INFO, "Connection Id {0}, All streams disposed and references cleared.", args0: _connectionId); } } public override uint Receive(out SNIPacket packet, int timeout) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SNINpHandle))) { SNIPacket errorPacket; lock (this) @@ -197,14 +174,14 @@ public override uint Receive(out SNIPacket packet, int timeout) { packet = RentPacket(headerSize: 0, dataSize: _bufferSize); packet.ReadFromStream(_stream); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Rented and read packet, dataLeft {1}", args0: _connectionId, args1: packet?.DataLeft); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.INFO, "Connection Id {0}, Rented and read packet, dataLeft {1}", args0: _connectionId, args1: packet?.DataLeft); if (packet.DataLength == 0) { errorPacket = packet; packet = null; var e = new Win32Exception(); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, Packet length found 0, Win32 exception raised: {1}", args0: _connectionId, args1: e?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.ERR, "Connection Id {0}, Packet length found 0, Win32 exception raised: {1}", args0: _connectionId, args1: e?.Message); return ReportErrorAndReleasePacket(errorPacket, (uint)e.NativeErrorCode, 0, e.Message); } } @@ -212,29 +189,24 @@ public override uint Receive(out SNIPacket packet, int timeout) { errorPacket = packet; packet = null; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, ObjectDisposedException occurred: {1}.", args0: _connectionId, args1: ode?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.ERR, "Connection Id {0}, ObjectDisposedException occurred: {1}.", args0: _connectionId, args1: ode?.Message); return ReportErrorAndReleasePacket(errorPacket, ode); } catch (IOException ioe) { errorPacket = packet; packet = null; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, IOException occurred: {1}.", args0: _connectionId, args1: ioe?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.ERR, "Connection Id {0}, IOException occurred: {1}.", args0: _connectionId, args1: ioe?.Message); return ReportErrorAndReleasePacket(errorPacket, ioe); } return TdsEnums.SNI_SUCCESS; } } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } public override uint ReceiveAsync(ref SNIPacket packet) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SNINpHandle))) { SNIPacket errorPacket; packet = RentPacket(headerSize: 0, dataSize: _bufferSize); @@ -242,34 +214,29 @@ public override uint ReceiveAsync(ref SNIPacket packet) try { packet.ReadFromStreamAsync(_stream, _receiveCallback); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Rented and read packet asynchronously, dataLeft {1}", args0: _connectionId, args1: packet?.DataLeft); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.INFO, "Connection Id {0}, Rented and read packet asynchronously, dataLeft {1}", args0: _connectionId, args1: packet?.DataLeft); return TdsEnums.SNI_SUCCESS_IO_PENDING; } catch (ObjectDisposedException ode) { errorPacket = packet; packet = null; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, ObjectDisposedException occurred: {1}.", args0: _connectionId, args1: ode?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.ERR, "Connection Id {0}, ObjectDisposedException occurred: {1}.", args0: _connectionId, args1: ode?.Message); return ReportErrorAndReleasePacket(errorPacket, ode); } catch (IOException ioe) { errorPacket = packet; packet = null; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, IOException occurred: {1}.", args0: _connectionId, args1: ioe?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.ERR, "Connection Id {0}, IOException occurred: {1}.", args0: _connectionId, args1: ioe?.Message); return ReportErrorAndReleasePacket(errorPacket, ioe); } } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } public override uint Send(SNIPacket packet) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SNINpHandle))) { bool releaseLock = false; try @@ -295,18 +262,18 @@ public override uint Send(SNIPacket packet) { try { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Packet writing to stream, dataLeft {1}", args0: _connectionId, args1: packet?.DataLeft); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.INFO, "Connection Id {0}, Packet writing to stream, dataLeft {1}", args0: _connectionId, args1: packet?.DataLeft); packet.WriteToStream(_stream); return TdsEnums.SNI_SUCCESS; } catch (ObjectDisposedException ode) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, ObjectDisposedException occurred: {1}.", args0: _connectionId, args1: ode?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.ERR, "Connection Id {0}, ObjectDisposedException occurred: {1}.", args0: _connectionId, args1: ode?.Message); return ReportErrorAndReleasePacket(packet, ode); } catch (IOException ioe) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, IOException occurred: {1}.", args0: _connectionId, args1: ioe?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.ERR, "Connection Id {0}, IOException occurred: {1}.", args0: _connectionId, args1: ioe?.Message); return ReportErrorAndReleasePacket(packet, ioe); } } @@ -319,26 +286,17 @@ public override uint Send(SNIPacket packet) } } } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } public override uint SendAsync(SNIPacket packet, SNIAsyncCallback callback = null) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SNINpHandle))) { SNIAsyncCallback cb = callback ?? _sendCallback; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Packet writing to stream, dataLeft {1}", args0: _connectionId, args1: packet?.DataLeft); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.INFO, "Connection Id {0}, Packet writing to stream, dataLeft {1}", args0: _connectionId, args1: packet?.DataLeft); packet.WriteToStreamAsync(_stream, cb, SNIProviders.NP_PROV); return TdsEnums.SNI_SUCCESS_IO_PENDING; } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } public override void SetAsyncCallbacks(SNIAsyncCallback receiveCallback, SNIAsyncCallback sendCallback) @@ -349,8 +307,7 @@ public override void SetAsyncCallbacks(SNIAsyncCallback receiveCallback, SNIAsyn public override uint EnableSsl(uint options) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SNINpHandle))) { _validateCert = (options & TdsEnums.SNI_SSL_VALIDATE_CERTIFICATE) != 0; try @@ -361,21 +318,17 @@ public override uint EnableSsl(uint options) } catch (AuthenticationException aue) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, AuthenticationException message = {1}.", args0: ConnectionId, args1: aue?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.ERR, "Connection Id {0}, AuthenticationException message = {1}.", args0: ConnectionId, args1: aue?.Message); return SNICommon.ReportSNIError(SNIProviders.NP_PROV, SNICommon.InternalExceptionError, aue); } catch (InvalidOperationException ioe) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, InvalidOperationException message = {1}.", args0: ConnectionId, args1: ioe?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.ERR, "Connection Id {0}, InvalidOperationException message = {1}.", args0: ConnectionId, args1: ioe?.Message); return SNICommon.ReportSNIError(SNIProviders.NP_PROV, SNICommon.InternalExceptionError, ioe); } _stream = _sslStream; return TdsEnums.SNI_SUCCESS; } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } public override void DisableSsl() @@ -398,22 +351,17 @@ public override void DisableSsl() /// true if valid private bool ValidateServerCertificate(object sender, X509Certificate cert, X509Chain chain, SslPolicyErrors policyErrors) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SNINpHandle))) { if (!_validateCert) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Certificate validation not requested.", args0: ConnectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.INFO, "Connection Id {0}, Certificate validation not requested.", args0: ConnectionId); return true; } - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Proceeding to SSL certificate validation.", args0: ConnectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.INFO, "Connection Id {0}, Proceeding to SSL certificate validation.", args0: ConnectionId); return SNICommon.ValidateSslServerCertificate(_targetServer, cert, policyErrors); } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } /// @@ -431,7 +379,7 @@ private uint ReportErrorAndReleasePacket(SNIPacket packet, Exception sniExceptio { ReturnPacket(packet); } - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Packet returned, error occurred: {1}", args0: ConnectionId, args1: sniException?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.INFO, "Connection Id {0}, Packet returned, error occurred: {1}", args0: ConnectionId, args1: sniException?.Message); return SNICommon.ReportSNIError(SNIProviders.NP_PROV, SNICommon.InternalExceptionError, sniException); } @@ -441,7 +389,7 @@ private uint ReportErrorAndReleasePacket(SNIPacket packet, uint nativeError, uin { ReturnPacket(packet); } - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Packet returned, error occurred: {1}", args0: ConnectionId, args1: errorMessage); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINpHandle), EventType.INFO, "Connection Id {0}, Packet returned, error occurred: {1}", args0: ConnectionId, args1: errorMessage); return SNICommon.ReportSNIError(SNIProviders.NP_PROV, nativeError, sniError, errorMessage); } diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIPacket.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIPacket.cs index 973be0f61c..99725577bb 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIPacket.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIPacket.cs @@ -16,7 +16,6 @@ namespace Microsoft.Data.SqlClient.SNI /// internal sealed partial class SNIPacket { - private const string s_className = nameof(SNIPacket); private int _dataLength; // the length of the data in the data segment, advanced by Append-ing data, does not include smux header length private int _dataCapacity; // the total capacity requested, if the array is rented this may be less than the _data.Length, does not include smux header length private int _dataOffset; // the start point of the data in the data segment, advanced by Take-ing data @@ -115,7 +114,7 @@ public int TakeData(SNIPacket packet, int size) Debug.Assert(packet._dataLength + dataSize <= packet._dataCapacity, "added too much data to a packet"); packet._dataLength += dataSize; #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Packet Id {1} took data from Packet Id {2} dataSize {3}, _dataLength {4}", args0: _owner?.ConnectionId, args1: _id, args2: packet?._id, args3: dataSize, args4: packet._dataLength); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIPacket), EventType.INFO, "Connection Id {0}, Packet Id {1} took data from Packet Id {2} dataSize {3}, _dataLength {4}", args0: _owner?.ConnectionId, args1: _id, args2: packet?._id, args3: dataSize, args4: packet._dataLength); #endif return dataSize; } @@ -131,7 +130,7 @@ public void AppendData(byte[] data, int size) Buffer.BlockCopy(data, 0, _data, _headerLength + _dataLength, size); _dataLength += size; #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Packet Id {1} was appended with size {2}, _dataLength {3}", args0: _owner?.ConnectionId, args1: _id, args2: size, args3: _dataLength); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIPacket), EventType.INFO, "Connection Id {0}, Packet Id {1} was appended with size {2}, _dataLength {3}", args0: _owner?.ConnectionId, args1: _id, args2: size, args3: _dataLength); #endif } @@ -157,7 +156,7 @@ public int TakeData(byte[] buffer, int dataOffset, int size) Buffer.BlockCopy(_data, _headerLength + _dataOffset, buffer, dataOffset, size); _dataOffset += size; #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Packet Id {1} took data size {2}, _dataLength {3}, _dataOffset {4}", args0: _owner?.ConnectionId, args1: _id, args2: size, args3: _dataLength, args4: _dataOffset); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIPacket), EventType.INFO, "Connection Id {0}, Packet Id {1} took data size {2}, _dataLength {3}, _dataOffset {4}", args0: _owner?.ConnectionId, args1: _id, args2: size, args3: _dataLength, args4: _dataOffset); #endif return size; } @@ -177,7 +176,7 @@ public void SetHeaderActive() _dataLength += _headerLength; _headerLength = 0; #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Packet Id {1} _dataLength {2} header set to active.", args0: _owner?.ConnectionId, args1: _id, args2: _dataLength); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIPacket), EventType.INFO, "Connection Id {0}, Packet Id {1} _dataLength {2} header set to active.", args0: _owner?.ConnectionId, args1: _id, args2: _dataLength); #endif } @@ -201,7 +200,7 @@ public void Release() _dataCapacity = 0; } #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Packet Id {1} _headerLength {2} and _dataLength {3} released.", args0: _owner?.ConnectionId, args1: _id, args2: _headerLength, args3: _dataLength); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIPacket), EventType.INFO, "Connection Id {0}, Packet Id {1} _headerLength {2} and _dataLength {3} released.", args0: _owner?.ConnectionId, args1: _id, args2: _headerLength, args3: _dataLength); #endif _dataLength = 0; _dataOffset = 0; @@ -218,7 +217,7 @@ public void ReadFromStream(Stream stream) { _dataLength = stream.Read(_data, _headerLength, _dataCapacity); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Packet Id {1} _dataLength {2} read from stream.", args0: _owner?.ConnectionId, args1: _id, args2: _dataLength); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIPacket), EventType.INFO, "Connection Id {0}, Packet Id {1} _dataLength {2} read from stream.", args0: _owner?.ConnectionId, args1: _id, args2: _dataLength); #endif } @@ -248,7 +247,7 @@ private void ReadFromStreamAsyncContinuation(Task t, object state) { SNILoadHandle.SingletonInstance.LastError = new SNIError(SNIProviders.TCP_PROV, SNICommon.InternalExceptionError, e); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, Internal Exception occurred while reading data: {1}", args0: _owner?.ConnectionId, args1: e?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIPacket), EventType.ERR, "Connection Id {0}, Internal Exception occurred while reading data: {1}", args0: _owner?.ConnectionId, args1: e?.Message); #endif error = true; } @@ -256,13 +255,13 @@ private void ReadFromStreamAsyncContinuation(Task t, object state) { _dataLength = t.Result; #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Packet Id {1} _dataLength {2} read from stream.", args0: _owner?.ConnectionId, args1: _id, args2: _dataLength); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIPacket), EventType.INFO, "Connection Id {0}, Packet Id {1} _dataLength {2} read from stream.", args0: _owner?.ConnectionId, args1: _id, args2: _dataLength); #endif if (_dataLength == 0) { SNILoadHandle.SingletonInstance.LastError = new SNIError(SNIProviders.TCP_PROV, 0, SNICommon.ConnTerminatedError, Strings.SNI_ERROR_2); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, No data read from stream, connection was terminated.", args0: _owner?.ConnectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIPacket), EventType.ERR, "Connection Id {0}, No data read from stream, connection was terminated.", args0: _owner?.ConnectionId); #endif error = true; } @@ -279,7 +278,7 @@ public void WriteToStream(Stream stream) { stream.Write(_data, _headerLength, _dataLength); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Packet Id {1} _dataLength {2} written to stream.", args0: _owner?.ConnectionId, args1: _id, args2: _dataLength); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIPacket), EventType.INFO, "Connection Id {0}, Packet Id {1} _dataLength {2} written to stream.", args0: _owner?.ConnectionId, args1: _id, args2: _dataLength); #endif } @@ -296,14 +295,14 @@ public async void WriteToStreamAsync(Stream stream, SNIAsyncCallback callback, S { await stream.WriteAsync(_data, 0, _dataLength, CancellationToken.None).ConfigureAwait(false); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Packet Id {1} _dataLength {2} written to stream.", args0: _owner?.ConnectionId, args1: _id, args2: _dataLength); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIPacket), EventType.INFO, "Connection Id {0}, Packet Id {1} _dataLength {2} written to stream.", args0: _owner?.ConnectionId, args1: _id, args2: _dataLength); #endif } catch (Exception e) { SNILoadHandle.SingletonInstance.LastError = new SNIError(provider, SNICommon.InternalExceptionError, e); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, Internal Exception occurred while writing data: {1}", args0: _owner?.ConnectionId, args1: e?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNIPacket), EventType.ERR, "Connection Id {0}, Internal Exception occurred while writing data: {1}", args0: _owner?.ConnectionId, args1: e?.Message); #endif status = TdsEnums.SNI_ERROR; } diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNITcpHandle.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNITcpHandle.cs index 0ee3e91291..d3e3a7548f 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNITcpHandle.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNITcpHandle.cs @@ -22,7 +22,6 @@ namespace Microsoft.Data.SqlClient.SNI /// internal sealed class SNITCPHandle : SNIPhysicalHandle { - private static string s_className = nameof(SNITCPHandle); private readonly string _targetServer; private readonly object _sendSync; private readonly Socket _socket; @@ -68,7 +67,7 @@ public override void Dispose() //Release any references held by _stream. _stream = null; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, All streams disposed.", args0: _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connection Id {0}, All streams disposed.", args0: _connectionId); } } @@ -121,10 +120,10 @@ public override int ProtocolVersion /// Used for DNS Cache public SNITCPHandle(string serverName, int port, long timerExpire, bool parallel, SqlConnectionIPAddressPreference ipPreference, string cachedFQDN, ref SQLDNSInfo pendingDNSInfo) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Setting server name = {1}", args0: _connectionId, args1: serverName); - try + using (TrySNIEventScope.Create(nameof(SNITCPHandle))) { + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connection Id {0}, Setting server name = {1}", args0: _connectionId, args1: serverName); + _targetServer = serverName; _sendSync = new object(); @@ -146,7 +145,7 @@ public SNITCPHandle(string serverName, int port, long timerExpire, bool parallel bool reportError = true; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Connecting to serverName {1} and port {2}", args0: _connectionId, args1: serverName, args2: port); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connection Id {0}, Connecting to serverName {1} and port {2}", args0: _connectionId, args1: serverName, args2: port); // We will always first try to connect with serverName as before and let the DNS server to resolve the serverName. // If the DSN resolution fails, we will try with IPs in the DNS cache if existed. We try with cached IPs based on IPAddressPreference. // The exceptions will be throw to upper level and be handled as before. @@ -168,13 +167,13 @@ public SNITCPHandle(string serverName, int port, long timerExpire, bool parallel { if (hasCachedDNSInfo == false) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, Cached DNS Info not found, exception occurred thrown: {1}", args0: _connectionId, args1: ex?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0}, Cached DNS Info not found, exception occurred thrown: {1}", args0: _connectionId, args1: ex?.Message); throw; } else { int portRetry = string.IsNullOrEmpty(cachedDNSInfo.Port) ? port : int.Parse(cachedDNSInfo.Port); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Retrying with cached DNS IP Address {1} and port {2}", args0: _connectionId, args1: cachedDNSInfo.AddrIPv4, args2: cachedDNSInfo.Port); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connection Id {0}, Retrying with cached DNS IP Address {1} and port {2}", args0: _connectionId, args1: cachedDNSInfo.AddrIPv4, args2: cachedDNSInfo.Port); string firstCachedIP; string secondCachedIP; @@ -206,7 +205,7 @@ public SNITCPHandle(string serverName, int port, long timerExpire, bool parallel if (exRetry is SocketException || exRetry is ArgumentNullException || exRetry is ArgumentException || exRetry is ArgumentOutOfRangeException || exRetry is AggregateException) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Retrying exception {1}", args0: _connectionId, args1: exRetry?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connection Id {0}, Retrying exception {1}", args0: _connectionId, args1: exRetry?.Message); if (parallel) { _socket = TryConnectParallel(secondCachedIP, portRetry, ts, isInfiniteTimeOut, ref reportError, cachedFQDN, ref pendingDNSInfo); @@ -218,7 +217,7 @@ public SNITCPHandle(string serverName, int port, long timerExpire, bool parallel } else { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, Retry failed, exception occurred: {1}", args0: _connectionId, args1: exRetry?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0}, Retry failed, exception occurred: {1}", args0: _connectionId, args1: exRetry?.Message); throw; } } @@ -240,10 +239,10 @@ public SNITCPHandle(string serverName, int port, long timerExpire, bool parallel if (reportError) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0} could not be opened, exception occurred: {1}", args0: _connectionId, args1: Strings.SNI_ERROR_40); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0} could not be opened, exception occurred: {1}", args0: _connectionId, args1: Strings.SNI_ERROR_40); ReportTcpSNIError(0, SNICommon.ConnOpenFailedError, Strings.SNI_ERROR_40); } - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0} Socket could not be opened.", args0: _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0} Socket could not be opened.", args0: _connectionId); return; } @@ -255,24 +254,20 @@ public SNITCPHandle(string serverName, int port, long timerExpire, bool parallel } catch (SocketException se) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0} Socket exception occurred: Error Code {1}, Message {2}", args0: _connectionId, args1: se?.SocketErrorCode, args2: se?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0} Socket exception occurred: Error Code {1}, Message {2}", args0: _connectionId, args1: se?.SocketErrorCode, args2: se?.Message); ReportTcpSNIError(se); return; } catch (Exception e) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0} Exception occurred: {1}", args0: _connectionId, args1: e?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0} Exception occurred: {1}", args0: _connectionId, args1: e?.Message); ReportTcpSNIError(e); return; } _stream = _tcpStream; _status = TdsEnums.SNI_SUCCESS; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0} Socket opened successfully, TCP stream ready.", args0: _connectionId); - } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connection Id {0} Socket opened successfully, TCP stream ready.", args0: _connectionId); } } @@ -292,7 +287,7 @@ private Socket TryConnectParallel(string hostName, int port, TimeSpan ts, bool i { // Fail if above 64 to match legacy behavior callerReportError = false; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0} serverAddresses.Length {1} Exception: {2}", args0: _connectionId, args1: serverAddresses.Length, args2: Strings.SNI_ERROR_47); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0} serverAddresses.Length {1} Exception: {2}", args0: _connectionId, args1: serverAddresses.Length, args2: Strings.SNI_ERROR_47); ReportTcpSNIError(0, SNICommon.MultiSubnetFailoverWithMoreThan64IPs, Strings.SNI_ERROR_47); return availableSocket; } @@ -322,7 +317,7 @@ private Socket TryConnectParallel(string hostName, int port, TimeSpan ts, bool i if (!(isInfiniteTimeOut ? connectTask.Wait(-1) : connectTask.Wait(ts))) { callerReportError = false; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0} Connection timed out, Exception: {1}", args0: _connectionId, args1: Strings.SNI_ERROR_40); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0} Connection timed out, Exception: {1}", args0: _connectionId, args1: Strings.SNI_ERROR_40); ReportTcpSNIError(0, SNICommon.ConnOpenFailedError, Strings.SNI_ERROR_40); return availableSocket; } @@ -337,7 +332,7 @@ private Socket TryConnectParallel(string hostName, int port, TimeSpan ts, bool i // Only write to the DNS cache when we receive IsSupported flag as true in the Feature Ext Ack from server. private static Socket Connect(string serverName, int port, TimeSpan timeout, bool isInfiniteTimeout, SqlConnectionIPAddressPreference ipPreference, string cachedFQDN, ref SQLDNSInfo pendingDNSInfo) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "IP preference : {0}", Enum.GetName(typeof(SqlConnectionIPAddressPreference), ipPreference)); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "IP preference : {0}", Enum.GetName(typeof(SqlConnectionIPAddressPreference), ipPreference)); IPAddress[] ipAddresses = Dns.GetHostAddresses(serverName); @@ -399,7 +394,7 @@ private static Socket Connect(string serverName, int port, TimeSpan timeout, boo // enable keep-alive on socket SetKeepAliveValues(ref sockets[n]); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connecting to IP address {0} and port {1} using {2} address family.", + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connecting to IP address {0} and port {1} using {2} address family.", args0: ipAddress, args1: port, args2: ipAddress.AddressFamily); @@ -430,8 +425,8 @@ private static Socket Connect(string serverName, int port, TimeSpan timeout, boo } catch (Exception e) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "THIS EXCEPTION IS BEING SWALLOWED: {0}", args0: e?.Message); - SqlClientEventSource.Log.TryAdvancedTraceEvent($"{s_className}.{System.Reflection.MethodBase.GetCurrentMethod().Name}{EventType.ERR}THIS EXCEPTION IS BEING SWALLOWED: {e}"); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "THIS EXCEPTION IS BEING SWALLOWED: {0}", args0: e?.Message); + SqlClientEventSource.Log.TryAdvancedTraceEvent($"{nameof(SNITCPHandle)}.{System.Reflection.MethodBase.GetCurrentMethod().Name}{EventType.ERR}THIS EXCEPTION IS BEING SWALLOWED: {e}"); } } @@ -470,7 +465,7 @@ void Cancel() } catch (Exception e) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "THIS EXCEPTION IS BEING SWALLOWED: {0}", args0: e?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "THIS EXCEPTION IS BEING SWALLOWED: {0}", args0: e?.Message); } } } @@ -592,17 +587,17 @@ public override uint EnableSsl(uint options) } catch (AuthenticationException aue) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, Authentication exception occurred: {1}", args0: _connectionId, args1: aue?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0}, Authentication exception occurred: {1}", args0: _connectionId, args1: aue?.Message); return ReportTcpSNIError(aue, SNIError.CertificateValidationErrorCode); } catch (InvalidOperationException ioe) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, Invalid Operation Exception occurred: {1}", args0: _connectionId, args1: ioe?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0}, Invalid Operation Exception occurred: {1}", args0: _connectionId, args1: ioe?.Message); return ReportTcpSNIError(ioe); } _stream = _sslStream; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, SSL enabled successfully.", args0: _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connection Id {0}, SSL enabled successfully.", args0: _connectionId); return TdsEnums.SNI_SUCCESS; } @@ -616,7 +611,7 @@ public override void DisableSsl() _sslOverTdsStream.Dispose(); _sslOverTdsStream = null; _stream = _tcpStream; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, SSL Disabled. Communication will continue on TCP Stream.", args0: _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connection Id {0}, SSL Disabled. Communication will continue on TCP Stream.", args0: _connectionId); } /// @@ -631,11 +626,11 @@ private bool ValidateServerCertificate(object sender, X509Certificate cert, X509 { if (!_validateCert) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Certificate will not be validated.", args0: _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connection Id {0}, Certificate will not be validated.", args0: _connectionId); return true; } - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Certificate will be validated for Target Server name", args0: _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connection Id {0}, Certificate will be validated for Target Server name", args0: _connectionId); return SNICommon.ValidateSslServerCertificate(_targetServer, cert, policyErrors); } @@ -680,22 +675,22 @@ public override uint Send(SNIPacket packet) try { packet.WriteToStream(_stream); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Data sent to stream synchronously", args0: _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connection Id {0}, Data sent to stream synchronously", args0: _connectionId); return TdsEnums.SNI_SUCCESS; } catch (ObjectDisposedException ode) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, ObjectDisposedException occurred: {1}", args0: _connectionId, args1: ode?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0}, ObjectDisposedException occurred: {1}", args0: _connectionId, args1: ode?.Message); return ReportTcpSNIError(ode); } catch (SocketException se) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, SocketException occurred: {1}", args0: _connectionId, args1: se?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0}, SocketException occurred: {1}", args0: _connectionId, args1: se?.Message); return ReportTcpSNIError(se); } catch (IOException ioe) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, IOException occurred: {1}", args0: _connectionId, args1: ioe?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0}, IOException occurred: {1}", args0: _connectionId, args1: ioe?.Message); return ReportTcpSNIError(ioe); } } @@ -735,7 +730,7 @@ public override uint Receive(out SNIPacket packet, int timeoutInMilliseconds) else { // otherwise it is timeout for 0 or less than -1 - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, Error 258, Timeout error occurred.", args0: _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0}, Error 258, Timeout error occurred.", args0: _connectionId); ReportTcpSNIError(0, SNICommon.ConnTimeoutError, Strings.SNI_ERROR_11); return TdsEnums.SNI_WAIT_TIMEOUT; } @@ -748,25 +743,25 @@ public override uint Receive(out SNIPacket packet, int timeoutInMilliseconds) errorPacket = packet; packet = null; var e = new Win32Exception(); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, Win32 exception occurred: {1}", args0: _connectionId, args1: e?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0}, Win32 exception occurred: {1}", args0: _connectionId, args1: e?.Message); return ReportErrorAndReleasePacket(errorPacket, (uint)e.NativeErrorCode, 0, e.Message); } - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Data read from stream synchronously", args0: _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connection Id {0}, Data read from stream synchronously", args0: _connectionId); return TdsEnums.SNI_SUCCESS; } catch (ObjectDisposedException ode) { errorPacket = packet; packet = null; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, ObjectDisposedException occurred: {1}", args0: _connectionId, args1: ode?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0}, ObjectDisposedException occurred: {1}", args0: _connectionId, args1: ode?.Message); return ReportErrorAndReleasePacket(errorPacket, ode); } catch (SocketException se) { errorPacket = packet; packet = null; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, Socket exception occurred: {1}", args0: _connectionId, args1: se?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0}, Socket exception occurred: {1}", args0: _connectionId, args1: se?.Message); return ReportErrorAndReleasePacket(errorPacket, se); } catch (IOException ioe) @@ -776,11 +771,11 @@ public override uint Receive(out SNIPacket packet, int timeoutInMilliseconds) uint errorCode = ReportErrorAndReleasePacket(errorPacket, ioe); if (ioe.InnerException is SocketException socketException && socketException.SocketErrorCode == SocketError.TimedOut) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, IO exception occurred with Wait Timeout (error 258): {1}", args0: _connectionId, args1: ioe?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0}, IO exception occurred with Wait Timeout (error 258): {1}", args0: _connectionId, args1: ioe?.Message); errorCode = TdsEnums.SNI_WAIT_TIMEOUT; } - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, IO exception occurred: {1}", args0: _connectionId, args1: ioe?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.ERR, "Connection Id {0}, IO exception occurred: {1}", args0: _connectionId, args1: ioe?.Message); return errorCode; } finally @@ -809,18 +804,13 @@ public override void SetAsyncCallbacks(SNIAsyncCallback receiveCallback, SNIAsyn /// SNI error code public override uint SendAsync(SNIPacket packet, SNIAsyncCallback callback = null) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SNITCPHandle))) { SNIAsyncCallback cb = callback ?? _sendCallback; packet.WriteToStreamAsync(_stream, cb, SNIProviders.TCP_PROV); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Data sent to stream asynchronously", args0: _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connection Id {0}, Data sent to stream asynchronously", args0: _connectionId); return TdsEnums.SNI_SUCCESS_IO_PENDING; } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } /// @@ -836,7 +826,7 @@ public override uint ReceiveAsync(ref SNIPacket packet) try { packet.ReadFromStreamAsync(_stream, _receiveCallback); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Data received from stream asynchronously", args0: _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connection Id {0}, Data received from stream asynchronously", args0: _connectionId); return TdsEnums.SNI_SUCCESS_IO_PENDING; } catch (Exception e) when (e is ObjectDisposedException || e is SocketException || e is IOException) @@ -867,18 +857,18 @@ public override uint CheckConnection() // return true we can safely determine that the connection is no longer active. if (!_socket.Connected || (_socket.Poll(100, SelectMode.SelectRead) && _socket.Available == 0)) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Socket not usable.", args0: _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connection Id {0}, Socket not usable.", args0: _connectionId); return TdsEnums.SNI_ERROR; } } catch (SocketException se) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Socket Exception occurred: {1}", args0: _connectionId, args1: se?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connection Id {0}, Socket Exception occurred: {1}", args0: _connectionId, args1: se?.Message); return ReportTcpSNIError(se); } catch (ObjectDisposedException ode) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, ObjectDisposedException occurred: {1}", args0: _connectionId, args1: ode?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNITCPHandle), EventType.INFO, "Connection Id {0}, ObjectDisposedException occurred: {1}", args0: _connectionId, args1: ode?.Message); return ReportTcpSNIError(ode); } diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SSRP.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SSRP.cs index e49fc4c89a..0147b29f17 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SSRP.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SSRP.cs @@ -13,7 +13,6 @@ namespace Microsoft.Data.SqlClient.SNI { internal class SSRP { - private const string s_className = nameof(SSRP); private const char SemicolonSeparator = ';'; private const int SqlServerBrowserPort = 1434; @@ -27,8 +26,7 @@ internal static int GetPortByInstanceName(string browserHostName, string instanc { Debug.Assert(!string.IsNullOrWhiteSpace(browserHostName), "browserHostName should not be null, empty, or whitespace"); Debug.Assert(!string.IsNullOrWhiteSpace(instanceName), "instanceName should not be null, empty, or whitespace"); - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SSRP))) { byte[] instanceInfoRequest = CreateInstanceInfoRequest(instanceName); byte[] responsePacket = null; @@ -38,7 +36,7 @@ internal static int GetPortByInstanceName(string browserHostName, string instanc } catch (SocketException se) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "SocketException Message = {0}", args0: se?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SSRP), EventType.ERR, "SocketException Message = {0}", args0: se?.Message); throw new Exception(SQLMessage.SqlServerBrowserNotAccessible(), se); } @@ -60,10 +58,6 @@ internal static int GetPortByInstanceName(string browserHostName, string instanc return ushort.Parse(elements[tcpIndex + 1]); } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } /// @@ -74,8 +68,7 @@ internal static int GetPortByInstanceName(string browserHostName, string instanc private static byte[] CreateInstanceInfoRequest(string instanceName) { Debug.Assert(!string.IsNullOrWhiteSpace(instanceName), "instanceName should not be null, empty, or whitespace"); - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SSRP))) { const byte ClntUcastInst = 0x04; instanceName += char.MinValue; @@ -87,10 +80,6 @@ private static byte[] CreateInstanceInfoRequest(string instanceName) return requestPacket; } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } /// @@ -151,8 +140,7 @@ private static byte[] CreateDacPortInfoRequest(string instanceName) /// response packet from UDP server private static byte[] SendUDPRequest(string browserHostname, int port, byte[] requestPacket) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SSRP))) { Debug.Assert(!string.IsNullOrWhiteSpace(browserHostname), "browserhostname should not be null, empty, or whitespace"); Debug.Assert(port >= 0 && port <= 65535, "Invalid port"); @@ -170,20 +158,16 @@ private static byte[] SendUDPRequest(string browserHostname, int port, byte[] re Task sendTask = client.SendAsync(requestPacket, requestPacket.Length, browserHostname, port); Task receiveTask = null; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Waiting for UDP Client to fetch Port info."); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SSRP), EventType.INFO, "Waiting for UDP Client to fetch Port info."); if (sendTask.Wait(sendTimeOutMs) && (receiveTask = client.ReceiveAsync()).Wait(receiveTimeOutMs)) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Received Port info from UDP Client."); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SSRP), EventType.INFO, "Received Port info from UDP Client."); responsePacket = receiveTask.Result.Buffer; } } return responsePacket; } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } } } diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SslOverTdsStream.NetCoreApp.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SslOverTdsStream.NetCoreApp.cs index 5f676ec457..be8d1a0160 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SslOverTdsStream.NetCoreApp.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SslOverTdsStream.NetCoreApp.cs @@ -25,8 +25,7 @@ public override Task WriteAsync(byte[] buffer, int offset, int count, Cancellati public override int Read(Span buffer) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SslOverTdsStream))) { if (!_encapsulate) { @@ -72,16 +71,11 @@ public override int Read(Span buffer) return packetBytesRead; } } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } public override async ValueTask ReadAsync(Memory buffer, CancellationToken cancellationToken = default) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SslOverTdsStream))) { if (!_encapsulate) { @@ -176,16 +170,11 @@ public override async ValueTask ReadAsync(Memory buffer, Cancellation return packetBytesRead; } } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } public override void Write(ReadOnlySpan buffer) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SslOverTdsStream))) { // During the SSL negotiation phase, SSL is tunnelled over TDS packet type 0x12. After // negotiation, the underlying socket only sees SSL frames. @@ -234,16 +223,11 @@ public override void Write(ReadOnlySpan buffer) } } } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } public override async ValueTask WriteAsync(ReadOnlyMemory buffer, CancellationToken cancellationToken = default) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SslOverTdsStream))) { if (!_encapsulate) { @@ -306,10 +290,6 @@ public override async ValueTask WriteAsync(ReadOnlyMemory buffer, Cancella } } } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } } } diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SslOverTdsStream.NetStandard.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SslOverTdsStream.NetStandard.cs index ec7bdac54b..60bb597974 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SslOverTdsStream.NetStandard.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SslOverTdsStream.NetStandard.cs @@ -14,8 +14,7 @@ internal sealed partial class SslOverTdsStream : Stream { public override int Read(byte[] buffer, int offset, int count) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SslOverTdsStream))) { if (!_encapsulate) { @@ -66,16 +65,11 @@ public override int Read(byte[] buffer, int offset, int count) return packetBytesRead; } } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } public override async Task ReadAsync(byte[] buffer, int offset, int count, CancellationToken cancellationToken) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SslOverTdsStream))) { if (!_encapsulate) { @@ -126,16 +120,11 @@ public override async Task ReadAsync(byte[] buffer, int offset, int count, return packetBytesRead; } } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } public override void Write(byte[] buffer, int offset, int count) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SslOverTdsStream))) { // During the SSL negotiation phase, SSL is tunnelled over TDS packet type 0x12. After // negotiation, the underlying socket only sees SSL frames. @@ -179,16 +168,11 @@ public override void Write(byte[] buffer, int offset, int count) ArrayPool.Shared.Return(packetBuffer, clearArray: true); } } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } public override async Task WriteAsync(byte[] buffer, int offset, int count, CancellationToken cancellationToken) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); - try + using (TrySNIEventScope.Create(nameof(SslOverTdsStream))) { if (!_encapsulate) { @@ -234,10 +218,6 @@ public override async Task WriteAsync(byte[] buffer, int offset, int count, Canc ArrayPool.Shared.Return(packetBuffer, clearArray: true); } } - finally - { - SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); - } } } } diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SslOverTdsStream.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SslOverTdsStream.cs index 3696b1323f..e95c5a6cf9 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SslOverTdsStream.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SslOverTdsStream.cs @@ -15,7 +15,6 @@ namespace Microsoft.Data.SqlClient.SNI /// internal sealed partial class SslOverTdsStream : Stream { - private const string s_className = nameof(SslOverTdsStream); private readonly Stream _stream; private Guid _connectionId; @@ -49,7 +48,7 @@ public SslOverTdsStream(Stream stream, Guid connectionId = default) public void FinishHandshake() { _encapsulate = false; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Switched from encapsulation to passthrough mode", args0: _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SslOverTdsStream), EventType.INFO, "Connection Id {0}, Switched from encapsulation to passthrough mode", args0: _connectionId); } /// @@ -68,7 +67,7 @@ public override void Flush() if (!(_stream is PipeStream)) { _stream.Flush(); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Flushed stream", args0: _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SslOverTdsStream), EventType.INFO, "Connection Id {0}, Flushed stream", args0: _connectionId); } }