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 e6801e05b1..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 @@ -128,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("LocalDB.Windows.LoadUserInstanceDll | SNI | ERR | User instance DLL path is null."); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "User instance DLL path is null."); return false; } @@ -136,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("LocalDB.Windows.LoadUserInstanceDll | SNI | ERR | 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; } @@ -146,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("LocalDB.Windows.LoadUserInstanceDll | SNI | ERR | 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; } @@ -157,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("LocalDB.Windows.LoadUserInstanceDll | SNI | ERR | 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; } @@ -174,7 +174,7 @@ private bool LoadUserInstanceDll() } _sqlUserInstanceLibraryHandle = libraryHandle; - SqlClientEventSource.Log.TrySNITraceEvent("LocalDB.Windows.LoadUserInstanceDll | SNI | INFO | User Instance DLL was loaded successfully."); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "User Instance DLL was loaded successfully."); return true; } } @@ -200,7 +200,7 @@ private string GetUserInstanceDllPath(out LocalDBErrorState errorState) if (key == null) { errorState = LocalDBErrorState.NO_INSTALLATION; - SqlClientEventSource.Log.TrySNITraceEvent("LocalDB.Windows.GetUserInstanceDllPath | SNI | ERR | No installation found."); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "No installation found."); return null; } @@ -215,7 +215,7 @@ private string GetUserInstanceDllPath(out LocalDBErrorState errorState) if (!Version.TryParse(subKey, out currentKeyVersion)) { errorState = LocalDBErrorState.INVALID_CONFIG; - SqlClientEventSource.Log.TrySNITraceEvent("LocalDB.Windows.GetUserInstanceDllPath | SNI | ERR | Invalid Configuration."); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Invalid Configuration."); return null; } @@ -229,7 +229,7 @@ private string GetUserInstanceDllPath(out LocalDBErrorState errorState) if (latestVersion.Equals(zeroVersion)) { errorState = LocalDBErrorState.INVALID_CONFIG; - SqlClientEventSource.Log.TrySNITraceEvent("LocalDB.Windows.GetUserInstanceDllPath | SNI | ERR | Invalid Configuration."); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Invalid Configuration."); return null; } @@ -242,7 +242,7 @@ private string GetUserInstanceDllPath(out LocalDBErrorState errorState) if (instanceAPIPathRegistryObject == null) { errorState = LocalDBErrorState.NO_SQLUSERINSTANCEDLL_PATH; - SqlClientEventSource.Log.TrySNITraceEvent("LocalDB.Windows.GetUserInstanceDllPath | SNI | ERR | No SQL user instance DLL. Instance API Path Registry Object Error."); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "No SQL user instance DLL. Instance API Path Registry Object Error."); return null; } @@ -251,7 +251,7 @@ private string GetUserInstanceDllPath(out LocalDBErrorState errorState) if (valueKind != RegistryValueKind.String) { errorState = LocalDBErrorState.INVALID_SQLUSERINSTANCEDLL_PATH; - SqlClientEventSource.Log.TrySNITraceEvent("LocalDB.Windows.GetUserInstanceDllPath | SNI | ERR | Invalid SQL user instance DLL path. Registry value kind mismatch."); + 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 f42ff57c7d..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; @@ -141,7 +143,7 @@ internal static bool ValidateSslServerCertificate(string targetServerName, X509C { if (policyErrors == SslPolicyErrors.None) { - SqlClientEventSource.Log.TrySNITraceEvent("SNICommon.ValidateSslServerCertificate | SNI | INFO | targetServerName {0}, SSL Server certificate not validated as PolicyErrors set to None.", targetServerName); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "targetServerName {0}, SSL Server certificate not validated as PolicyErrors set to None.", args0: targetServerName); return true; } @@ -152,7 +154,7 @@ internal static bool ValidateSslServerCertificate(string targetServerName, X509C // Verify that target server name matches subject in the certificate if (targetServerName.Length > certServerName.Length) { - SqlClientEventSource.Log.TrySNITraceEvent("SNICommon.ValidateSslServerCertificate | SNI | ERR | targetServerName {0}, Target Server name is of greater length than Subject in Certificate.", targetServerName); + 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,7 +162,7 @@ internal static bool ValidateSslServerCertificate(string targetServerName, X509C // Both strings have the same length, so targetServerName must be a FQDN if (!targetServerName.Equals(certServerName, StringComparison.OrdinalIgnoreCase)) { - SqlClientEventSource.Log.TrySNITraceEvent("SNICommon.ValidateSslServerCertificate | SNI | ERR | targetServerName {0}, Target Server name does not match Subject in Certificate.", targetServerName); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "targetServerName {0}, Target Server name does not match Subject in Certificate.", args0: targetServerName); return false; } } @@ -168,7 +170,7 @@ internal static bool ValidateSslServerCertificate(string targetServerName, X509C { if (string.Compare(targetServerName, 0, certServerName, 0, targetServerName.Length, StringComparison.OrdinalIgnoreCase) != 0) { - SqlClientEventSource.Log.TrySNITraceEvent("SNICommon.ValidateSslServerCertificate | SNI | ERR | targetServerName {0}, Target Server name does not match Subject in Certificate.", targetServerName); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "targetServerName {0}, Target Server name does not match Subject in Certificate.", args0: targetServerName); return false; } @@ -178,7 +180,7 @@ internal static bool ValidateSslServerCertificate(string targetServerName, X509C // (Names have different lengths, so the target server can't be a FQDN.) if (certServerName[targetServerName.Length] != '.') { - SqlClientEventSource.Log.TrySNITraceEvent("SNICommon.ValidateSslServerCertificate | SNI | ERR | targetServerName {0}, Target Server name does not match Subject in Certificate.", targetServerName); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "targetServerName {0}, Target Server name does not match Subject in Certificate.", args0: targetServerName); return false; } } @@ -186,10 +188,10 @@ internal static bool ValidateSslServerCertificate(string targetServerName, X509C else { // Fail all other SslPolicy cases besides RemoteCertificateNameMismatch - SqlClientEventSource.Log.TrySNITraceEvent("SNICommon.ValidateSslServerCertificate | SNI | ERR | targetServerName {0}, SslPolicyError {1}, SSL Policy invalidated certificate.", targetServerName, policyErrors); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "targetServerName {0}, SslPolicyError {1}, SSL Policy invalidated certificate.", args0: targetServerName, args1: policyErrors); return false; } - SqlClientEventSource.Log.TrySNITraceEvent("SNICommon.ValidateSslServerCertificate | SNI | INFO | targetServerName {0}, Client certificate validated successfully.", targetServerName); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "targetServerName {0}, Client certificate validated successfully.", args0: targetServerName); return true; } finally @@ -208,7 +210,7 @@ internal static bool ValidateSslServerCertificate(string targetServerName, X509C /// internal static uint ReportSNIError(SNIProviders provider, uint nativeError, uint sniError, string errorMessage) { - SqlClientEventSource.Log.TrySNITraceEvent("SNICommon.ReportSNIError | SNI | ERR | 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)); } @@ -221,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("SNICommon.ReportSNIError | SNI | ERR | 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 bfada20446..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("SNILoadHandle.LastError | SNI | INFO | SETTER | Last Error Value = {0}", value?.errorMessage); _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 badae43200..597172c37f 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 @@ -46,7 +46,7 @@ public Guid ConnectionId public SNIMarsConnection(SNIHandle lowerHandle) { _lowerHandle = lowerHandle; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "Created MARS Session Id {0}", args0: ConnectionId); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Created MARS Session Id {0}", args0: ConnectionId); _lowerHandle.SetAsyncCallbacks(HandleReceiveComplete, HandleSendComplete); } @@ -57,7 +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, " | SNI | INFO | ", "MARS Session Id {0}, SNI MARS Handle Id {1}, created new MARS Session {2}", args0: ConnectionId, args1: handle?.ConnectionId, args2: sessionId); + 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; } } @@ -75,10 +75,10 @@ public uint StartReceive() if (ReceiveAsync(ref packet) == TdsEnums.SNI_SUCCESS_IO_PENDING) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, Success IO pending.", args0: ConnectionId); + 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(s_className, " | SNI | ERR | ", "MARS Session Id {0}, Connection not usable.", args0: ConnectionId); + 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 @@ -144,7 +144,7 @@ public uint ReceiveAsync(ref SNIPacket packet) { ReturnPacket(packet); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, Packet {1} returned", args0: ConnectionId, args1: packet?._id); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, Packet {1} returned", args0: ConnectionId, args1: packet?._id); #endif packet = null; } @@ -153,7 +153,7 @@ public uint ReceiveAsync(ref SNIPacket packet) { var response = _lowerHandle.ReceiveAsync(ref packet); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, Received new packet {1}", args0: ConnectionId, args1: packet?._id); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, Received new packet {1}", args0: ConnectionId, args1: packet?._id); #endif return response; } @@ -196,11 +196,11 @@ public void HandleReceiveError(SNIPacket packet) { handle.HandleReceiveError(packet); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | ERR | ", "MARS Session Id {0}, Packet {1} has Completion Callback", args0: ConnectionId, args1: packet?._id); + 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, " | SNI | ERR | ", "MARS Session Id {0}, Packet {1} does not have Completion Callback, error not handled.", args0: ConnectionId, args1: packet?._id); + 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 } } @@ -237,7 +237,7 @@ public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) lock (this) { HandleReceiveError(packet); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | ERR | ", "MARS Session Id {0}, Handled receive error code: {1}", args0: _lowerHandle?.ConnectionId, args1: sniErrorCode); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "MARS Session Id {0}, Handled receive error code: {1}", args0: _lowerHandle?.ConnectionId, args1: sniErrorCode); return; } } @@ -260,7 +260,7 @@ public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) if (bytesTaken == 0) { sniErrorCode = ReceiveAsync(ref packet); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, Non-SMUX Header SNI Packet received with code {1}", args0: ConnectionId, args1: sniErrorCode); + 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) { @@ -268,7 +268,7 @@ public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) } HandleReceiveError(packet); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | ERR | ", "MARS Session Id {0}, Handled receive error code: {1}", args0: _lowerHandle?.ConnectionId, args1: sniErrorCode); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "MARS Session Id {0}, Handled receive error code: {1}", args0: _lowerHandle?.ConnectionId, args1: sniErrorCode); return; } } @@ -277,7 +277,7 @@ public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) _dataBytesLeft = (int)_currentHeader.length; _currentPacket = _lowerHandle.RentPacket(headerSize: 0, dataSize: (int)_currentHeader.length); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | 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); + 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 } @@ -294,7 +294,7 @@ public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) if (_dataBytesLeft > 0) { sniErrorCode = ReceiveAsync(ref packet); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, SMUX DATA Header SNI Packet received with code {1}, _dataBytesLeft {2}", args0: ConnectionId, args1: sniErrorCode, args2: _dataBytesLeft); + 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) { @@ -302,7 +302,7 @@ public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) } HandleReceiveError(packet); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | ERR | ", "MARS Session Id {0}, Handled receive error code: {1}", args0: _lowerHandle?.ConnectionId, args1: sniErrorCode); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "MARS Session Id {0}, Handled receive error code: {1}", args0: _lowerHandle?.ConnectionId, args1: sniErrorCode); return; } } @@ -314,7 +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, " | SNI | 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); + 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; @@ -323,19 +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, " | SNI | FIN | ", "MARS Session Id {0}, SMUX_FIN flag received, Current Header Session Id {1} removed", args0: _lowerHandle?.ConnectionId, args1: _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, " | SNI | INFO | ", "MARS Session Id {0}, Current Session assigned to Session Id {1}", args0: _lowerHandle?.ConnectionId, args1: _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, " | SNI | INFO | SMUX_DATA | ", "MARS Session Id {0}, Current Session {1} completed receiving Data", args0: _lowerHandle?.ConnectionId, args1: _currentHeader?.sessionId); + 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) @@ -343,16 +343,16 @@ public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) try { currentSession.HandleAck(currentHeader.highwater); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | SMUX_ACK | ", "MARS Session Id {0}, Current Session {1} handled ack", args0: _lowerHandle?.ConnectionId, args1: _currentHeader?.sessionId); + 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, " | SNI | ERR | ", "MARS Session Id {0}, Exception occurred: {2}", args0: _currentHeader?.sessionId, args1: e?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "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, " | SNI | INFO | SMUX_ACK | ", "MARS Session Id {0}, Current Packet {1} returned", args0: _lowerHandle?.ConnectionId, args1: currentPacket?._id); + 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; @@ -371,7 +371,7 @@ public void HandleReceiveComplete(SNIPacket packet, uint sniErrorCode) } HandleReceiveError(packet); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | ERR | ", "MARS Session Id {0}, packet.DataLeft 0, SNI error {2}", args0: _lowerHandle?.ConnectionId, args1: sniErrorCode); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "MARS Session Id {0}, packet.DataLeft 0, SNI error {2}", args0: _lowerHandle?.ConnectionId, args1: sniErrorCode); return; } } 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 7671cb33c1..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 @@ -59,11 +59,11 @@ public override void Dispose() try { SendControlPacket(SNISMUXFlags.SMUX_FIN); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, Sent SMUX_FIN packet to terminate session.", args0: ConnectionId); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, Sent SMUX_FIN packet to terminate session.", args0: ConnectionId); } catch (Exception e) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | ERR | ", "MARS Session Id {0}, Internal exception error = {1}, Member Name={2}", args0: ConnectionId, args1: e?.Message, args2: 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 @@ -87,7 +87,7 @@ public SNIMarsHandle(SNIMarsConnection connection, ushort sessionId, object call _callbackObject = callbackObject; _handleSendCompleteCallback = HandleSendComplete; SendControlPacket(SNISMUXFlags.SMUX_SYN); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, Sent SMUX_SYN packet to start a new session, session Id {1}", args0: ConnectionId, args1: _sessionId); + 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; } @@ -102,7 +102,7 @@ private void SendControlPacket(SNISMUXFlags flags) { SNIPacket packet = RentPacket(headerSize: SNISMUXHeader.HEADER_LENGTH, dataSize: 0); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, Packet rented {1}, packet dataLeft {2}", args0: ConnectionId, args1: packet?._id, args2: packet?.DataLeft); + 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) { @@ -114,7 +114,7 @@ private void SendControlPacket(SNISMUXFlags flags) _connection.Send(packet); ReturnPacket(packet); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, Packet returned {1}, packet dataLeft {2}", args0: ConnectionId, args1: packet?._id, args2: packet?.DataLeft); + 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 } @@ -150,7 +150,7 @@ private SNIPacket SetPacketSMUXHeader(SNIPacket packet) _currentHeader.Write(packet.GetHeaderBuffer(SNISMUXHeader.HEADER_LENGTH)); packet.SetHeaderActive(); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, Setting SMUX_DATA header in current header for packet {1}", args0: ConnectionId, args1: packet?._id); + 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; } @@ -176,12 +176,12 @@ public override uint Send(SNIPacket packet) } } - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, Waiting for Acknowledgment event.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); + 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, " | SNI | INFO | ", "MARS Session Id {0}, _sendPacketQueue count found {1}, Acknowledgment event Reset", args0: ConnectionId, args1: _sendPacketQueue?.Count); + 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(); } } @@ -191,7 +191,7 @@ public override uint Send(SNIPacket packet) { muxedPacket = SetPacketSMUXHeader(packet); } - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, SMUX Packet is going to be sent.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); + SqlClientEventSource.Log.TrySNITraceEvent(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 @@ -216,13 +216,13 @@ private uint InternalSendAsync(SNIPacket packet, SNIAsyncCallback callback) { if (_sequenceNumber >= _sendHighwater) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, SNI Queue is full", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, SNI Queue is full", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); return TdsEnums.SNI_QUEUE_FULL; } SNIPacket muxedPacket = SetPacketSMUXHeader(packet); muxedPacket.SetCompletionCallback(callback ?? HandleSendComplete); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, Sending packet", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); + 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); } } @@ -255,18 +255,18 @@ private uint SendPendingPackets() if (result != TdsEnums.SNI_SUCCESS && result != TdsEnums.SNI_SUCCESS_IO_PENDING) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | ERR | ", "MARS Session Id {0}, InternalSendAsync result is not SNI_SUCCESS and is not SNI_SUCCESS_IO_PENDING", args0: ConnectionId); + 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, " | SNI | INFO | ", "MARS Session Id {0}, _sendPacketQueue dequeued, count {1}", args0: ConnectionId, args1: _sendPacketQueue?.Count); + 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, " | SNI | INFO | ", "MARS Session Id {0}, _sendPacketQueue count found {1}, acknowledgment set", args0: ConnectionId, args1: _sendPacketQueue?.Count); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, _sendPacketQueue count found {1}, acknowledgment set", args0: ConnectionId, args1: _sendPacketQueue?.Count); } } @@ -299,7 +299,7 @@ public override uint SendAsync(SNIPacket packet, SNIAsyncCallback callback = nul } SendPendingPackets(); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, _sendPacketQueue enqueued, count {1}", args0: ConnectionId, args1: _sendPacketQueue?.Count); + 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; } @@ -325,14 +325,14 @@ public override uint ReceiveAsync(ref SNIPacket packet) if (_connectionError != null) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | ERR | ", "MARS Session Id {0}, _asyncReceives {1}, _receiveHighwater {2}, _sendHighwater {3}, _receiveHighwaterLastAck {4}, _connectionError {5}", args0: ConnectionId, args1: _asyncReceives, args2: _receiveHighwater, args3: _sendHighwater, args4: _receiveHighwaterLastAck, args5: _connectionError); + SqlClientEventSource.Log.TrySNITraceEvent(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, " | SNI | INFO | ", "MARS Session Id {0}, queueCount 0, _asyncReceives {1}, _receiveHighwater {2}, _sendHighwater {3}, _receiveHighwaterLastAck {4}", args0: ConnectionId, args1: _asyncReceives, args2: _receiveHighwater, args3: _sendHighwater, args4: _receiveHighwaterLastAck); + SqlClientEventSource.Log.TrySNITraceEvent(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; } @@ -342,7 +342,7 @@ public override uint ReceiveAsync(ref SNIPacket packet) if (queueCount == 1) { #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, packet dequeued {1}, packet Owner {2}, packet refCount {3}, received Packet Queue count {4}", args0: ConnectionId, args1: packet?._id, args2: packet?._owner, args3: packet?._refCount, args4: _receivedPacketQueue?.Count); + SqlClientEventSource.Log.TrySNITraceEvent(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(); } @@ -353,7 +353,7 @@ public override uint ReceiveAsync(ref SNIPacket packet) _receiveHighwater++; } - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, _asyncReceives {1}, _receiveHighwater {2}, _sendHighwater {3}, _receiveHighwaterLastAck {4}, queueCount {5}", args0: ConnectionId, args1: _asyncReceives, args2: _receiveHighwater, args3: _sendHighwater, args4: _receiveHighwaterLastAck, args5: _receivedPacketQueue?.Count); + SqlClientEventSource.Log.TrySNITraceEvent(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; } @@ -378,7 +378,7 @@ public void HandleReceiveError(SNIPacket packet) lock (_receivedPacketQueue) { _connectionError = SNILoadHandle.SingletonInstance.LastError; - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | ERR | ", "MARS Session Id {0}, _connectionError to be handled: {1}", args0: ConnectionId, args1: _connectionError); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "MARS Session Id {0}, _connectionError to be handled: {1}", args0: ConnectionId, args1: _connectionError); _packetEvent.Set(); } @@ -408,7 +408,7 @@ public void HandleSendComplete(SNIPacket packet, uint sniErrorCode) } _connection.ReturnPacket(packet); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, Returned Packet: {1}", args0: ConnectionId, args1: packet?._id); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "MARS Session Id {0}, Returned Packet: {1}", args0: ConnectionId, args1: packet?._id); #endif } finally @@ -430,7 +430,7 @@ public void HandleAck(uint highwater) { if (_sendHighwater != highwater) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, Setting _sendHighwater {1} to highwater {2} and send pending packets.", args0: ConnectionId, args1: _sendHighwater, args2: 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(); } @@ -456,7 +456,7 @@ public void HandleReceiveComplete(SNIPacket packet, SNISMUXHeader header) { if (_sendHighwater != header.highwater) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, header.highwater {1}, _sendHighwater {2}, Handle Ack with header.highwater", args0: ConnectionId, args1: header?.highwater, args2: _sendHighwater); + SqlClientEventSource.Log.TrySNITraceEvent(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); } @@ -466,13 +466,13 @@ public void HandleReceiveComplete(SNIPacket packet, SNISMUXHeader header) { _receivedPacketQueue.Enqueue(packet); _packetEvent.Set(); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, _receivedPacketQueue count {3}, packet event set", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater, args3: _receivedPacketQueue?.Count); + SqlClientEventSource.Log.TrySNITraceEvent(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, " | SNI | INFO | ", "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, _asyncReceives {3}", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater, args3: _asyncReceives); + 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); } @@ -484,7 +484,7 @@ public void HandleReceiveComplete(SNIPacket packet, SNISMUXHeader header) { _receiveHighwater++; } - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, _asyncReceives {1}, _receiveHighwater {2}, _sendHighwater {3}, _receiveHighwaterLastAck {4}", args0: ConnectionId, args1: _asyncReceives, args2: _receiveHighwater, args3: _sendHighwater, args4: _receiveHighwaterLastAck); + SqlClientEventSource.Log.TrySNITraceEvent(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 @@ -510,7 +510,7 @@ private void SendAckIfNecessary() if (receiveHighwater - receiveHighwaterLastAck > ACK_THRESHOLD) { SendControlPacket(SNISMUXFlags.SMUX_ACK); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, _asyncReceives {1}, _receiveHighwater {2}, _sendHighwater {3}, _receiveHighwaterLastAck {4} Sending acknowledgment ACK_THRESHOLD {5}", args0: ConnectionId, args1: _asyncReceives, args2: _receiveHighwater, args3: _sendHighwater, args4: _receiveHighwaterLastAck, args5: ACK_THRESHOLD); + SqlClientEventSource.Log.TrySNITraceEvent(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); } } @@ -535,12 +535,12 @@ public override uint Receive(out SNIPacket packet, int timeoutInMilliseconds) { if (_connectionError != null) { - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | ERR | ", "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, _connectionError found: {3}.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater, args3: _connectionError); + 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, " | SNI | INFO | ", "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, W_receivedPacketQueue count {3}.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater, args3: queueCount); + 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) { @@ -549,7 +549,7 @@ public override uint Receive(out SNIPacket packet, int timeoutInMilliseconds) if (queueCount == 1) { _packetEvent.Reset(); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, packet event reset, _receivedPacketQueue count 1.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); + 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; @@ -564,15 +564,15 @@ public override uint Receive(out SNIPacket packet, int timeoutInMilliseconds) } SendAckIfNecessary(); - SqlClientEventSource.Log.TrySNITraceEvent(s_className, " | SNI | INFO | ", "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, returning with result {3}.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater, args3: result); + 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, " | SNI | INFO | ", "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, Waiting for packet event.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); + 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, " | SNI | INFO | ", "MARS Session Id {0}, _sequenceNumber {1}, _sendHighwater {2}, _packetEvent wait timed out.", args0: ConnectionId, args1: _sequenceNumber, args2: _sendHighwater); + 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 ce3f5e698c..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,6 +18,7 @@ namespace Microsoft.Data.SqlClient.SNI /// internal sealed class SNINpHandle : SNIPhysicalHandle { + private const string s_className = nameof(SNINpHandle); internal const string DefaultPipePath = @"sql\query"; // e.g. \\HOSTNAME\pipe\sql\query // private const int MAX_PIPE_INSTANCES = 255; // TODO: Investigate pipe instance limit. @@ -39,8 +40,8 @@ internal sealed class SNINpHandle : SNIPhysicalHandle public SNINpHandle(string serverName, string pipeName, long timerExpire) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SNINpHandle.ctor | SNI | INFO | SCOPE | Entering Scope {0}"); - SqlClientEventSource.Log.TrySNITraceEvent("SNINpHandle.ctor | SNI | INFO | Connection Id {0}, Setting server name = {1}, pipe name = {2}", _connectionId, 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(); @@ -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("SNINpHandle.ctor | SNI | ERR | Connection Id {0}, Connection Timed out. Error Code 1 Exception = {1}", _connectionId, 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("SNINpHandle.ctor | SNI | ERR | Connection Id {0}, IO Exception occurred. Error Code 1 Exception = {1}", _connectionId, 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,7 +87,7 @@ public SNINpHandle(string serverName, string pipeName, long timerExpire) { SNICommon.ReportSNIError(SNIProviders.NP_PROV, 0, SNICommon.ConnOpenFailedError, Strings.SNI_ERROR_40); _status = TdsEnums.SNI_ERROR; - SqlClientEventSource.Log.TrySNITraceEvent("SNINpHandle.ctor | SNI | ERR | Connection Id {0}, Pipe Stream not operational. Error Code 1 Exception = {1}", _connectionId, Strings.SNI_ERROR_1); + 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; } @@ -135,17 +136,17 @@ public override int ProtocolVersion public override uint CheckConnection() { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SNINpHandle.CheckConnection | SNI | INFO | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { if (!_stream.CanWrite || !_stream.CanRead) { - SqlClientEventSource.Log.TrySNITraceEvent("SNINpHandle.CheckConnection | SNI | ERR | Connection Id {0}, Cannot write or read to/from the stream", _connectionId); + 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("SNINpHandle.CheckConnection | SNI | INFO | Connection Id {0}, Can read and write to/from stream.", _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Can read and write to/from stream.", args0: _connectionId); return TdsEnums.SNI_SUCCESS; } } @@ -179,13 +180,13 @@ public override void Dispose() //Release any references held by _stream. _stream = null; - SqlClientEventSource.Log.TrySNITraceEvent("SNINpHandle.Dispose | SNI | INFO | Connection Id {0}, All streams disposed and references cleared.", _connectionId); + 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("SNINpHandle.Receive | SNI | INFO | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { SNIPacket errorPacket; @@ -196,14 +197,14 @@ public override uint Receive(out SNIPacket packet, int timeout) { packet = RentPacket(headerSize: 0, dataSize: _bufferSize); packet.ReadFromStream(_stream); - SqlClientEventSource.Log.TrySNITraceEvent("SNINpHandle.Receive | SNI | INFO | Connection Id {0}, Rented and read packet, dataLeft {1}", _connectionId, packet?.DataLeft); + 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("SNINpHandle.Receive | SNI | ERR | Connection Id {0}, Packet length found 0, Win32 exception raised: {1}", _connectionId, e?.Message); + 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); } } @@ -211,14 +212,14 @@ public override uint Receive(out SNIPacket packet, int timeout) { errorPacket = packet; packet = null; - SqlClientEventSource.Log.TrySNITraceEvent("SNINpHandle.Receive | SNI | ERR | Connection Id {0}, ObjectDisposedException occurred: {1}.", _connectionId, 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("SNINpHandle.Receive | SNI | ERR | Connection Id {0}, IOException occurred: {1}.", _connectionId, 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; @@ -232,7 +233,7 @@ public override uint Receive(out SNIPacket packet, int timeout) public override uint ReceiveAsync(ref SNIPacket packet) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SNINpHandle.ReceiveAsync | SNI | INFO | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { SNIPacket errorPacket; @@ -241,21 +242,21 @@ public override uint ReceiveAsync(ref SNIPacket packet) try { packet.ReadFromStreamAsync(_stream, _receiveCallback); - SqlClientEventSource.Log.TrySNITraceEvent("SNINpHandle.ReceiveAsync | SNI | INFO | Connection Id {0}, Rented and read packet asynchronously, dataLeft {1}", _connectionId, packet?.DataLeft); + 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("SNINpHandle.ReceiveAsync | SNI | ERR | Connection Id {0}, ObjectDisposedException occurred: {1}.", _connectionId, 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("SNINpHandle.ReceiveAsync | SNI | ERR | Connection Id {0}, IOException occurred: {1}.", _connectionId, ioe?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, IOException occurred: {1}.", args0: _connectionId, args1: ioe?.Message); return ReportErrorAndReleasePacket(errorPacket, ioe); } } @@ -267,7 +268,7 @@ public override uint ReceiveAsync(ref SNIPacket packet) public override uint Send(SNIPacket packet) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SNINpHandle.Send | SNI | INFO | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { bool releaseLock = false; @@ -294,18 +295,18 @@ public override uint Send(SNIPacket packet) { try { - SqlClientEventSource.Log.TrySNITraceEvent("SNINpHandle.Send | SNI | INFO | Connection Id {0}, Packet writing to stream, dataLeft {1}", _connectionId, packet?.DataLeft); + 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("SNINpHandle.Send | SNI | ERR | Connection Id {0}, ObjectDisposedException occurred: {1}.", _connectionId, 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("SNINpHandle.Send | SNI | ERR | Connection Id {0}, IOException occurred: {1}.", _connectionId, ioe?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, IOException occurred: {1}.", args0: _connectionId, args1: ioe?.Message); return ReportErrorAndReleasePacket(packet, ioe); } } @@ -326,11 +327,11 @@ public override uint Send(SNIPacket packet) public override uint SendAsync(SNIPacket packet, SNIAsyncCallback callback = null) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SNINpHandle.SendAsync | SNI | INFO | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { SNIAsyncCallback cb = callback ?? _sendCallback; - SqlClientEventSource.Log.TrySNITraceEvent("SNINpHandle.SendAsync | SNI | INFO | Connection Id {0}, Packet writing to stream, dataLeft {1}", _connectionId, packet?.DataLeft); + 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; } @@ -348,7 +349,7 @@ public override void SetAsyncCallbacks(SNIAsyncCallback receiveCallback, SNIAsyn public override uint EnableSsl(uint options) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SNINpHandle.EnableSsl | SNI | INFO | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { _validateCert = (options & TdsEnums.SNI_SSL_VALIDATE_CERTIFICATE) != 0; @@ -360,12 +361,12 @@ public override uint EnableSsl(uint options) } catch (AuthenticationException aue) { - SqlClientEventSource.Log.TrySNITraceEvent("SNINpHandle.EnableSsl | SNI | ERR | Connection Id {0}, AuthenticationException message = {1}.", ConnectionId, 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("SNINpHandle.EnableSsl | SNI | ERR | Connection Id {0}, InvalidOperationException message = {1}.", ConnectionId, 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; @@ -397,16 +398,16 @@ public override void DisableSsl() /// true if valid private bool ValidateServerCertificate(object sender, X509Certificate cert, X509Chain chain, SslPolicyErrors policyErrors) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SNINpHandle.ValidateServerCertificate | SNI | INFO | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { if (!_validateCert) { - SqlClientEventSource.Log.TrySNITraceEvent("SNINpHandle.ValidateServerCertificate | SNI | INFO | Connection Id {0}, Certificate validation not requested.", ConnectionId); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Certificate validation not requested.", args0: ConnectionId); return true; } - SqlClientEventSource.Log.TrySNITraceEvent("SNINpHandle.ValidateServerCertificate | SNI | INFO | Connection Id {0}, Proceeding to SSL certificate validation.", ConnectionId); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Proceeding to SSL certificate validation.", args0: ConnectionId); return SNICommon.ValidateSslServerCertificate(_targetServer, cert, policyErrors); } finally @@ -430,7 +431,7 @@ private uint ReportErrorAndReleasePacket(SNIPacket packet, Exception sniExceptio { ReturnPacket(packet); } - SqlClientEventSource.Log.TrySNITraceEvent("SNINpHandle.ReportErrorAndReleasePacket | SNI | INFO | Connection Id {0}, Packet returned, error occurred: {1}", ConnectionId, sniException?.Message); + 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); } @@ -440,7 +441,7 @@ private uint ReportErrorAndReleasePacket(SNIPacket packet, uint nativeError, uin { ReturnPacket(packet); } - SqlClientEventSource.Log.TrySNITraceEvent("SNINpHandle.ReportErrorAndReleasePacket | SNI | INFO | Connection Id {0}, Packet returned, error occurred: {1}", ConnectionId, errorMessage); + 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 ccaefb5958..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 @@ -68,7 +69,7 @@ public SNIPacket(SNIHandle owner, int id) #endif _id = id; _owner = owner; - SqlClientEventSource.Log.TrySNITraceEvent("SNIPacket.ctor | SNI | INFO | Connection Id {0}, Packet Id {1} instantiated,", _owner?.ConnectionId, _id); + 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 @@ -78,7 +79,7 @@ public SNIPacket(SNIHandle owner, int id) { if (_data != null) { - SqlClientEventSource.Log.TrySNITraceEvent("SNIPacket.dtor | SNI | ERR | Finalizer called for unreleased SNIPacket, Connection Id {0}, Packet Id {1}, _refCount {2}, DataLeft {3}, tag {4}", _owner?.ConnectionId, _id, _refCount, DataLeft, _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); } } @@ -143,7 +144,7 @@ public void Allocate(int headerLength, int dataLength) _dataOffset = 0; _headerLength = headerLength; #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent("SNIPacket.Allocate | SNI | INFO | Connection Id {0}, Packet Id {1} allocated with _headerLength {2}, _dataCapacity {3}", _owner?.ConnectionId, _id, _headerLength, _dataCapacity); + 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 } @@ -169,7 +170,7 @@ 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("SNIPacket.TakeData | SNI | INFO | Connection Id {0}, Packet Id {1} took data from Packet Id {2} dataSize {3}, _dataLength {4}", _owner?.ConnectionId, _id, packet?._id, dataSize, packet._dataLength); + 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; } @@ -184,7 +185,7 @@ public void AppendData(byte[] data, int size) Buffer.BlockCopy(data, 0, _data, _headerLength + _dataLength, size); _dataLength += size; #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent("SNIPacket.AppendData | SNI | INFO | Connection Id {0}, Packet Id {1} was appended with size {2}, _dataLength {3}", _owner?.ConnectionId, _id, size, _dataLength); + 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 } @@ -210,7 +211,7 @@ public int TakeData(byte[] buffer, int dataOffset, int size) Buffer.BlockCopy(_data, _headerLength + _dataOffset, buffer, dataOffset, size); _dataOffset += size; #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent("SNIPacket.TakeData | SNI | INFO | Connection Id {0}, Packet Id {1} took data size {2}, _dataLength {3}, _dataOffset {4}", _owner?.ConnectionId, _id, size, _dataLength, _dataOffset); + 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; } @@ -230,7 +231,7 @@ public void SetHeaderActive() _dataLength += _headerLength; _headerLength = 0; #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent("SNIPacket.SetHeaderActive | SNI | INFO | Connection Id {0}, Packet Id {1} _dataLength {2} header set to active.", _owner?.ConnectionId, _id, _dataLength); + 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 } @@ -248,7 +249,7 @@ public void Release() _dataCapacity = 0; } #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent("SNIPacket.Release | SNI | INFO | Connection Id {0}, Packet Id {1} _headerLength {2} and _dataLength {3} released.", _owner?.ConnectionId, _id, _headerLength, _dataLength); + 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; @@ -265,7 +266,7 @@ public void ReadFromStream(Stream stream) { _dataLength = stream.Read(_data, _headerLength, _dataCapacity); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent("SNIPacket.ReadFromStream | SNI | INFO | Connection Id {0}, Packet Id {1} _dataLength {2} read from stream.", _owner?.ConnectionId, _id, _dataLength); + 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 } @@ -295,7 +296,7 @@ private void ReadFromStreamAsyncContinuation(Task t, object state) { SNILoadHandle.SingletonInstance.LastError = new SNIError(SNIProviders.TCP_PROV, SNICommon.InternalExceptionError, e); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent("SNIPacket.ReadFromStreamAsyncContinuation | SNI | ERR | Connection Id {0}, Internal Exception occurred while reading data: {1}", _owner?.ConnectionId, e.Message); + 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; } @@ -303,13 +304,13 @@ private void ReadFromStreamAsyncContinuation(Task t, object state) { _dataLength = t.Result; #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent("SNIPacket.ReadFromStreamAsyncContinuation | SNI | INFO | Connection Id {0}, Packet Id {1} _dataLength {2} read from stream.", _owner?.ConnectionId, _id, _dataLength); + 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("SNIPacket.ReadFromStreamAsyncContinuation | SNI | ERR | Connection Id {0}, No data read from stream, connection was terminated.", _owner?.ConnectionId); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, No data read from stream, connection was terminated.", args0: _owner?.ConnectionId); #endif error = true; } @@ -326,7 +327,7 @@ public void WriteToStream(Stream stream) { stream.Write(_data, _headerLength, _dataLength); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent("SNIPacket.WriteToStream | SNI | INFO | Connection Id {0}, Packet Id {1} _dataLength {2} written to stream.", _owner?.ConnectionId, _id, _dataLength); + 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 } @@ -343,14 +344,14 @@ public async void WriteToStreamAsync(Stream stream, SNIAsyncCallback callback, S { await stream.WriteAsync(_data, 0, _dataLength, CancellationToken.None).ConfigureAwait(false); #if DEBUG - SqlClientEventSource.Log.TrySNITraceEvent("SNIPacket.WriteToStreamAsync | SNI | INFO | Connection Id {0}, Packet Id {1} _dataLength {2} written to stream.", _owner?.ConnectionId, _id, _dataLength); + 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("SNIPacket.WriteToStreamAsync | SNI | ERR | Connection Id {0}, Internal Exception occurred while writing data: {1}", _owner?.ConnectionId, e.Message); + 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; } 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 1e36db4199..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,7 +68,7 @@ public override void Dispose() //Release any references held by _stream. _stream = null; - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.Dispose | SNI | INFO | Connection Id {0}, All streams disposed.", _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, All streams disposed.", args0: _connectionId); } } @@ -119,8 +120,8 @@ public override int ProtocolVersion /// Used for DNS Cache public SNITCPHandle(string serverName, int port, long timerExpire, bool parallel, string cachedFQDN, ref SQLDNSInfo pendingDNSInfo) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SNITCPHandle.ctor | SNI | INFO | SCOPE | Entering Scope {0}"); - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.ctor | SNI | INFO | Connection Id {0}, Setting server name = {1}", _connectionId, serverName); + 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 { _targetServer = serverName; @@ -144,7 +145,7 @@ public SNITCPHandle(string serverName, int port, long timerExpire, bool parallel bool reportError = true; - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.ctor | SNI | INFO | Connection Id {0}, Connecting to serverName {1} and port {2}", _connectionId, serverName, port); + 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. @@ -166,13 +167,13 @@ public SNITCPHandle(string serverName, int port, long timerExpire, bool parallel { if (hasCachedDNSInfo == false) { - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.ctor | SNI | ERR | Connection Id {0}, Cached DNS Info not found, exception occurred thrown: {1}", _connectionId, ex?.Message); + 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; } else { int portRetry = string.IsNullOrEmpty(cachedDNSInfo.Port) ? port : int.Parse(cachedDNSInfo.Port); - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.ctor | SNI | INFO | Connection Id {0}, Retrying with cached DNS IP Address {1} and port {2}", _connectionId, cachedDNSInfo.AddrIPv4, 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 { @@ -190,7 +191,7 @@ public SNITCPHandle(string serverName, int port, long timerExpire, bool parallel if (exRetry is SocketException || exRetry is ArgumentNullException || exRetry is ArgumentException || exRetry is ArgumentOutOfRangeException || exRetry is AggregateException) { - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.ctor | SNI | INFO | Connection Id {0}, Retrying exception {1}", _connectionId, exRetry?.Message); + 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); @@ -202,7 +203,7 @@ public SNITCPHandle(string serverName, int port, long timerExpire, bool parallel } else { - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.ctor | SNI | ERR | Connection Id {0}, Retry failed, exception occurred: {1}", _connectionId, exRetry?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, Retry failed, exception occurred: {1}", args0: _connectionId, args1: exRetry?.Message); throw; } } @@ -224,10 +225,10 @@ public SNITCPHandle(string serverName, int port, long timerExpire, bool parallel if (reportError) { - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.ctor | SNI | ERR | Connection Id {0} could not be opened, exception occurred: {1}", _connectionId, Strings.SNI_ERROR_40); + 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("SNITCPHandle.ctor | SNI | ERR | Connection Id {0} Socket could not be opened.", _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0} Socket could not be opened.", args0: _connectionId); return; } @@ -239,20 +240,20 @@ public SNITCPHandle(string serverName, int port, long timerExpire, bool parallel } catch (SocketException se) { - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.ctor | SNI | ERR | Connection Id {0} Socket exception occurred: Error Code {1}, Message {2}", _connectionId, se?.SocketErrorCode, se?.Message); + 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("SNITCPHandle.ctor | SNI | ERR | Connection Id {0} Exception occurred: {1}", _connectionId, e?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0} Exception occurred: {1}", args0: _connectionId, args1: e?.Message); ReportTcpSNIError(e); return; } _stream = _tcpStream; _status = TdsEnums.SNI_SUCCESS; - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.ctor | SNI | INFO | Connection Id {0} Socket opened successfully, TCP stream ready.", _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0} Socket opened successfully, TCP stream ready.", args0: _connectionId); } finally { @@ -276,7 +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("SNITCPHandle.TryConnectParallel | SNI | ERR | Connection Id {0} serverAddresses.Length {1} Exception: {2}", _connectionId, serverAddresses.Length, Strings.SNI_ERROR_47); + 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; } @@ -306,7 +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("SNITCPHandle.TryConnectParallel | SNI | ERR | Connection Id {0} Connection timed out, Exception: {1}", _connectionId, Strings.SNI_ERROR_40); + 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; } @@ -365,7 +366,7 @@ void Cancel() } catch (Exception e) { - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.Connect | SNI | ERR | THIS EXCEPTION IS BEING SWALLOWED: {0}", e?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "THIS EXCEPTION IS BEING SWALLOWED: {0}", args0: e?.Message); } } } @@ -390,7 +391,7 @@ void Cancel() // enable keep-alive on socket SetKeepAliveValues(ref sockets[i]); - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.Connect | SNI | INFO | Connecting to IP address {0} and port {1}", ipAddresses[i], port); + 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() { @@ -409,7 +410,7 @@ void Cancel() } catch (Exception e) { - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.Connect | SNI | ERR | THIS EXCEPTION IS BEING SWALLOWED: {0}", e?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "THIS EXCEPTION IS BEING SWALLOWED: {0}", args0: e?.Message); } } } @@ -537,17 +538,17 @@ public override uint EnableSsl(uint options) } catch (AuthenticationException aue) { - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.EnableSsl | SNI | ERR | Connection Id {0}, Authentication exception occurred: {1}", _connectionId, aue?.Message); + 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("SNITCPHandle.EnableSsl | SNI | ERR | Connection Id {0}, Invalid Operation Exception occurred: {1}", _connectionId, ioe?.Message); + 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("SNITCPHandle.EnableSsl | SNI | INFO | Connection Id {0}, SSL enabled successfully.", _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, SSL enabled successfully.", args0: _connectionId); return TdsEnums.SNI_SUCCESS; } @@ -561,7 +562,7 @@ public override void DisableSsl() _sslOverTdsStream.Dispose(); _sslOverTdsStream = null; _stream = _tcpStream; - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.DisableSsl | SNI | INFO | Connection Id {0}, SSL Disabled. Communication will continue on TCP Stream.", _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, SSL Disabled. Communication will continue on TCP Stream.", args0: _connectionId); } /// @@ -576,11 +577,11 @@ private bool ValidateServerCertificate(object sender, X509Certificate cert, X509 { if (!_validateCert) { - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.ValidateServerCertificate | SNI | INFO | Connection Id {0}, Certificate will not be validated.", _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Certificate will not be validated.", args0: _connectionId); return true; } - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.ValidateServerCertificate | SNI | INFO | Connection Id {0}, Certificate will be validated for Target Server name", _connectionId); + 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); } @@ -625,22 +626,22 @@ public override uint Send(SNIPacket packet) try { packet.WriteToStream(_stream); - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.Send | SNI | INFO | Connection Id {0}, Data sent to stream synchronously", _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Data sent to stream synchronously", args0: _connectionId); return TdsEnums.SNI_SUCCESS; } catch (ObjectDisposedException ode) { - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.Send | SNI | ERR | Connection Id {0}, ObjectDisposedException occurred: {1}", _connectionId, ode.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, ObjectDisposedException occurred: {1}", args0: _connectionId, args1: ode?.Message); return ReportTcpSNIError(ode); } catch (SocketException se) { - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.Send | SNI | ERR | Connection Id {0}, SocketException occurred: {1}", _connectionId, se.Message); + 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("SNITCPHandle.Send | SNI | ERR | Connection Id {0}, IOException occurred: {1}", _connectionId, ioe.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, IOException occurred: {1}", args0: _connectionId, args1: ioe?.Message); return ReportTcpSNIError(ioe); } } @@ -680,7 +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("SNITCPHandle.Receive | SNI | ERR | Connection Id {0}, Error 258, Timeout error occurred.", _connectionId); + 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; } @@ -693,25 +694,25 @@ public override uint Receive(out SNIPacket packet, int timeoutInMilliseconds) errorPacket = packet; packet = null; var e = new Win32Exception(); - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.Receive | SNI | ERR | Connection Id {0}, Win32 exception occurred: {1}", _connectionId, e?.Message); + 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("SNITCPHandle.Receive | SNI | INFO | Connection Id {0}, Data read from stream synchronously", _connectionId); + 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("SNITCPHandle.Receive | SNI | ERR | Connection Id {0}, ObjectDisposedException occurred: {1}", _connectionId, 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 (SocketException se) { errorPacket = packet; packet = null; - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.Receive | SNI | ERR | Connection Id {0}, Socket exception occurred: {1}", _connectionId, se?.Message); + 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) @@ -721,11 +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("SNITCPHandle.Receive | SNI | ERR | Connection Id {0}, IO exception occurred with Wait Timeout (error 258): {1}", _connectionId, ioe?.Message); + 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("SNITCPHandle.Receive | SNI | ERR | Connection Id {0}, IO exception occurred: {1}", _connectionId, ioe?.Message); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.ERR, "Connection Id {0}, IO exception occurred: {1}", args0: _connectionId, args1: ioe?.Message); return errorCode; } finally @@ -754,12 +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("SNITcpHandle.SendAsync | SNI | INFO | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { SNIAsyncCallback cb = callback ?? _sendCallback; packet.WriteToStreamAsync(_stream, cb, SNIProviders.TCP_PROV); - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.SendAsync | SNI | INFO | Connection Id {0}, Data sent to stream asynchronously", _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Data sent to stream asynchronously", args0: _connectionId); return TdsEnums.SNI_SUCCESS_IO_PENDING; } finally @@ -781,7 +782,7 @@ public override uint ReceiveAsync(ref SNIPacket packet) try { packet.ReadFromStreamAsync(_stream, _receiveCallback); - SqlClientEventSource.Log.TrySNITraceEvent("SNITCPHandle.ReceiveAsync | SNI | INFO | Connection Id {0}, Data received from stream asynchronously", _connectionId); + 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) @@ -812,18 +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("SNITCPHandle.CheckConnection | SNI | INFO | Connection Id {0}, Socket not usable.", _connectionId); + 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("SNITCPHandle.ReceiveAsync | SNI | INFO | Connection Id {0}, Socket Exception occurred: {1}", _connectionId, se?.Message); + 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("SNITCPHandle.ReceiveAsync | SNI | INFO | Connection Id {0}, ObjectDisposedException occurred: {1}", _connectionId, ode?.Message); + 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 72e34e5803..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("SSRP.GetPortByInstanceName | SNI | SCOPE | Entering Scope {0}"); + 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("SSRP.GetPortByInstanceName | SNI | ERR | 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("SSRP.CreateInstanceInfoRequest | SNI | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { const byte ClntUcastInst = 0x04; @@ -150,7 +151,7 @@ private static byte[] CreateDacPortInfoRequest(string instanceName) /// response packet from UDP server private static byte[] SendUDPRequest(string browserHostname, int port, byte[] requestPacket) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SSRP.SendUDPRequest | SNI | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { Debug.Assert(!string.IsNullOrWhiteSpace(browserHostname), "browserhostname should not be null, empty, or whitespace"); @@ -169,10 +170,10 @@ private static byte[] SendUDPRequest(string browserHostname, int port, byte[] re Task sendTask = client.SendAsync(requestPacket, requestPacket.Length, browserHostname, port); Task receiveTask = null; - SqlClientEventSource.Log.TrySNITraceEvent("SSRP.SendUDPRequest | SNI | INFO | Waiting for UDP Client to fetch Port info."); + 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("SSRP.SendUDPRequest | SNI | INFO | Received Port info from UDP Client."); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Received Port info from UDP Client."); responsePacket = receiveTask.Result.Buffer; } } 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 ab1ef65a68..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,7 +25,7 @@ public override Task WriteAsync(byte[] buffer, int offset, int count, Cancellati public override int Read(Span buffer) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SslOverTdsStream.Read | SNI | INFO | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { if (!_encapsulate) @@ -80,7 +80,7 @@ public override int Read(Span buffer) public override async ValueTask ReadAsync(Memory buffer, CancellationToken cancellationToken = default) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SslOverTdsStream.ReadAsync | SNI | INFO | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { if (!_encapsulate) @@ -184,7 +184,7 @@ public override async ValueTask ReadAsync(Memory buffer, Cancellation public override void Write(ReadOnlySpan buffer) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SslOverTdsStream.Write | SNI | INFO | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { // During the SSL negotiation phase, SSL is tunnelled over TDS packet type 0x12. After @@ -242,7 +242,7 @@ public override void Write(ReadOnlySpan buffer) public override async ValueTask WriteAsync(ReadOnlyMemory buffer, CancellationToken cancellationToken = default) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SslOverTdsStream.WriteAsync | SNI | INFO | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { if (!_encapsulate) 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 3ee7f77c93..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,7 +14,7 @@ internal sealed partial class SslOverTdsStream : Stream { public override int Read(byte[] buffer, int offset, int count) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SslOverTdsStream.Read | SNI | INFO | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { if (!_encapsulate) @@ -74,7 +74,7 @@ public override int Read(byte[] buffer, int offset, int count) public override async Task ReadAsync(byte[] buffer, int offset, int count, CancellationToken cancellationToken) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SslOverTdsStream.ReadAsync | SNI | INFO | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { if (!_encapsulate) @@ -134,7 +134,7 @@ public override async Task ReadAsync(byte[] buffer, int offset, int count, public override void Write(byte[] buffer, int offset, int count) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SslOverTdsStream.Write | SNI | INFO | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { // During the SSL negotiation phase, SSL is tunnelled over TDS packet type 0x12. After @@ -187,7 +187,7 @@ public override void Write(byte[] buffer, int offset, int count) public override async Task WriteAsync(byte[] buffer, int offset, int count, CancellationToken cancellationToken) { - long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent("SslOverTdsStream.WriteAsync | SNI | INFO | SCOPE | Entering Scope {0}"); + long scopeID = SqlClientEventSource.Log.TrySNIScopeEnterEvent(s_className); try { if (!_encapsulate) 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 10fdd7fd28..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,6 +15,7 @@ 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; @@ -48,7 +49,7 @@ public SslOverTdsStream(Stream stream, Guid connectionId = default) public void FinishHandshake() { _encapsulate = false; - SqlClientEventSource.Log.TrySNITraceEvent("SslOverTdsStream.FinishHandshake | SNI | INFO | Connection Id {0}, Switched from encapsulation to passthrough mode", _connectionId); + SqlClientEventSource.Log.TrySNITraceEvent(s_className, EventType.INFO, "Connection Id {0}, Switched from encapsulation to passthrough mode", args0: _connectionId); } /// @@ -67,7 +68,7 @@ public override void Flush() if (!(_stream is PipeStream)) { _stream.Flush(); - SqlClientEventSource.Log.TrySNITraceEvent("SslOverTdsStream.Flush | SNI | INFO | Connection Id {0}, Flushed stream", _connectionId); + 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 a3fa23baca..7b5a2df68e 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 @@ -1301,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/netfx/src/Microsoft/Data/SqlClient/SqlCommand.cs b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlCommand.cs index d813e0dc8a..d9252a5be0 100644 --- a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlCommand.cs +++ b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlCommand.cs @@ -7372,10 +7372,7 @@ private SmiRequestExecutor SetUpSmiRequest(SqlInternalConnectionSmi innerConnect private void WriteBeginExecuteEvent() { - if (Connection != null) - { - SqlClientEventSource.Log.BeginExecute(GetHashCode(), Connection.DataSource, Connection.Database, CommandText); - } + SqlClientEventSource.Log.TryBeginExecuteEvent(ObjectID, Connection?.ClientConnectionId, CommandText); } /// @@ -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/src/Microsoft/Data/SqlClient/SqlClientEventSource.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlClientEventSource.cs index 1e9252d0e8..045b8c7eba 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlClientEventSource.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlClientEventSource.cs @@ -16,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 @@ -227,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 @@ -268,8 +289,8 @@ public static class Tasks internal bool IsSNIScopeEnabled() => Log.IsEnabled(EventLevel.Informational, Keywords.SNIScope); #endregion - private string GetFormattedMessage(string className, string memberName, string infoType, string message) => - new StringBuilder(className).Append(".").Append(memberName).Append(infoType).Append(message).ToString(); + 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. @@ -426,6 +447,28 @@ internal void TryScopeLeaveEvent(long 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 + #region Notification Trace #region Notification Traces without if statements @@ -802,65 +845,65 @@ internal void StateDumpEvent(string message, T0 args0, T1 args1) #region SNI Trace [NonEvent] - internal void TrySNITraceEvent(string className, string infoType, string message, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") + internal void TrySNITraceEvent(string className, string eventType, string message, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") { if (Log.IsSNITraceEnabled()) { - SNITrace(GetFormattedMessage(className, memberName, infoType, message)); + SNITrace(GetFormattedMessage(className, memberName, eventType, message)); } } [NonEvent] - internal void TrySNITraceEvent(string className, string infoType, string message, T0 args0, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") + internal void TrySNITraceEvent(string className, string eventType, string message, T0 args0, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") { if (Log.IsSNITraceEnabled()) { - SNITrace(GetFormattedMessage(className, memberName, infoType, string.Format(message, args0?.ToString() ?? NullStr))); + SNITrace(GetFormattedMessage(className, memberName, eventType, string.Format(message, args0?.ToString() ?? NullStr))); } } [NonEvent] - internal void TrySNITraceEvent(string className, string infoType, string message, T0 args0, T1 args1, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") + internal void TrySNITraceEvent(string className, string eventType, string message, T0 args0, T1 args1, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") { if (Log.IsSNITraceEnabled()) { - SNITrace(GetFormattedMessage(className, memberName, infoType, 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 className, string infoType, string message, T0 args0, T1 args1, T2 args2, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") + 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(GetFormattedMessage(className, memberName, infoType, 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 className, string infoType, string message, T0 args0, T1 args1, T2 args2, T3 args3, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") + 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(GetFormattedMessage(className, memberName, infoType, 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 className, string infoType, string message, T0 args0, T1 args1, T2 args2, T3 args3, T4 args4, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") + 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(GetFormattedMessage(className, memberName, infoType, string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr, args2?.ToString() ?? NullStr, args3?.ToString() ?? NullStr, args4?.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))); } } [NonEvent] - internal void TrySNITraceEvent(string className, string infoType, string message, T0 args0, T1 args1, T2 args2, T3 args3, T4 args4, T5 args5, [System.Runtime.CompilerServices.CallerMemberName] string memberName = "") + 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.IsSNITraceEnabled()) { - SNITrace(GetFormattedMessage(className, memberName, infoType, string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr, args2?.ToString() ?? NullStr, args3?.ToString() ?? NullStr, args4?.ToString() ?? NullStr, args5?.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))); } } #endregion @@ -892,28 +935,18 @@ 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) => 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); @@ -921,7 +954,7 @@ internal long ScopeEnter(string message) return scopeId; } - [Event(ScopeExitId, Level = EventLevel.Informational, Opcode = EventOpcode.Stop, Keywords = Keywords.Scope)] + [Event(ScopeExitId, Level = EventLevel.Informational, Task = Tasks.Scope, Opcode = EventOpcode.Stop, Keywords = Keywords.Scope)] internal void ScopeLeave(string message) => WriteEvent(ScopeExitId, message); @@ -929,7 +962,7 @@ internal void ScopeLeave(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); @@ -937,7 +970,7 @@ internal long NotificationScopeEnter(string message) return scopeId; } - [Event(NotificationScopeExitId, Level = EventLevel.Informational, Opcode = EventOpcode.Stop, Keywords = Keywords.NotificationScope)] + [Event(NotificationScopeExitId, Level = EventLevel.Informational, Task = Tasks.NotificationScope, Opcode = EventOpcode.Stop, Keywords = Keywords.NotificationScope)] internal void NotificationScopeLeave(string message) => WriteEvent(NotificationScopeExitId, message); @@ -945,7 +978,7 @@ internal void NotificationScopeLeave(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); @@ -953,7 +986,7 @@ internal long PoolerScopeEnter(string message) return scopeId; } - [Event(PoolerScopeExitId, Level = EventLevel.Informational, Opcode = EventOpcode.Stop, Keywords = Keywords.PoolerScope)] + [Event(PoolerScopeExitId, Level = EventLevel.Informational, Task = Tasks.PoolerScope, Opcode = EventOpcode.Stop, Keywords = Keywords.PoolerScope)] internal void PoolerScopeLeave(string message) => WriteEvent(PoolerScopeExitId, message); @@ -981,7 +1014,7 @@ internal void AdvancedTraceBin(string message) => internal void AdvancedTraceError(string message) => WriteEvent(AdvancedTraceErrorId, message); - [Event(CorrelationTraceId, Level = EventLevel.Informational, Keywords = Keywords.CorrelationTrace, Opcode = EventOpcode.Start)] + [Event(CorrelationTraceId, Level = EventLevel.Informational, Keywords = Keywords.CorrelationTrace)] internal void CorrelationTrace(string message) => WriteEvent(CorrelationTraceId, message); @@ -993,7 +1026,7 @@ internal void StateDump(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); @@ -1001,12 +1034,18 @@ internal long SNIScopeEnter(string message) return scopeId; } - [Event(SNIScopeExitId, Level = EventLevel.Informational, Opcode = EventOpcode.Stop, Keywords = Keywords.SNIScope)] + [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;