From 3bb47fdc1690018c5987dacd239aa212df0947cd Mon Sep 17 00:00:00 2001 From: David Engel Date: Fri, 10 May 2024 14:54:02 -0700 Subject: [PATCH 1/4] Add scope trace for GenerateSspiClientContext Also fixed some *Scope.Create usages --- .../src/Microsoft/Data/SqlClient/SNI/SNICommon.cs | 8 ++++---- .../src/Microsoft/Data/SqlClient/SNI/SNIMarsHandle.cs | 4 ++-- .../netcore/src/Microsoft/Data/SqlClient/TdsParser.cs | 2 +- .../Data/SqlClient/SSPI/ManagedSSPIContextProvider.cs | 11 +++++++---- 4 files changed, 14 insertions(+), 11 deletions(-) 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 9ccc98a779..cd61156637 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 @@ -148,7 +148,7 @@ internal class SNICommon /// True if certificate is valid internal static bool ValidateSslServerCertificate(string targetServerName, X509Certificate cert, SslPolicyErrors policyErrors) { - using (TrySNIEventScope.Create("SNICommon.ValidateSslServerCertificate | SNI | SCOPE | INFO | Entering Scope {0} ")) + using (TrySNIEventScope.Create(nameof(SNICommon))) { if (policyErrors == SslPolicyErrors.None) { @@ -258,7 +258,7 @@ internal static bool ValidateSslServerCertificate(string targetServerName, X509C /// True if certificate is valid internal static bool ValidateSslServerCertificate(X509Certificate clientCert, X509Certificate serverCert, SslPolicyErrors policyErrors) { - using (TrySNIEventScope.Create("SNICommon.ValidateSslServerCertificate | SNI | SCOPE | INFO | Entering Scope {0} ")) + using (TrySNIEventScope.Create(nameof(SNICommon))) { if (policyErrors == SslPolicyErrors.None) { @@ -334,7 +334,7 @@ internal static bool ValidateSslServerCertificate(X509Certificate clientCert, X5 internal static IPAddress[] GetDnsIpAddresses(string serverName, TimeoutTimer timeout) { - using (TrySNIEventScope.Create(nameof(GetDnsIpAddresses))) + using (TrySNIEventScope.Create(nameof(SNICommon))) { int remainingTimeout = timeout.MillisecondsRemainingInt; SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNICommon), EventType.INFO, @@ -352,7 +352,7 @@ internal static IPAddress[] GetDnsIpAddresses(string serverName, TimeoutTimer ti internal static IPAddress[] GetDnsIpAddresses(string serverName) { - using (TrySNIEventScope.Create(nameof(GetDnsIpAddresses))) + using (TrySNIEventScope.Create(nameof(SNICommon))) { SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNICommon), EventType.INFO, "Getting DNS host entries for serverName {0}.", args0: serverName); return Dns.GetHostAddresses(serverName); 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 8246ce3d6f..b7f682f6d5 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 @@ -94,7 +94,7 @@ public SNIMarsHandle(SNIMarsConnection connection, ushort sessionId, object call /// SMUX header flags private void SendControlPacket(SNISMUXFlags flags) { - using (TrySNIEventScope.Create("SNIMarsHandle.SendControlPacket | SNI | INFO | SCOPE | Entering Scope {0}")) + using (TrySNIEventScope.Create(nameof(SNIMarsHandle))) { SNIPacket packet = RentPacket(headerSize: SNISMUXHeader.HEADER_LENGTH, dataSize: 0); #if DEBUG @@ -195,7 +195,7 @@ public override uint Send(SNIPacket packet) private uint InternalSendAsync(SNIPacket packet) { Debug.Assert(packet.ReservedHeaderSize == SNISMUXHeader.HEADER_LENGTH, "mars handle attempting to send muxed packet without smux reservation in InternalSendAsync"); - using (TrySNIEventScope.Create("SNIMarsHandle.InternalSendAsync | SNI | INFO | SCOPE | Entering Scope {0}")) + using (TrySNIEventScope.Create(nameof(SNIMarsHandle))) { lock (this) { 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 84b3978bdf..bce2609d99 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 @@ -1448,7 +1448,7 @@ internal void ThrowExceptionAndWarning(TdsParserStateObject stateObj, SqlCommand internal SqlError ProcessSNIError(TdsParserStateObject stateObj) { - using (TryEventScope.Create("")) + using (TryEventScope.Create(nameof(TdsParser))) { #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 diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/ManagedSSPIContextProvider.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/ManagedSSPIContextProvider.cs index 8395371de7..4510f17877 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/ManagedSSPIContextProvider.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/ManagedSSPIContextProvider.cs @@ -13,11 +13,14 @@ internal sealed class ManagedSSPIContextProvider : SSPIContextProvider internal override void GenerateSspiClientContext(ReadOnlyMemory received, ref byte[] sendBuff, ref uint sendLength, byte[][] _sniSpnBuffer) { - _sspiClientContextStatus ??= new SspiClientContextStatus(); + using (TrySNIEventScope.Create(nameof(ManagedSSPIContextProvider))) + { + _sspiClientContextStatus ??= new SspiClientContextStatus(); - SNIProxy.GenSspiClientContext(_sspiClientContextStatus, received, ref sendBuff, _sniSpnBuffer); - SqlClientEventSource.Log.TryTraceEvent("TdsParserStateObjectManaged.GenerateSspiClientContext | Info | Session Id {0}", _physicalStateObj.SessionId); - sendLength = (uint)(sendBuff != null ? sendBuff.Length : 0); + SNIProxy.GenSspiClientContext(_sspiClientContextStatus, received, ref sendBuff, _sniSpnBuffer); + SqlClientEventSource.Log.TryTraceEvent("TdsParserStateObjectManaged.GenerateSspiClientContext | Info | Session Id {0}", _physicalStateObj.SessionId); + sendLength = (uint)(sendBuff != null ? sendBuff.Length : 0); + } } } } From 5782901e5b0d3b9724c289162e9495cd8c06047c Mon Sep 17 00:00:00 2001 From: David Engel Date: Mon, 13 May 2024 14:20:33 -0700 Subject: [PATCH 2/4] Missed some --- .../src/Microsoft/Data/ProviderBase/DbConnectionFactory.cs | 2 +- .../src/Microsoft/Data/ProviderBase/DbConnectionFactory.cs | 2 +- .../netfx/src/Microsoft/Data/SqlClient/SqlConnection.cs | 4 ++-- 3 files changed, 4 insertions(+), 4 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Common/src/Microsoft/Data/ProviderBase/DbConnectionFactory.cs b/src/Microsoft.Data.SqlClient/netcore/src/Common/src/Microsoft/Data/ProviderBase/DbConnectionFactory.cs index df16ee4d23..e5c76701e4 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Common/src/Microsoft/Data/ProviderBase/DbConnectionFactory.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Common/src/Microsoft/Data/ProviderBase/DbConnectionFactory.cs @@ -49,7 +49,7 @@ abstract public DbProviderFactory ProviderFactory public void ClearAllPools() { - using (TryEventScope.Create(" connectionPoolGroups = _connectionPoolGroups; foreach (KeyValuePair entry in connectionPoolGroups) diff --git a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/ProviderBase/DbConnectionFactory.cs b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/ProviderBase/DbConnectionFactory.cs index 701719796a..b857323bb1 100644 --- a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/ProviderBase/DbConnectionFactory.cs +++ b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/ProviderBase/DbConnectionFactory.cs @@ -65,7 +65,7 @@ internal int ObjectID public void ClearAllPools() { - using (TryEventScope.Create("")) + using (TryEventScope.Create(nameof(DbConnectionFactory))) { Dictionary connectionPoolGroups = _connectionPoolGroups; foreach (KeyValuePair entry in connectionPoolGroups) diff --git a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlConnection.cs b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlConnection.cs index b6104b9075..8775c1406e 100644 --- a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlConnection.cs +++ b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlConnection.cs @@ -2758,7 +2758,7 @@ private void IssueSQLDebug(uint option, string machineName, uint pid, uint id, s /// public static void ChangePassword(string connectionString, string newPassword) { - using (TryEventScope.Create("")) + using (TryEventScope.Create(nameof(SqlConnection))) { SqlClientEventSource.Log.TryCorrelationTraceEvent(" ActivityID {0}", ActivityCorrelator.Current); @@ -2801,7 +2801,7 @@ public static void ChangePassword(string connectionString, string newPassword) /// public static void ChangePassword(string connectionString, SqlCredential credential, SecureString newSecurePassword) { - using (TryEventScope.Create("")) + using (TryEventScope.Create(nameof(SqlConnection))) { SqlClientEventSource.Log.TryCorrelationTraceEvent(" ActivityID {0}", ActivityCorrelator.Current); From 673f53f057d0c37d8178f7a1c979f5adfa3faec7 Mon Sep 17 00:00:00 2001 From: David Engel Date: Thu, 16 May 2024 17:18:44 -0700 Subject: [PATCH 3/4] Move event scope trace to SSPIContextProvider Fix some incorrect class strings in log messages in ManagedSSPIContextProvider and NegotiateSSPIContextProvider --- .../SqlClient/SSPI/ManagedSSPIContextProvider.cs | 11 ++++------- .../SSPI/NegotiateSSPIContextProvider.cs | 3 ++- .../Data/SqlClient/SSPI/SSPIContextProvider.cs | 15 +++++++++------ 3 files changed, 15 insertions(+), 14 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/ManagedSSPIContextProvider.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/ManagedSSPIContextProvider.cs index 2b4c25bd19..186be63502 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/ManagedSSPIContextProvider.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/ManagedSSPIContextProvider.cs @@ -13,14 +13,11 @@ internal sealed class ManagedSSPIContextProvider : SSPIContextProvider internal override void GenerateSspiClientContext(ReadOnlyMemory received, ref byte[] sendBuff, ref uint sendLength, byte[][] _sniSpnBuffer) { - using (TrySNIEventScope.Create(nameof(ManagedSSPIContextProvider))) - { - _sspiClientContextStatus ??= new SspiClientContextStatus(); + _sspiClientContextStatus ??= new SspiClientContextStatus(); - SNIProxy.GenSspiClientContext(_sspiClientContextStatus, received, ref sendBuff, _sniSpnBuffer); - SqlClientEventSource.Log.TryTraceEvent("TdsParserStateObjectManaged.GenerateSspiClientContext | Info | Session Id {0}", _physicalStateObj.SessionId); - sendLength = (uint)(sendBuff != null ? sendBuff.Length : 0); - } + SNIProxy.GenSspiClientContext(_sspiClientContextStatus, received, ref sendBuff, _sniSpnBuffer); + SqlClientEventSource.Log.TryTraceEvent("{0}.{1} | Info | Session Id {2}", nameof(ManagedSSPIContextProvider), nameof(GenerateSspiClientContext), _physicalStateObj.SessionId); + sendLength = (uint)(sendBuff != null ? sendBuff.Length : 0); } } } diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/NegotiateSSPIContextProvider.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/NegotiateSSPIContextProvider.cs index 2c68839e3f..2fb4ff14cc 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/NegotiateSSPIContextProvider.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/NegotiateSSPIContextProvider.cs @@ -16,7 +16,8 @@ internal override void GenerateSspiClientContext(ReadOnlyMemory received, { _negotiateAuth ??= new(new NegotiateAuthenticationClientOptions { Package = "Negotiate", TargetName = Encoding.Unicode.GetString(_sniSpnBuffer[0]) }); sendBuff = _negotiateAuth.GetOutgoingBlob(received.Span, out NegotiateAuthenticationStatusCode statusCode)!; - SqlClientEventSource.Log.TryTraceEvent("TdsParserStateObjectManaged.GenerateSspiClientContext | Info | Session Id {0}, StatusCode={1}", _physicalStateObj.SessionId, statusCode); + SqlClientEventSource.Log.TryTraceEvent("{0}.{1} | Info | Session Id {2}, StatusCode={3}", nameof(NegotiateSSPIContextProvider), + nameof(GenerateSspiClientContext), _physicalStateObj.SessionId, statusCode); if (statusCode is not NegotiateAuthenticationStatusCode.Completed and not NegotiateAuthenticationStatusCode.ContinueNeeded) { throw new InvalidOperationException(SQLMessage.SSPIGenerateError() + Environment.NewLine + statusCode); diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/SSPIContextProvider.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/SSPIContextProvider.cs index 256818660e..e9770ebb67 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/SSPIContextProvider.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/SSPIContextProvider.cs @@ -34,13 +34,16 @@ internal void SSPIData(ReadOnlyMemory receivedBuff, ref byte[] sendBuff, r internal void SSPIData(ReadOnlyMemory receivedBuff, ref byte[] sendBuff, ref UInt32 sendLength, byte[][] sniSpnBuffer) { - try + using (TrySNIEventScope.Create(nameof(SSPIContextProvider))) { - GenerateSspiClientContext(receivedBuff, ref sendBuff, ref sendLength, sniSpnBuffer); - } - catch (Exception e) - { - SSPIError(e.Message + Environment.NewLine + e.StackTrace, TdsEnums.GEN_CLIENT_CONTEXT); + try + { + GenerateSspiClientContext(receivedBuff, ref sendBuff, ref sendLength, sniSpnBuffer); + } + catch (Exception e) + { + SSPIError(e.Message + Environment.NewLine + e.StackTrace, TdsEnums.GEN_CLIENT_CONTEXT); + } } } From 73fbd5c7839b91a2b01ae38873d8ff8281fa2a89 Mon Sep 17 00:00:00 2001 From: David Engel Date: Tue, 11 Jun 2024 13:35:20 -0700 Subject: [PATCH 4/4] Reapply changes after merge conflicts --- .../netcore/src/Microsoft/Data/SqlClient/SNI/SNICommon.cs | 6 +++--- .../Data/SqlClient/SSPI/NegotiateSSPIContextProvider.cs | 3 ++- 2 files changed, 5 insertions(+), 4 deletions(-) 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 f8f2facb59..c9515d971f 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 @@ -151,7 +151,7 @@ internal class SNICommon /// True if certificate is valid internal static bool ValidateSslServerCertificate(Guid connectionId, string targetServerName, string hostNameInCertificate, X509Certificate serverCert, string validationCertFileName, SslPolicyErrors policyErrors) { - using (TrySNIEventScope.Create("SNICommon.ValidateSslServerCertificate | SNI | SCOPE | INFO | Entering Scope {0} ")) + using (TrySNIEventScope.Create(nameof(SNICommon))) { if (policyErrors == SslPolicyErrors.None) { @@ -292,7 +292,7 @@ internal static bool ValidateSslServerCertificate(Guid connectionId, string targ internal static IPAddress[] GetDnsIpAddresses(string serverName, TimeoutTimer timeout) { - using (TrySNIEventScope.Create(nameof(GetDnsIpAddresses))) + using (TrySNIEventScope.Create(nameof(SNICommon))) { int remainingTimeout = timeout.MillisecondsRemainingInt; SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNICommon), EventType.INFO, @@ -310,7 +310,7 @@ internal static IPAddress[] GetDnsIpAddresses(string serverName, TimeoutTimer ti internal static IPAddress[] GetDnsIpAddresses(string serverName) { - using (TrySNIEventScope.Create(nameof(GetDnsIpAddresses))) + using (TrySNIEventScope.Create(nameof(SNICommon))) { SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNICommon), EventType.INFO, "Getting DNS host entries for serverName {0}.", args0: serverName); return Dns.GetHostAddresses(serverName); diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/NegotiateSSPIContextProvider.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/NegotiateSSPIContextProvider.cs index 21ab4a15b7..431cf5cd6f 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/NegotiateSSPIContextProvider.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SSPI/NegotiateSSPIContextProvider.cs @@ -21,7 +21,8 @@ internal override void GenerateSspiClientContext(ReadOnlyMemory received, _negotiateAuth ??= new(new NegotiateAuthenticationClientOptions { Package = "Negotiate", TargetName = Encoding.Unicode.GetString(_sniSpnBuffer[i]) }); sendBuff = _negotiateAuth.GetOutgoingBlob(received.Span, out statusCode)!; // Log session id, status code and the actual SPN used in the negotiation - SqlClientEventSource.Log.TryTraceEvent("TdsParserStateObjectManaged.GenerateSspiClientContext | Info | Session Id {0}, StatusCode={1}, SPN={2}", _physicalStateObj.SessionId, statusCode, _negotiateAuth.TargetName); + SqlClientEventSource.Log.TryTraceEvent("{0}.{1} | Info | Session Id {2}, StatusCode={3}, SPN={4}", nameof(NegotiateSSPIContextProvider), + nameof(GenerateSspiClientContext), _physicalStateObj.SessionId, statusCode, _negotiateAuth.TargetName); if (statusCode == NegotiateAuthenticationStatusCode.Completed || statusCode == NegotiateAuthenticationStatusCode.ContinueNeeded) break; // Successful case, exit the loop with current SPN. else