From 45942182fe8a71ee2acbca6d42f0a6e8c9e7f559 Mon Sep 17 00:00:00 2001 From: Cheena Malhotra Date: Thu, 25 Feb 2021 09:52:06 -0800 Subject: [PATCH] [.NET Core] Event Source traces revision - Part 3 (#897) --- .../Data/SqlClient/SNI/LocalDB.Windows.cs | 37 +-- .../Microsoft/Data/SqlClient/SNI/SNICommon.cs | 25 +- .../Data/SqlClient/SNI/SNILoadHandle.cs | 1 - .../Data/SqlClient/SNI/SNIMarsConnection.cs | 68 +++-- .../Data/SqlClient/SNI/SNIMarsHandle.cs | 92 ++++-- .../Data/SqlClient/SNI/SNINpHandle.cs | 67 ++-- .../Microsoft/Data/SqlClient/SNI/SNIPacket.cs | 54 +++- .../Data/SqlClient/SNI/SNIPhysicalHandle.cs | 16 +- .../Microsoft/Data/SqlClient/SNI/SNIProxy.cs | 18 +- .../Data/SqlClient/SNI/SNITcpHandle.cs | 284 ++++++++++------- .../src/Microsoft/Data/SqlClient/SNI/SSRP.cs | 50 +-- .../SNI/SslOverTdsStream.NetCoreApp.cs | 101 ++++--- .../SNI/SslOverTdsStream.NetStandard.cs | 77 +++-- .../Data/SqlClient/SNI/SslOverTdsStream.cs | 15 +- .../Microsoft/Data/SqlClient/SqlCommand.cs | 15 +- .../src/Microsoft/Data/SqlClient/TdsParser.cs | 37 +-- .../Data/SqlClient/TdsParserStateObject.cs | 58 ++-- .../SqlClient/TdsParserStateObjectManaged.cs | 45 ++- .../Microsoft/Data/SqlClient/SqlCommand.cs | 7 +- .../Data/SqlClient/TdsParserStateObject.cs | 12 +- .../Data/SqlClient/SqlClientEventSource.cs | 286 +++++++++--------- 21 files changed, 804 insertions(+), 561 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 3df18d1148..6e1f0e19e8 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,6 +13,7 @@ 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\\"; @@ -26,7 +27,7 @@ internal sealed class LocalDB private IntPtr _startInstanceHandle = IntPtr.Zero; // Local Db api doc https://msdn.microsoft.com/en-us/library/hh217143.aspx - // HRESULT LocalDBStartInstance( [Input ] PCWSTR pInstanceName, [Input ] DWORD dwFlags,[Output] LPWSTR wszSqlConnection,[Input/Output] LPDWORD lpcchSqlConnection); + // HRESULT LocalDBStartInstance( [Input ] PCWSTR pInstanceName, [Input ] DWORD dwFlags,[Output] LPWSTR wszSqlConnection,[Input/Output] LPDWORD lpcchSqlConnection); [UnmanagedFunctionPointer(CallingConvention.Cdecl)] internal delegate int LocalDBStartInstance( [In] [MarshalAs(UnmanagedType.LPWStr)] string localDBInstanceName, @@ -64,26 +65,16 @@ internal static uint MapLocalDBErrorStateToCode(LocalDBErrorState errorState) switch (errorState) { case LocalDBErrorState.NO_INSTALLATION: - SqlClientEventSource.Log.TrySNITraceEvent(" LocalDB is not installed. Error State ={0}", errorState); return SNICommon.LocalDBNoInstallation; - case LocalDBErrorState.INVALID_CONFIG: - SqlClientEventSource.Log.TrySNITraceEvent(" Invalid configuration. Error State ={0}", errorState); return SNICommon.LocalDBInvalidConfig; - case LocalDBErrorState.NO_SQLUSERINSTANCEDLL_PATH: - SqlClientEventSource.Log.TrySNITraceEvent(" No SQL user instance path. Error State ={0}", errorState); return SNICommon.LocalDBNoSqlUserInstanceDllPath; - case LocalDBErrorState.INVALID_SQLUSERINSTANCEDLL_PATH: - SqlClientEventSource.Log.TrySNITraceEvent(" Invalid SQL user instance path. Error State ={0}", errorState); return SNICommon.LocalDBInvalidSqlUserInstanceDllPath; - case LocalDBErrorState.NONE: return 0; - default: - SqlClientEventSource.Log.TrySNITraceEvent(" Invalid configuration. Error State ={0}", errorState); return SNICommon.LocalDBInvalidConfig; } } @@ -112,7 +103,7 @@ internal static string MapLocalDBErrorStateToErrorMessage(LocalDBErrorState erro /// private bool LoadUserInstanceDll() { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { // Check in a non thread-safe way if the handle is already set for performance. @@ -137,7 +128,7 @@ private bool LoadUserInstanceDll() if (dllPath == null) { SNILoadHandle.SingletonInstance.LastError = new SNIError(SNIProviders.INVALID_PROV, 0, MapLocalDBErrorStateToCode(registryQueryErrorState), MapLocalDBErrorStateToErrorMessage(registryQueryErrorState)); - SqlClientEventSource.Log.TrySNITraceEvent("User instance DLL path is null."); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "User instance DLL path is null."); return false; } @@ -145,7 +136,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(" User instance DLL path is invalid. DLL path ={0}", dllPath); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "User instance DLL path is invalid. DLL path = {0}", dllPath); return false; } @@ -155,7 +146,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(" Library Handle is invalid. Could not load the dll."); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Library Handle is invalid. Could not load the dll."); libraryHandle.Dispose(); return false; } @@ -166,7 +157,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(" Was not able to load the PROC from DLL. Bad Runtime."); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Was not able to load the PROC from DLL. Bad Runtime."); libraryHandle.Dispose(); return false; } @@ -183,7 +174,7 @@ private bool LoadUserInstanceDll() } _sqlUserInstanceLibraryHandle = libraryHandle; - SqlClientEventSource.Log.TrySNITraceEvent(" User Instance DLL was loaded successfully."); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "User Instance DLL was loaded successfully."); return true; } } @@ -200,7 +191,7 @@ private bool LoadUserInstanceDll() /// private string GetUserInstanceDllPath(out LocalDBErrorState errorState) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(" GetUserInstanceDllPath"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { string dllPath = null; @@ -209,7 +200,7 @@ private string GetUserInstanceDllPath(out LocalDBErrorState errorState) if (key == null) { errorState = LocalDBErrorState.NO_INSTALLATION; - SqlClientEventSource.Log.TrySNITraceEvent(" not installed. Error state ={0}.", errorState); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "No installation found."); return null; } @@ -224,7 +215,7 @@ private string GetUserInstanceDllPath(out LocalDBErrorState errorState) if (!Version.TryParse(subKey, out currentKeyVersion)) { errorState = LocalDBErrorState.INVALID_CONFIG; - SqlClientEventSource.Log.TrySNITraceEvent(" Invalid Configuration. state ={0}.", errorState); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Invalid Configuration."); return null; } @@ -238,7 +229,7 @@ private string GetUserInstanceDllPath(out LocalDBErrorState errorState) if (latestVersion.Equals(zeroVersion)) { errorState = LocalDBErrorState.INVALID_CONFIG; - SqlClientEventSource.Log.TrySNITraceEvent(" Invalid Configuration. state ={0}.", errorState); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Invalid Configuration."); return null; } @@ -251,7 +242,7 @@ private string GetUserInstanceDllPath(out LocalDBErrorState errorState) if (instanceAPIPathRegistryObject == null) { errorState = LocalDBErrorState.NO_SQLUSERINSTANCEDLL_PATH; - SqlClientEventSource.Log.TrySNITraceEvent(" No SQL user instance DLL. Instance API Path Registry Object Error. state ={0}.", errorState); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "No SQL user instance DLL. Instance API Path Registry Object Error."); return null; } @@ -260,7 +251,7 @@ private string GetUserInstanceDllPath(out LocalDBErrorState errorState) if (valueKind != RegistryValueKind.String) { errorState = LocalDBErrorState.INVALID_SQLUSERINSTANCEDLL_PATH; - SqlClientEventSource.Log.TrySNITraceEvent(" No SQL user instance DLL. state ={0}. Registry value kind error.", errorState); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Invalid SQL user instance DLL path. Registry value kind mismatch."); return null; } 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 475660aa2b..8ae171fc68 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 @@ -101,6 +101,8 @@ internal enum SNISMUXFlags 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; @@ -126,33 +128,33 @@ internal class SNICommon internal const int LocalDBBadRuntime = 57; /// - /// Validate server certificate callback for SSL + /// We only validate Server name in Certificate to match with "targetServerName". + /// Certificate validation and chain trust validations are done by SSLStream class [System.Net.Security.SecureChannel.VerifyRemoteCertificate method] + /// This method is called as a result of callback for SSL Stream Certificate validation. /// /// Server that client is expecting to connect to - /// Sender object /// X.509 certificate - /// X.509 chain /// Policy errors /// True if certificate is valid - internal static bool ValidateSslServerCertificate(string targetServerName, object sender, X509Certificate cert, X509Chain chain, SslPolicyErrors policyErrors) + internal static bool ValidateSslServerCertificate(string targetServerName, X509Certificate cert, SslPolicyErrors policyErrors) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SNICommon.ValidateSslServerCertificate | SNI | SCOPE | INFO | Entering Scope {0} "); try { if (policyErrors == SslPolicyErrors.None) { - SqlClientEventSource.Log.TrySNITraceEvent(" SSL Server certificate validated."); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "targetServerName {0}, SSL Server certificate not validated as PolicyErrors set to None.", args0: targetServerName); return true; } if ((policyErrors & SslPolicyErrors.RemoteCertificateNameMismatch) != 0) { - SqlClientEventSource.Log.TrySNITraceEvent(" SSL Remote certificate name mismatched."); string certServerName = cert.Subject.Substring(cert.Subject.IndexOf('=') + 1); // 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); return false; } else if (targetServerName.Length == certServerName.Length) @@ -160,6 +162,7 @@ internal static bool ValidateSslServerCertificate(string targetServerName, objec // 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); return false; } } @@ -167,6 +170,7 @@ internal static bool ValidateSslServerCertificate(string targetServerName, objec { 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); return false; } @@ -176,6 +180,7 @@ internal static bool ValidateSslServerCertificate(string targetServerName, objec // (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); return false; } } @@ -183,8 +188,10 @@ internal static bool ValidateSslServerCertificate(string targetServerName, objec 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); return false; } + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "targetServerName {0}, Client certificate validated successfully.", args0: targetServerName); return true; } finally @@ -203,7 +210,7 @@ internal static bool ValidateSslServerCertificate(string targetServerName, objec /// internal static uint ReportSNIError(SNIProviders provider, uint nativeError, uint sniError, string errorMessage) { - SqlClientEventSource.Log.TrySNITraceEvent(" Provider ={0}, native Error ={1}, SNI Error ={2}, Error Message ={3}", provider, nativeError, sniError, 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); return ReportSNIError(new SNIError(provider, nativeError, sniError, errorMessage)); } @@ -216,7 +223,7 @@ internal static uint ReportSNIError(SNIProviders provider, uint nativeError, uin /// internal static uint ReportSNIError(SNIProviders provider, uint sniError, Exception sniException) { - SqlClientEventSource.Log.TrySNITraceEvent(" Provider ={0}, SNI Error ={1}, Exception ={2}", provider, sniError, sniException.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Provider = {0}, SNI Error = {1}, Exception = {2}", args0: provider, args1: sniError, args2: sniException?.Message); return ReportSNIError(new SNIError(provider, sniError, sniException)); } diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNILoadHandle.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNILoadHandle.cs index 6e885462e5..1fa6c58a3f 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNILoadHandle.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNILoadHandle.cs @@ -30,7 +30,6 @@ public SNIError LastError set { - SqlClientEventSource.Log.TrySNITraceEvent(" Last Error Value = {0}", value); _lastError.Value = value; } } diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIMarsConnection.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIMarsConnection.cs index 19a4f8ea2b..395cfed4be 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIMarsConnection.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIMarsConnection.cs @@ -14,6 +14,8 @@ namespace Microsoft.Data.SqlClient.SNI /// internal class SNIMarsConnection { + private const string s_className = nameof(SNIMarsConnection); + private readonly Guid _connectionId = Guid.NewGuid(); private readonly Dictionary _sessions = new Dictionary(); private readonly byte[] _headerBytes = new byte[SNISMUXHeader.HEADER_LENGTH]; @@ -44,6 +46,7 @@ public Guid ConnectionId public SNIMarsConnection(SNIHandle lowerHandle) { _lowerHandle = lowerHandle; + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Created MARS Session Id {0}", args0: ConnectionId); _lowerHandle.SetAsyncCallbacks(HandleReceiveComplete, HandleSendComplete); } @@ -54,6 +57,7 @@ public SNIMarsHandle CreateMarsSession(object callbackObject, bool async) ushort sessionId = _nextSessionId++; SNIMarsHandle handle = new SNIMarsHandle(this, sessionId, callbackObject, async); _sessions.Add(sessionId, handle); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, SNI MARS Handle Id {1}, created new MARS Session {2}", args0: ConnectionId, args1: handle?.ConnectionId, args2: sessionId); return handle; } } @@ -64,17 +68,17 @@ public SNIMarsHandle CreateMarsSession(object callbackObject, bool async) /// public uint StartReceive() { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(" StartReceive"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { SNIPacket packet = null; if (ReceiveAsync(ref packet) == TdsEnums.SNI_SUCCESS_IO_PENDING) { - SqlClientEventSource.Log.TrySNITraceEvent(" Success IO pending."); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, Success IO pending.", args0: ConnectionId); return TdsEnums.SNI_SUCCESS_IO_PENDING; } - SqlClientEventSource.Log.TrySNITraceEvent(" Connection not useable."); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "MARS Session Id {0}, Connection not usable.", args0: ConnectionId); return SNICommon.ReportSNIError(SNIProviders.SMUX_PROV, 0, SNICommon.ConnNotUsableError, Strings.SNI_ERROR_19); } finally @@ -90,7 +94,7 @@ public uint StartReceive() /// SNI error code public uint Send(SNIPacket packet) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(" Send"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { lock (this) @@ -112,7 +116,7 @@ public uint Send(SNIPacket packet) /// SNI error code public uint SendAsync(SNIPacket packet, SNIAsyncCallback callback) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(" SendAsync"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { lock (this) @@ -133,18 +137,25 @@ public uint SendAsync(SNIPacket packet, SNIAsyncCallback callback) /// SNI error code public uint ReceiveAsync(ref SNIPacket packet) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(" SendAsync"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { if (packet != null) { ReturnPacket(packet); +#if DEBUG + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, Packet {1} returned", args0: ConnectionId, args1: packet?._id); +#endif packet = null; } lock (this) { - return _lowerHandle.ReceiveAsync(ref packet); + var response = _lowerHandle.ReceiveAsync(ref packet); +#if DEBUG + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, Received new packet {1}", args0: ConnectionId, args1: packet?._id); +#endif + return response; } } finally @@ -159,7 +170,7 @@ public uint ReceiveAsync(ref SNIPacket packet) /// SNI error status public uint CheckConnection() { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { lock (this) @@ -179,15 +190,18 @@ public uint CheckConnection() public void HandleReceiveError(SNIPacket packet) { Debug.Assert(Monitor.IsEntered(this), "HandleReceiveError was called without being locked."); - if (!Monitor.IsEntered(this)) - { - SqlClientEventSource.Log.TrySNITraceEvent(" HandleReceiveError was called without being locked."); - } foreach (SNIMarsHandle handle in _sessions.Values) { if (packet.HasCompletionCallback) { handle.HandleReceiveError(packet); +#if DEBUG + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "MARS Session Id {0}, Packet {1} has Completion Callback", args0: ConnectionId, args1: packet?._id); + } + else + { + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "MARS Session Id {0}, Packet {1} does not have Completion Callback, error not handled.", args0: ConnectionId, args1: packet?._id); +#endif } } Debug.Assert(!packet.IsInvalid, "packet was returned by MarsConnection child, child sessions should not release the packet"); @@ -211,7 +225,7 @@ public void HandleSendComplete(SNIPacket packet, uint sniErrorCode) /// SNI error code public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { SNISMUXHeader currentHeader = null; @@ -223,7 +237,7 @@ public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) lock (this) { HandleReceiveError(packet); - SqlClientEventSource.Log.TrySNITraceEvent(" not successful."); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "MARS Session Id {0}, Handled receive error code: {1}", args0: _lowerHandle?.ConnectionId, args1: sniErrorCode); return; } } @@ -246,22 +260,25 @@ public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) if (bytesTaken == 0) { sniErrorCode = ReceiveAsync(ref packet); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, Non-SMUX Header SNI Packet received with code {1}", args0: ConnectionId, args1: sniErrorCode); if (sniErrorCode == TdsEnums.SNI_SUCCESS_IO_PENDING) { - SqlClientEventSource.Log.TrySNITraceEvent(" not successful."); return; } HandleReceiveError(packet); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "MARS Session Id {0}, Handled receive error code: {1}", args0: _lowerHandle?.ConnectionId, args1: sniErrorCode); return; } } _currentHeader.Read(_headerBytes); - _dataBytesLeft = (int)_currentHeader.length; _currentPacket = _lowerHandle.RentPacket(headerSize: 0, dataSize: (int)_currentHeader.length); +#if DEBUG + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _dataBytesLeft {1}, _currentPacket {2}, Reading data of length: _currentHeader.length {3}", args0: _lowerHandle?.ConnectionId, args1: _dataBytesLeft, args2: currentPacket?._id, args3: _currentHeader?.length); +#endif } currentHeader = _currentHeader; @@ -277,6 +294,7 @@ public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) if (_dataBytesLeft > 0) { sniErrorCode = ReceiveAsync(ref packet); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, SMUX DATA Header SNI Packet received with code {1}, _dataBytesLeft {2}", args0: ConnectionId, args1: sniErrorCode, args2: _dataBytesLeft); if (sniErrorCode == TdsEnums.SNI_SUCCESS_IO_PENDING) { @@ -284,6 +302,7 @@ public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) } HandleReceiveError(packet); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "MARS Session Id {0}, Handled receive error code: {1}", args0: _lowerHandle?.ConnectionId, args1: sniErrorCode); return; } } @@ -295,6 +314,7 @@ public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) { SNILoadHandle.SingletonInstance.LastError = new SNIError(SNIProviders.SMUX_PROV, 0, SNICommon.InvalidParameterError, Strings.SNI_ERROR_5); HandleReceiveError(packet); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Current Header Session Id {0} not found, MARS Session Id {1} will be destroyed, New SNI error created: {2}", args0: _currentHeader?.sessionId, args1: _lowerHandle?.ConnectionId, args2: sniErrorCode); _lowerHandle.Dispose(); _lowerHandle = null; return; @@ -303,16 +323,19 @@ public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) if (_currentHeader.flags == (byte)SNISMUXFlags.SMUX_FIN) { _sessions.Remove(_currentHeader.sessionId); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "SMUX_FIN | MARS Session Id {0}, SMUX_FIN flag received, Current Header Session Id {1} removed", args0: _lowerHandle?.ConnectionId, args1: _currentHeader?.sessionId); } else { currentSession = _sessions[_currentHeader.sessionId]; + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, Current Session assigned to Session Id {1}", args0: _lowerHandle?.ConnectionId, args1: _currentHeader?.sessionId); } } if (currentHeader.flags == (byte)SNISMUXFlags.SMUX_DATA) { currentSession.HandleReceiveComplete(currentPacket, currentHeader); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "SMUX_DATA | MARS Session Id {0}, Current Session {1} completed receiving Data", args0: _lowerHandle?.ConnectionId, args1: _currentHeader?.sessionId); } if (_currentHeader.flags == (byte)SNISMUXFlags.SMUX_ACK) @@ -320,13 +343,17 @@ public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) try { currentSession.HandleAck(currentHeader.highwater); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "SMUX_ACK | MARS Session Id {0}, Current Session {1} handled ack", args0: _lowerHandle?.ConnectionId, args1: _currentHeader?.sessionId); } catch (Exception e) { + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "SMUX_ACK | MARS Session Id {0}, Exception occurred: {2}", args0: _currentHeader?.sessionId, args1: e?.Message); SNICommon.ReportSNIError(SNIProviders.SMUX_PROV, SNICommon.InternalExceptionError, e); } - +#if DEBUG Debug.Assert(_currentPacket == currentPacket, "current and _current are not the same"); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "SMUX_ACK | MARS Session Id {0}, Current Packet {1} returned", args0: _lowerHandle?.ConnectionId, args1: currentPacket?._id); +#endif ReturnPacket(currentPacket); currentPacket = null; _currentPacket = null; @@ -344,6 +371,7 @@ public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) } HandleReceiveError(packet); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "MARS Session Id {0}, packet.DataLeft 0, SNI error {2}", args0: _lowerHandle?.ConnectionId, args1: sniErrorCode); return; } } @@ -360,7 +388,7 @@ public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) /// public uint EnableSsl(uint options) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { return _lowerHandle.EnableSsl(options); @@ -376,7 +404,7 @@ public uint EnableSsl(uint options) /// public void DisableSsl() { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { _lowerHandle.DisableSsl(); @@ -403,7 +431,7 @@ public void ReturnPacket(SNIPacket packet) /// public void KillConnection() { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { _lowerHandle.KillConnection(); 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 c6fd0a7620..1c1523d73e 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,13 +15,14 @@ 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; private readonly Queue _receivedPacketQueue = new Queue(); private readonly Queue _sendPacketQueue = new Queue(); private readonly object _callbackObject; - private readonly Guid _connectionId = Guid.NewGuid(); + private readonly Guid _connectionId; private readonly ushort _sessionId; private readonly ManualResetEventSlim _packetEvent = new ManualResetEventSlim(false); private readonly ManualResetEventSlim _ackEvent = new ManualResetEventSlim(false); @@ -54,14 +55,15 @@ internal sealed class SNIMarsHandle : SNIHandle /// public override void Dispose() { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { 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(" internal exception error = {0}, Member Name={1}", e.Message, e.GetType().Name); + 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 @@ -81,9 +83,11 @@ public SNIMarsHandle(SNIMarsConnection connection, ushort sessionId, object call { _sessionId = sessionId; _connection = connection; + _connectionId = connection.ConnectionId; _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); _status = TdsEnums.SNI_SUCCESS; } @@ -93,11 +97,13 @@ public SNIMarsHandle(SNIMarsConnection connection, ushort sessionId, object call /// SMUX header flags private void SendControlPacket(SNISMUXFlags flags) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SNIMarsHandle.SendControlPacket | SNI | INFO | SCOPE | Entering Scope {0}"); try { 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); +#endif lock (this) { SetupSMUXHeader(0, flags); @@ -107,6 +113,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); + ; +#endif } finally { @@ -116,7 +126,7 @@ private void SendControlPacket(SNISMUXFlags flags) private void SetupSMUXHeader(int length, SNISMUXFlags flags) { - Debug.Assert(Monitor.IsEntered(this), "must take lock on self before updating mux header"); + Debug.Assert(Monitor.IsEntered(this), "must take lock on self before updating smux header"); _currentHeader.SMID = 83; _currentHeader.flags = (byte)flags; @@ -134,12 +144,14 @@ private void SetupSMUXHeader(int length, SNISMUXFlags flags) /// The packet with the SMUx header set. private SNIPacket SetPacketSMUXHeader(SNIPacket packet) { - Debug.Assert(packet.ReservedHeaderSize == SNISMUXHeader.HEADER_LENGTH, "mars handle attempting to mux packet without mux reservation"); + Debug.Assert(packet.ReservedHeaderSize == SNISMUXHeader.HEADER_LENGTH, "mars handle attempting to smux packet without smux reservation"); SetupSMUXHeader(packet.Length, SNISMUXFlags.SMUX_DATA); _currentHeader.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); +#endif return packet; } @@ -150,8 +162,8 @@ private SNIPacket SetPacketSMUXHeader(SNIPacket packet) /// SNI error code public override uint Send(SNIPacket packet) { - Debug.Assert(packet.ReservedHeaderSize == SNISMUXHeader.HEADER_LENGTH, "mars handle attempting to send muxed packet without mux reservation in Send"); - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + 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 { while (true) @@ -164,10 +176,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); _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); _ackEvent.Reset(); } } @@ -177,6 +191,7 @@ 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); return _connection.Send(muxedPacket); } finally @@ -193,20 +208,21 @@ public override uint Send(SNIPacket packet) /// SNI error code private uint InternalSendAsync(SNIPacket packet, SNIAsyncCallback callback) { - Debug.Assert(packet.ReservedHeaderSize == SNISMUXHeader.HEADER_LENGTH, "mars handle attempting to send muxed packet without mux reservation in InternalSendAsync"); - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + 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 { lock (this) { if (_sequenceNumber >= _sendHighwater) { - SqlClientEventSource.Log.TrySNITraceEvent(" SNI Queue is full"); + 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); 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); return _connection.SendAsync(muxedPacket, callback); } } @@ -222,7 +238,7 @@ private uint InternalSendAsync(SNIPacket packet, SNIAsyncCallback callback) /// SNI error code private uint SendPendingPackets() { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); SNIMarsQueuedPacket packet = null; try { @@ -239,16 +255,18 @@ private uint SendPendingPackets() if (result != TdsEnums.SNI_SUCCESS && result != TdsEnums.SNI_SUCCESS_IO_PENDING) { - SqlClientEventSource.Log.TrySNITraceEvent(" InternalSendAsync result is not SNI_SUCCESS and is not 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); return result; } _sendPacketQueue.Dequeue(); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, 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); } } @@ -272,7 +290,7 @@ private uint SendPendingPackets() /// SNI error code public override uint SendAsync(SNIPacket packet, SNIAsyncCallback callback = null) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { lock (this) @@ -281,6 +299,8 @@ 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); + return TdsEnums.SNI_SUCCESS_IO_PENDING; } finally @@ -296,7 +316,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(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { lock (_receivedPacketQueue) @@ -305,12 +325,15 @@ 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); 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); + return TdsEnums.SNI_SUCCESS_IO_PENDING; } @@ -318,6 +341,9 @@ 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); +#endif _packetEvent.Reset(); } } @@ -327,6 +353,7 @@ 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); SendAckIfNecessary(); return TdsEnums.SNI_SUCCESS; } @@ -341,16 +368,17 @@ public override uint ReceiveAsync(ref SNIPacket packet) /// public void HandleReceiveError(SNIPacket packet) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { // 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 + // which should handle ownership of the packet because the individual mars handles are not aware of // each other and cannot know if they are the last one in the list and that it is safe to return the 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); _packetEvent.Set(); } @@ -369,7 +397,7 @@ public void HandleReceiveError(SNIPacket packet) /// SNI error code public void HandleSendComplete(SNIPacket packet, uint sniErrorCode) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { lock (this) @@ -379,6 +407,9 @@ public void HandleSendComplete(SNIPacket packet, uint sniErrorCode) ((TdsParserStateObject)_callbackObject).WriteAsyncCallback(PacketHandle.FromManagedPacket(packet), 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); +#endif } finally { @@ -387,18 +418,19 @@ public void HandleSendComplete(SNIPacket packet, uint sniErrorCode) } /// - /// Handle SMUX acknowledgement + /// Handle SMUX acknowledgment /// /// Send highwater mark public void HandleAck(uint highwater) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { 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); _sendHighwater = highwater; SendPendingPackets(); } @@ -417,13 +449,14 @@ public void HandleAck(uint highwater) /// SMUX header public void HandleReceiveComplete(SNIPacket packet, SNISMUXHeader header) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { 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); HandleAck(header.highwater); } @@ -433,11 +466,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); 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); ((TdsParserStateObject)_callbackObject).ReadAsyncCallback(PacketHandle.FromManagedPacket(packet), 0); } @@ -449,7 +484,7 @@ 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); SendAckIfNecessary(); } finally @@ -475,6 +510,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); } } @@ -486,7 +522,7 @@ private void SendAckIfNecessary() /// SNI error code public override uint Receive(out SNIPacket packet, int timeoutInMilliseconds) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { packet = null; @@ -499,10 +535,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); 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); if (queueCount > 0) { @@ -511,6 +549,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); } result = TdsEnums.SNI_SUCCESS; @@ -525,12 +564,15 @@ 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); 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); 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); return TdsEnums.SNI_WAIT_TIMEOUT; } } 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 2914ac3c1b..4571dd470b 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,8 +18,9 @@ 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; + // private const int MAX_PIPE_INSTANCES = 255; // TODO: Investigate pipe instance limit. private readonly string _targetServer; private readonly object _sendSync; @@ -39,8 +40,8 @@ internal sealed class SNINpHandle : SNIPhysicalHandle public SNINpHandle(string serverName, string pipeName, long timerExpire) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(" Constructor"); - SqlClientEventSource.Log.TrySNITraceEvent(" Constructor. server name = {0}, pipe name = {1}", serverName, pipeName); + 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 { _sendSync = new object(); @@ -57,7 +58,7 @@ public SNINpHandle(string serverName, string pipeName, long timerExpire) bool isInfiniteTimeOut = long.MaxValue == timerExpire; if (isInfiniteTimeOut) { - _pipeStream.Connect(System.Threading.Timeout.Infinite); + _pipeStream.Connect(Timeout.Infinite); } else { @@ -71,14 +72,14 @@ public SNINpHandle(string serverName, string pipeName, long timerExpire) { SNICommon.ReportSNIError(SNIProviders.NP_PROV, SNICommon.ConnOpenFailedError, te); _status = TdsEnums.SNI_ERROR; - SqlClientEventSource.Log.TrySNITraceEvent(" Timed out. Exception = {0}", te.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, 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(" IOException = {0}", ioe.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, IO Exception occurred. Error Code 1 Exception = {1}", args0: _connectionId, args1: ioe?.Message); return; } @@ -86,11 +87,11 @@ 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(" Pipe stream is not connected or cannot write or read to/from it."); + 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); return; } - _sslOverTdsStream = new SslOverTdsStream(_pipeStream); + _sslOverTdsStream = new SslOverTdsStream(_pipeStream, _connectionId); _sslStream = new SNISslStream(_sslOverTdsStream, true, new RemoteCertificateValidationCallback(ValidateServerCertificate)); _stream = _pipeStream; @@ -135,16 +136,17 @@ public override int ProtocolVersion public override uint CheckConnection() { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { if (!_stream.CanWrite || !_stream.CanRead) { - SqlClientEventSource.Log.TrySNITraceEvent(" cannot write or read to/from the stream"); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, 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); return TdsEnums.SNI_SUCCESS; } } @@ -178,12 +180,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); } } public override uint Receive(out SNIPacket packet, int timeout) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { SNIPacket errorPacket; @@ -194,13 +197,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); if (packet.Length == 0) { errorPacket = packet; packet = null; var e = new Win32Exception(); - SqlClientEventSource.Log.TrySNITraceEvent(" packet length is 0."); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, 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); } } @@ -208,14 +212,14 @@ public override uint Receive(out SNIPacket packet, int timeout) { errorPacket = packet; packet = null; - SqlClientEventSource.Log.TrySNITraceEvent(" ObjectDisposedException message = {0}.", ode.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, 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(" IOException message = {0}.", ioe.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, IOException occurred: {1}.", args0: _connectionId, args1: ioe?.Message); return ReportErrorAndReleasePacket(errorPacket, ioe); } return TdsEnums.SNI_SUCCESS; @@ -229,7 +233,7 @@ public override uint Receive(out SNIPacket packet, int timeout) public override uint ReceiveAsync(ref SNIPacket packet) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { SNIPacket errorPacket; @@ -238,20 +242,21 @@ 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); return TdsEnums.SNI_SUCCESS_IO_PENDING; } catch (ObjectDisposedException ode) { errorPacket = packet; packet = null; - SqlClientEventSource.Log.TrySNITraceEvent(" ObjectDisposedException message = {0}.", ode.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, 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(" IOException message = {0}.", ioe.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, IOException occurred: {1}.", args0: _connectionId, args1: ioe?.Message); return ReportErrorAndReleasePacket(errorPacket, ioe); } } @@ -263,14 +268,14 @@ public override uint ReceiveAsync(ref SNIPacket packet) public override uint Send(SNIPacket packet) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { bool releaseLock = false; try { // is the packet is marked out out-of-band (attention packets only) it must be - // sent immediately even if a send of recieve operation is already in progress + // sent immediately even if a send of receive operation is already in progress // because out of band packets are used to cancel ongoing operations // so try to take the lock if possible but continue even if it can't be taken if (packet.IsOutOfBand) @@ -290,18 +295,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); packet.WriteToStream(_stream); return TdsEnums.SNI_SUCCESS; } catch (ObjectDisposedException ode) { - SqlClientEventSource.Log.TrySNITraceEvent(" ObjectDisposedException message = {0}.", ode.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, ObjectDisposedException occurred: {1}.", args0: _connectionId, args1: ode?.Message); return ReportErrorAndReleasePacket(packet, ode); } catch (IOException ioe) { - SqlClientEventSource.Log.TrySNITraceEvent(" IOException message = {0}.", ioe.Message); - + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, IOException occurred: {1}.", args0: _connectionId, args1: ioe?.Message); return ReportErrorAndReleasePacket(packet, ioe); } } @@ -322,10 +327,11 @@ public override uint Send(SNIPacket packet) public override uint SendAsync(SNIPacket packet, SNIAsyncCallback callback = null) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { 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); packet.WriteToStreamAsync(_stream, cb, SNIProviders.NP_PROV); return TdsEnums.SNI_SUCCESS_IO_PENDING; } @@ -343,23 +349,24 @@ public override void SetAsyncCallbacks(SNIAsyncCallback receiveCallback, SNIAsyn public override uint EnableSsl(uint options) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { _validateCert = (options & TdsEnums.SNI_SSL_VALIDATE_CERTIFICATE) != 0; try { + _sslStream.AuthenticateAsClient(_targetServer); _sslOverTdsStream.FinishHandshake(); } catch (AuthenticationException aue) { - SqlClientEventSource.Log.TrySNITraceEvent(" AuthenticationException message = {0}.", aue.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, 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("InvalidOperationException message = {0}.", ioe.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, InvalidOperationException message = {1}.", args0: ConnectionId, args1: ioe?.Message); return SNICommon.ReportSNIError(SNIProviders.NP_PROV, SNICommon.InternalExceptionError, ioe); } _stream = _sslStream; @@ -391,15 +398,17 @@ public override void DisableSsl() /// true if valid private bool ValidateServerCertificate(object sender, X509Certificate cert, X509Chain chain, SslPolicyErrors policyErrors) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { if (!_validateCert) { + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Certificate validation not requested.", args0: ConnectionId); return true; } - return SNICommon.ValidateSslServerCertificate(_targetServer, sender, cert, chain, policyErrors); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Proceeding to SSL certificate validation.", args0: ConnectionId); + return SNICommon.ValidateSslServerCertificate(_targetServer, cert, policyErrors); } finally { @@ -422,6 +431,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); return SNICommon.ReportSNIError(SNIProviders.NP_PROV, SNICommon.InternalExceptionError, sniException); } @@ -431,6 +441,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); 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 857a300259..7fe953d8d8 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 @@ -19,6 +19,7 @@ namespace Microsoft.Data.SqlClient.SNI /// internal sealed 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 @@ -36,6 +37,7 @@ internal sealed class SNIPacket internal readonly SNIHandle _owner; // used in debug builds to check that packets are being returned to the correct pool internal string _traceTag; // used in debug builds to assist tracing what steps the packet has been through +#if TRACE_HISTORY [DebuggerDisplay("{Action.ToString(),nq}")] internal struct History { @@ -51,6 +53,7 @@ public enum Direction } internal List _history = null; +#endif /// /// uses the packet refcount in debug mode to identify if the packet is considered active @@ -58,7 +61,7 @@ public enum Direction /// public bool IsActive => _refCount == 1; - public SNIPacket(SNIHandle owner,int id) + public SNIPacket(SNIHandle owner, int id) : this() { #if TRACE_HISTORY @@ -66,6 +69,7 @@ public SNIPacket(SNIHandle owner,int id) #endif _id = id; _owner = owner; + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Packet Id {1} instantiated,", args0: _owner?.ConnectionId, args1: _id); } // the finalizer is only included in debug builds and is used to ensure that all packets are correctly recycled @@ -75,7 +79,7 @@ public SNIPacket(SNIHandle owner,int id) { if (_data != null) { - Debug.Fail($@"finalizer called for unreleased SNIPacket, tag: {_traceTag}"); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Finalizer called for unreleased SNIPacket, Connection Id {0}, Packet Id {1}, _refCount {2}, DataLeft {3}, tag {4}", args0: _owner?.ConnectionId, args1: _id, args2: _refCount, args3: DataLeft, args4: _traceTag); } } @@ -119,7 +123,7 @@ public void SetCompletionCallback(SNIAsyncCallback completionCallback) } /// - /// Invoke the completion callback + /// Invoke the completion callback /// /// SNI error public void InvokeCompletionCallback(uint sniErrorCode) @@ -139,13 +143,16 @@ public void Allocate(int headerLength, int dataLength) _dataLength = 0; _dataOffset = 0; _headerLength = headerLength; +#if DEBUG + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Packet Id {1} allocated with _headerLength {2}, _dataCapacity {3}", args0: _owner?.ConnectionId, args1: _id, args2: _headerLength, args3: _dataCapacity); +#endif } /// /// Read packet data into a buffer without removing it from the packet /// /// Buffer - /// Number of bytes read from the packet into the buffer + /// Number of bytes read from the packet into the buffer public void GetData(byte[] buffer, ref int dataSize) { Buffer.BlockCopy(_data, _headerLength, buffer, 0, _dataLength); @@ -162,6 +169,9 @@ public int TakeData(SNIPacket packet, int size) { int dataSize = TakeData(packet._data, packet._headerLength + packet._dataLength, size); 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); +#endif return dataSize; } @@ -174,6 +184,9 @@ 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); +#endif } /// @@ -181,7 +194,7 @@ public void AppendData(byte[] data, int size) /// /// Buffer /// Data offset to write data at - /// Number of bytes to read from the packet into the buffer + /// Number of bytes to read from the packet into the buffer /// public int TakeData(byte[] buffer, int dataOffset, int size) { @@ -197,6 +210,9 @@ 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); +#endif return size; } @@ -214,6 +230,9 @@ public void SetHeaderActive() _dataCapacity += _headerLength; _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); +#endif } /// @@ -229,6 +248,9 @@ public void Release() _data = null; _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); +#endif _dataLength = 0; _dataOffset = 0; _headerLength = 0; @@ -243,6 +265,9 @@ public void Release() 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); +#endif } /// @@ -270,15 +295,23 @@ private void ReadFromStreamAsyncContinuation(Task t, object state) if (e != null) { 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); +#endif error = true; } else { _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); +#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); +#endif error = true; } } @@ -293,6 +326,9 @@ private void ReadFromStreamAsyncContinuation(Task t, object state) 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); +#endif } /// @@ -307,10 +343,16 @@ public async void WriteToStreamAsync(Stream stream, SNIAsyncCallback callback, S try { 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); +#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); +#endif status = TdsEnums.SNI_ERROR; } callback(this, status); diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIPhysicalHandle.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIPhysicalHandle.cs index 65a4432f80..ca11e8c4ac 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIPhysicalHandle.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIPhysicalHandle.cs @@ -4,10 +4,8 @@ using System; using System.Diagnostics; -using System.Collections.Concurrent; using System.Threading; using System.Linq; -using System.Text; namespace Microsoft.Data.SqlClient.SNI { @@ -40,16 +38,18 @@ public override SNIPacket RentPacket(int headerSize, int dataSize) else { Debug.Assert(packet != null, "dequeue returned null SNIPacket"); - Debug.Assert(!packet.IsActive, "SNIPacket _refcount must be 1 or a lifetime issue has occured, trace with the #TRACE_HISTORY define"); + Debug.Assert(!packet.IsActive, "SNIPacket _refcount must be 1 or a lifetime issue has occurred, trace with the #TRACE_HISTORY define"); Debug.Assert(packet.IsInvalid, "dequeue returned valid packet"); GC.ReRegisterForFinalize(packet); } +#if TRACE_HISTORY if (packet._history != null) { packet._history.Add(new SNIPacket.History { Action = SNIPacket.History.Direction.Rent, Stack = GetStackParts(), RefCount = packet._refCount }); } +#endif Interlocked.Add(ref packet._refCount, 1); - Debug.Assert(packet.IsActive, "SNIPacket _refcount must be 1 or a lifetime issue has occured, trace with the #TRACE_HISTORY define"); + Debug.Assert(packet.IsActive, "SNIPacket _refcount must be 1 or a lifetime issue has occurred, trace with the #TRACE_HISTORY define"); #endif packet.Allocate(headerSize, dataSize); return packet; @@ -57,21 +57,23 @@ public override SNIPacket RentPacket(int headerSize, int dataSize) public override void ReturnPacket(SNIPacket packet) { - Debug.Assert(packet != null, "releasing null SNIPacket"); #if DEBUG - Debug.Assert(packet.IsActive, "SNIPacket _refcount must be 1 or a lifetime issue has occured, trace with the #TRACE_HISTORY define"); + Debug.Assert(packet != null, "releasing null SNIPacket"); + Debug.Assert(packet.IsActive, "SNIPacket _refcount must be 1 or a lifetime issue has occurred, trace with the #TRACE_HISTORY define"); Debug.Assert(ReferenceEquals(packet._owner, this), "releasing SNIPacket that belongs to another physical handle"); -#endif Debug.Assert(!packet.IsInvalid, "releasing already released SNIPacket"); +#endif packet.Release(); #if DEBUG Interlocked.Add(ref packet._refCount, -1); packet._traceTag = null; +#if TRACE_HISTORY if (packet._history != null) { packet._history.Add(new SNIPacket.History { Action = SNIPacket.History.Direction.Return, Stack = GetStackParts(), RefCount = packet._refCount }); } +#endif GC.SuppressFinalize(packet); #endif _pool.Return(packet); diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIProxy.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIProxy.cs index 55ee594a0b..1204b129d0 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIProxy.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIProxy.cs @@ -30,10 +30,7 @@ internal class SspiClientContextResult internal static readonly SNIProxy s_singleton = new SNIProxy(); - internal static SNIProxy GetInstance() - { - return s_singleton; - } + internal static SNIProxy GetInstance() => s_singleton; /// /// Enable SSL on a connection @@ -45,10 +42,12 @@ internal uint EnableSsl(SNIHandle handle, uint options) { try { + SqlClientEventSource.Log.TryTraceEvent("SNIProxy.EnableSsl | Info | Session Id {0}", handle?.ConnectionId); return handle.EnableSsl(options); } catch (Exception e) { + SqlClientEventSource.Log.TryTraceEvent("SNIProxy.EnableSsl | Err | Session Id {0}, SNI Handshake failed with exception: {1}", handle?.ConnectionId, e?.Message); return SNICommon.ReportSNIError(SNIProviders.SSL_PROV, SNICommon.HandshakeFailureError, e); } } @@ -60,6 +59,7 @@ internal uint EnableSsl(SNIHandle handle, uint options) /// SNI error code internal uint DisableSsl(SNIHandle handle) { + SqlClientEventSource.Log.TryTraceEvent("SNIProxy.DisableSsl | Info | Session Id {0}", handle?.ConnectionId); handle.DisableSsl(); return TdsEnums.SNI_SUCCESS; } @@ -104,7 +104,7 @@ internal void GenSspiClientContext(SspiClientContextStatus sspiClientContextStat | ContextFlagsPal.Delegate | ContextFlagsPal.MutualAuth; - string serverSPN = System.Text.Encoding.UTF8.GetString(serverName); + string serverSPN = Encoding.UTF8.GetString(serverName); SecurityStatusPal statusCode = NegotiateStreamPal.InitializeSecurityContext( credentialsHandle, @@ -211,7 +211,7 @@ internal uint ReadSyncOverAsync(SNIHandle handle, out SNIPacket packet, int time internal uint GetConnectionId(SNIHandle handle, ref Guid clientConnectionId) { clientConnectionId = handle.ConnectionId; - + SqlClientEventSource.Log.TryTraceEvent("SNIProxy.GetConnectionId | Info | Session Id {0}", clientConnectionId); return TdsEnums.SNI_SUCCESS; } @@ -235,6 +235,7 @@ internal uint WritePacket(SNIHandle handle, SNIPacket packet, bool sync) result = handle.SendAsync(packet); } + SqlClientEventSource.Log.TryTraceEvent("SNIProxy.WritePacket | Info | Session Id {0}, SendAsync Result {1}", handle?.ConnectionId, result); return result; } @@ -302,6 +303,7 @@ internal SNIHandle CreateConnectionHandle(string fullServerName, bool ignoreSniO } } + SqlClientEventSource.Log.TryTraceEvent("SNIProxy.CreateConnectionHandle | Info | Session Id {0}, SNI Handle Type: {1}", sniHandle?.ConnectionId, sniHandle?.GetType()); return sniHandle; } @@ -325,6 +327,7 @@ private static byte[] GetSqlServerSPN(DataSource dataSource) postfix = DefaultSqlServerPort.ToString(); } + SqlClientEventSource.Log.TryTraceEvent("SNIProxy.GetSqlServerSPN | Info | ServerName {0}, InstanceName {1}, Port {2}, postfix {3}", dataSource?.ServerName, dataSource?.InstanceName, dataSource?.Port, postfix); return GetSqlServerSPN(hostName, postfix); } @@ -356,6 +359,9 @@ private static byte[] GetSqlServerSPN(string hostNameOrAddress, string portOrIns { serverSpn += $":{DefaultSqlServerPort}"; } + + SqlClientEventSource.Log.TryAdvancedTraceEvent("SNIProxy.GetSqlServerSPN | Info | ServerSPN {0}", serverSpn); + return Encoding.UTF8.GetBytes(serverSpn); } 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 1f900a43f0..98ed3f222b 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,6 +22,7 @@ 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; @@ -67,6 +68,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); } } @@ -118,126 +120,145 @@ public override int ProtocolVersion /// Used for DNS Cache public SNITCPHandle(string serverName, int port, long timerExpire, bool parallel, string cachedFQDN, ref SQLDNSInfo pendingDNSInfo) { - _targetServer = serverName; - _sendSync = new object(); - - SQLDNSInfo cachedDNSInfo; - bool hasCachedDNSInfo = SQLFallbackDNSCache.Instance.GetDNSInfo(cachedFQDN, out cachedDNSInfo); - + 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 { - TimeSpan ts = default(TimeSpan); - - // In case the Timeout is Infinite, we will receive the max value of Int64 as the tick count - // The infinite Timeout is a function of ConnectionString Timeout=0 - bool isInfiniteTimeOut = long.MaxValue == timerExpire; - if (!isInfiniteTimeOut) - { - ts = DateTime.FromFileTime(timerExpire) - DateTime.Now; - ts = ts.Ticks < 0 ? TimeSpan.FromTicks(0) : ts; - } + _targetServer = serverName; + _sendSync = new object(); - bool reportError = true; + SQLDNSInfo cachedDNSInfo; + bool hasCachedDNSInfo = SQLFallbackDNSCache.Instance.GetDNSInfo(cachedFQDN, out cachedDNSInfo); - // 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 IPv4 first and followed by IPv6 if - // IPv4 fails. The exceptions will be throw to upper level and be handled as before. try { - if (parallel) - { - _socket = TryConnectParallel(serverName, port, ts, isInfiniteTimeOut, ref reportError, cachedFQDN, ref pendingDNSInfo); - } - else + TimeSpan ts = default(TimeSpan); + + // In case the Timeout is Infinite, we will receive the max value of Int64 as the tick count + // The infinite Timeout is a function of ConnectionString Timeout=0 + bool isInfiniteTimeOut = long.MaxValue == timerExpire; + if (!isInfiniteTimeOut) { - _socket = Connect(serverName, port, ts, isInfiniteTimeOut, cachedFQDN, ref pendingDNSInfo); + ts = DateTime.FromFileTime(timerExpire) - DateTime.Now; + ts = ts.Ticks < 0 ? TimeSpan.FromTicks(0) : ts; } - } - catch (Exception ex) - { - // Retry with cached IP address - if (ex is SocketException || ex is ArgumentException || ex is AggregateException) + + 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); + // 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 IPv4 first and followed by IPv6 if + // IPv4 fails. The exceptions will be throw to upper level and be handled as before. + try { - if (hasCachedDNSInfo == false) + if (parallel) { - throw; + _socket = TryConnectParallel(serverName, port, ts, isInfiniteTimeOut, ref reportError, cachedFQDN, ref pendingDNSInfo); } else { - int portRetry = String.IsNullOrEmpty(cachedDNSInfo.Port) ? port : Int32.Parse(cachedDNSInfo.Port); - - try + _socket = Connect(serverName, port, ts, isInfiniteTimeOut, cachedFQDN, ref pendingDNSInfo); + } + } + catch (Exception ex) + { + // Retry with cached IP address + if (ex is SocketException || ex is ArgumentException || ex is AggregateException) + { + if (hasCachedDNSInfo == false) { - if (parallel) - { - _socket = TryConnectParallel(cachedDNSInfo.AddrIPv4, portRetry, ts, isInfiniteTimeOut, ref reportError, cachedFQDN, ref pendingDNSInfo); - } - else - { - _socket = Connect(cachedDNSInfo.AddrIPv4, portRetry, ts, isInfiniteTimeOut, cachedFQDN, ref pendingDNSInfo); - } + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, Cached DNS Info not found, exception occurred thrown: {1}", args0: _connectionId, args1: ex?.Message); + throw; } - catch (Exception exRetry) + else { - if (exRetry is SocketException || exRetry is ArgumentNullException - || exRetry is ArgumentException || exRetry is ArgumentOutOfRangeException || exRetry is AggregateException) + 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); + + try { if (parallel) { - _socket = TryConnectParallel(cachedDNSInfo.AddrIPv6, portRetry, ts, isInfiniteTimeOut, ref reportError, cachedFQDN, ref pendingDNSInfo); + _socket = TryConnectParallel(cachedDNSInfo.AddrIPv4, portRetry, ts, isInfiniteTimeOut, ref reportError, cachedFQDN, ref pendingDNSInfo); } else { - _socket = Connect(cachedDNSInfo.AddrIPv6, portRetry, ts, isInfiniteTimeOut, cachedFQDN, ref pendingDNSInfo); + _socket = Connect(cachedDNSInfo.AddrIPv4, portRetry, ts, isInfiniteTimeOut, cachedFQDN, ref pendingDNSInfo); } } - else + catch (Exception exRetry) { - throw; + 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); + if (parallel) + { + _socket = TryConnectParallel(cachedDNSInfo.AddrIPv6, portRetry, ts, isInfiniteTimeOut, ref reportError, cachedFQDN, ref pendingDNSInfo); + } + else + { + _socket = Connect(cachedDNSInfo.AddrIPv6, portRetry, ts, isInfiniteTimeOut, cachedFQDN, ref pendingDNSInfo); + } + } + else + { + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, Retry failed, exception occurred: {1}", args0: _connectionId, args1: exRetry?.Message); + throw; + } } } } + else + { + throw; + } } - else - { - throw; - } - } - if (_socket == null || !_socket.Connected) - { - if (_socket != null) + if (_socket == null || !_socket.Connected) { - _socket.Dispose(); - _socket = null; - } + if (_socket != null) + { + _socket.Dispose(); + _socket = null; + } - if (reportError) - { - ReportTcpSNIError(0, SNICommon.ConnOpenFailedError, Strings.SNI_ERROR_40); + 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); + 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); + return; } + + _socket.NoDelay = true; + _tcpStream = new SNINetworkStream(_socket, true); + + _sslOverTdsStream = new SslOverTdsStream(_tcpStream, _connectionId); + _sslStream = new SNISslStream(_sslOverTdsStream, true, new RemoteCertificateValidationCallback(ValidateServerCertificate)); + } + 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); + ReportTcpSNIError(se); + return; + } + catch (Exception e) + { + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0} Exception occurred: {1}", args0: _connectionId, args1: e?.Message); + ReportTcpSNIError(e); return; } - _socket.NoDelay = true; - _tcpStream = new SNINetworkStream(_socket, true); - - _sslOverTdsStream = new SslOverTdsStream(_tcpStream); - _sslStream = new SNISslStream(_sslOverTdsStream, true, new RemoteCertificateValidationCallback(ValidateServerCertificate)); - } - catch (SocketException se) - { - ReportTcpSNIError(se); - 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); } - catch (Exception e) + finally { - ReportTcpSNIError(e); - return; + SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); } - - _stream = _tcpStream; - _status = TdsEnums.SNI_SUCCESS; } // Connect to server with hostName and port in parellel mode. @@ -256,6 +277,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); ReportTcpSNIError(0, SNICommon.MultiSubnetFailoverWithMoreThan64IPs, Strings.SNI_ERROR_47); return availableSocket; } @@ -285,6 +307,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); ReportTcpSNIError(0, SNICommon.ConnOpenFailedError, Strings.SNI_ERROR_40); return availableSocket; } @@ -341,7 +364,10 @@ void Cancel() sockets[i] = null; } } - catch { } + catch (Exception e) + { + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "THIS EXCEPTION IS BEING SWALLOWED: {0}", args0: e?.Message); + } } } @@ -365,6 +391,7 @@ void Cancel() // enable keep-alive on socket SetKeepAliveValues(ref sockets[i]); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connecting to IP address {0} and port {1}", args0: ipAddresses[i], args1: port); sockets[i].Connect(ipAddresses[i], port); if (sockets[i] != null) // sockets[i] can be null if cancel callback is executed during connect() { @@ -381,7 +408,10 @@ void Cancel() } } } - catch { } + catch (Exception e) + { + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "THIS EXCEPTION IS BEING SWALLOWED: {0}", args0: e?.Message); + } } } finally @@ -508,14 +538,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); return ReportTcpSNIError(aue); } catch (InvalidOperationException ioe) { + SqlClientEventSource.Log.TrySNITraceEvent(s_className, 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); return TdsEnums.SNI_SUCCESS; } @@ -529,6 +562,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); } /// @@ -543,10 +577,12 @@ 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); return true; } - return SNICommon.ValidateSslServerCertificate(_targetServer, sender, cert, chain, policyErrors); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Certificate will be validated for Target Server name", args0: _connectionId); + return SNICommon.ValidateSslServerCertificate(_targetServer, cert, policyErrors); } /// @@ -567,45 +603,49 @@ public override uint Send(SNIPacket packet) { bool releaseLock = false; try + { + // is the packet is marked out out-of-band (attention packets only) it must be + // sent immediately even if a send of recieve operation is already in progress + // because out of band packets are used to cancel ongoing operations + // so try to take the lock if possible but continue even if it can't be taken + if (packet.IsOutOfBand) { - // is the packet is marked out out-of-band (attention packets only) it must be - // sent immediately even if a send of recieve operation is already in progress - // because out of band packets are used to cancel ongoing operations - // so try to take the lock if possible but continue even if it can't be taken - if (packet.IsOutOfBand) + Monitor.TryEnter(this, ref releaseLock); + } + else + { + Monitor.Enter(this); + releaseLock = true; + } + + // this lock ensures that two packets are not being written to the transport at the same time + // so that sending a standard and an out-of-band packet are both written atomically no data is + // interleaved + lock (_sendSync) + { + try { - Monitor.TryEnter(this, ref releaseLock); + packet.WriteToStream(_stream); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Data sent to stream synchronously", args0: _connectionId); + return TdsEnums.SNI_SUCCESS; } - else + catch (ObjectDisposedException ode) { - Monitor.Enter(this); - releaseLock = true; + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, ObjectDisposedException occurred: {1}", args0: _connectionId, args1: ode?.Message); + return ReportTcpSNIError(ode); } - - // this lock ensures that two packets are not being written to the transport at the same time - // so that sending a standard and an out-of-band packet are both written atomically no data is - // interleaved - lock (_sendSync) + catch (SocketException se) { - try - { - packet.WriteToStream(_stream); - return TdsEnums.SNI_SUCCESS; - } - catch (ObjectDisposedException ode) - { - return ReportTcpSNIError(ode); - } - catch (SocketException se) - { - return ReportTcpSNIError(se); - } - catch (IOException ioe) - { - return ReportTcpSNIError(ioe); - } + SqlClientEventSource.Log.TrySNITraceEvent(s_className, 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); + return ReportTcpSNIError(ioe); } } + } finally { if (releaseLock) @@ -641,6 +681,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); ReportTcpSNIError(0, SNICommon.ConnTimeoutError, Strings.SNI_ERROR_11); return TdsEnums.SNI_WAIT_TIMEOUT; } @@ -653,21 +694,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); 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); 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); 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); return ReportErrorAndReleasePacket(errorPacket, se); } catch (IOException ioe) @@ -677,9 +722,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); errorCode = TdsEnums.SNI_WAIT_TIMEOUT; } + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, IO exception occurred: {1}", args0: _connectionId, args1: ioe?.Message); return errorCode; } finally @@ -708,11 +755,12 @@ public override void SetAsyncCallbacks(SNIAsyncCallback receiveCallback, SNIAsyn /// SNI error code public override uint SendAsync(SNIPacket packet, SNIAsyncCallback callback = null) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { 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); return TdsEnums.SNI_SUCCESS_IO_PENDING; } finally @@ -734,6 +782,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); return TdsEnums.SNI_SUCCESS_IO_PENDING; } catch (Exception e) when (e is ObjectDisposedException || e is SocketException || e is IOException) @@ -764,15 +813,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); 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); return ReportTcpSNIError(se); } catch (ObjectDisposedException ode) { + SqlClientEventSource.Log.TrySNITraceEvent(s_className, 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 e4359e2c42..e49fc4c89a 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,6 +13,7 @@ namespace Microsoft.Data.SqlClient.SNI { internal class SSRP { + private const string s_className = nameof(SSRP); private const char SemicolonSeparator = ';'; private const int SqlServerBrowserPort = 1434; @@ -26,7 +27,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(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { byte[] instanceInfoRequest = CreateInstanceInfoRequest(instanceName); @@ -37,7 +38,7 @@ internal static int GetPortByInstanceName(string browserHostName, string instanc } catch (SocketException se) { - SqlClientEventSource.Log.TrySNITraceEvent(" SocketException Message = {0}", se.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "SocketException Message = {0}", args0: se?.Message); throw new Exception(SQLMessage.SqlServerBrowserNotAccessible(), se); } @@ -73,7 +74,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(""); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { const byte ClntUcastInst = 0x04; @@ -150,28 +151,39 @@ private static byte[] CreateDacPortInfoRequest(string instanceName) /// response packet from UDP server private static byte[] SendUDPRequest(string browserHostname, int port, byte[] requestPacket) { - Debug.Assert(!string.IsNullOrWhiteSpace(browserHostname), "browserhostname should not be null, empty, or whitespace"); - Debug.Assert(port >= 0 && port <= 65535, "Invalid port"); - Debug.Assert(requestPacket != null && requestPacket.Length > 0, "requestPacket should not be null or 0-length array"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); + try + { + Debug.Assert(!string.IsNullOrWhiteSpace(browserHostname), "browserhostname should not be null, empty, or whitespace"); + Debug.Assert(port >= 0 && port <= 65535, "Invalid port"); + Debug.Assert(requestPacket != null && requestPacket.Length > 0, "requestPacket should not be null or 0-length array"); - const int sendTimeOutMs = 1000; - const int receiveTimeOutMs = 1000; + const int sendTimeOutMs = 1000; + const int receiveTimeOutMs = 1000; - IPAddress address = null; - bool isIpAddress = IPAddress.TryParse(browserHostname, out address); + IPAddress address = null; + bool isIpAddress = IPAddress.TryParse(browserHostname, out address); - byte[] responsePacket = null; - using (UdpClient client = new UdpClient(!isIpAddress ? AddressFamily.InterNetwork : address.AddressFamily)) - { - Task sendTask = client.SendAsync(requestPacket, requestPacket.Length, browserHostname, port); - Task receiveTask = null; - if (sendTask.Wait(sendTimeOutMs) && (receiveTask = client.ReceiveAsync()).Wait(receiveTimeOutMs)) + byte[] responsePacket = null; + using (UdpClient client = new UdpClient(!isIpAddress ? AddressFamily.InterNetwork : address.AddressFamily)) { - responsePacket = receiveTask.Result.Buffer; + 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."); + if (sendTask.Wait(sendTimeOutMs) && (receiveTask = client.ReceiveAsync()).Wait(receiveTimeOutMs)) + { + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Received Port info from UDP Client."); + responsePacket = receiveTask.Result.Buffer; + } } - } - return responsePacket; + 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 97a1181ae3..5f676ec457 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,13 +25,13 @@ public override Task WriteAsync(byte[] buffer, int offset, int count, Cancellati public override int Read(Span buffer) { - if (!_encapsulate) - { - return _stream.Read(buffer); - } - - using (SNIEventScope.Create(" reading encapsulated bytes")) + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); + try { + if (!_encapsulate) + { + return _stream.Read(buffer); + } if (_packetBytes > 0) { // there are queued bytes from a previous packet available @@ -72,28 +72,33 @@ public override int Read(Span buffer) return packetBytesRead; } } + finally + { + SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); + } } public override async ValueTask ReadAsync(Memory buffer, CancellationToken cancellationToken = default) { - if (!_encapsulate) + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); + try { - int read; + if (!_encapsulate) { - ValueTask readValueTask = _stream.ReadAsync(buffer, cancellationToken); - if (readValueTask.IsCompletedSuccessfully) - { - read = readValueTask.Result; - } - else + int read; { - read = await readValueTask.ConfigureAwait(false); + ValueTask readValueTask = _stream.ReadAsync(buffer, cancellationToken); + if (readValueTask.IsCompletedSuccessfully) + { + read = readValueTask.Result; + } + else + { + read = await readValueTask.ConfigureAwait(false); + } } + return read; } - return read; - } - using (SNIEventScope.Create(" reading encapsulated bytes")) - { if (_packetBytes > 0) { // there are queued bytes from a previous packet available @@ -171,21 +176,26 @@ public override async ValueTask ReadAsync(Memory buffer, Cancellation return packetBytesRead; } } + finally + { + SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); + } } public override void Write(ReadOnlySpan buffer) { - // During the SSL negotiation phase, SSL is tunnelled over TDS packet type 0x12. After - // negotiation, the underlying socket only sees SSL frames. - if (!_encapsulate) + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); + try { - _stream.Write(buffer); - _stream.Flush(); - return; - } + // During the SSL negotiation phase, SSL is tunnelled over TDS packet type 0x12. After + // negotiation, the underlying socket only sees SSL frames. + if (!_encapsulate) + { + _stream.Write(buffer); + _stream.Flush(); + return; + } - using (SNIEventScope.Create(" writing encapsulated bytes")) - { ReadOnlySpan remaining = buffer; byte[] packetBuffer = null; try @@ -224,29 +234,34 @@ public override void Write(ReadOnlySpan buffer) } } } + finally + { + SqlClientEventSource.Log.TrySNIScopeLeaveEvent(scopeID); + } } public override async ValueTask WriteAsync(ReadOnlyMemory buffer, CancellationToken cancellationToken = default) { - if (!_encapsulate) + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); + try { + if (!_encapsulate) { - ValueTask valueTask = _stream.WriteAsync(buffer, cancellationToken); - if (!valueTask.IsCompletedSuccessfully) { - await valueTask.ConfigureAwait(false); + ValueTask valueTask = _stream.WriteAsync(buffer, cancellationToken); + if (!valueTask.IsCompletedSuccessfully) + { + await valueTask.ConfigureAwait(false); + } } + Task flushTask = _stream.FlushAsync(); + if (flushTask.IsCompletedSuccessfully) + { + await flushTask.ConfigureAwait(false); + } + return; } - Task flushTask = _stream.FlushAsync(); - if (flushTask.IsCompletedSuccessfully) - { - await flushTask.ConfigureAwait(false); - } - return; - } - using (SNIEventScope.Create(" writing encapsulated bytes")) - { ReadOnlyMemory remaining = buffer; byte[] packetBuffer = null; try @@ -291,6 +306,10 @@ 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 7798b25d06..ec7bdac54b 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,13 +14,14 @@ internal sealed partial class SslOverTdsStream : Stream { public override int Read(byte[] buffer, int offset, int count) { - if (!_encapsulate) + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); + try { - return _stream.Read(buffer, offset, count); - } + if (!_encapsulate) + { + return _stream.Read(buffer, offset, count); + } - using (SNIEventScope.Create(" reading encapsulated bytes")) - { if (_packetBytes > 0) { // there are queued bytes from a previous packet available @@ -65,18 +66,22 @@ 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) { - if (!_encapsulate) + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); + try { - return await _stream.ReadAsync(buffer, offset, count, cancellationToken); - } + if (!_encapsulate) + { + return await _stream.ReadAsync(buffer, offset, count, cancellationToken); + } - using (SNIEventScope.Create(" reading encapsulated bytes")) - { if (_packetBytes > 0) { // there are queued bytes from a previous packet available @@ -121,21 +126,26 @@ 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) { - // During the SSL negotiation phase, SSL is tunnelled over TDS packet type 0x12. After - // negotiation, the underlying socket only sees SSL frames. - if (!_encapsulate) + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); + try { - _stream.Write(buffer, offset, count); - _stream.Flush(); - return; - } + // During the SSL negotiation phase, SSL is tunnelled over TDS packet type 0x12. After + // negotiation, the underlying socket only sees SSL frames. + if (!_encapsulate) + { + _stream.Write(buffer, offset, count); + _stream.Flush(); + return; + } - using (SNIEventScope.Create(" writing encapsulated bytes")) - { int remainingBytes = count; int dataOffset = offset; byte[] packetBuffer = null; @@ -169,23 +179,28 @@ 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) { - if (!_encapsulate) + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); + try { - await _stream.WriteAsync(buffer, offset, count).ConfigureAwait(false); - Task flushTask = _stream.FlushAsync(); - if (flushTask.Status == TaskStatus.RanToCompletion) + if (!_encapsulate) { - await flushTask.ConfigureAwait(false); + await _stream.WriteAsync(buffer, offset, count).ConfigureAwait(false); + Task flushTask = _stream.FlushAsync(); + if (flushTask.Status == TaskStatus.RanToCompletion) + { + await flushTask.ConfigureAwait(false); + } + return; } - return; - } - using (SNIEventScope.Create(" writing encapsulated bytes")) - { int remainingBytes = count; int dataOffset = offset; byte[] packetBuffer = null; @@ -219,6 +234,10 @@ 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 58384dfd58..3696b1323f 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,9 @@ 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; private int _packetBytes = 0; private bool _encapsulate; @@ -27,9 +29,17 @@ internal sealed partial class SslOverTdsStream : Stream /// Constructor /// /// Underlying stream - public SslOverTdsStream(Stream stream) + public SslOverTdsStream(Stream stream) : this(stream, default) { } + + /// + /// Constructor + /// + /// Underlying stream + /// Connection Id of parent stream handle + public SslOverTdsStream(Stream stream, Guid connectionId = default) { _stream = stream; + _connectionId = connectionId; _encapsulate = true; } @@ -39,7 +49,7 @@ public SslOverTdsStream(Stream stream) public void FinishHandshake() { _encapsulate = false; - SqlClientEventSource.Log.TrySNITraceEvent(" switched from encapsulation to passthrough mode"); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Switched from encapsulation to passthrough mode", args0: _connectionId); } /// @@ -58,6 +68,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); } } diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs index e529110f7b..78da5056f2 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs @@ -1001,6 +1001,7 @@ public override object ExecuteScalar() try { statistics = SqlStatistics.StartTimer(Statistics); + WriteBeginExecuteEvent(); SqlDataReader ds; ds = RunExecuteReader(0, RunBehavior.ReturnImmediately, returnStream: true); success = true; @@ -1081,6 +1082,7 @@ public override int ExecuteNonQuery() try { statistics = SqlStatistics.StartTimer(Statistics); + WriteBeginExecuteEvent(); InternalExecuteNonQuery(completion: null, sendToPipe: false, timeout: CommandTimeout, out _, methodName: nameof(ExecuteNonQuery)); return _rowsAffected; } @@ -1571,7 +1573,7 @@ public XmlReader ExecuteXmlReader() try { statistics = SqlStatistics.StartTimer(Statistics); - + WriteBeginExecuteEvent(); // use the reader to consume metadata SqlDataReader ds; ds = RunExecuteReader(CommandBehavior.SequentialAccess, RunBehavior.ReturnImmediately, returnStream: true); @@ -1646,6 +1648,7 @@ private IAsyncResult BeginExecuteXmlReaderInternal(CommandBehavior behavior, Asy if (!inRetry) { statistics = SqlStatistics.StartTimer(Statistics); + WriteBeginExecuteEvent(); } bool usedCache; @@ -1893,6 +1896,7 @@ protected override DbDataReader ExecuteDbDataReader(CommandBehavior behavior) Exception e = null; try { + WriteBeginExecuteEvent(); statistics = SqlStatistics.StartTimer(Statistics); return RunExecuteReader(behavior, RunBehavior.ReturnImmediately, returnStream: true); } @@ -2071,7 +2075,7 @@ private IAsyncResult BeginExecuteReaderInternal(CommandBehavior behavior, AsyncC if (!inRetry) { statistics = SqlStatistics.StartTimer(Statistics); - + WriteBeginExecuteEvent(); ValidateAsyncCommand(); // Special case - done outside of try/catches to prevent putting a stateObj // back into pool when we should not. } @@ -6272,6 +6276,11 @@ public SqlCommand Clone() return clone; } + private void WriteBeginExecuteEvent() + { + SqlClientEventSource.Log.TryBeginExecuteEvent(ObjectID, Connection?.ClientConnectionId, CommandText); + } + private void WriteEndExecuteEvent(bool success, int? sqlExceptionNumber, bool synchronous) { if (SqlClientEventSource.Log.IsExecutionTraceEnabled()) @@ -6290,7 +6299,7 @@ private void WriteEndExecuteEvent(bool success, int? sqlExceptionNumber, bool sy int compositeState = successFlag | isSqlExceptionFlag | synchronousFlag; - SqlClientEventSource.Log.EndExecute(GetHashCode(), compositeState, sqlExceptionNumber.GetValueOrDefault()); + SqlClientEventSource.Log.TryEndExecuteEvent(ObjectID, Connection?.ClientConnectionId, compositeState, sqlExceptionNumber.GetValueOrDefault()); } } } diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs index 11bc15e092..90f5d0bf02 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs @@ -340,6 +340,7 @@ internal void ProcessPendingAck(TdsParserStateObject stateObj) { if (stateObj._attentionSent) { + SqlClientEventSource.Log.TryTraceEvent("TdsParser.ProcessPendingAck | INFO | Connection Object Id {0}, State Obj Id {1}, Processing Attention.", _connHandler._objectID, stateObj.ObjectID); ProcessAttention(stateObj); } } @@ -379,36 +380,8 @@ internal void Connect( else { _sniSpnBuffer = null; - switch (authType) - { - case SqlAuthenticationMethod.ActiveDirectoryPassword: - SqlClientEventSource.Log.TryTraceEvent(" Active Directory Password authentication"); - break; - case SqlAuthenticationMethod.ActiveDirectoryIntegrated: - SqlClientEventSource.Log.TryTraceEvent(" Active Directory Integrated authentication"); - break; - case SqlAuthenticationMethod.ActiveDirectoryInteractive: - SqlClientEventSource.Log.TryTraceEvent(" Active Directory Interactive authentication"); - break; - case SqlAuthenticationMethod.ActiveDirectoryServicePrincipal: - SqlClientEventSource.Log.TryTraceEvent(" Active Directory Service Principal authentication"); - break; - case SqlAuthenticationMethod.ActiveDirectoryDeviceCodeFlow: - SqlClientEventSource.Log.TryTraceEvent(" Active Directory Device Code Flow authentication"); - break; - case SqlAuthenticationMethod.ActiveDirectoryManagedIdentity: - SqlClientEventSource.Log.TryTraceEvent(" Active Directory Managed Identity authentication"); - break; - case SqlAuthenticationMethod.ActiveDirectoryMSI: - SqlClientEventSource.Log.TryTraceEvent(" Active Directory MSI authentication"); - break; - case SqlAuthenticationMethod.SqlPassword: - SqlClientEventSource.Log.TryTraceEvent(" SQL Password authentication"); - break; - default: - SqlClientEventSource.Log.TryTraceEvent(" SQL authentication"); - break; - } + SqlClientEventSource.Log.TryTraceEvent("TdsParser.Connect | SEC | Connection Object Id {0}, Authentication Mode: {1}", _connHandler._objectID, + authType == SqlAuthenticationMethod.NotSpecified ? SqlAuthenticationMethod.SqlPassword.ToString() : authType.ToString()); } _sniSpnBuffer = null; @@ -417,7 +390,7 @@ internal void Connect( if (integratedSecurity || authType == SqlAuthenticationMethod.ActiveDirectoryIntegrated) { LoadSSPILibrary(); - SqlClientEventSource.Log.TryTraceEvent(" SSPI or Active Directory Authentication Library for SQL Server based integrated authentication"); + SqlClientEventSource.Log.TryTraceEvent("TdsParser.Connect | SEC | SSPI or Active Directory Authentication Library loaded for SQL Server based integrated authentication"); } byte[] instanceName = null; @@ -1328,7 +1301,7 @@ internal SqlError ProcessSNIError(TdsParserStateObject stateObj) #if DEBUG // There is an exception here for MARS as its possible that another thread has closed the connection just as we see an error Debug.Assert(SniContext.Undefined != stateObj.DebugOnlyCopyOfSniContext || ((_fMARS) && ((_state == TdsParserState.Closed) || (_state == TdsParserState.Broken))), "SniContext must not be None"); - SqlClientEventSource.Log.TrySNITraceEvent(" SNIContext must not be None = {0}, _fMARS = {1}, TDS Parser State = {2}", stateObj.DebugOnlyCopyOfSniContext, _fMARS, _state); + SqlClientEventSource.Log.TryTraceEvent(" SNIContext must not be None = {0}, _fMARS = {1}, TDS Parser State = {2}", stateObj.DebugOnlyCopyOfSniContext, _fMARS, _state); #endif SNIErrorDetails details = GetSniErrorDetails(); diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index 55c73b99b9..2a583702a4 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -65,7 +65,7 @@ public TimeoutState(int value) private const long CheckConnectionWindow = 50000; - protected readonly TdsParser _parser; // TdsParser pointer + protected readonly TdsParser _parser; // TdsParser pointer private readonly WeakReference _owner = new WeakReference(null); // the owner of this session, used to track when it's been orphaned internal SqlDataReader.SharedState _readerState; // susbset of SqlDataReader state (if it is the owner) necessary for parsing abandoned results in TDS private int _activateCount; // 0 when we're in the pool, 1 when we're not, all others are an error @@ -263,8 +263,8 @@ public TimeoutState(int value) // instead of blocking it will fail. internal static bool _failAsyncPends = false; - // If this is set and an async read is made, then - // we will switch to syncOverAsync mode for the + // If this is set and an async read is made, then + // we will switch to syncOverAsync mode for the // remainder of the async operation. internal static bool _forceSyncOverAsyncAfterFirstPend = false; @@ -567,8 +567,8 @@ internal bool TryInitialize(TdsParserStateObject stateObj, int columnsCount) return false; } - SqlClientEventSource.Log.TryAdvancedTraceEvent(" {0}, NBCROW bitmap received, column count = {1}", stateObj.ObjectID, columnsCount); - SqlClientEventSource.Log.TryAdvancedTraceBinEvent(" NBCROW bitmap data: ", _nullBitmap, (ushort)_nullBitmap.Length); + SqlClientEventSource.Log.TryAdvancedTraceEvent("TdsParserStateObject.NullBitmap.Initialize | INFO | ADV | State Object Id {0}, NBCROW bitmap received, column count = {1}", stateObj._objectID, columnsCount); + SqlClientEventSource.Log.TryAdvancedTraceBinEvent("TdsParserStateObject.NullBitmap.Initialize | INFO | ADV | State Object Id {0}, Null Bitmap length {1}, NBCROW bitmap data: {2}", stateObj._objectID, (ushort)_nullBitmap.Length, _nullBitmap); return true; } @@ -592,7 +592,7 @@ internal void Clean() } /// - /// If this method returns true, the value is guaranteed to be null. This is not true vice versa: + /// If this method returns true, the value is guaranteed to be null. This is not true vice versa: /// if the bitmap value is false (if this method returns false), the value can be either null or non-null - no guarantee in this case. /// To determine whether it is null or not, read it from the TDS (per NBCROW design spec, for IMAGE/TEXT/NTEXT columns server might send /// bitmap = 0, when the actual value is null). @@ -702,12 +702,12 @@ internal void Cancel(object caller) internal void CancelRequest() { ResetBuffer(); // clear out unsent buffer - // If the first sqlbulkcopy timeout, _outputPacketNumber may not be 1, - // the next sqlbulkcopy (same connection string) requires this to be 1, hence reset + // If the first sqlbulkcopy timeout, _outputPacketNumber may not be 1, + // the next sqlbulkcopy (same connection string) requires this to be 1, hence reset // it here when exception happens in the first sqlbulkcopy ResetPacketCounters(); - // VSDD#907507, if bulkcopy write timeout happens, it already sent the attention, + // VSDD#907507, if bulkcopy write timeout happens, it already sent the attention, // so no need to send it again if (!_bulkCopyWriteTimeout) { @@ -884,6 +884,7 @@ internal void DecrementOpenResultCount() { // If we were not executed under a transaction - decrement the global count // on the parser. + SqlClientEventSource.Log.TryTraceEvent("TdsParserStateObject.DecrementOpenResultCount | INFO | State Object Id {0}, Processing Attention.", _objectID); _parser.DecrementNonTransactedOpenResultCount(); } else @@ -898,7 +899,7 @@ internal void DecrementOpenResultCount() internal int DecrementPendingCallbacks(bool release) { int remaining = Interlocked.Decrement(ref _pendingCallbacks); - SqlClientEventSource.Log.TryAdvancedTraceEvent(" {0}, after decrementing _pendingCallbacks: {1}", ObjectID, _pendingCallbacks); + SqlClientEventSource.Log.TryAdvancedTraceEvent("TdsParserStateObject.DecrementPendingCallbacks | ADV | State Object Id {0}, after decrementing _pendingCallbacks: {1}", _objectID, _pendingCallbacks); FreeGcHandle(remaining, release); // NOTE: TdsParserSessionPool may call DecrementPendingCallbacks on a TdsParserStateObject which is already disposed // This is not dangerous (since the stateObj is no longer in use), but we need to add a workaround in the assert for it @@ -951,7 +952,7 @@ internal int IncrementAndObtainOpenResultCount(SqlInternalTransaction transactio internal int IncrementPendingCallbacks() { int remaining = Interlocked.Increment(ref _pendingCallbacks); - SqlClientEventSource.Log.TryAdvancedTraceEvent(" {0}, after incrementing _pendingCallbacks: {1}", ObjectID, _pendingCallbacks); + SqlClientEventSource.Log.TryAdvancedTraceEvent("TdsParserStateObject.IncrementPendingCallbacks | ADV | State Object Id {0}, after incrementing _pendingCallbacks: {1}", _objectID, _pendingCallbacks); Debug.Assert(0 < remaining && remaining <= 3, $"_pendingCallbacks values is invalid after incrementing: {remaining}"); return remaining; } @@ -1025,7 +1026,7 @@ internal bool TryProcessHeader() // if the header splits buffer reads - special case! if ((_partialHeaderBytesRead > 0) || (_inBytesUsed + _inputHeaderLen > _inBytesRead)) { - // VSTS 219884: when some kind of MITM (man-in-the-middle) tool splits the network packets, the message header can be split over + // VSTS 219884: when some kind of MITM (man-in-the-middle) tool splits the network packets, the message header can be split over // several network packets. // Note: cannot use ReadByteArray here since it uses _inBytesPacket which is not set yet. do @@ -2241,7 +2242,7 @@ internal void ReadSniSyncOverAsync() internal void OnConnectionClosed() { // the stateObj is not null, so the async invocation that registered this callback - // via the SqlReferenceCollection has not yet completed. We will look for a + // via the SqlReferenceCollection has not yet completed. We will look for a // _networkPacketTaskSource and mark it faulted. If we don't find it, then // TdsParserStateObject.ReadSni will abort when it does look to see if the parser // is open. If we do, then when the call that created it completes and a continuation @@ -2255,7 +2256,7 @@ internal void OnConnectionClosed() Parser.State = TdsParserState.Broken; Parser.Connection.BreakConnection(); - // Ensure that changing state occurs before checking _networkPacketTaskSource + // Ensure that changing state occurs before checking _networkPacketTaskSource Interlocked.MemoryBarrier(); // then check for networkPacketTaskSource @@ -2403,7 +2404,7 @@ private bool OnTimeoutCore(int expectedState, int targetState) } } - // Ensure that the connection is no longer usable + // Ensure that the connection is no longer usable // This is needed since the timeout error added above is non-fatal (and so throwing it won't break the connection) _parser.State = TdsParserState.Broken; _parser.Connection.BreakConnection(); @@ -2599,7 +2600,7 @@ internal bool IsConnectionAlive(bool throwOnException) if ((error != TdsEnums.SNI_SUCCESS) && (error != TdsEnums.SNI_WAIT_TIMEOUT)) { // Connection is dead - SqlClientEventSource.Log.TryTraceEvent(" received error {0} on idle connection", (int)error); + SqlClientEventSource.Log.TryTraceEvent("TdsParserStateObject.IsConnectionAlive | Info | State Object Id {0}, received error {1} on idle connection", _objectID, (int)error); isAlive = false; if (throwOnException) { @@ -2619,7 +2620,7 @@ internal bool IsConnectionAlive(bool throwOnException) } /// - /// Checks to see if the underlying connection is still valid (used by idle connection resiliency - for active connections) + /// Checks to see if the underlying connection is still valid (used by idle connection resiliency - for active connections) /// NOTE: This is not safe to do on a connection that is currently in use /// NOTE: This will mark the connection as broken if it is found to be dead /// @@ -2881,7 +2882,8 @@ public void ReadAsyncCallback(IntPtr key, PacketHandle packet, uint error) Debug.Assert(CheckPacket(packet, source) && source != null, "AsyncResult null on callback"); if (_parser.MARSOn) - { // Only take reset lock on MARS and Async. + { + // Only take reset lock on MARS and Async. CheckSetResetConnectionState(error, CallbackType.Read); } @@ -2987,7 +2989,7 @@ private void ReadAsyncCallbackCaptureException(TaskCompletionSource sour Debug.Assert(_parser.State == TdsParserState.Broken || _parser.State == TdsParserState.Closed || _parser.Connection.IsConnectionDoomed, "Failed to capture exception while the connection was still healthy"); // The safest thing to do is to ensure that the connection is broken and attempt to cancel the task - // This must be done from another thread to not block the callback thread + // This must be done from another thread to not block the callback thread Task.Factory.StartNew(() => { _parser.State = TdsParserState.Broken; @@ -3007,7 +3009,7 @@ public void WriteAsyncCallback(IntPtr key, PacketHandle packet, uint sniError) { if (sniError != TdsEnums.SNI_SUCCESS) { - SqlClientEventSource.Log.TryTraceEvent(" write async returned error code {0}", (int)sniError); + SqlClientEventSource.Log.TryTraceEvent("TdsParserStateObject.WriteAsyncCallback | Info | State Object Id {0}, Write async returned error code {1}", _objectID, (int)sniError); try { AddError(_parser.ProcessSNIError(this)); @@ -3187,7 +3189,7 @@ internal Task WriteByteArray(byte[] b, int len, int offsetBuffer, bool canAccumu // Takes a span or a byte array and writes it to the buffer // If you pass in a span and a null array then the span wil be used. // If you pass in a non-null array then the array will be used and the span is ignored. - // if the span cannot be written into the current packet then the remaining contents of the span are copied to a + // if the span cannot be written into the current packet then the remaining contents of the span are copied to a // new heap allocated array that will used to callback into the method to continue the write operation. private Task WriteBytes(ReadOnlySpan b, int len, int offsetBuffer, bool canAccumulate = true, TaskCompletionSource completion = null, byte[] array = null) { @@ -3483,7 +3485,7 @@ private Task SNIWritePacket(PacketHandle packet, out uint sniError, bool canAccu #if DEBUG else if (!sync && !canAccumulate && SqlCommand.DebugForceAsyncWriteDelay > 0) { - // Executed synchronously - callback will not be called + // Executed synchronously - callback will not be called TaskCompletionSource completion = new TaskCompletionSource(); uint error = sniError; new Timer(obj => @@ -3497,7 +3499,7 @@ private Task SNIWritePacket(PacketHandle packet, out uint sniError, bool canAccu if (error != TdsEnums.SNI_SUCCESS) { - SqlClientEventSource.Log.TryTraceEvent(" write async returned error code {0}", (int)error); + SqlClientEventSource.Log.TryTraceEvent("TdsParserStateObject.SNIWritePacket | Info | State Object Id {0}, Write async returned error code {1}", _objectID, (int)error); AddError(_parser.ProcessSNIError(this)); ThrowExceptionAndWarning(); } @@ -3532,7 +3534,7 @@ private Task SNIWritePacket(PacketHandle packet, out uint sniError, bool canAccu } else { - SqlClientEventSource.Log.TryTraceEvent(" write async returned error code {0}", (int)sniError); + SqlClientEventSource.Log.TryTraceEvent("TdsParserStateObject.SNIWritePacket | Info | State Object Id {0}, Write async returned error code {1}", _objectID, (int)sniError); AddError(_parser.ProcessSNIError(this)); ThrowExceptionAndWarning(callerHasConnectionLock); } @@ -3587,9 +3589,9 @@ internal void SendAttention(bool mustTakeWriteLock = false) } uint sniError; - _parser._asyncWrite = false; // stop async write + _parser._asyncWrite = false; // stop async write SNIWritePacket(attnPacket, out sniError, canAccumulate: false, callerHasConnectionLock: false); - SqlClientEventSource.Log.TryTraceEvent(" Send Attention ASync."); + SqlClientEventSource.Log.TryTraceEvent("TdsParserStateObject.SendAttention | Info | State Object Id {0}, Sent Attention.", _objectID); } finally { @@ -3611,8 +3613,8 @@ internal void SendAttention(bool mustTakeWriteLock = false) _attentionSending = false; } - SqlClientEventSource.Log.TryAdvancedTraceBinEvent(" Packet sent", _outBuff, (ushort)_outBytesUsed); - SqlClientEventSource.Log.TryTraceEvent(" Attention sent to the server."); + SqlClientEventSource.Log.TryAdvancedTraceBinEvent("TdsParserStateObject.SendAttention | INFO | ADV | State Object Id {0}, Packet sent. Out Buffer {1}, Out Bytes Used: {2}", _objectID, _outBuff, (ushort)_outBytesUsed); + SqlClientEventSource.Log.TryTraceEvent("TdsParserStateObject.SendAttention | Info | State Object Id {0}, Attention sent to the server.", _objectID); AssertValidState(); } diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObjectManaged.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObjectManaged.cs index 0040aaecf5..b1e61a976e 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObjectManaged.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObjectManaged.cs @@ -35,14 +35,15 @@ protected override bool CheckPacket(PacketHandle packet, TaskCompletionSource @@ -7402,7 +7399,7 @@ private void WriteEndExecuteEvent(bool success, int? sqlExceptionNumber, bool sy int compositeState = successFlag | isSqlExceptionFlag | synchronousFlag; - SqlClientEventSource.Log.EndExecute(GetHashCode(), compositeState, sqlExceptionNumber.GetValueOrDefault()); + SqlClientEventSource.Log.TryEndExecuteEvent(ObjectID, Connection?.ClientConnectionId, compositeState, sqlExceptionNumber.GetValueOrDefault()); } } diff --git a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index 0b2baeb0be..919f048dcc 100644 --- a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -590,8 +590,8 @@ internal bool TryInitialize(TdsParserStateObject stateObj, int columnsCount) { return false; } - SqlClientEventSource.Log.TryAdvancedTraceEvent(" {0}, NBCROW bitmap received, column count = {1}", stateObj.ObjectID, columnsCount); - SqlClientEventSource.Log.TryAdvancedTraceBinEvent(" NBCROW bitmap data: ", _nullBitmap, (ushort)_nullBitmap.Length); + SqlClientEventSource.Log.TryAdvancedTraceEvent("TdsParserStateObject.NullBitmap.Initialize | INFO | ADV | State Object Id {0}, NBCROW bitmap received, column count = {1}", stateObj.ObjectID, columnsCount); + SqlClientEventSource.Log.TryAdvancedTraceBinEvent("TdsParserStateObject.NullBitmap.Initialize | INFO | ADV | State Object Id {0}, NBCROW bitmap data. Null Bitmap {1}, Null bitmap length: {2}", stateObj.ObjectID, _nullBitmap, (ushort)_nullBitmap.Length); return true; } @@ -2908,7 +2908,7 @@ public void ProcessSniPacket(IntPtr packet, UInt32 error) } } SniReadStatisticsAndTracing(); - SqlClientEventSource.Log.TryAdvancedTraceBinEvent(" Packet read", _inBuff, (ushort)_inBytesRead); + SqlClientEventSource.Log.TryAdvancedTraceBinEvent("TdsParser.ReadNetworkPacketAsyncCallback | INFO | ADV | State Object Id {0}, Packet read. In Buffer {1}, In Bytes Read: {2}", ObjectID, _inBuff, (ushort)_inBytesRead); AssertValidState(); } else @@ -3673,8 +3673,8 @@ internal void SendAttention(bool mustTakeWriteLock = false) _attentionSending = false; } - SqlClientEventSource.Log.TryAdvancedTraceBinEvent(" Packet sent", _outBuff, (ushort)_outBytesUsed); - SqlClientEventSource.Log.TryTraceEvent(" Attention sent to the server.", "Info"); + SqlClientEventSource.Log.TryAdvancedTraceBinEvent("TdsParser.WritePacket | INFO | ADV | State Object Id {0}, Packet sent. Out Buffer {1}, Out Bytes Used {2}", ObjectID, _outBuff, (ushort)_outBytesUsed); + SqlClientEventSource.Log.TryTraceEvent("TdsParser.SendAttention | INFO | Attention sent to the server."); AssertValidState(); } @@ -3860,7 +3860,7 @@ private void SniWriteStatisticsAndTracing() _traceChangePasswordLength = 0; } } - SqlClientEventSource.Log.TryAdvancedTraceBinEvent(" Packet sent", _outBuff, (ushort)_outBytesUsed); + SqlClientEventSource.Log.TryAdvancedTraceBinEvent("TdsParser.WritePacket | INFO | ADV | State Object Id {0}, Packet sent. Out buffer: {1}, Out Bytes Used: {2}", ObjectID, _outBuff, (ushort)_outBytesUsed); } [Conditional("DEBUG")] diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlClientEventSource.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlClientEventSource.cs index 971f719ec9..045b8c7eba 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlClientEventSource.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlClientEventSource.cs @@ -4,6 +4,7 @@ using System; using System.Diagnostics.Tracing; +using System.Text; using System.Threading; namespace Microsoft.Data.SqlClient @@ -15,6 +16,7 @@ internal partial class SqlClientEventSource : EventSource internal static readonly SqlClientEventSource Log = new SqlClientEventSource(); private const string NullStr = "null"; + private const string SqlCommand_ClassName = nameof(SqlCommand); #region Event IDs // Initialized static Scope IDs @@ -226,6 +228,26 @@ public static class Tasks /// Task that tracks SqlCommand execution. /// public const EventTask ExecuteCommand = (EventTask)1; + + /// + /// Task that tracks trace scope. + /// + public const EventTask Scope = (EventTask)2; + + /// + /// Task that tracks trace scope. + /// + public const EventTask PoolerScope = (EventTask)3; + + /// + /// Task that tracks trace scope. + /// + public const EventTask NotificationScope = (EventTask)4; + + /// + /// Task that tracks trace scope. + /// + public const EventTask SNIScope = (EventTask)5; } #endregion @@ -267,6 +289,9 @@ public static class Tasks internal bool IsSNIScopeEnabled() => Log.IsEnabled(EventLevel.Informational, Keywords.SNIScope); #endregion + private string GetFormattedMessage(string className, string memberName, string eventType, string message) => + new StringBuilder(className).Append(".").Append(memberName).Append(eventType).Append(message).ToString(); + #region overloads //Never use event writer directly as they are not checking for enabled/disabled situations. Always use overloads. @@ -274,7 +299,7 @@ public static class Tasks #region Traces without if statements [NonEvent] - internal void TraceEvent(string message, T0 args0, T1 args1) + internal void TraceEvent(string message, T0 args0, T1 args1, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") { Trace(string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr)); } @@ -361,11 +386,13 @@ internal void TryTraceEvent(string message, T0 args0, T1 #region Scope [NonEvent] - internal long TryScopeEnterEvent(string message) + internal long TryScopeEnterEvent(string className, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") { if (Log.IsScopeEnabled()) { - return ScopeEnter(message); + StringBuilder sb = new StringBuilder(className); + sb.Append(".").Append(memberName).Append(" | INFO | SCOPE | Entering Scope {0}"); + return SNIScopeEnter(sb.ToString()); } return 0; } @@ -415,7 +442,29 @@ internal void TryScopeLeaveEvent(long scopeId) { if (Log.IsScopeEnabled()) { - ScopeLeave(scopeId); + ScopeLeave(string.Format("Exit Scope {0}", scopeId)); + } + } + #endregion + + #region Execution Trace + [NonEvent] + internal void TryBeginExecuteEvent(int objectId, object connectionId, string commandText, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") + { + if (Log.IsExecutionTraceEnabled()) + { + BeginExecute(GetFormattedMessage(SqlCommand_ClassName, memberName, EventType.INFO, + string.Format("Object Id {0}, Client Connection Id {1}, Command Text {2}", objectId, connectionId, commandText))); + } + } + + [NonEvent] + internal void TryEndExecuteEvent(int objectId, object connectionId, int compositeState, int sqlExceptionNumber, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") + { + if (Log.IsExecutionTraceEnabled()) + { + EndExecute(GetFormattedMessage(SqlCommand_ClassName, memberName, EventType.INFO, + string.Format("Object Id {0}, Client Connection Id {1}, Composite State {2}, Sql Exception Number {3}", objectId, connectionId, compositeState, sqlExceptionNumber))); } } #endregion @@ -525,7 +574,7 @@ internal void TryNotificationScopeLeaveEvent(long scopeId) { if (Log.IsNotificationScopeEnabled()) { - NotificationScopeLeave(scopeId); + NotificationScopeLeave(string.Format("Exit Notification Scope {0}", scopeId)); } } #endregion @@ -584,7 +633,7 @@ internal void TryPoolerScopeLeaveEvent(long scopeId) { if (Log.IsPoolerScopeEnabled()) { - PoolerScopeLeave(scopeId); + PoolerScopeLeave(string.Format("Exit Pooler Scope {0}", scopeId)); } } #endregion @@ -663,6 +712,15 @@ internal void TryAdvancedTraceEvent(string message, T0 args0, T1 } } + [NonEvent] + internal void TryAdvancedTraceEvent(string message, T0 args0, T1 args1, T2 args2, T3 args3, T4 args4) + { + if (Log.IsAdvancedTraceOn()) + { + AdvancedTrace(string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr, args2?.ToString() ?? NullStr, args3?.ToString() ?? NullStr, args4?.ToString() ?? NullStr)); + } + } + [NonEvent] internal void TryAdvancedTraceEvent(string message, T0 args0, T1 args1, T2 args2, T3 args3, T4 args4, T5 args5) { @@ -696,16 +754,16 @@ internal void TryAdvanceScopeLeave(long scopeId) { if (Log.IsAdvancedTraceOn()) { - AdvancedScopeLeave(scopeId); + AdvancedScopeLeave(string.Format("Exit Advanced Scope {0}", scopeId)); } } [NonEvent] - internal void TryAdvancedTraceBinEvent(string message, T0 args0, T1 args1) + internal void TryAdvancedTraceBinEvent(string message, T0 args0, T1 args1, T2 args) { if (Log.IsAdvancedTraceOn()) { - AdvancedTraceBin(string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr)); + AdvancedTraceBin(string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr, args1?.ToString() ?? NullStr)); } } @@ -787,107 +845,78 @@ internal void StateDumpEvent(string message, T0 args0, T1 args1) #region SNI Trace [NonEvent] - internal void TrySNITraceEvent(string message) + internal void TrySNITraceEvent(string className, string eventType, string message, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") { if (Log.IsSNITraceEnabled()) { - SNITrace(string.Format(message)); + SNITrace(GetFormattedMessage(className, memberName, eventType, message)); } } [NonEvent] - internal void TrySNITraceEvent(string message, T0 args0) + internal void TrySNITraceEvent(string className, string eventType, string message, T0 args0, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") { if (Log.IsSNITraceEnabled()) { - SNITrace(string.Format(message, args0?.ToString() ?? NullStr)); + SNITrace(GetFormattedMessage(className, memberName, eventType, string.Format(message, args0?.ToString() ?? NullStr))); } } [NonEvent] - internal void TrySNITraceEvent(string message, T0 args0, T1 args1) + internal void TrySNITraceEvent(string className, string eventType, string message, T0 args0, T1 args1, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") { if (Log.IsSNITraceEnabled()) { - SNITrace(string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr)); + SNITrace(GetFormattedMessage(className, memberName, eventType, string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr))); } } [NonEvent] - internal void TrySNITraceEvent(string message, T0 args0, T1 args1, T2 args2) + internal void TrySNITraceEvent(string className, string eventType, string message, T0 args0, T1 args1, T2 args2, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") { if (Log.IsSNITraceEnabled()) { - SNITrace(string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr, args2?.ToString() ?? NullStr)); + SNITrace(GetFormattedMessage(className, memberName, eventType, string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr, args2?.ToString() ?? NullStr))); } } [NonEvent] - internal void TrySNITraceEvent(string message, T0 args0, T1 args1, T2 args2, T3 args3) + internal void TrySNITraceEvent(string className, string eventType, string message, T0 args0, T1 args1, T2 args2, T3 args3, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") { if (Log.IsSNITraceEnabled()) { - SNITrace(string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr, args2?.ToString() ?? NullStr, args3?.ToString() ?? NullStr)); + SNITrace(GetFormattedMessage(className, memberName, eventType, string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr, args2?.ToString() ?? NullStr, args3?.ToString() ?? NullStr))); } } [NonEvent] - internal void TrySNITraceEvent(string message, T0 args0, T1 args1, T2 args2, T3 args3, T4 args4) + internal void TrySNITraceEvent(string className, string eventType, string message, T0 args0, T1 args1, T2 args2, T3 args3, T4 args4, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") { if (Log.IsSNITraceEnabled()) { - SNITrace(string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr, args2?.ToString() ?? NullStr, args3?.ToString() ?? NullStr, args4?.ToString() ?? NullStr)); - } - } - #endregion - - #region SNI Scope - [NonEvent] - internal long TrySNIScopeEnterEvent(string message) - { - if (Log.IsSNIScopeEnabled()) - { - return SNIScopeEnter(message); - } - return 0; - } - - [NonEvent] - internal long TrySNIScopeEnterEvent(string message, T0 args0) - { - if (Log.IsSNIScopeEnabled()) - { - return SNIScopeEnter(string.Format(message, args0?.ToString() ?? NullStr)); + SNITrace(GetFormattedMessage(className, memberName, eventType, string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr, args2?.ToString() ?? NullStr, args3?.ToString() ?? NullStr, args4?.ToString() ?? NullStr))); } - return 0; } [NonEvent] - internal long TrySNIScopeEnterEvent(string message, T0 args0, T1 args1) + internal void TrySNITraceEvent(string className, string eventType, string message, T0 args0, T1 args1, T2 args2, T3 args3, T4 args4, T5 args5, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") { - if (Log.IsSNIScopeEnabled()) - { - return SNIScopeEnter(string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr)); - } - return 0; - } - - [NonEvent] - internal long TrySNIScopeEnterEvent(string message, T0 args0, T1 args1, T2 args2) - { - if (Log.IsSNIScopeEnabled()) + if (Log.IsSNITraceEnabled()) { - return SNIScopeEnter(string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr, args2?.ToString() ?? NullStr)); + SNITrace(GetFormattedMessage(className, memberName, eventType, string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr, args2?.ToString() ?? NullStr, args3?.ToString() ?? NullStr, args4?.ToString() ?? NullStr, args5?.ToString() ?? NullStr))); } - return 0; } + #endregion + #region SNI Scope [NonEvent] - internal long TrySNIScopeEnterEvent(string message, T0 args0, T1 args1, T2 args2, T3 args3) + internal long TrySNIScopeEnterEvent(string className, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") { if (Log.IsSNIScopeEnabled()) { - return SNIScopeEnter(string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr, args2?.ToString() ?? NullStr, args3?.ToString() ?? NullStr)); + StringBuilder sb = new StringBuilder(className); + sb.Append(".").Append(memberName).Append(" | SNI | INFO | SCOPE | Entering Scope {0}"); + return SNIScopeEnter(sb.ToString()); } return 0; } @@ -897,7 +926,7 @@ internal void TrySNIScopeLeaveEvent(long scopeId) { if (Log.IsSNIScopeEnabled()) { - SNIScopeLeave(scopeId); + SNIScopeLeave(string.Format("Exit SNI Scope {0}", scopeId)); } } #endregion @@ -906,166 +935,125 @@ internal void TrySNIScopeLeaveEvent(long scopeId) #region Write Events [Event(BeginExecuteEventId, Keywords = Keywords.ExecutionTrace, Task = Tasks.ExecuteCommand, Opcode = EventOpcode.Start)] - internal void BeginExecute(int objectId, string dataSource, string database, string commandText) - { - if (Log.IsExecutionTraceEnabled()) - { - WriteEvent(BeginExecuteEventId, objectId, dataSource, database, commandText); - } - } + internal void BeginExecute(string message) => + WriteEvent(BeginExecuteEventId, message); [Event(EndExecuteEventId, Keywords = Keywords.ExecutionTrace, Task = Tasks.ExecuteCommand, Opcode = EventOpcode.Stop)] - internal void EndExecute(int objectId, int compositeState, int sqlExceptionNumber) - { - if (Log.IsExecutionTraceEnabled()) - { - WriteEvent(EndExecuteEventId, objectId, compositeState, sqlExceptionNumber); - } - } + internal void EndExecute(string message) => + WriteEvent(EndExecuteEventId, message); [Event(TraceEventId, Level = EventLevel.Informational, Keywords = Keywords.Trace)] - internal void Trace(string message) - { + internal void Trace(string message) => WriteEvent(TraceEventId, message); - } - [Event(ScopeEnterId, Level = EventLevel.Informational, Opcode = EventOpcode.Start, Keywords = Keywords.Scope)] + [Event(ScopeEnterId, Level = EventLevel.Informational, Task = Tasks.Scope, Opcode = EventOpcode.Start, Keywords = Keywords.Scope)] internal long ScopeEnter(string message) { long scopeId = Interlocked.Increment(ref s_nextScopeId); - WriteEvent(ScopeEnterId, message); + WriteEvent(ScopeEnterId, string.Format(message, scopeId)); return scopeId; } - [Event(ScopeExitId, Level = EventLevel.Informational, Opcode = EventOpcode.Stop, Keywords = Keywords.Scope)] - internal void ScopeLeave(long scopeId) - { - WriteEvent(ScopeExitId, scopeId); - } + [Event(ScopeExitId, Level = EventLevel.Informational, Task = Tasks.Scope, Opcode = EventOpcode.Stop, Keywords = Keywords.Scope)] + internal void ScopeLeave(string message) => + WriteEvent(ScopeExitId, message); [Event(NotificationTraceId, Level = EventLevel.Informational, Keywords = Keywords.NotificationTrace)] - internal void NotificationTrace(string message) - { + internal void NotificationTrace(string message) => WriteEvent(NotificationTraceId, message); - } - [Event(NotificationScopeEnterId, Level = EventLevel.Informational, Opcode = EventOpcode.Start, Keywords = Keywords.NotificationScope)] + [Event(NotificationScopeEnterId, Level = EventLevel.Informational, Task = Tasks.NotificationScope, Opcode = EventOpcode.Start, Keywords = Keywords.NotificationScope)] internal long NotificationScopeEnter(string message) { long scopeId = Interlocked.Increment(ref s_nextNotificationScopeId); - WriteEvent(NotificationScopeEnterId, message); + WriteEvent(NotificationScopeEnterId, string.Format(message, scopeId)); return scopeId; } - [Event(NotificationScopeExitId, Level = EventLevel.Informational, Opcode = EventOpcode.Stop, Keywords = Keywords.NotificationScope)] - internal void NotificationScopeLeave(long scopeId) - { - WriteEvent(NotificationScopeExitId, scopeId); - } + [Event(NotificationScopeExitId, Level = EventLevel.Informational, Task = Tasks.NotificationScope, Opcode = EventOpcode.Stop, Keywords = Keywords.NotificationScope)] + internal void NotificationScopeLeave(string message) => + WriteEvent(NotificationScopeExitId, message); [Event(PoolerTraceId, Level = EventLevel.Informational, Keywords = Keywords.PoolerTrace)] - internal void PoolerTrace(string message) - { + internal void PoolerTrace(string message) => WriteEvent(PoolerTraceId, message); - } - [Event(PoolerScopeEnterId, Level = EventLevel.Informational, Opcode = EventOpcode.Start, Keywords = Keywords.PoolerScope)] + [Event(PoolerScopeEnterId, Level = EventLevel.Informational, Task = Tasks.PoolerScope, Opcode = EventOpcode.Start, Keywords = Keywords.PoolerScope)] internal long PoolerScopeEnter(string message) { long scopeId = Interlocked.Increment(ref s_nextPoolerScopeId); - WriteEvent(PoolerScopeEnterId, message); + WriteEvent(PoolerScopeEnterId, string.Format(message, scopeId)); return scopeId; } - [Event(PoolerScopeExitId, Level = EventLevel.Informational, Opcode = EventOpcode.Stop, Keywords = Keywords.PoolerScope)] - internal void PoolerScopeLeave(long scopeId) - { - WriteEvent(PoolerScopeExitId, scopeId); - } + [Event(PoolerScopeExitId, Level = EventLevel.Informational, Task = Tasks.PoolerScope, Opcode = EventOpcode.Stop, Keywords = Keywords.PoolerScope)] + internal void PoolerScopeLeave(string message) => + WriteEvent(PoolerScopeExitId, message); [Event(AdvancedTraceId, Level = EventLevel.Verbose, Keywords = Keywords.AdvancedTrace)] - internal void AdvancedTrace(string message) - { + internal void AdvancedTrace(string message) => WriteEvent(AdvancedTraceId, message); - } [Event(AdvancedScopeEnterId, Level = EventLevel.Verbose, Opcode = EventOpcode.Start, Keywords = Keywords.AdvancedTrace)] internal long AdvancedScopeEnter(string message) { long scopeId = Interlocked.Increment(ref s_nextScopeId); - WriteEvent(AdvancedScopeEnterId, message); + WriteEvent(AdvancedScopeEnterId, string.Format(message, scopeId)); return scopeId; } [Event(AdvancedScopeExitId, Level = EventLevel.Verbose, Opcode = EventOpcode.Stop, Keywords = Keywords.AdvancedTrace)] - internal void AdvancedScopeLeave(long scopeId) - { - WriteEvent(AdvancedScopeExitId, scopeId); - } + internal void AdvancedScopeLeave(string message) => + WriteEvent(AdvancedScopeExitId, message); [Event(AdvancedTraceBinId, Level = EventLevel.Verbose, Keywords = Keywords.AdvancedTraceBin)] - internal void AdvancedTraceBin(string message) - { + internal void AdvancedTraceBin(string message) => WriteEvent(AdvancedTraceBinId, message); - } [Event(AdvancedTraceErrorId, Level = EventLevel.Error, Keywords = Keywords.AdvancedTrace)] - internal void AdvancedTraceError(string message) - { + internal void AdvancedTraceError(string message) => WriteEvent(AdvancedTraceErrorId, message); - } - [Event(CorrelationTraceId, Level = EventLevel.Informational, Keywords = Keywords.CorrelationTrace, Opcode = EventOpcode.Start)] - internal void CorrelationTrace(string message) - { + [Event(CorrelationTraceId, Level = EventLevel.Informational, Keywords = Keywords.CorrelationTrace)] + internal void CorrelationTrace(string message) => WriteEvent(CorrelationTraceId, message); - } [Event(StateDumpEventId, Level = EventLevel.Verbose, Keywords = Keywords.StateDump)] - internal void StateDump(string message) - { + internal void StateDump(string message) => WriteEvent(StateDumpEventId, message); - } [Event(SNITraceEventId, Level = EventLevel.Informational, Keywords = Keywords.SNITrace)] - internal void SNITrace(string message) - { + internal void SNITrace(string message) => WriteEvent(SNITraceEventId, message); - } - [Event(SNIScopeEnterId, Level = EventLevel.Informational, Opcode = EventOpcode.Start, Keywords = Keywords.SNIScope)] + [Event(SNIScopeEnterId, Level = EventLevel.Informational, Task = Tasks.SNIScope, Opcode = EventOpcode.Start, Keywords = Keywords.SNIScope)] internal long SNIScopeEnter(string message) { long scopeId = Interlocked.Increment(ref s_nextSNIScopeId); - WriteEvent(SNIScopeEnterId, message); + WriteEvent(SNIScopeEnterId, string.Format(message, scopeId)); return scopeId; } - [Event(SNIScopeExitId, Level = EventLevel.Informational, Opcode = EventOpcode.Stop, Keywords = Keywords.SNIScope)] - internal void SNIScopeLeave(long scopeId) - { - WriteEvent(SNIScopeExitId, scopeId); - } + [Event(SNIScopeExitId, Level = EventLevel.Informational, Task = Tasks.SNIScope, Opcode = EventOpcode.Stop, Keywords = Keywords.SNIScope)] + internal void SNIScopeLeave(string message) => + WriteEvent(SNIScopeExitId, message); #endregion } + internal static class EventType + { + public const string INFO = " | INFO | "; + public const string ERR = " | ERR | "; + } + internal readonly struct SNIEventScope : IDisposable { - private readonly long _scopeID; + private readonly long _scopeId; - public SNIEventScope(long scopeID) - { - _scopeID = scopeID; - } + public SNIEventScope(long scopeID) => _scopeId = scopeID; + public void Dispose() => + SqlClientEventSource.Log.SNIScopeLeave(string.Format("Exit SNI Scope {0}", _scopeId)); - public void Dispose() - { - SqlClientEventSource.Log.SNIScopeLeave(_scopeID); - } - - public static SNIEventScope Create(string message) - { - return new SNIEventScope(SqlClientEventSource.Log.SNIScopeEnter(message)); - } + public static SNIEventScope Create(string message) => new SNIEventScope(SqlClientEventSource.Log.SNIScopeEnter(message)); } }