From 210db67eaae4eb326c689bddb4b223691ff9e241 Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Fri, 7 Aug 2026 17:36:25 -0700 Subject: [PATCH 1/5] Avoid eager string interpolation at guarded trace call sites Interpolated strings passed to SqlClientEventSource.Try*Event are built unconditionally at the call site, so the overload's internal IsTraceEnabled/IsAdvancedTraceOn check no longer avoids the cost. This allocates on every call even with tracing off. SqlConnectionInternal.Deactivate runs on every pooled connection return and accounted for ~200 bytes per open/close cycle, which is most of the +264 bytes/op regression the connection pool benchmarks show against 6.1.6. Wrap the affected call sites in the matching enablement check so the string is only built when the event will be written. The guards mirror the checks already inside each overload, so behavior is unchanged. Measured on a pooled open/close loop against the in-proc TDS server: sync 688.5 -> 488.5 bytes/op, async 880.5 -> 680.5 bytes/op. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../Connection/SqlConnectionInternal.cs | 695 +++++++++++------- .../Microsoft/Data/SqlClient/SqlCommand.cs | 198 +++-- .../Data/SqlClient/Utilities/AsyncHelper.cs | 5 +- 3 files changed, 566 insertions(+), 332 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs index fd8817b9aa..87a5c503f4 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs @@ -424,10 +424,13 @@ internal SqlConnectionInternal( _parserLock.Release(); } - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.ctor | ADV | " + - $"Object ID {ObjectID}, " + - $"constructed new TDS internal connection"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.ctor | ADV | " + + $"Object ID {ObjectID}, " + + $"constructed new TDS internal connection"); + } } #endregion @@ -842,10 +845,13 @@ internal SqlTransaction BeginSqlTransaction( internal void BreakConnection() { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.BreakConnection | RES | CPOOL " + - $"Object ID {ObjectID}, " + - $"Breaking connection."); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.BreakConnection | RES | CPOOL " + + $"Object ID {ObjectID}, " + + $"Breaking connection."); + } DoomThisConnection(); // Mark connection as unusable, so it will be destroyed Connection?.Close(); @@ -919,9 +925,12 @@ internal void DisconnectTransaction(SqlInternalTransaction internalTransaction) // @TODO: Make internal by making the DbConnectionInternal implementation internal public override void Dispose() { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.Dispose | ADV | " + - $"Object ID {ObjectID} disposing"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.Dispose | ADV | " + + $"Object ID {ObjectID} disposing"); + } try { @@ -949,10 +958,13 @@ public override void Dispose() internal void EnlistNull() { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnection.EnlistNull | ADV | " + - $"Object ID {ObjectID}, " + - $"unenlisting."); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnection.EnlistNull | ADV | " + + $"Object ID {ObjectID}, " + + $"unenlisting."); + } // We were in a transaction, but now we are not - so send message to server with empty // transaction - confirmed proper behavior from Sameet Agarwal. @@ -969,10 +981,13 @@ internal void EnlistNull() IsEnlistedInTransaction = false; EnlistedTransaction = null; - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnection.EnlistNull | ADV | " + - $"Object ID {ObjectID}, " + - $"unenlisted."); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnection.EnlistNull | ADV | " + + $"Object ID {ObjectID}, " + + $"unenlisted."); + } // The EnlistTransaction above will return an TransactionEnded event, which causes the // TdsParser to clear the current transaction. In either case, when we're working with @@ -1179,10 +1194,13 @@ internal void OnEnvChange(SqlEnvChange rec) break; case TdsEnums.ENV_ROUTING: - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnEnvChange | ADV | " + - $"Object ID {ObjectID}, " + - $"Received routing info"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.OnEnvChange | ADV | " + + $"Object ID {ObjectID}, " + + $"Received routing info"); + } if (string.IsNullOrEmpty(rec._newRoutingInfo.ServerName) || rec._newRoutingInfo.Protocol != 0 || @@ -1195,10 +1213,13 @@ internal void OnEnvChange(SqlEnvChange rec) break; case TdsEnums.ENV_ENHANCEDROUTING: - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnEnvChange | ADV | " + - $"Object ID {ObjectID}, " + - $"Received enhanced routing info"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.OnEnvChange | ADV | " + + $"Object ID {ObjectID}, " + + $"Received enhanced routing info"); + } if (string.IsNullOrEmpty(rec._newRoutingInfo.ServerName) || string.IsNullOrEmpty(rec._newRoutingInfo.DatabaseName) || @@ -1319,17 +1340,23 @@ internal void OnFeatureExtAck(int featureId, byte[] data) case TdsEnums.FEATUREEXT_GLOBALTRANSACTIONS: { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for GlobalTransactions"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + $"Object ID {ObjectID}, " + + $"Received feature extension acknowledgement for GlobalTransactions"); + } if (data.Length < 1) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown version number for GlobalTransactions"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID}, " + + $"Unknown version number for GlobalTransactions"); + } throw SQL.ParsingError(); } @@ -1341,17 +1368,23 @@ internal void OnFeatureExtAck(int featureId, byte[] data) case TdsEnums.FEATUREEXT_FEDAUTH: { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {0}, " + - $"Received feature extension acknowledgement for federated authentication"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + $"Object ID {0}, " + + $"Received feature extension acknowledgement for federated authentication"); + } if (!_federatedAuthenticationRequested) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Did not request federated authentication"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID}, " + + $"Did not request federated authentication"); + } throw SQL.ParsingErrorFeatureId(ParsingErrorState.UnrequestedFeatureAckReceived, featureId); } @@ -1366,10 +1399,13 @@ internal void OnFeatureExtAck(int featureId, byte[] data) // The server shouldn't have sent any additional data with the ack (like a nonce) if (data.Length != 0) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Federated authentication feature extension ack for MSAL and Security Token includes extra data"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID}, " + + $"Federated authentication feature extension ack for MSAL and Security Token includes extra data"); + } throw SQL.ParsingError(ParsingErrorState.FedAuthFeatureAckContainsExtraData); } @@ -1377,10 +1413,13 @@ internal void OnFeatureExtAck(int featureId, byte[] data) break; default: - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Attempting to use unknown federated authentication library"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID}, " + + $"Attempting to use unknown federated authentication library"); + } Debug.Fail("Unknown _fedAuthLibrary type"); throw SQL.ParsingErrorLibraryType( @@ -1417,18 +1456,24 @@ internal void OnFeatureExtAck(int featureId, byte[] data) // with the new one or some other thread's context won the expiration race. if (newAuthenticationContextInCacheAfterAddOrUpdate == _newDbConnectionPoolAuthenticationContext) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Updated the new dbAuthenticationContext in the _dbConnectionPool.AuthenticationContexts."); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID}, " + + $"Updated the new dbAuthenticationContext in the _dbConnectionPool.AuthenticationContexts."); + } } else { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID }, " + - $"AddOrUpdate attempted on _dbConnectionPool.AuthenticationContexts, " + - $"but it did not update the new value."); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID }, " + + $"AddOrUpdate attempted on _dbConnectionPool.AuthenticationContexts, " + + $"but it did not update the new value."); + } } #endif } @@ -1437,17 +1482,23 @@ internal void OnFeatureExtAck(int featureId, byte[] data) } case TdsEnums.FEATUREEXT_TCE: { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for TCE"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + $"Object ID {ObjectID}, " + + $"Received feature extension acknowledgement for TCE"); + } if (data.Length < 1) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown version number for TCE"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID}, " + + $"Unknown version number for TCE"); + } throw SQL.ParsingError(ParsingErrorState.TceUnknownVersion); } @@ -1455,10 +1506,13 @@ internal void OnFeatureExtAck(int featureId, byte[] data) byte supportedTceVersion = data[0]; if (supportedTceVersion == 0 || supportedTceVersion > TdsEnums.MAX_SUPPORTED_TCE_VERSION) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Invalid version number for TCE"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID}, " + + $"Invalid version number for TCE"); + } throw SQL.ParsingErrorValue(ParsingErrorState.TceInvalidVersion, supportedTceVersion); } @@ -1474,10 +1528,13 @@ internal void OnFeatureExtAck(int featureId, byte[] data) } case TdsEnums.FEATUREEXT_AZURESQLSUPPORT: { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for AzureSQLSupport"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + $"Object ID {ObjectID}, " + + $"Received feature extension acknowledgement for AzureSQLSupport"); + } if (data.Length < 1) { @@ -1490,27 +1547,36 @@ internal void OnFeatureExtAck(int featureId, byte[] data) if (Capabilities.ReadOnlyFailoverPartnerConnection && SqlClientEventSource.Log.IsTraceEnabled()) { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"FailoverPartner enabled with Readonly intent for AzureSQL DB"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + $"Object ID {ObjectID}, " + + $"FailoverPartner enabled with Readonly intent for AzureSQL DB"); + } } break; } case TdsEnums.FEATUREEXT_DATACLASSIFICATION: { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for DATACLASSIFICATION"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + $"Object ID {ObjectID}, " + + $"Received feature extension acknowledgement for DATACLASSIFICATION"); + } if (data.Length < 1) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown token for DATACLASSIFICATION"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID}, " + + $"Unknown token for DATACLASSIFICATION"); + } throw SQL.ParsingError(ParsingErrorState.CorruptedTdsStream); } @@ -1519,10 +1585,13 @@ internal void OnFeatureExtAck(int featureId, byte[] data) if (supportedDataClassificationVersion == 0 || supportedDataClassificationVersion > TdsEnums.DATA_CLASSIFICATION_VERSION_MAX_SUPPORTED) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Invalid version number for DATACLASSIFICATION"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID}, " + + $"Invalid version number for DATACLASSIFICATION"); + } throw SQL.ParsingErrorValue( ParsingErrorState.DataClassificationInvalidVersion, @@ -1531,10 +1600,13 @@ internal void OnFeatureExtAck(int featureId, byte[] data) if (data.Length != 2) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown token for DATACLASSIFICATION"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID}, " + + $"Unknown token for DATACLASSIFICATION"); + } throw SQL.ParsingError(ParsingErrorState.CorruptedTdsStream); } @@ -1549,17 +1621,23 @@ internal void OnFeatureExtAck(int featureId, byte[] data) case TdsEnums.FEATUREEXT_UTF8SUPPORT: { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for UTF8 support"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + $"Object ID {ObjectID}, " + + $"Received feature extension acknowledgement for UTF8 support"); + } if (data.Length < 1) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown value for UTF8 support", ObjectID); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID}, " + + $"Unknown value for UTF8 support", ObjectID); + } throw SQL.ParsingError(); } @@ -1570,17 +1648,23 @@ internal void OnFeatureExtAck(int featureId, byte[] data) } case TdsEnums.FEATUREEXT_SQLDNSCACHING: { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for SQLDNSCACHING"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + $"Object ID {ObjectID}, " + + $"Received feature extension acknowledgement for SQLDNSCACHING"); + } if (data.Length < 1) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown token for SQLDNSCACHING"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID}, " + + $"Unknown token for SQLDNSCACHING"); + } throw SQL.ParsingError(ParsingErrorState.CorruptedTdsStream); } @@ -1610,17 +1694,23 @@ internal void OnFeatureExtAck(int featureId, byte[] data) } case TdsEnums.FEATUREEXT_JSONSUPPORT: { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for JSONSUPPORT"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + $"Object ID {ObjectID}, " + + $"Received feature extension acknowledgement for JSONSUPPORT"); + } if (data.Length != 1) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown token for JSONSUPPORT"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID}, " + + $"Unknown token for JSONSUPPORT"); + } throw SQL.ParsingError(ParsingErrorState.CorruptedTdsStream); } @@ -1628,10 +1718,13 @@ internal void OnFeatureExtAck(int featureId, byte[] data) byte jsonSupportVersion = data[0]; if (jsonSupportVersion == 0 || jsonSupportVersion > TdsEnums.MAX_SUPPORTED_JSON_VERSION) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Invalid version number for JSONSUPPORT"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID}, " + + $"Invalid version number for JSONSUPPORT"); + } throw SQL.ParsingError(); } @@ -1641,17 +1734,23 @@ internal void OnFeatureExtAck(int featureId, byte[] data) } case TdsEnums.FEATUREEXT_VECTORSUPPORT: { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for VECTORSUPPORT"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + $"Object ID {ObjectID}, " + + $"Received feature extension acknowledgement for VECTORSUPPORT"); + } if (data.Length != 1) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown token for VECTORSUPPORT"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID}, " + + $"Unknown token for VECTORSUPPORT"); + } throw SQL.ParsingError(ParsingErrorState.CorruptedTdsStream); } @@ -1659,11 +1758,14 @@ internal void OnFeatureExtAck(int featureId, byte[] data) byte vectorSupportVersion = data[0]; if (vectorSupportVersion == 0 || vectorSupportVersion > TdsEnums.MAX_SUPPORTED_VECTOR_VERSION) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Invalid version number {vectorSupportVersion} for VECTORSUPPORT, " + - $"Max supported version is {TdsEnums.MAX_SUPPORTED_VECTOR_VERSION}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID}, " + + $"Invalid version number {vectorSupportVersion} for VECTORSUPPORT, " + + $"Max supported version is {TdsEnums.MAX_SUPPORTED_VECTOR_VERSION}"); + } throw SQL.ParsingError(); } @@ -1676,10 +1778,13 @@ internal void OnFeatureExtAck(int featureId, byte[] data) { if (data.Length != 1) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown token for ENHANCEDROUTINGSUPPORT"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + $"Object ID {ObjectID}, " + + $"Unknown token for ENHANCEDROUTINGSUPPORT"); + } throw SQL.ParsingError(ParsingErrorState.CorruptedTdsStream); } @@ -1687,20 +1792,26 @@ internal void OnFeatureExtAck(int featureId, byte[] data) // A value of 1 indicates that the server supports the feature. Capabilities.EnhancedRouting = data[0] == 1; - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for " + - $"ENHANCEDROUTINGSUPPORT = {IsEnhancedRoutingSupportEnabled}"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + $"Object ID {ObjectID}, " + + $"Received feature extension acknowledgement for " + + $"ENHANCEDROUTINGSUPPORT = {IsEnhancedRoutingSupportEnabled}"); + } break; } case TdsEnums.FEATUREEXT_USERAGENT: { // Unexpected ack from server but we ignore it entirely - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for USERAGENTSUPPORT (ignored)"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + $"Object ID {ObjectID}, " + + $"Received feature extension acknowledgement for USERAGENTSUPPORT (ignored)"); + } break; } @@ -1772,13 +1883,16 @@ internal void OnFedAuthInfo(SqlFedAuthInfo fedAuthInfo) // If the authentication context is expiring within next 10 minutes, lets // just re-create a token for this connection attempt. And on successful // login, try to update the cache with the new token. - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFedAuthInfo | " + - $"Object ID {ObjectID}, " + - $"The expiration time is less than 10 mins, trying to get new access " + - $"token regardless of if an other thread is also trying to update it. " + - $"The expiration time is {dbConnectionPoolAuthenticationContext.ExpirationTime:T}. " + - $"Current Time is {DateTime.UtcNow:T}."); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFedAuthInfo | " + + $"Object ID {ObjectID}, " + + $"The expiration time is less than 10 mins, trying to get new access " + + $"token regardless of if an other thread is also trying to update it. " + + $"The expiration time is {dbConnectionPoolAuthenticationContext.ExpirationTime:T}. " + + $"Current Time is {DateTime.UtcNow:T}."); + } attemptRefreshTokenUnLocked = true; } #if DEBUG @@ -1800,12 +1914,15 @@ internal void OnFedAuthInfo(SqlFedAuthInfo fedAuthInfo) // If the token is expiring within the next 45 mins, try to fetch a new // token, if there is no thread already doing it. If a thread is already // doing the refresh, just use the existing token in the cache and proceed. - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFedAuthInfo | ADV | " + - $"Object ID {ObjectID}, " + - $"The authentication context needs a refresh. " + - $"The expiration time is {dbConnectionPoolAuthenticationContext.ExpirationTime:T}. " + - $"Current Time is {DateTime.UtcNow:T}."); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.OnFedAuthInfo | ADV | " + + $"Object ID {ObjectID}, " + + $"The authentication context needs a refresh. " + + $"The expiration time is {dbConnectionPoolAuthenticationContext.ExpirationTime:T}. " + + $"Current Time is {DateTime.UtcNow:T}."); + } // Call the function which tries to acquire a lock over the authentication // context before trying to update. If the lock could not be obtained, it @@ -1827,18 +1944,24 @@ internal void OnFedAuthInfo(SqlFedAuthInfo fedAuthInfo) // Indicate in EventSource Trace that we are successful with the update. if (attemptRefreshTokenLocked) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFedAuthInfo | " + - $"Object ID {ObjectID}, " + - $"The attempt to get a new access token succeeded under the locked mode."); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.OnFedAuthInfo | " + + $"Object ID {ObjectID}, " + + $"The attempt to get a new access token succeeded under the locked mode."); + } } } - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFedAuthInfo | " + - $"Object ID {ObjectID}, " + - $"Found an authentication context in the cache that does not need a refresh at this time. " + - $"Re-using the cached token."); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.OnFedAuthInfo | " + + $"Object ID {ObjectID}, " + + $"Found an authentication context in the cache that does not need a refresh at this time. " + + $"Re-using the cached token."); + } } } @@ -2016,10 +2139,13 @@ protected override void Deactivate() { try { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnection.Deactivate | ADV | " + - $"Object ID {ObjectID} deactivating, " + - $"Client Connection Id {Connection?.ClientConnectionId}"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnection.Deactivate | ADV | " + + $"Object ID {ObjectID} deactivating, " + + $"Client Connection Id {Connection?.ClientConnectionId}"); + } SqlReferenceCollection referenceCollection = (SqlReferenceCollection)ReferenceCollection; referenceCollection?.Deactivate(); @@ -2217,19 +2343,25 @@ private void CompleteLogin(bool enlistOK) // @TODO: Rename as per guidelines // ROR should not affect state of connection recovery if (_federatedAuthenticationRequested && !_federatedAuthenticationAcknowledged) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.CompleteLogin | ERR | " + - $"Object ID {ObjectID}, " + - $"Server did not acknowledge the federated authentication request"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.CompleteLogin | ERR | " + + $"Object ID {ObjectID}, " + + $"Server did not acknowledge the federated authentication request"); + } throw SQL.ParsingError(ParsingErrorState.FedAuthNotAcknowledged); } if (_federatedAuthenticationInfoRequested && !_federatedAuthenticationInfoReceived) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.CompleteLogin | ERR | " + - $"Object ID {ObjectID}, " + - $"Server never sent the requested federated authentication info"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.CompleteLogin | ERR | " + + $"Object ID {ObjectID}, " + + $"Server never sent the requested federated authentication info"); + } throw SQL.ParsingError(ParsingErrorState.FedAuthInfoNotReceived); } @@ -2345,11 +2477,14 @@ private void EnlistNonNull(Transaction transaction) { Debug.Assert(transaction != null, "null transaction?"); - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnection.EnlistNonNull | ADV | " + - $"Object ID {ObjectID}, " + - $"Transaction Id {transaction?.TransactionInformation?.LocalIdentifier}, " + - $"attempting to delegate."); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnection.EnlistNonNull | ADV | " + + $"Object ID {ObjectID}, " + + $"Transaction Id {transaction?.TransactionInformation?.LocalIdentifier}, " + + $"attempting to delegate."); + } bool hasDelegatedTransaction = false; SqlDelegatedTransaction delegatedTransaction = new(this, transaction); @@ -2407,12 +2542,15 @@ private void EnlistNonNull(Transaction transaction) if (hasDelegatedTransaction) { DelegatedTransaction = delegatedTransaction; - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnection.EnlistNonNull | ADV | " + - $"Object ID {ObjectID}, " + - $"Client Connection Id {Connection?.ClientConnectionId} " + - $"delegated to transaction {delegatedTransaction?.ObjectID} " + - $"with transactionId {delegatedTransaction?.Transaction?.TransactionInformation?.LocalIdentifier}"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnection.EnlistNonNull | ADV | " + + $"Object ID {ObjectID}, " + + $"Client Connection Id {Connection?.ClientConnectionId} " + + $"delegated to transaction {delegatedTransaction?.ObjectID} " + + $"with transactionId {delegatedTransaction?.Transaction?.TransactionInformation?.LocalIdentifier}"); + } } } catch (SqlException e) @@ -2441,10 +2579,13 @@ private void EnlistNonNull(Transaction transaction) if (!hasDelegatedTransaction) { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnection.EnlistNonNull | ADV | " + - $"Object ID {ObjectID}, " + - $"delegation not possible, enlisting."); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnection.EnlistNonNull | ADV | " + + $"Object ID {ObjectID}, " + + $"delegation not possible, enlisting."); + } byte[] cookie = null; @@ -2472,11 +2613,14 @@ private void EnlistNonNull(Transaction transaction) PropagateTransactionCookie(cookie); IsEnlistedInTransaction = true; - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnection.EnlistNonNull | ADV | " + - $"Object ID {ObjectID}, " + - $"Client Connection Id {Connection?.ClientConnectionId}, " + - $"Enlisted in transaction with transactionId {transaction?.TransactionInformation?.LocalIdentifier}"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnection.EnlistNonNull | ADV | " + + $"Object ID {ObjectID}, " + + $"Client Connection Id {Connection?.ClientConnectionId}, " + + $"Enlisted in transaction with transactionId {transaction?.TransactionInformation?.LocalIdentifier}"); + } } // Tell the base class about our enlistment @@ -3062,9 +3206,12 @@ private void Login( private void LoginFailure() { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.LoginFailure | RES | CPOOL | " + - $"Object ID {ObjectID}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.LoginFailure | RES | CPOOL | " + + $"Object ID {ObjectID}"); + } // If the parser was allocated, and we failed, then we must have failed on either the // Connect or Login, either way we should call Disconnect. Disconnect can be called if @@ -3102,10 +3249,13 @@ private void LoginNoFailover( // to set CurrentDatasource ServerInfo originalServerInfo = serverInfo; - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.LoginNoFailover | ADV | " + - $"Object ID {ObjectID}, " + - $"Host={serverInfo.UserServerName}"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.LoginNoFailover | ADV | " + + $"Object ID {ObjectID}, " + + $"Host={serverInfo.UserServerName}"); + } // Milliseconds to sleep (back off) between attempts. int sleepInterval = 100; @@ -3241,16 +3391,22 @@ private void LoginNoFailover( // In this case, we should ignore the routing info and connect to the current server. if (!string.IsNullOrEmpty(RoutingInfo.DatabaseName) && !IsEnhancedRoutingSupportEnabled) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.LoginNoFailover | " + - $"Ignoring enhanced routing info because the server did not acknowledge the feature."); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.LoginNoFailover | " + + $"Ignoring enhanced routing info because the server did not acknowledge the feature."); + } RoutingInfo = null; break; } - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.LoginNoFailover | " + - $"Routed to {serverInfo.ExtendedServerName}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.LoginNoFailover | " + + $"Routed to {serverInfo.ExtendedServerName}"); + } if (routingAttempts > MaxNumberOfRedirectRoute) { @@ -3354,10 +3510,13 @@ private void LoginNoFailover( // Sleep for a bit to prevent clogging the network with requests, then update sleep // interval for next iteration (max 1 second interval) - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.LoginNoFailover | ADV " + - $"Object ID {ObjectID}, " + - $"Sleeping {sleepInterval}ms"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.LoginNoFailover | ADV " + + $"Object ID {ObjectID}, " + + $"Sleeping {sleepInterval}ms"); + } Thread.Sleep(sleepInterval); @@ -3419,12 +3578,15 @@ private void LoginWithFailover( Debug.Assert(!connectionOptions.MultiSubnetFailover, "MultiSubnetFailover should not be set if failover partner is used"); - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.LoginWithFailover | ADV | " + - $"Object ID {ObjectID}, " + - $"useFailover={useFailoverHost}, " + - $"primary={primaryServerInfo.UserServerName}, " + - $"failover={failoverHost}"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.LoginWithFailover | ADV | " + + $"Object ID {ObjectID}, " + + $"useFailover={useFailoverHost}, " + + $"primary={primaryServerInfo.UserServerName}, " + + $"failover={failoverHost}"); + } #if NETFRAMEWORK string protocol = ConnectionOptions.NetworkLibrary; @@ -3504,18 +3666,24 @@ private void LoginWithFailover( { if (LocalAppContextSwitches.IgnoreServerProvidedFailoverPartner) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.LoginWithFailover | ADV | " + - $"Object ID {ObjectID}, " + - $"Ignoring server provided failover partner '{ServerProvidedFailoverPartner}' " + - $"due to IgnoreServerProvidedFailoverPartner AppContext switch."); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.LoginWithFailover | ADV | " + + $"Object ID {ObjectID}, " + + $"Ignoring server provided failover partner '{ServerProvidedFailoverPartner}' " + + $"due to IgnoreServerProvidedFailoverPartner AppContext switch."); + } } else { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.LoginWithFailover | ADV | " + - $"Object ID {ObjectID}, " + - $"new failover partner={ServerProvidedFailoverPartner}"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.LoginWithFailover | ADV | " + + $"Object ID {ObjectID}, " + + $"new failover partner={ServerProvidedFailoverPartner}"); + } #if NET failoverServerInfo.SetDerivedNames(string.Empty, ServerProvidedFailoverPartner); @@ -3552,9 +3720,12 @@ private void LoginWithFailover( // In this case, we should ignore the routing info and connect to the current server. if (!string.IsNullOrEmpty(RoutingInfo.DatabaseName) && !IsEnhancedRoutingSupportEnabled) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.LoginWithFailover | " + - $"Ignoring enhanced routing info because the server did not acknowledge the feature."); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.LoginWithFailover | " + + $"Ignoring enhanced routing info because the server did not acknowledge the feature."); + } RoutingInfo = null; continue; } @@ -3565,9 +3736,12 @@ private void LoginWithFailover( } routingAttempts++; - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.LoginWithFailover | " + - $"Routed to {RoutingInfo.ServerName}", RoutingInfo.ServerName); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.LoginWithFailover | " + + $"Routed to {RoutingInfo.ServerName}", RoutingInfo.ServerName); + } _parser?.Disconnect(); _parser = new TdsParser(ConnectionOptions.MARS, connectionOptions.Asynchronous); @@ -3652,10 +3826,13 @@ private void LoginWithFailover( // iteration (max 1 second interval). if (attemptNumber % 2 == 1) { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.LoginWithFailover | ADV | " + - $"Object ID {ObjectID}, " + - $"sleeping {sleepInterval}ms"); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + $"SqlInternalConnectionTds.LoginWithFailover | ADV | " + + $"Object ID {ObjectID}, " + + $"sleeping {sleepInterval}ms"); + } Thread.Sleep(sleepInterval); @@ -3973,21 +4150,27 @@ private bool TryGetFedAuthTokenLocked( // proceed forward with the existing token in the cache. if (dbConnectionPoolAuthenticationContext.LockToUpdate()) { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.TryGetFedAuthTokenLocked | " + - $"Object ID {ObjectID}, " + - $"Acquired the lock to update the authentication context. " + - $"The expiration time is {dbConnectionPoolAuthenticationContext.ExpirationTime:T}. " + - $"Current Time is {DateTime.UtcNow:T}."); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.TryGetFedAuthTokenLocked | " + + $"Object ID {ObjectID}, " + + $"Acquired the lock to update the authentication context. " + + $"The expiration time is {dbConnectionPoolAuthenticationContext.ExpirationTime:T}. " + + $"Current Time is {DateTime.UtcNow:T}."); + } authenticationContextLocked = true; } else { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.TryGetFedAuthTokenLocked | " + - $"Object ID {ObjectID}, " + - $"Refreshing the context is already in progress by another thread."); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlInternalConnectionTds.TryGetFedAuthTokenLocked | " + + $"Object ID {ObjectID}, " + + $"Refreshing the context is already in progress by another thread."); + } } if (authenticationContextLocked) diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.cs index 76399749a0..dfb0106673 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.cs @@ -550,11 +550,14 @@ public override int CommandTimeout _commandTimeout = value; } - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.Set_CommandTimeout | API | " + - $"Object Id {ObjectID}, " + - $"Command Timeout value {value}, " + - $"Client Connection Id {Connection?.ClientConnectionId}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.Set_CommandTimeout | API | " + + $"Object Id {ObjectID}, " + + $"Command Timeout value {value}, " + + $"Client Connection Id {Connection?.ClientConnectionId}"); + } } } @@ -574,11 +577,14 @@ public override string CommandText _commandText = value; } - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.Set_CommandText | API | " + - $"Object Id {ObjectID}, " + - $"String Value = '{value}', " + - $"Client Connection Id {Connection?.ClientConnectionId}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.Set_CommandText | API | " + + $"Object Id {ObjectID}, " + + $"String Value = '{value}', " + + $"Client Connection Id {Connection?.ClientConnectionId}"); + } } } @@ -608,11 +614,14 @@ public override CommandType CommandType } // @TODO: Either move this outside the if block or move all the other instances inside the if block. - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.Set_CommandType | API | " + - $"Object Id {ObjectID}, " + - $"Command Type value {(int)value}, " + - $"Client Connection Id {Connection?.ClientConnectionId}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.Set_CommandType | API | " + + $"Object Id {ObjectID}, " + + $"Command Type value {(int)value}, " + + $"Client Connection Id {Connection?.ClientConnectionId}"); + } } } } @@ -671,10 +680,13 @@ public override CommandType CommandType _activeConnection = value; - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.Set_Connection | API | " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {value?.ClientConnectionId}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.Set_Connection | API | " + + $"Object Id {ObjectID}, " + + $"Client Connection Id {value?.ClientConnectionId}"); + } } } @@ -711,9 +723,12 @@ public SqlNotificationRequest Notification { _sqlDep = null; _notification = value; - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.Set_Notification | API | " + - $"Object Id {ObjectID}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.Set_Notification | API | " + + $"Object Id {ObjectID}"); + } } } @@ -788,11 +803,14 @@ public SqlRetryLogicBaseProvider RetryLogicProvider _transaction = value; - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.Set_Transaction | API | " + - $"Object Id {ObjectID}, " + - $"Internal Transaction Id {value?.InternalTransaction?.TransactionId}, " + - $"Client Connection Id {Connection?.ClientConnectionId}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.Set_Transaction | API | " + + $"Object Id {ObjectID}, " + + $"Internal Transaction Id {value?.InternalTransaction?.TransactionId}, " + + $"Client Connection Id {Connection?.ClientConnectionId}"); + } } } @@ -817,11 +835,14 @@ public override UpdateRowSource UpdatedRowSource throw ADP.InvalidUpdateRowSource(value); } - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.UpdatedRowSource | API | " + - $"Object Id {ObjectID}, " + - $"Updated Row Source value {(int)value}, " + - $"Client Connection Id {Connection?.ClientConnectionId}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.UpdatedRowSource | API | " + + $"Object Id {ObjectID}, " + + $"Updated Row Source value {(int)value}, " + + $"Client Connection Id {Connection?.ClientConnectionId}"); + } } } @@ -940,10 +961,13 @@ protected override DbTransaction DbTransaction { // @TODO: Does this need a trace event, we have one in Transaction? Transaction = (SqlTransaction)value; - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.Set_DbTransaction | API | " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {Connection?.ClientConnectionId}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.Set_DbTransaction | API | " + + $"Object Id {ObjectID}, " + + $"Client Connection Id {Connection?.ClientConnectionId}"); + } } } @@ -1064,12 +1088,15 @@ public override void Cancel() // via another thread. using var eventScope = SqlClientEventScope.Create($"SqlCommand.Cancel | API | Object Id {ObjectID}"); - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.Cancel | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.Cancel | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } SqlStatistics statistics = null; try @@ -1155,11 +1182,14 @@ public override void Cancel() public SqlCommand Clone() { SqlCommand clone = new SqlCommand(this); - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.Clone | API | " + - $"Object Id {ObjectID}, " + - $"Clone Object Id {clone.ObjectID}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.Clone | API | " + + $"Object Id {ObjectID}, " + + $"Clone Object Id {clone.ObjectID}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}"); + } return clone; } @@ -1176,11 +1206,14 @@ public override void Prepare() #endif using var eventScope = SqlClientEventScope.Create($"SqlCommand.Prepare | API | Object Id {ObjectID}"); - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.Prepare | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"ActivityID {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.Prepare | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"ActivityID {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}"); + } // Reset _pendingCancel upon entry into any Execute - used to synchronize state // between entry into Execute* API and the thread obtaining the stateObject. @@ -1821,11 +1854,14 @@ internal void OnStatementCompleted(int recordCount) { try { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlCommand.OnStatementCompleted | Info | " + - $"Object Id {ObjectID}, " + - $"Record Count {recordCount}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlCommand.OnStatementCompleted | Info | " + + $"Object Id {ObjectID}, " + + $"Record Count {recordCount}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}"); + } handler(this, new StatementCompletedEventArgs(recordCount)); } @@ -2901,10 +2937,13 @@ private void Unprepare() Debug.Assert(_activeConnection is not null, "must have an open connection to UnPrepare"); Debug.Assert(!_inPrepare, "_inPrepare should be false!"); - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.UnPrepare | Info | " + - $"Object Id {ObjectID}, " + - $"Current Prepared Handle {_prepareHandle}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.UnPrepare | Info | " + + $"Object Id {ObjectID}, " + + $"Current Prepared Handle {_prepareHandle}"); + } _execType = EXECTYPE.PREPAREPENDING; @@ -2919,9 +2958,12 @@ private void Unprepare() _cachedMetaData = null; - SqlClientEventSource.Log.TryTraceEvent( - $"SqlCommand.UnPrepare | Info | " + - $"Object Id {ObjectID}, Command unprepared."); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlCommand.UnPrepare | Info | " + + $"Object Id {ObjectID}, Command unprepared."); + } } private void ValidateAsyncCommand() @@ -3026,12 +3068,15 @@ private void VerifyEndExecuteState( { Debug.Assert(completionTask is not null); - SqlClientEventSource.Log.TryTraceEvent( - $"SqlCommand.VerifyEndExecuteState | API | " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"MARS={_activeConnection?.Parser?.MARSOn}, " + - $"AsyncCommandInProgress={_activeConnection?.AsyncCommandInProgress}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlCommand.VerifyEndExecuteState | API | " + + $"Object Id {ObjectID}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"MARS={_activeConnection?.Parser?.MARSOn}, " + + $"AsyncCommandInProgress={_activeConnection?.AsyncCommandInProgress}"); + } if (completionTask.IsCanceled) { @@ -3226,11 +3271,14 @@ internal void SetActiveConnectionAndResult(TaskCompletionSource completi TdsParser parser = activeConnection?.Parser; - SqlClientEventSource.Log.TryTraceEvent( - $"SqlCommand.SetActiveConnectionAndResult | API | " + - $"Object ID {activeConnection.ObjectID}, " + - $"Client Connection ID {activeConnection.ClientConnectionId}, " + - $"MARS={parser?.MARSOn}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + $"SqlCommand.SetActiveConnectionAndResult | API | " + + $"Object ID {activeConnection.ObjectID}, " + + $"Client Connection ID {activeConnection.ClientConnectionId}, " + + $"MARS={parser?.MARSOn}"); + } if (parser == null || parser.State == TdsParserState.Closed || parser.State == TdsParserState.Broken) { diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Utilities/AsyncHelper.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Utilities/AsyncHelper.cs index 9ce1bf336f..77fdb0a21f 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Utilities/AsyncHelper.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Utilities/AsyncHelper.cs @@ -836,7 +836,10 @@ private static void ObserveContinuationException(Task continuationTask) continuationTask.ContinueWith( static task => { - SqlClientEventSource.Log.TryTraceEvent($"Unobserved task exception: {task.Exception}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent($"Unobserved task exception: {task.Exception}"); + } _ = task.Exception; }, CancellationToken.None, From ef115f5f51bb3158b73ae9900096307cc8761b8e Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Mon, 10 Aug 2026 12:04:22 -0700 Subject: [PATCH 2/5] Fix trace message artifacts from the interpolated-string conversion Three call sites were mis-converted when they moved to interpolated strings: - OnFeatureExtAck logged "Object ID {0}", which in an interpolated string is the expression 0, so it always reported an object ID of 0 instead of the actual one. - Two sites kept a trailing format argument after interpolation. These bind to the generic overload, which runs string.Format over already-formatted text. The argument is redundant, and a value containing a brace (a routed server name, for instance) would raise a FormatException from inside tracing. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../Data/SqlClient/Connection/SqlConnectionInternal.cs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs index 87a5c503f4..0750fd0850 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs @@ -1372,7 +1372,7 @@ internal void OnFeatureExtAck(int featureId, byte[] data) { SqlClientEventSource.Log.TryAdvancedTraceEvent( $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {0}, " + + $"Object ID {ObjectID}, " + $"Received feature extension acknowledgement for federated authentication"); } @@ -1636,7 +1636,7 @@ internal void OnFeatureExtAck(int featureId, byte[] data) SqlClientEventSource.Log.TryTraceEvent( $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + $"Object ID {ObjectID}, " + - $"Unknown value for UTF8 support", ObjectID); + $"Unknown value for UTF8 support"); } throw SQL.ParsingError(); @@ -3740,7 +3740,7 @@ private void LoginWithFailover( { SqlClientEventSource.Log.TryTraceEvent( $"SqlInternalConnectionTds.LoginWithFailover | " + - $"Routed to {RoutingInfo.ServerName}", RoutingInfo.ServerName); + $"Routed to {RoutingInfo.ServerName}"); } _parser?.Disconnect(); From bb887dd280cb7827a4ba689d80df364ebe8b872e Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Mon, 10 Aug 2026 12:09:58 -0700 Subject: [PATCH 3/5] Guard remaining eager trace strings on the command execution path The earlier sweep only matched calls whose first argument began with an interpolated string, so it missed the "literal " + $"..." form. That form allocates the same way. The remaining 41 sites include the correlation traces in ExecuteReader, ExecuteNonQuery, ExecuteScalar and ExecuteXmlReader, which interpolate CommandText and ClientConnectionId on every execution. In 6.1.6 these passed a constant format string with arguments, so nothing was built unless the event was enabled. Measured on a repeated ExecuteReader loop: 3199.4 -> 1027.5 bytes/op. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../SqlAuthenticationProviderManager.cs | 107 ++++++---- .../Data/SqlClient/SqlCommand.NonQuery.cs | 163 +++++++++------ .../Data/SqlClient/SqlCommand.Reader.cs | 186 +++++++++++------- .../Data/SqlClient/SqlCommand.Scalar.cs | 43 ++-- .../Data/SqlClient/SqlCommand.Xml.cs | 90 +++++---- 5 files changed, 356 insertions(+), 233 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlAuthenticationProviderManager.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlAuthenticationProviderManager.cs index 4c77fbe8df..87bc5800b7 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlAuthenticationProviderManager.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlAuthenticationProviderManager.cs @@ -66,11 +66,14 @@ static SqlAuthenticationProviderManager() // When strong-name signing is enabled, build a fully-qualified AssemblyName // that includes the expected public key token. - SqlClientEventSource.Log.TryTraceEvent( - nameof(SqlAuthenticationProviderManager) + - $": Attempting to load Azure extension assembly={azureAssemblyName} with " + - "expected public key token=" + - BitConverter.ToString(s_azurePublicKeyToken).Replace("-", "")); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + nameof(SqlAuthenticationProviderManager) + + $": Attempting to load Azure extension assembly={azureAssemblyName} with " + + "expected public key token=" + + BitConverter.ToString(s_azurePublicKeyToken).Replace("-", "")); + } var qualifiedName = new AssemblyName(azureAssemblyName); qualifiedName.SetPublicKeyToken(s_azurePublicKeyToken); @@ -94,11 +97,14 @@ static SqlAuthenticationProviderManager() if (actualToken is null || !actualToken.AsSpan().SequenceEqual(s_azurePublicKeyToken)) { - SqlClientEventSource.Log.TryTraceEvent( - nameof(SqlAuthenticationProviderManager) + - $": Azure extension assembly={assembly.GetName()} has an " + - "unexpected public key token; " + - "no default Active Directory provider installed"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + nameof(SqlAuthenticationProviderManager) + + $": Azure extension assembly={assembly.GetName()} has an " + + "unexpected public key token; " + + "no default Active Directory provider installed"); + } return; } } @@ -106,10 +112,13 @@ static SqlAuthenticationProviderManager() #else - SqlClientEventSource.Log.TryTraceEvent( - nameof(SqlAuthenticationProviderManager) + - $": Attempting to load Azure extension assembly={azureAssemblyName} without " + - "strong name verification; ensure this assembly is from a trusted source"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + nameof(SqlAuthenticationProviderManager) + + $": Attempting to load Azure extension assembly={azureAssemblyName} without " + + "strong name verification; ensure this assembly is from a trusted source"); + } var assembly = Assembly.Load(azureAssemblyName); @@ -117,18 +126,24 @@ static SqlAuthenticationProviderManager() if (assembly is null) { - SqlClientEventSource.Log.TryTraceEvent( - nameof(SqlAuthenticationProviderManager) + - $": Azure extension assembly={azureAssemblyName} not found; " + - "no default Active Directory provider installed"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + nameof(SqlAuthenticationProviderManager) + + $": Azure extension assembly={azureAssemblyName} not found; " + + "no default Active Directory provider installed"); + } return; } - SqlClientEventSource.Log.TryTraceEvent( - nameof(SqlAuthenticationProviderManager) + - $": Azure extension assembly={assembly.GetName()} found; " + - "attempting to set as default provider for all Active " + - "Directory authentication methods"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + nameof(SqlAuthenticationProviderManager) + + $": Azure extension assembly={assembly.GetName()} found; " + + "attempting to set as default provider for all Active " + + "Directory authentication methods"); + } // Look for the authentication provider class. const string className = "Microsoft.Data.SqlClient.ActiveDirectoryAuthenticationProvider"; @@ -136,10 +151,13 @@ static SqlAuthenticationProviderManager() if (type is null) { - SqlClientEventSource.Log.TryTraceEvent( - nameof(SqlAuthenticationProviderManager) + - $": Azure extension does not contain class={className}; " + - "no default Active Directory provider installed"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + nameof(SqlAuthenticationProviderManager) + + $": Azure extension does not contain class={className}; " + + "no default Active Directory provider installed"); + } return; } @@ -169,10 +187,13 @@ static SqlAuthenticationProviderManager() if (instance is null) { - SqlClientEventSource.Log.TryTraceEvent( - nameof(SqlAuthenticationProviderManager) + - $": Failed to instantiate Azure extension class={className}; " + - "no default Active Directory provider installed"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + nameof(SqlAuthenticationProviderManager) + + $": Failed to instantiate Azure extension class={className}; " + + "no default Active Directory provider installed"); + } return; } @@ -195,10 +216,13 @@ static SqlAuthenticationProviderManager() SetProvider(SqlAuthenticationMethod.ActiveDirectoryDefault, instance); SetProvider(SqlAuthenticationMethod.ActiveDirectoryWorkloadIdentity, instance); - SqlClientEventSource.Log.TryTraceEvent( - nameof(SqlAuthenticationProviderManager) + - $": Azure extension class={className} installed as " + - "provider for all Active Directory authentication methods"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + nameof(SqlAuthenticationProviderManager) + + $": Azure extension class={className} installed as " + + "provider for all Active Directory authentication methods"); + } } // All of these exceptions mean we couldn't find or instantiate the // Azure extension's authentication provider, in which case we @@ -219,11 +243,14 @@ TargetInvocationException or TypeInitializationException or TypeLoadException) { - SqlClientEventSource.Log.TryTraceEvent( - nameof(SqlAuthenticationProviderManager) + - $": Azure extension assembly={azureAssemblyName} not found or " + - "not usable; no default provider installed; " + - $"{ex.GetType().Name}: {ex.Message}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + nameof(SqlAuthenticationProviderManager) + + $": Azure extension assembly={azureAssemblyName} not found or " + + "not usable; no default provider installed; " + + $"{ex.GetType().Name}: {ex.Message}"); + } } // Any other exceptions are fatal. } diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.NonQuery.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.NonQuery.cs index 311c26b4e5..854557d33c 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.NonQuery.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.NonQuery.cs @@ -44,12 +44,15 @@ public IAsyncResult BeginExecuteNonQuery(AsyncCallback callback, object stateObj SqlConnection.ExecutePermission.Demand(); #endif - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.BeginExecuteNonQuery | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.BeginExecuteNonQuery | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } return BeginExecuteNonQueryInternal( CommandBehavior.Default, @@ -68,12 +71,15 @@ public int EndExecuteNonQuery(IAsyncResult asyncResult) } finally { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.EndExecuteNonQuery | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.EndExecuteNonQuery | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } } } @@ -91,12 +97,15 @@ public override int ExecuteNonQuery() using var diagnosticScope = s_diagnosticListener.CreateCommandScope(this, _transaction); using var eventScope = SqlClientEventScope.Create($"SqlCommand.ExecuteNonQuery | API | Object Id {ObjectID}"); - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.ExecuteNonQuery | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.ExecuteNonQuery | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } SqlStatistics statistics = null; bool success = false; @@ -159,12 +168,15 @@ public override Task ExecuteNonQueryAsync(CancellationToken cancellationTok // @TODO: This can be inlined into InternalExecuteNonQueryAsync before restructuring into async pathway private IAsyncResult BeginExecuteNonQueryAsync(AsyncCallback callback, object stateObject) { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.BeginExecuteNonQueryAsync | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.BeginExecuteNonQueryAsync | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } return BeginExecuteNonQueryInternal( CommandBehavior.Default, @@ -343,12 +355,15 @@ private int EndExecuteNonQueryAsync(IAsyncResult asyncResult) { Debug.Assert(!_internalEndExecuteInitiated || _stateObj == null); - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.EndExecuteNonQueryAsync | Info | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.EndExecuteNonQueryAsync | Info | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } Exception asyncException = ((Task)asyncResult).Exception; if (asyncException is not null) @@ -421,12 +436,15 @@ private object InternalEndExecuteNonQuery( bool isInternal, // @TODO: is this ever true? [CallerMemberName] string endMethod = "") { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.InternalEndExecuteNonQuery | INFO | " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"MARS={_activeConnection?.Parser.MARSOn}, " + - $"AsyncCommandInProgress={_activeConnection?.AsyncCommandInProgress}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.InternalEndExecuteNonQuery | INFO | " + + $"Object Id {ObjectID}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"MARS={_activeConnection?.Parser.MARSOn}, " + + $"AsyncCommandInProgress={_activeConnection?.AsyncCommandInProgress}"); + } VerifyEndExecuteState((Task)asyncResult, endMethod); WaitForAsyncResults(asyncResult, isInternal); @@ -526,11 +544,14 @@ private Task InternalExecuteNonQuery( bool isRetry = false, [CallerMemberName] string methodName = "") { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.InternalExecuteNonQuery | INFO | " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"AsyncCommandInProgress={_activeConnection?.AsyncCommandInProgress}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.InternalExecuteNonQuery | INFO | " + + $"Object Id {ObjectID}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"AsyncCommandInProgress={_activeConnection?.AsyncCommandInProgress}"); + } bool isAsync = completion is not null; usedCache = false; @@ -575,24 +596,30 @@ private Task InternalExecuteNonQuery( // We should never get here for a retry since we only have retries for parameters. Debug.Assert(!isRetry); - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.InternalExecuteNonQuery | INFO | " + - $"Object Id {ObjectID}," + - $" RPC execute method name {methodName}, " + - $"isAsync {isAsync}, " + - $"isRetry {isRetry}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.InternalExecuteNonQuery | INFO | " + + $"Object Id {ObjectID}," + + $" RPC execute method name {methodName}, " + + $"isAsync {isAsync}, " + + $"isRetry {isRetry}"); + } task = RunExecuteNonQueryTds(methodName, isAsync, timeout, asyncWrite); } else { // Otherwise, use a full-fledged execute that can handle parameters and sprocs - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.InternalExecuteNonQuery | INFO | " + - $"Object Id {ObjectID}, " + - $"RPC execute method name {methodName}, " + - $"isAsync {isAsync}, " + - $"isRetry {isRetry}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.InternalExecuteNonQuery | INFO | " + + $"Object Id {ObjectID}, " + + $"RPC execute method name {methodName}, " + + $"isAsync {isAsync}, " + + $"isRetry {isRetry}"); + } SqlDataReader reader = RunExecuteReader( CommandBehavior.Default, @@ -632,12 +659,15 @@ private Task InternalExecuteNonQueryAsync(CancellationToken cancellationTok SqlConnection.ExecutePermission.Demand(); #endif - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.InternalExecuteNonQueryAsync | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.InternalExecuteNonQueryAsync | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } Guid operationId = s_diagnosticListener.WriteCommandBefore(this, _transaction); @@ -790,12 +820,15 @@ private Task RunExecuteNonQueryTds(string methodName, bool isAsync, int timeout, // We just send over the raw text with no annotation - no parameters are sent over, // no data reader is returned. - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.RunExecuteNonQueryTds | Info | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command executed as SQLBATCH, Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.RunExecuteNonQueryTds | Info | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command executed as SQLBATCH, Command Text '{CommandText}'"); + } Task executeTask = _stateObj.Parser.TdsExecuteSQLBatch( CommandText, diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Reader.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Reader.cs index 33af6073fb..627e37a99a 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Reader.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Reader.cs @@ -69,24 +69,30 @@ public SqlDataReader EndExecuteReader(IAsyncResult asyncResult) } finally { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.EndExecuteReader | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.EndExecuteReader | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } } } /// public new SqlDataReader ExecuteReader() { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.ExecuteReader | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.ExecuteReader | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } SqlStatistics statistics = null; try @@ -210,12 +216,15 @@ internal SqlDataReader RunExecuteReader( protected override DbDataReader ExecuteDbDataReader(CommandBehavior behavior) { // @TODO: Yknow, we use this all over the place. It could be factored out. - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.ExecuteDbDataReader | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.ExecuteDbDataReader | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } return ExecuteReader(behavior); } @@ -365,12 +374,15 @@ private void BeginExecuteReaderInternalReadStage(TaskCompletionSource co { Debug.Assert(completion is not null, "CompletionSource should not be null"); - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.BeginExecuteReaderInternalReadStage | INFO | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.BeginExecuteReaderInternalReadStage | INFO | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } // Read SNI does not have catches for async exceptions, handle here. try @@ -653,12 +665,15 @@ private SqlDataReader EndExecuteReaderAsync(IAsyncResult asyncResult) { Debug.Assert(!_internalEndExecuteInitiated || _stateObj is null); - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.EndExecuteReaderAsync | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.EndExecuteReaderAsync | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } Exception asyncException = ((Task)asyncResult).Exception; if (asyncException is not null) @@ -685,12 +700,15 @@ private SqlDataReader EndExecuteReaderAsync(IAsyncResult asyncResult) private SqlDataReader EndExecuteReaderInternal(IAsyncResult asyncResult) { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.EndExecuteReaderInternal | API | " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"MARS={_activeConnection?.Parser?.MARSOn}, " + - $"AsyncCommandInProgress={_activeConnection?.AsyncCommandInProgress}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.EndExecuteReaderInternal | API | " + + $"Object Id {ObjectID}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"MARS={_activeConnection?.Parser?.MARSOn}, " + + $"AsyncCommandInProgress={_activeConnection?.AsyncCommandInProgress}"); + } SqlStatistics statistics = null; bool success = false; @@ -933,18 +951,24 @@ private Task InternalExecuteReaderAsync( CommandBehavior commandBehavior, CancellationToken cancellationToken) { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.InternalExecuteReaderAsync | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Behavior {(int)commandBehavior}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.InternalExecuteReaderAsync | INFO | " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.InternalExecuteReaderAsync | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Behavior {(int)commandBehavior}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.InternalExecuteReaderAsync | INFO | " + + $"Object Id {ObjectID}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } Guid operationId = !_parentOperationStarted ? s_diagnosticListener.WriteCommandBefore(this, _transaction) : Guid.Empty; @@ -1037,12 +1061,15 @@ private Task InternalExecuteReaderWithRetryAsync( private SqlDataReader InternalEndExecuteReader(IAsyncResult asyncResult, bool isInternal, string endMethod) { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.InternalEndExecuteReader | INFO | " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"MARS={_activeConnection?.Parser?.MARSOn}, " + - $"AsyncCommandInProgress={_activeConnection?.AsyncCommandInProgress}"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.InternalEndExecuteReader | INFO | " + + $"Object Id {ObjectID}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"MARS={_activeConnection?.Parser?.MARSOn}, " + + $"AsyncCommandInProgress={_activeConnection?.AsyncCommandInProgress}"); + } VerifyEndExecuteState((Task)asyncResult, endMethod); WaitForAsyncResults(asyncResult, isInternal); @@ -1364,13 +1391,16 @@ private SqlDataReader RunExecuteReaderTds( if (returnStream) { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.RunExecuteReaderTds | Info | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command executed as SQLBATCH, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.RunExecuteReaderTds | Info | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command executed as SQLBATCH, " + + $"Command Text '{CommandText}'"); + } } string text = GetCommandText(cmdBehavior) + GetOptionsResetString(cmdBehavior); @@ -1451,13 +1481,16 @@ private SqlDataReader RunExecuteReaderTds( rpc.options = TdsEnums.RPC_NOMETADATA; if (returnStream) { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.RunExecuteReaderTds | Info | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command executed as RPC, " + - $"RPC Name '{rpc.rpcName}'"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.RunExecuteReaderTds | Info | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command executed as RPC, " + + $"RPC Name '{rpc.rpcName}'"); + } } Debug.Assert(_rpcArrayOf1[0] == rpc); @@ -1485,13 +1518,16 @@ private SqlDataReader RunExecuteReaderTds( if (returnStream) { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.RunExecuteReaderTds | Info | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command executed as RPC, " + - $"RPC Name '{CommandText}'"); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.RunExecuteReaderTds | Info | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command executed as RPC, " + + $"RPC Name '{CommandText}'"); + } } // Turn set options ON diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Scalar.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Scalar.cs index 0582d23d98..6872046826 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Scalar.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Scalar.cs @@ -32,12 +32,15 @@ public override object ExecuteScalar() using var diagnosticScope = s_diagnosticListener.CreateCommandScope(this, _transaction); using var eventScope = SqlClientEventScope.Create($"SqlCommand.ExecuteScalar | API | Object Id {ObjectID}"); - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.ExecuteScalar | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.ExecuteScalar | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } SqlStatistics statistics = null; bool success = false; @@ -221,17 +224,23 @@ private async Task ExecuteScalarUntilEndAsync( private Task ExecuteScalarAsyncInternal(CancellationToken cancellationToken) { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.InternalExecuteScalarAsync | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.ExecuteScalarAsyncInternal | API " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.InternalExecuteScalarAsync | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.ExecuteScalarAsyncInternal | API " + + $"Object Id {ObjectID}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } Guid operationId = s_diagnosticListener.WriteCommandBefore(this, _transaction); _parentOperationStarted = true; diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Xml.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Xml.cs index 39d043df12..6b4843ce7a 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Xml.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Xml.cs @@ -45,12 +45,15 @@ public IAsyncResult BeginExecuteXmlReader(AsyncCallback callback, object stateOb SqlConnection.ExecutePermission.Demand(); #endif - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.BeginExecuteXmlReader | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.BeginExecuteXmlReader | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } return BeginExecuteXmlReaderInternal( CommandBehavior.SequentialAccess, @@ -70,12 +73,15 @@ public XmlReader EndExecuteXmlReader(IAsyncResult asyncResult) } finally { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.EndExecuteXmlReader | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.EndExecuteXmlReader | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } } } @@ -93,12 +99,15 @@ public XmlReader ExecuteXmlReader() using var diagnosticScope = s_diagnosticListener.CreateCommandScope(this, _transaction); using var eventScope = SqlClientEventScope.Create($"SqlCommand.ExecuteXmlReader | API | Object Id {ObjectID}"); - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.ExecuteXmlReader | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.ExecuteXmlReader | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } SqlStatistics statistics = null; bool success = false; @@ -184,12 +193,15 @@ private static XmlReader CompleteXmlReader(SqlDataReader dataReader, bool isAsyn private IAsyncResult BeginExecuteXmlReaderAsync(AsyncCallback callback, object stateObject) { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.BeginExecuteXmlReaderAsync | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.BeginExecuteXmlReaderAsync | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } return BeginExecuteXmlReaderInternal( CommandBehavior.SequentialAccess, @@ -376,12 +388,15 @@ private XmlReader EndExecuteXmlReaderAsync(IAsyncResult asyncResult) { Debug.Assert(!_internalEndExecuteInitiated || _stateObj is null); - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.EndExecuteXmlReaderAsync | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.EndExecuteXmlReaderAsync | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } Exception asyncException = ((Task)asyncResult).Exception; if (asyncException is not null) @@ -451,12 +466,15 @@ private Task InternalExecuteXmlReaderAsync(CancellationToken cancella SqlConnection.ExecutePermission.Demand(); #endif - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.InternalExecuteXmlReaderAsync | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); + if (SqlClientEventSource.Log.IsCorrelationEnabled()) + { + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.InternalExecuteXmlReaderAsync | API | Correlation | " + + $"Object Id {ObjectID}, " + + $"Activity Id {ActivityCorrelator.Current}, " + + $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + + $"Command Text '{CommandText}'"); + } Guid operationId = s_diagnosticListener.WriteCommandBefore(this, _transaction); From 80a30a61b8d507c01a1de420f53ec5f93eabbb5a Mon Sep 17 00:00:00 2001 From: Michael Daigle <13396919+cheenamalhotra@users.noreply.github.com> Date: Mon, 10 Aug 2026 12:21:08 -0700 Subject: [PATCH 4/5] Use parameterized trace calls instead of eager interpolated strings The Try*Event overloads check whether the event is enabled before doing any formatting work. Passing an interpolated string defeats that, because the string is built at the call site before the call is made, so every traced operation allocated even with tracing switched off. Converts the 119 interpolated call sites introduced since 6.1.6 back to a composite format string plus arguments, which is what the overloads are designed for. Trace output is unchanged. Also corrects two artifacts of the original conversion: - OnFeatureExtAck logged "Object ID {0}", which inside an interpolated string is the expression 0, so it always reported 0. - Two calls kept a trailing argument that duplicated an interpolated expression; the argument is now the format argument. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../Connection/SqlConnectionInternal.cs | 778 ++++++++---------- .../SqlAuthenticationProviderManager.cs | 118 ++- .../Data/SqlClient/SqlCommand.NonQuery.cs | 206 ++--- .../Data/SqlClient/SqlCommand.Reader.cs | 234 +++--- .../Data/SqlClient/SqlCommand.Scalar.cs | 54 +- .../Data/SqlClient/SqlCommand.Xml.cs | 114 +-- .../Microsoft/Data/SqlClient/SqlCommand.cs | 241 +++--- .../Data/SqlClient/Utilities/AsyncHelper.cs | 5 +- 8 files changed, 828 insertions(+), 922 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs index 0750fd0850..a7c929f7ef 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs @@ -424,13 +424,11 @@ internal SqlConnectionInternal( _parserLock.Release(); } - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.ctor | ADV | " + - $"Object ID {ObjectID}, " + - $"constructed new TDS internal connection"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.ctor | ADV | " + + "Object ID {0}, " + + "constructed new TDS internal connection", + ObjectID); } #endregion @@ -845,13 +843,11 @@ internal SqlTransaction BeginSqlTransaction( internal void BreakConnection() { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.BreakConnection | RES | CPOOL " + - $"Object ID {ObjectID}, " + - $"Breaking connection."); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.BreakConnection | RES | CPOOL " + + "Object ID {0}, " + + "Breaking connection.", + ObjectID); DoomThisConnection(); // Mark connection as unusable, so it will be destroyed Connection?.Close(); @@ -925,12 +921,10 @@ internal void DisconnectTransaction(SqlInternalTransaction internalTransaction) // @TODO: Make internal by making the DbConnectionInternal implementation internal public override void Dispose() { - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.Dispose | ADV | " + - $"Object ID {ObjectID} disposing"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.Dispose | ADV | " + + "Object ID {0} disposing", + ObjectID); try { @@ -958,13 +952,11 @@ public override void Dispose() internal void EnlistNull() { - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnection.EnlistNull | ADV | " + - $"Object ID {ObjectID}, " + - $"unenlisting."); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnection.EnlistNull | ADV | " + + "Object ID {0}, " + + "unenlisting.", + ObjectID); // We were in a transaction, but now we are not - so send message to server with empty // transaction - confirmed proper behavior from Sameet Agarwal. @@ -981,13 +973,11 @@ internal void EnlistNull() IsEnlistedInTransaction = false; EnlistedTransaction = null; - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnection.EnlistNull | ADV | " + - $"Object ID {ObjectID}, " + - $"unenlisted."); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnection.EnlistNull | ADV | " + + "Object ID {0}, " + + "unenlisted.", + ObjectID); // The EnlistTransaction above will return an TransactionEnded event, which causes the // TdsParser to clear the current transaction. In either case, when we're working with @@ -1194,13 +1184,11 @@ internal void OnEnvChange(SqlEnvChange rec) break; case TdsEnums.ENV_ROUTING: - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnEnvChange | ADV | " + - $"Object ID {ObjectID}, " + - $"Received routing info"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.OnEnvChange | ADV | " + + "Object ID {0}, " + + "Received routing info", + ObjectID); if (string.IsNullOrEmpty(rec._newRoutingInfo.ServerName) || rec._newRoutingInfo.Protocol != 0 || @@ -1213,13 +1201,11 @@ internal void OnEnvChange(SqlEnvChange rec) break; case TdsEnums.ENV_ENHANCEDROUTING: - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnEnvChange | ADV | " + - $"Object ID {ObjectID}, " + - $"Received enhanced routing info"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.OnEnvChange | ADV | " + + "Object ID {0}, " + + "Received enhanced routing info", + ObjectID); if (string.IsNullOrEmpty(rec._newRoutingInfo.ServerName) || string.IsNullOrEmpty(rec._newRoutingInfo.DatabaseName) || @@ -1340,23 +1326,19 @@ internal void OnFeatureExtAck(int featureId, byte[] data) case TdsEnums.FEATUREEXT_GLOBALTRANSACTIONS: { - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for GlobalTransactions"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + "Object ID {0}, " + + "Received feature extension acknowledgement for GlobalTransactions", + ObjectID); if (data.Length < 1) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown version number for GlobalTransactions"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "Unknown version number for GlobalTransactions", + ObjectID); throw SQL.ParsingError(); } @@ -1368,23 +1350,19 @@ internal void OnFeatureExtAck(int featureId, byte[] data) case TdsEnums.FEATUREEXT_FEDAUTH: { - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for federated authentication"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + "Object ID {0}, " + + "Received feature extension acknowledgement for federated authentication", + ObjectID); if (!_federatedAuthenticationRequested) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Did not request federated authentication"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "Did not request federated authentication", + ObjectID); throw SQL.ParsingErrorFeatureId(ParsingErrorState.UnrequestedFeatureAckReceived, featureId); } @@ -1399,13 +1377,11 @@ internal void OnFeatureExtAck(int featureId, byte[] data) // The server shouldn't have sent any additional data with the ack (like a nonce) if (data.Length != 0) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Federated authentication feature extension ack for MSAL and Security Token includes extra data"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "Federated authentication feature extension ack for MSAL and Security Token includes extra data", + ObjectID); throw SQL.ParsingError(ParsingErrorState.FedAuthFeatureAckContainsExtraData); } @@ -1413,13 +1389,11 @@ internal void OnFeatureExtAck(int featureId, byte[] data) break; default: - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Attempting to use unknown federated authentication library"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "Attempting to use unknown federated authentication library", + ObjectID); Debug.Fail("Unknown _fedAuthLibrary type"); throw SQL.ParsingErrorLibraryType( @@ -1456,24 +1430,20 @@ internal void OnFeatureExtAck(int featureId, byte[] data) // with the new one or some other thread's context won the expiration race. if (newAuthenticationContextInCacheAfterAddOrUpdate == _newDbConnectionPoolAuthenticationContext) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Updated the new dbAuthenticationContext in the _dbConnectionPool.AuthenticationContexts."); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "Updated the new dbAuthenticationContext in the _dbConnectionPool.AuthenticationContexts.", + ObjectID); } else { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID }, " + - $"AddOrUpdate attempted on _dbConnectionPool.AuthenticationContexts, " + - $"but it did not update the new value."); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "AddOrUpdate attempted on _dbConnectionPool.AuthenticationContexts, " + + "but it did not update the new value.", + ObjectID); } #endif } @@ -1482,23 +1452,19 @@ internal void OnFeatureExtAck(int featureId, byte[] data) } case TdsEnums.FEATUREEXT_TCE: { - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for TCE"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + "Object ID {0}, " + + "Received feature extension acknowledgement for TCE", + ObjectID); if (data.Length < 1) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown version number for TCE"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "Unknown version number for TCE", + ObjectID); throw SQL.ParsingError(ParsingErrorState.TceUnknownVersion); } @@ -1506,13 +1472,11 @@ internal void OnFeatureExtAck(int featureId, byte[] data) byte supportedTceVersion = data[0]; if (supportedTceVersion == 0 || supportedTceVersion > TdsEnums.MAX_SUPPORTED_TCE_VERSION) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Invalid version number for TCE"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "Invalid version number for TCE", + ObjectID); throw SQL.ParsingErrorValue(ParsingErrorState.TceInvalidVersion, supportedTceVersion); } @@ -1528,13 +1492,11 @@ internal void OnFeatureExtAck(int featureId, byte[] data) } case TdsEnums.FEATUREEXT_AZURESQLSUPPORT: { - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for AzureSQLSupport"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + "Object ID {0}, " + + "Received feature extension acknowledgement for AzureSQLSupport", + ObjectID); if (data.Length < 1) { @@ -1547,36 +1509,30 @@ internal void OnFeatureExtAck(int featureId, byte[] data) if (Capabilities.ReadOnlyFailoverPartnerConnection && SqlClientEventSource.Log.IsTraceEnabled()) { - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"FailoverPartner enabled with Readonly intent for AzureSQL DB"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + "Object ID {0}, " + + "FailoverPartner enabled with Readonly intent for AzureSQL DB", + ObjectID); } break; } case TdsEnums.FEATUREEXT_DATACLASSIFICATION: { - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for DATACLASSIFICATION"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + "Object ID {0}, " + + "Received feature extension acknowledgement for DATACLASSIFICATION", + ObjectID); if (data.Length < 1) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown token for DATACLASSIFICATION"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "Unknown token for DATACLASSIFICATION", + ObjectID); throw SQL.ParsingError(ParsingErrorState.CorruptedTdsStream); } @@ -1585,13 +1541,11 @@ internal void OnFeatureExtAck(int featureId, byte[] data) if (supportedDataClassificationVersion == 0 || supportedDataClassificationVersion > TdsEnums.DATA_CLASSIFICATION_VERSION_MAX_SUPPORTED) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Invalid version number for DATACLASSIFICATION"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "Invalid version number for DATACLASSIFICATION", + ObjectID); throw SQL.ParsingErrorValue( ParsingErrorState.DataClassificationInvalidVersion, @@ -1600,13 +1554,11 @@ internal void OnFeatureExtAck(int featureId, byte[] data) if (data.Length != 2) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown token for DATACLASSIFICATION"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "Unknown token for DATACLASSIFICATION", + ObjectID); throw SQL.ParsingError(ParsingErrorState.CorruptedTdsStream); } @@ -1621,23 +1573,19 @@ internal void OnFeatureExtAck(int featureId, byte[] data) case TdsEnums.FEATUREEXT_UTF8SUPPORT: { - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for UTF8 support"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + "Object ID {0}, " + + "Received feature extension acknowledgement for UTF8 support", + ObjectID); if (data.Length < 1) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown value for UTF8 support"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "Unknown value for UTF8 support", + ObjectID); throw SQL.ParsingError(); } @@ -1648,23 +1596,19 @@ internal void OnFeatureExtAck(int featureId, byte[] data) } case TdsEnums.FEATUREEXT_SQLDNSCACHING: { - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for SQLDNSCACHING"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + "Object ID {0}, " + + "Received feature extension acknowledgement for SQLDNSCACHING", + ObjectID); if (data.Length < 1) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown token for SQLDNSCACHING"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "Unknown token for SQLDNSCACHING", + ObjectID); throw SQL.ParsingError(ParsingErrorState.CorruptedTdsStream); } @@ -1694,23 +1638,19 @@ internal void OnFeatureExtAck(int featureId, byte[] data) } case TdsEnums.FEATUREEXT_JSONSUPPORT: { - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for JSONSUPPORT"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + "Object ID {0}, " + + "Received feature extension acknowledgement for JSONSUPPORT", + ObjectID); if (data.Length != 1) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown token for JSONSUPPORT"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "Unknown token for JSONSUPPORT", + ObjectID); throw SQL.ParsingError(ParsingErrorState.CorruptedTdsStream); } @@ -1718,13 +1658,11 @@ internal void OnFeatureExtAck(int featureId, byte[] data) byte jsonSupportVersion = data[0]; if (jsonSupportVersion == 0 || jsonSupportVersion > TdsEnums.MAX_SUPPORTED_JSON_VERSION) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Invalid version number for JSONSUPPORT"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "Invalid version number for JSONSUPPORT", + ObjectID); throw SQL.ParsingError(); } @@ -1734,23 +1672,19 @@ internal void OnFeatureExtAck(int featureId, byte[] data) } case TdsEnums.FEATUREEXT_VECTORSUPPORT: { - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for VECTORSUPPORT"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + "Object ID {0}, " + + "Received feature extension acknowledgement for VECTORSUPPORT", + ObjectID); if (data.Length != 1) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown token for VECTORSUPPORT"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "Unknown token for VECTORSUPPORT", + ObjectID); throw SQL.ParsingError(ParsingErrorState.CorruptedTdsStream); } @@ -1758,14 +1692,14 @@ internal void OnFeatureExtAck(int featureId, byte[] data) byte vectorSupportVersion = data[0]; if (vectorSupportVersion == 0 || vectorSupportVersion > TdsEnums.MAX_SUPPORTED_VECTOR_VERSION) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Invalid version number {vectorSupportVersion} for VECTORSUPPORT, " + - $"Max supported version is {TdsEnums.MAX_SUPPORTED_VECTOR_VERSION}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "Invalid version number {1} for VECTORSUPPORT, " + + "Max supported version is {2}", + ObjectID, + vectorSupportVersion, + TdsEnums.MAX_SUPPORTED_VECTOR_VERSION); throw SQL.ParsingError(); } @@ -1778,13 +1712,11 @@ internal void OnFeatureExtAck(int featureId, byte[] data) { if (data.Length != 1) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + - $"Object ID {ObjectID}, " + - $"Unknown token for ENHANCEDROUTINGSUPPORT"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ERR | " + + "Object ID {0}, " + + "Unknown token for ENHANCEDROUTINGSUPPORT", + ObjectID); throw SQL.ParsingError(ParsingErrorState.CorruptedTdsStream); } @@ -1792,26 +1724,23 @@ internal void OnFeatureExtAck(int featureId, byte[] data) // A value of 1 indicates that the server supports the feature. Capabilities.EnhancedRouting = data[0] == 1; - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for " + - $"ENHANCEDROUTINGSUPPORT = {IsEnhancedRoutingSupportEnabled}"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + "Object ID {0}, " + + "Received feature extension acknowledgement for " + + "ENHANCEDROUTINGSUPPORT = {1}", + ObjectID, + IsEnhancedRoutingSupportEnabled); break; } case TdsEnums.FEATUREEXT_USERAGENT: { // Unexpected ack from server but we ignore it entirely - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + - $"Object ID {ObjectID}, " + - $"Received feature extension acknowledgement for USERAGENTSUPPORT (ignored)"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.OnFeatureExtAck | ADV | " + + "Object ID {0}, " + + "Received feature extension acknowledgement for USERAGENTSUPPORT (ignored)", + ObjectID); break; } @@ -1883,16 +1812,16 @@ internal void OnFedAuthInfo(SqlFedAuthInfo fedAuthInfo) // If the authentication context is expiring within next 10 minutes, lets // just re-create a token for this connection attempt. And on successful // login, try to update the cache with the new token. - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFedAuthInfo | " + - $"Object ID {ObjectID}, " + - $"The expiration time is less than 10 mins, trying to get new access " + - $"token regardless of if an other thread is also trying to update it. " + - $"The expiration time is {dbConnectionPoolAuthenticationContext.ExpirationTime:T}. " + - $"Current Time is {DateTime.UtcNow:T}."); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFedAuthInfo | " + + "Object ID {0}, " + + "The expiration time is less than 10 mins, trying to get new access " + + "token regardless of if an other thread is also trying to update it. " + + "The expiration time is {1:T}. " + + "Current Time is {2:T}.", + ObjectID, + dbConnectionPoolAuthenticationContext.ExpirationTime, + DateTime.UtcNow); attemptRefreshTokenUnLocked = true; } #if DEBUG @@ -1914,15 +1843,15 @@ internal void OnFedAuthInfo(SqlFedAuthInfo fedAuthInfo) // If the token is expiring within the next 45 mins, try to fetch a new // token, if there is no thread already doing it. If a thread is already // doing the refresh, just use the existing token in the cache and proceed. - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFedAuthInfo | ADV | " + - $"Object ID {ObjectID}, " + - $"The authentication context needs a refresh. " + - $"The expiration time is {dbConnectionPoolAuthenticationContext.ExpirationTime:T}. " + - $"Current Time is {DateTime.UtcNow:T}."); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.OnFedAuthInfo | ADV | " + + "Object ID {0}, " + + "The authentication context needs a refresh. " + + "The expiration time is {1:T}. " + + "Current Time is {2:T}.", + ObjectID, + dbConnectionPoolAuthenticationContext.ExpirationTime, + DateTime.UtcNow); // Call the function which tries to acquire a lock over the authentication // context before trying to update. If the lock could not be obtained, it @@ -1944,24 +1873,20 @@ internal void OnFedAuthInfo(SqlFedAuthInfo fedAuthInfo) // Indicate in EventSource Trace that we are successful with the update. if (attemptRefreshTokenLocked) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.OnFedAuthInfo | " + - $"Object ID {ObjectID}, " + - $"The attempt to get a new access token succeeded under the locked mode."); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFedAuthInfo | " + + "Object ID {0}, " + + "The attempt to get a new access token succeeded under the locked mode.", + ObjectID); } } - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.OnFedAuthInfo | " + - $"Object ID {ObjectID}, " + - $"Found an authentication context in the cache that does not need a refresh at this time. " + - $"Re-using the cached token."); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.OnFedAuthInfo | " + + "Object ID {0}, " + + "Found an authentication context in the cache that does not need a refresh at this time. " + + "Re-using the cached token.", + ObjectID); } } @@ -2139,13 +2064,12 @@ protected override void Deactivate() { try { - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnection.Deactivate | ADV | " + - $"Object ID {ObjectID} deactivating, " + - $"Client Connection Id {Connection?.ClientConnectionId}"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnection.Deactivate | ADV | " + + "Object ID {0} deactivating, " + + "Client Connection Id {1}", + ObjectID, + Connection?.ClientConnectionId); SqlReferenceCollection referenceCollection = (SqlReferenceCollection)ReferenceCollection; referenceCollection?.Deactivate(); @@ -2343,25 +2267,21 @@ private void CompleteLogin(bool enlistOK) // @TODO: Rename as per guidelines // ROR should not affect state of connection recovery if (_federatedAuthenticationRequested && !_federatedAuthenticationAcknowledged) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.CompleteLogin | ERR | " + - $"Object ID {ObjectID}, " + - $"Server did not acknowledge the federated authentication request"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.CompleteLogin | ERR | " + + "Object ID {0}, " + + "Server did not acknowledge the federated authentication request", + ObjectID); throw SQL.ParsingError(ParsingErrorState.FedAuthNotAcknowledged); } if (_federatedAuthenticationInfoRequested && !_federatedAuthenticationInfoReceived) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.CompleteLogin | ERR | " + - $"Object ID {ObjectID}, " + - $"Server never sent the requested federated authentication info"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.CompleteLogin | ERR | " + + "Object ID {0}, " + + "Server never sent the requested federated authentication info", + ObjectID); throw SQL.ParsingError(ParsingErrorState.FedAuthInfoNotReceived); } @@ -2477,14 +2397,13 @@ private void EnlistNonNull(Transaction transaction) { Debug.Assert(transaction != null, "null transaction?"); - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnection.EnlistNonNull | ADV | " + - $"Object ID {ObjectID}, " + - $"Transaction Id {transaction?.TransactionInformation?.LocalIdentifier}, " + - $"attempting to delegate."); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnection.EnlistNonNull | ADV | " + + "Object ID {0}, " + + "Transaction Id {1}, " + + "attempting to delegate.", + ObjectID, + transaction?.TransactionInformation?.LocalIdentifier); bool hasDelegatedTransaction = false; SqlDelegatedTransaction delegatedTransaction = new(this, transaction); @@ -2542,15 +2461,16 @@ private void EnlistNonNull(Transaction transaction) if (hasDelegatedTransaction) { DelegatedTransaction = delegatedTransaction; - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnection.EnlistNonNull | ADV | " + - $"Object ID {ObjectID}, " + - $"Client Connection Id {Connection?.ClientConnectionId} " + - $"delegated to transaction {delegatedTransaction?.ObjectID} " + - $"with transactionId {delegatedTransaction?.Transaction?.TransactionInformation?.LocalIdentifier}"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnection.EnlistNonNull | ADV | " + + "Object ID {0}, " + + "Client Connection Id {1} " + + "delegated to transaction {2} " + + "with transactionId {3}", + ObjectID, + Connection?.ClientConnectionId, + delegatedTransaction?.ObjectID, + delegatedTransaction?.Transaction?.TransactionInformation?.LocalIdentifier); } } catch (SqlException e) @@ -2579,13 +2499,11 @@ private void EnlistNonNull(Transaction transaction) if (!hasDelegatedTransaction) { - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnection.EnlistNonNull | ADV | " + - $"Object ID {ObjectID}, " + - $"delegation not possible, enlisting."); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnection.EnlistNonNull | ADV | " + + "Object ID {0}, " + + "delegation not possible, enlisting.", + ObjectID); byte[] cookie = null; @@ -2613,14 +2531,14 @@ private void EnlistNonNull(Transaction transaction) PropagateTransactionCookie(cookie); IsEnlistedInTransaction = true; - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnection.EnlistNonNull | ADV | " + - $"Object ID {ObjectID}, " + - $"Client Connection Id {Connection?.ClientConnectionId}, " + - $"Enlisted in transaction with transactionId {transaction?.TransactionInformation?.LocalIdentifier}"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnection.EnlistNonNull | ADV | " + + "Object ID {0}, " + + "Client Connection Id {1}, " + + "Enlisted in transaction with transactionId {2}", + ObjectID, + Connection?.ClientConnectionId, + transaction?.TransactionInformation?.LocalIdentifier); } // Tell the base class about our enlistment @@ -3206,12 +3124,10 @@ private void Login( private void LoginFailure() { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.LoginFailure | RES | CPOOL | " + - $"Object ID {ObjectID}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.LoginFailure | RES | CPOOL | " + + "Object ID {0}", + ObjectID); // If the parser was allocated, and we failed, then we must have failed on either the // Connect or Login, either way we should call Disconnect. Disconnect can be called if @@ -3249,13 +3165,12 @@ private void LoginNoFailover( // to set CurrentDatasource ServerInfo originalServerInfo = serverInfo; - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.LoginNoFailover | ADV | " + - $"Object ID {ObjectID}, " + - $"Host={serverInfo.UserServerName}"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.LoginNoFailover | ADV | " + + "Object ID {0}, " + + "Host={1}", + ObjectID, + serverInfo.UserServerName); // Milliseconds to sleep (back off) between attempts. int sleepInterval = 100; @@ -3391,22 +3306,17 @@ private void LoginNoFailover( // In this case, we should ignore the routing info and connect to the current server. if (!string.IsNullOrEmpty(RoutingInfo.DatabaseName) && !IsEnhancedRoutingSupportEnabled) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.LoginNoFailover | " + - $"Ignoring enhanced routing info because the server did not acknowledge the feature."); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.LoginNoFailover | " + + "Ignoring enhanced routing info because the server did not acknowledge the feature."); RoutingInfo = null; break; } - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.LoginNoFailover | " + - $"Routed to {serverInfo.ExtendedServerName}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.LoginNoFailover | " + + "Routed to {0}", + serverInfo.ExtendedServerName); if (routingAttempts > MaxNumberOfRedirectRoute) { @@ -3510,13 +3420,12 @@ private void LoginNoFailover( // Sleep for a bit to prevent clogging the network with requests, then update sleep // interval for next iteration (max 1 second interval) - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.LoginNoFailover | ADV " + - $"Object ID {ObjectID}, " + - $"Sleeping {sleepInterval}ms"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.LoginNoFailover | ADV " + + "Object ID {0}, " + + "Sleeping {1}ms", + ObjectID, + sleepInterval); Thread.Sleep(sleepInterval); @@ -3578,15 +3487,16 @@ private void LoginWithFailover( Debug.Assert(!connectionOptions.MultiSubnetFailover, "MultiSubnetFailover should not be set if failover partner is used"); - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.LoginWithFailover | ADV | " + - $"Object ID {ObjectID}, " + - $"useFailover={useFailoverHost}, " + - $"primary={primaryServerInfo.UserServerName}, " + - $"failover={failoverHost}"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.LoginWithFailover | ADV | " + + "Object ID {0}, " + + "useFailover={1}, " + + "primary={2}, " + + "failover={3}", + ObjectID, + useFailoverHost, + primaryServerInfo.UserServerName, + failoverHost); #if NETFRAMEWORK string protocol = ConnectionOptions.NetworkLibrary; @@ -3666,24 +3576,22 @@ private void LoginWithFailover( { if (LocalAppContextSwitches.IgnoreServerProvidedFailoverPartner) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.LoginWithFailover | ADV | " + - $"Object ID {ObjectID}, " + - $"Ignoring server provided failover partner '{ServerProvidedFailoverPartner}' " + - $"due to IgnoreServerProvidedFailoverPartner AppContext switch."); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.LoginWithFailover | ADV | " + + "Object ID {0}, " + + "Ignoring server provided failover partner '{1}' " + + "due to IgnoreServerProvidedFailoverPartner AppContext switch.", + ObjectID, + ServerProvidedFailoverPartner); } else { - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.LoginWithFailover | ADV | " + - $"Object ID {ObjectID}, " + - $"new failover partner={ServerProvidedFailoverPartner}"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.LoginWithFailover | ADV | " + + "Object ID {0}, " + + "new failover partner={1}", + ObjectID, + ServerProvidedFailoverPartner); #if NET failoverServerInfo.SetDerivedNames(string.Empty, ServerProvidedFailoverPartner); @@ -3720,12 +3628,9 @@ private void LoginWithFailover( // In this case, we should ignore the routing info and connect to the current server. if (!string.IsNullOrEmpty(RoutingInfo.DatabaseName) && !IsEnhancedRoutingSupportEnabled) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.LoginWithFailover | " + - $"Ignoring enhanced routing info because the server did not acknowledge the feature."); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.LoginWithFailover | " + + "Ignoring enhanced routing info because the server did not acknowledge the feature."); RoutingInfo = null; continue; } @@ -3736,12 +3641,10 @@ private void LoginWithFailover( } routingAttempts++; - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.LoginWithFailover | " + - $"Routed to {RoutingInfo.ServerName}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.LoginWithFailover | " + + "Routed to {0}", + RoutingInfo.ServerName); _parser?.Disconnect(); _parser = new TdsParser(ConnectionOptions.MARS, connectionOptions.Asynchronous); @@ -3826,13 +3729,12 @@ private void LoginWithFailover( // iteration (max 1 second interval). if (attemptNumber % 2 == 1) { - if (SqlClientEventSource.Log.IsAdvancedTraceOn()) - { - SqlClientEventSource.Log.TryAdvancedTraceEvent( - $"SqlInternalConnectionTds.LoginWithFailover | ADV | " + - $"Object ID {ObjectID}, " + - $"sleeping {sleepInterval}ms"); - } + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.LoginWithFailover | ADV | " + + "Object ID {0}, " + + "sleeping {1}ms", + ObjectID, + sleepInterval); Thread.Sleep(sleepInterval); @@ -4150,27 +4052,25 @@ private bool TryGetFedAuthTokenLocked( // proceed forward with the existing token in the cache. if (dbConnectionPoolAuthenticationContext.LockToUpdate()) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.TryGetFedAuthTokenLocked | " + - $"Object ID {ObjectID}, " + - $"Acquired the lock to update the authentication context. " + - $"The expiration time is {dbConnectionPoolAuthenticationContext.ExpirationTime:T}. " + - $"Current Time is {DateTime.UtcNow:T}."); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.TryGetFedAuthTokenLocked | " + + "Object ID {0}, " + + "Acquired the lock to update the authentication context. " + + "The expiration time is {1:T}. " + + "Current Time is {2:T}.", + ObjectID, + dbConnectionPoolAuthenticationContext.ExpirationTime, + DateTime.UtcNow); authenticationContextLocked = true; } else { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlInternalConnectionTds.TryGetFedAuthTokenLocked | " + - $"Object ID {ObjectID}, " + - $"Refreshing the context is already in progress by another thread."); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.TryGetFedAuthTokenLocked | " + + "Object ID {0}, " + + "Refreshing the context is already in progress by another thread.", + ObjectID); } if (authenticationContextLocked) diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlAuthenticationProviderManager.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlAuthenticationProviderManager.cs index 87bc5800b7..082a5599ce 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlAuthenticationProviderManager.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlAuthenticationProviderManager.cs @@ -66,14 +66,12 @@ static SqlAuthenticationProviderManager() // When strong-name signing is enabled, build a fully-qualified AssemblyName // that includes the expected public key token. - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - nameof(SqlAuthenticationProviderManager) + - $": Attempting to load Azure extension assembly={azureAssemblyName} with " + - "expected public key token=" + - BitConverter.ToString(s_azurePublicKeyToken).Replace("-", "")); - } + SqlClientEventSource.Log.TryTraceEvent( + nameof(SqlAuthenticationProviderManager) + + ": Attempting to load Azure extension assembly={0} with " + + "expected public key token={1}", + azureAssemblyName, + BitConverter.ToString(s_azurePublicKeyToken).Replace("-", "")); var qualifiedName = new AssemblyName(azureAssemblyName); qualifiedName.SetPublicKeyToken(s_azurePublicKeyToken); @@ -97,14 +95,12 @@ static SqlAuthenticationProviderManager() if (actualToken is null || !actualToken.AsSpan().SequenceEqual(s_azurePublicKeyToken)) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - nameof(SqlAuthenticationProviderManager) + - $": Azure extension assembly={assembly.GetName()} has an " + - "unexpected public key token; " + - "no default Active Directory provider installed"); - } + SqlClientEventSource.Log.TryTraceEvent( + nameof(SqlAuthenticationProviderManager) + + ": Azure extension assembly={0} has an " + + "unexpected public key token; " + + "no default Active Directory provider installed", + assembly.GetName()); return; } } @@ -112,52 +108,44 @@ static SqlAuthenticationProviderManager() #else - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - nameof(SqlAuthenticationProviderManager) + - $": Attempting to load Azure extension assembly={azureAssemblyName} without " + - "strong name verification; ensure this assembly is from a trusted source"); - } + SqlClientEventSource.Log.TryTraceEvent( + nameof(SqlAuthenticationProviderManager) + + ": Attempting to load Azure extension assembly={0} without " + + "strong name verification; ensure this assembly is from a trusted source", + azureAssemblyName); var assembly = Assembly.Load(azureAssemblyName); #endif if (assembly is null) - { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - nameof(SqlAuthenticationProviderManager) + - $": Azure extension assembly={azureAssemblyName} not found; " + - "no default Active Directory provider installed"); - } - return; - } - - if (SqlClientEventSource.Log.IsTraceEnabled()) { SqlClientEventSource.Log.TryTraceEvent( nameof(SqlAuthenticationProviderManager) + - $": Azure extension assembly={assembly.GetName()} found; " + - "attempting to set as default provider for all Active " + - "Directory authentication methods"); + ": Azure extension assembly={0} not found; " + + "no default Active Directory provider installed", + azureAssemblyName); + return; } + SqlClientEventSource.Log.TryTraceEvent( + nameof(SqlAuthenticationProviderManager) + + ": Azure extension assembly={0} found; " + + "attempting to set as default provider for all Active " + + "Directory authentication methods", + assembly.GetName()); + // Look for the authentication provider class. const string className = "Microsoft.Data.SqlClient.ActiveDirectoryAuthenticationProvider"; Type? type = assembly.GetType(className); if (type is null) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - nameof(SqlAuthenticationProviderManager) + - $": Azure extension does not contain class={className}; " + - "no default Active Directory provider installed"); - } + SqlClientEventSource.Log.TryTraceEvent( + nameof(SqlAuthenticationProviderManager) + + ": Azure extension does not contain class={0}; " + + "no default Active Directory provider installed", + className); return; } @@ -187,13 +175,11 @@ static SqlAuthenticationProviderManager() if (instance is null) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - nameof(SqlAuthenticationProviderManager) + - $": Failed to instantiate Azure extension class={className}; " + - "no default Active Directory provider installed"); - } + SqlClientEventSource.Log.TryTraceEvent( + nameof(SqlAuthenticationProviderManager) + + ": Failed to instantiate Azure extension class={0}; " + + "no default Active Directory provider installed", + className); return; } @@ -216,13 +202,11 @@ static SqlAuthenticationProviderManager() SetProvider(SqlAuthenticationMethod.ActiveDirectoryDefault, instance); SetProvider(SqlAuthenticationMethod.ActiveDirectoryWorkloadIdentity, instance); - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - nameof(SqlAuthenticationProviderManager) + - $": Azure extension class={className} installed as " + - "provider for all Active Directory authentication methods"); - } + SqlClientEventSource.Log.TryTraceEvent( + nameof(SqlAuthenticationProviderManager) + + ": Azure extension class={0} installed as " + + "provider for all Active Directory authentication methods", + className); } // All of these exceptions mean we couldn't find or instantiate the // Azure extension's authentication provider, in which case we @@ -243,14 +227,14 @@ TargetInvocationException or TypeInitializationException or TypeLoadException) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - nameof(SqlAuthenticationProviderManager) + - $": Azure extension assembly={azureAssemblyName} not found or " + - "not usable; no default provider installed; " + - $"{ex.GetType().Name}: {ex.Message}"); - } + SqlClientEventSource.Log.TryTraceEvent( + nameof(SqlAuthenticationProviderManager) + + ": Azure extension assembly={0} not found or " + + "not usable; no default provider installed; " + + "{1}: {2}", + azureAssemblyName, + ex.GetType().Name, + ex.Message); } // Any other exceptions are fatal. } diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.NonQuery.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.NonQuery.cs index 854557d33c..ef3e8afe25 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.NonQuery.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.NonQuery.cs @@ -44,15 +44,16 @@ public IAsyncResult BeginExecuteNonQuery(AsyncCallback callback, object stateObj SqlConnection.ExecutePermission.Demand(); #endif - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.BeginExecuteNonQuery | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.BeginExecuteNonQuery | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); return BeginExecuteNonQueryInternal( CommandBehavior.Default, @@ -71,15 +72,16 @@ public int EndExecuteNonQuery(IAsyncResult asyncResult) } finally { - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.EndExecuteNonQuery | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.EndExecuteNonQuery | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); } } @@ -97,15 +99,16 @@ public override int ExecuteNonQuery() using var diagnosticScope = s_diagnosticListener.CreateCommandScope(this, _transaction); using var eventScope = SqlClientEventScope.Create($"SqlCommand.ExecuteNonQuery | API | Object Id {ObjectID}"); - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.ExecuteNonQuery | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.ExecuteNonQuery | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); SqlStatistics statistics = null; bool success = false; @@ -168,15 +171,16 @@ public override Task ExecuteNonQueryAsync(CancellationToken cancellationTok // @TODO: This can be inlined into InternalExecuteNonQueryAsync before restructuring into async pathway private IAsyncResult BeginExecuteNonQueryAsync(AsyncCallback callback, object stateObject) { - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.BeginExecuteNonQueryAsync | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.BeginExecuteNonQueryAsync | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); return BeginExecuteNonQueryInternal( CommandBehavior.Default, @@ -355,15 +359,16 @@ private int EndExecuteNonQueryAsync(IAsyncResult asyncResult) { Debug.Assert(!_internalEndExecuteInitiated || _stateObj == null); - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.EndExecuteNonQueryAsync | Info | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.EndExecuteNonQueryAsync | Info | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); Exception asyncException = ((Task)asyncResult).Exception; if (asyncException is not null) @@ -436,15 +441,16 @@ private object InternalEndExecuteNonQuery( bool isInternal, // @TODO: is this ever true? [CallerMemberName] string endMethod = "") { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.InternalEndExecuteNonQuery | INFO | " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"MARS={_activeConnection?.Parser.MARSOn}, " + - $"AsyncCommandInProgress={_activeConnection?.AsyncCommandInProgress}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.InternalEndExecuteNonQuery | INFO | " + + "Object Id {0}, " + + "Client Connection Id {1}, " + + "MARS={2}, " + + "AsyncCommandInProgress={3}", + ObjectID, + _activeConnection?.ClientConnectionId, + _activeConnection?.Parser.MARSOn, + _activeConnection?.AsyncCommandInProgress); VerifyEndExecuteState((Task)asyncResult, endMethod); WaitForAsyncResults(asyncResult, isInternal); @@ -544,14 +550,14 @@ private Task InternalExecuteNonQuery( bool isRetry = false, [CallerMemberName] string methodName = "") { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.InternalExecuteNonQuery | INFO | " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"AsyncCommandInProgress={_activeConnection?.AsyncCommandInProgress}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.InternalExecuteNonQuery | INFO | " + + "Object Id {0}, " + + "Client Connection Id {1}, " + + "AsyncCommandInProgress={2}", + ObjectID, + _activeConnection?.ClientConnectionId, + _activeConnection?.AsyncCommandInProgress); bool isAsync = completion is not null; usedCache = false; @@ -596,30 +602,32 @@ private Task InternalExecuteNonQuery( // We should never get here for a retry since we only have retries for parameters. Debug.Assert(!isRetry); - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.InternalExecuteNonQuery | INFO | " + - $"Object Id {ObjectID}," + - $" RPC execute method name {methodName}, " + - $"isAsync {isAsync}, " + - $"isRetry {isRetry}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.InternalExecuteNonQuery | INFO | " + + "Object Id {0}," + + " RPC execute method name {1}, " + + "isAsync {2}, " + + "isRetry {3}", + ObjectID, + methodName, + isAsync, + isRetry); task = RunExecuteNonQueryTds(methodName, isAsync, timeout, asyncWrite); } else { // Otherwise, use a full-fledged execute that can handle parameters and sprocs - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.InternalExecuteNonQuery | INFO | " + - $"Object Id {ObjectID}, " + - $"RPC execute method name {methodName}, " + - $"isAsync {isAsync}, " + - $"isRetry {isRetry}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.InternalExecuteNonQuery | INFO | " + + "Object Id {0}, " + + "RPC execute method name {1}, " + + "isAsync {2}, " + + "isRetry {3}", + ObjectID, + methodName, + isAsync, + isRetry); SqlDataReader reader = RunExecuteReader( CommandBehavior.Default, @@ -659,15 +667,16 @@ private Task InternalExecuteNonQueryAsync(CancellationToken cancellationTok SqlConnection.ExecutePermission.Demand(); #endif - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.InternalExecuteNonQueryAsync | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.InternalExecuteNonQueryAsync | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); Guid operationId = s_diagnosticListener.WriteCommandBefore(this, _transaction); @@ -820,15 +829,16 @@ private Task RunExecuteNonQueryTds(string methodName, bool isAsync, int timeout, // We just send over the raw text with no annotation - no parameters are sent over, // no data reader is returned. - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.RunExecuteNonQueryTds | Info | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command executed as SQLBATCH, Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.RunExecuteNonQueryTds | Info | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command executed as SQLBATCH, Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); Task executeTask = _stateObj.Parser.TdsExecuteSQLBatch( CommandText, diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Reader.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Reader.cs index 627e37a99a..ec4d7709da 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Reader.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Reader.cs @@ -69,30 +69,32 @@ public SqlDataReader EndExecuteReader(IAsyncResult asyncResult) } finally { - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.EndExecuteReader | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.EndExecuteReader | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); } } /// public new SqlDataReader ExecuteReader() { - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.ExecuteReader | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.ExecuteReader | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); SqlStatistics statistics = null; try @@ -216,15 +218,16 @@ internal SqlDataReader RunExecuteReader( protected override DbDataReader ExecuteDbDataReader(CommandBehavior behavior) { // @TODO: Yknow, we use this all over the place. It could be factored out. - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.ExecuteDbDataReader | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.ExecuteDbDataReader | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); return ExecuteReader(behavior); } @@ -374,15 +377,16 @@ private void BeginExecuteReaderInternalReadStage(TaskCompletionSource co { Debug.Assert(completion is not null, "CompletionSource should not be null"); - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.BeginExecuteReaderInternalReadStage | INFO | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.BeginExecuteReaderInternalReadStage | INFO | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); // Read SNI does not have catches for async exceptions, handle here. try @@ -665,15 +669,16 @@ private SqlDataReader EndExecuteReaderAsync(IAsyncResult asyncResult) { Debug.Assert(!_internalEndExecuteInitiated || _stateObj is null); - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.EndExecuteReaderAsync | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.EndExecuteReaderAsync | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); Exception asyncException = ((Task)asyncResult).Exception; if (asyncException is not null) @@ -700,15 +705,16 @@ private SqlDataReader EndExecuteReaderAsync(IAsyncResult asyncResult) private SqlDataReader EndExecuteReaderInternal(IAsyncResult asyncResult) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.EndExecuteReaderInternal | API | " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"MARS={_activeConnection?.Parser?.MARSOn}, " + - $"AsyncCommandInProgress={_activeConnection?.AsyncCommandInProgress}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.EndExecuteReaderInternal | API | " + + "Object Id {0}, " + + "Client Connection Id {1}, " + + "MARS={2}, " + + "AsyncCommandInProgress={3}", + ObjectID, + _activeConnection?.ClientConnectionId, + _activeConnection?.Parser?.MARSOn, + _activeConnection?.AsyncCommandInProgress); SqlStatistics statistics = null; bool success = false; @@ -951,24 +957,26 @@ private Task InternalExecuteReaderAsync( CommandBehavior commandBehavior, CancellationToken cancellationToken) { - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.InternalExecuteReaderAsync | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Behavior {(int)commandBehavior}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.InternalExecuteReaderAsync | INFO | " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.InternalExecuteReaderAsync | API | Correlation | " + + "Object Id {0}, " + + "Behavior {1}, " + + "Activity Id {2}, " + + "Client Connection Id {3}, " + + "Command Text '{4}'", + ObjectID, + (int)commandBehavior, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.InternalExecuteReaderAsync | INFO | " + + "Object Id {0}, " + + "Client Connection Id {1}, " + + "Command Text '{2}'", + ObjectID, + _activeConnection?.ClientConnectionId, + CommandText); Guid operationId = !_parentOperationStarted ? s_diagnosticListener.WriteCommandBefore(this, _transaction) : Guid.Empty; @@ -1061,15 +1069,16 @@ private Task InternalExecuteReaderWithRetryAsync( private SqlDataReader InternalEndExecuteReader(IAsyncResult asyncResult, bool isInternal, string endMethod) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.InternalEndExecuteReader | INFO | " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"MARS={_activeConnection?.Parser?.MARSOn}, " + - $"AsyncCommandInProgress={_activeConnection?.AsyncCommandInProgress}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.InternalEndExecuteReader | INFO | " + + "Object Id {0}, " + + "Client Connection Id {1}, " + + "MARS={2}, " + + "AsyncCommandInProgress={3}", + ObjectID, + _activeConnection?.ClientConnectionId, + _activeConnection?.Parser?.MARSOn, + _activeConnection?.AsyncCommandInProgress); VerifyEndExecuteState((Task)asyncResult, endMethod); WaitForAsyncResults(asyncResult, isInternal); @@ -1391,16 +1400,17 @@ private SqlDataReader RunExecuteReaderTds( if (returnStream) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.RunExecuteReaderTds | Info | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command executed as SQLBATCH, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.RunExecuteReaderTds | Info | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command executed as SQLBATCH, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); } string text = GetCommandText(cmdBehavior) + GetOptionsResetString(cmdBehavior); @@ -1481,16 +1491,17 @@ private SqlDataReader RunExecuteReaderTds( rpc.options = TdsEnums.RPC_NOMETADATA; if (returnStream) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.RunExecuteReaderTds | Info | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command executed as RPC, " + - $"RPC Name '{rpc.rpcName}'"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.RunExecuteReaderTds | Info | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command executed as RPC, " + + "RPC Name '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + rpc.rpcName); } Debug.Assert(_rpcArrayOf1[0] == rpc); @@ -1518,16 +1529,17 @@ private SqlDataReader RunExecuteReaderTds( if (returnStream) { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.RunExecuteReaderTds | Info | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command executed as RPC, " + - $"RPC Name '{CommandText}'"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.RunExecuteReaderTds | Info | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command executed as RPC, " + + "RPC Name '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); } // Turn set options ON diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Scalar.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Scalar.cs index 6872046826..fa53eb14ee 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Scalar.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Scalar.cs @@ -32,15 +32,16 @@ public override object ExecuteScalar() using var diagnosticScope = s_diagnosticListener.CreateCommandScope(this, _transaction); using var eventScope = SqlClientEventScope.Create($"SqlCommand.ExecuteScalar | API | Object Id {ObjectID}"); - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.ExecuteScalar | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.ExecuteScalar | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); SqlStatistics statistics = null; bool success = false; @@ -224,23 +225,24 @@ private async Task ExecuteScalarUntilEndAsync( private Task ExecuteScalarAsyncInternal(CancellationToken cancellationToken) { - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.InternalExecuteScalarAsync | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.ExecuteScalarAsyncInternal | API " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.InternalExecuteScalarAsync | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.ExecuteScalarAsyncInternal | API " + + "Object Id {0}, " + + "Client Connection Id {1}, " + + "Command Text '{2}'", + ObjectID, + _activeConnection?.ClientConnectionId, + CommandText); Guid operationId = s_diagnosticListener.WriteCommandBefore(this, _transaction); _parentOperationStarted = true; diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Xml.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Xml.cs index 6b4843ce7a..d74bda54d6 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Xml.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Xml.cs @@ -45,15 +45,16 @@ public IAsyncResult BeginExecuteXmlReader(AsyncCallback callback, object stateOb SqlConnection.ExecutePermission.Demand(); #endif - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.BeginExecuteXmlReader | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.BeginExecuteXmlReader | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); return BeginExecuteXmlReaderInternal( CommandBehavior.SequentialAccess, @@ -73,15 +74,16 @@ public XmlReader EndExecuteXmlReader(IAsyncResult asyncResult) } finally { - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.EndExecuteXmlReader | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.EndExecuteXmlReader | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection.ClientConnectionId, + CommandText); } } @@ -99,15 +101,16 @@ public XmlReader ExecuteXmlReader() using var diagnosticScope = s_diagnosticListener.CreateCommandScope(this, _transaction); using var eventScope = SqlClientEventScope.Create($"SqlCommand.ExecuteXmlReader | API | Object Id {ObjectID}"); - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.ExecuteXmlReader | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.ExecuteXmlReader | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); SqlStatistics statistics = null; bool success = false; @@ -193,15 +196,16 @@ private static XmlReader CompleteXmlReader(SqlDataReader dataReader, bool isAsyn private IAsyncResult BeginExecuteXmlReaderAsync(AsyncCallback callback, object stateObject) { - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.BeginExecuteXmlReaderAsync | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.BeginExecuteXmlReaderAsync | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); return BeginExecuteXmlReaderInternal( CommandBehavior.SequentialAccess, @@ -388,15 +392,16 @@ private XmlReader EndExecuteXmlReaderAsync(IAsyncResult asyncResult) { Debug.Assert(!_internalEndExecuteInitiated || _stateObj is null); - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.EndExecuteXmlReaderAsync | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.EndExecuteXmlReaderAsync | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); Exception asyncException = ((Task)asyncResult).Exception; if (asyncException is not null) @@ -466,15 +471,16 @@ private Task InternalExecuteXmlReaderAsync(CancellationToken cancella SqlConnection.ExecutePermission.Demand(); #endif - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.InternalExecuteXmlReaderAsync | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.InternalExecuteXmlReaderAsync | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); Guid operationId = s_diagnosticListener.WriteCommandBefore(this, _transaction); diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.cs index dfb0106673..294310a08f 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.cs @@ -550,14 +550,14 @@ public override int CommandTimeout _commandTimeout = value; } - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.Set_CommandTimeout | API | " + - $"Object Id {ObjectID}, " + - $"Command Timeout value {value}, " + - $"Client Connection Id {Connection?.ClientConnectionId}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.Set_CommandTimeout | API | " + + "Object Id {0}, " + + "Command Timeout value {1}, " + + "Client Connection Id {2}", + ObjectID, + value, + Connection?.ClientConnectionId); } } @@ -577,14 +577,14 @@ public override string CommandText _commandText = value; } - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.Set_CommandText | API | " + - $"Object Id {ObjectID}, " + - $"String Value = '{value}', " + - $"Client Connection Id {Connection?.ClientConnectionId}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.Set_CommandText | API | " + + "Object Id {0}, " + + "String Value = '{1}', " + + "Client Connection Id {2}", + ObjectID, + value, + Connection?.ClientConnectionId); } } @@ -614,14 +614,14 @@ public override CommandType CommandType } // @TODO: Either move this outside the if block or move all the other instances inside the if block. - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.Set_CommandType | API | " + - $"Object Id {ObjectID}, " + - $"Command Type value {(int)value}, " + - $"Client Connection Id {Connection?.ClientConnectionId}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.Set_CommandType | API | " + + "Object Id {0}, " + + "Command Type value {1}, " + + "Client Connection Id {2}", + ObjectID, + (int)value, + Connection?.ClientConnectionId); } } } @@ -680,13 +680,12 @@ public override CommandType CommandType _activeConnection = value; - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.Set_Connection | API | " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {value?.ClientConnectionId}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.Set_Connection | API | " + + "Object Id {0}, " + + "Client Connection Id {1}", + ObjectID, + value?.ClientConnectionId); } } @@ -723,12 +722,10 @@ public SqlNotificationRequest Notification { _sqlDep = null; _notification = value; - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.Set_Notification | API | " + - $"Object Id {ObjectID}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.Set_Notification | API | " + + "Object Id {0}", + ObjectID); } } @@ -803,14 +800,14 @@ public SqlRetryLogicBaseProvider RetryLogicProvider _transaction = value; - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.Set_Transaction | API | " + - $"Object Id {ObjectID}, " + - $"Internal Transaction Id {value?.InternalTransaction?.TransactionId}, " + - $"Client Connection Id {Connection?.ClientConnectionId}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.Set_Transaction | API | " + + "Object Id {0}, " + + "Internal Transaction Id {1}, " + + "Client Connection Id {2}", + ObjectID, + value?.InternalTransaction?.TransactionId, + Connection?.ClientConnectionId); } } @@ -835,14 +832,14 @@ public override UpdateRowSource UpdatedRowSource throw ADP.InvalidUpdateRowSource(value); } - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.UpdatedRowSource | API | " + - $"Object Id {ObjectID}, " + - $"Updated Row Source value {(int)value}, " + - $"Client Connection Id {Connection?.ClientConnectionId}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.UpdatedRowSource | API | " + + "Object Id {0}, " + + "Updated Row Source value {1}, " + + "Client Connection Id {2}", + ObjectID, + (int)value, + Connection?.ClientConnectionId); } } @@ -961,13 +958,12 @@ protected override DbTransaction DbTransaction { // @TODO: Does this need a trace event, we have one in Transaction? Transaction = (SqlTransaction)value; - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.Set_DbTransaction | API | " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {Connection?.ClientConnectionId}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.Set_DbTransaction | API | " + + "Object Id {0}, " + + "Client Connection Id {1}", + ObjectID, + Connection?.ClientConnectionId); } } @@ -1088,15 +1084,16 @@ public override void Cancel() // via another thread. using var eventScope = SqlClientEventScope.Create($"SqlCommand.Cancel | API | Object Id {ObjectID}"); - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.Cancel | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"Activity Id {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"Command Text '{CommandText}'"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.Cancel | API | Correlation | " + + "Object Id {0}, " + + "Activity Id {1}, " + + "Client Connection Id {2}, " + + "Command Text '{3}'", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId, + CommandText); SqlStatistics statistics = null; try @@ -1182,14 +1179,14 @@ public override void Cancel() public SqlCommand Clone() { SqlCommand clone = new SqlCommand(this); - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.Clone | API | " + - $"Object Id {ObjectID}, " + - $"Clone Object Id {clone.ObjectID}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.Clone | API | " + + "Object Id {0}, " + + "Clone Object Id {1}, " + + "Client Connection Id {2}", + ObjectID, + clone.ObjectID, + _activeConnection?.ClientConnectionId); return clone; } @@ -1206,14 +1203,14 @@ public override void Prepare() #endif using var eventScope = SqlClientEventScope.Create($"SqlCommand.Prepare | API | Object Id {ObjectID}"); - if (SqlClientEventSource.Log.IsCorrelationEnabled()) - { - SqlClientEventSource.Log.TryCorrelationTraceEvent( - "SqlCommand.Prepare | API | Correlation | " + - $"Object Id {ObjectID}, " + - $"ActivityID {ActivityCorrelator.Current}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}"); - } + SqlClientEventSource.Log.TryCorrelationTraceEvent( + "SqlCommand.Prepare | API | Correlation | " + + "Object Id {0}, " + + "ActivityID {1}, " + + "Client Connection Id {2}", + ObjectID, + ActivityCorrelator.Current, + _activeConnection?.ClientConnectionId); // Reset _pendingCancel upon entry into any Execute - used to synchronize state // between entry into Execute* API and the thread obtaining the stateObject. @@ -1854,14 +1851,14 @@ internal void OnStatementCompleted(int recordCount) { try { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlCommand.OnStatementCompleted | Info | " + - $"Object Id {ObjectID}, " + - $"Record Count {recordCount}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.OnStatementCompleted | Info | " + + "Object Id {0}, " + + "Record Count {1}, " + + "Client Connection Id {2}", + ObjectID, + recordCount, + _activeConnection?.ClientConnectionId); handler(this, new StatementCompletedEventArgs(recordCount)); } @@ -2937,13 +2934,12 @@ private void Unprepare() Debug.Assert(_activeConnection is not null, "must have an open connection to UnPrepare"); Debug.Assert(!_inPrepare, "_inPrepare should be false!"); - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - "SqlCommand.UnPrepare | Info | " + - $"Object Id {ObjectID}, " + - $"Current Prepared Handle {_prepareHandle}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.UnPrepare | Info | " + + "Object Id {0}, " + + "Current Prepared Handle {1}", + ObjectID, + _prepareHandle); _execType = EXECTYPE.PREPAREPENDING; @@ -2958,12 +2954,10 @@ private void Unprepare() _cachedMetaData = null; - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlCommand.UnPrepare | Info | " + - $"Object Id {ObjectID}, Command unprepared."); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.UnPrepare | Info | " + + "Object Id {0}, Command unprepared.", + ObjectID); } private void ValidateAsyncCommand() @@ -3068,15 +3062,16 @@ private void VerifyEndExecuteState( { Debug.Assert(completionTask is not null); - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlCommand.VerifyEndExecuteState | API | " + - $"Object Id {ObjectID}, " + - $"Client Connection Id {_activeConnection?.ClientConnectionId}, " + - $"MARS={_activeConnection?.Parser?.MARSOn}, " + - $"AsyncCommandInProgress={_activeConnection?.AsyncCommandInProgress}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.VerifyEndExecuteState | API | " + + "Object Id {0}, " + + "Client Connection Id {1}, " + + "MARS={2}, " + + "AsyncCommandInProgress={3}", + ObjectID, + _activeConnection?.ClientConnectionId, + _activeConnection?.Parser?.MARSOn, + _activeConnection?.AsyncCommandInProgress); if (completionTask.IsCanceled) { @@ -3271,14 +3266,14 @@ internal void SetActiveConnectionAndResult(TaskCompletionSource completi TdsParser parser = activeConnection?.Parser; - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent( - $"SqlCommand.SetActiveConnectionAndResult | API | " + - $"Object ID {activeConnection.ObjectID}, " + - $"Client Connection ID {activeConnection.ClientConnectionId}, " + - $"MARS={parser?.MARSOn}"); - } + SqlClientEventSource.Log.TryTraceEvent( + "SqlCommand.SetActiveConnectionAndResult | API | " + + "Object ID {0}, " + + "Client Connection ID {1}, " + + "MARS={2}", + activeConnection.ObjectID, + activeConnection.ClientConnectionId, + parser?.MARSOn); if (parser == null || parser.State == TdsParserState.Closed || parser.State == TdsParserState.Broken) { diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Utilities/AsyncHelper.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Utilities/AsyncHelper.cs index 77fdb0a21f..05a296bec0 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Utilities/AsyncHelper.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Utilities/AsyncHelper.cs @@ -836,10 +836,7 @@ private static void ObserveContinuationException(Task continuationTask) continuationTask.ContinueWith( static task => { - if (SqlClientEventSource.Log.IsTraceEnabled()) - { - SqlClientEventSource.Log.TryTraceEvent($"Unobserved task exception: {task.Exception}"); - } + SqlClientEventSource.Log.TryTraceEvent("Unobserved task exception: {0}", task.Exception); _ = task.Exception; }, CancellationToken.None, From bbac7ab620c0ed5bb9d0644413f0c3c1853d4e7e Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Mon, 10 Aug 2026 15:39:48 -0700 Subject: [PATCH 5/5] Preserve time-only formatting in fed auth trace messages The generic Try*Event overloads call ToString() on each argument before string.Format, so a {1:T} specifier in the composite format string is never applied. Three fed auth trace sites relied on :T and would have logged full date and time instead of time only. Guard these three sites on the matching enablement check and pass pre-formatted time strings, which keeps the output identical to the interpolated version and still allocates nothing when tracing is off. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../Connection/SqlConnectionInternal.cs | 65 +++++++++++-------- 1 file changed, 37 insertions(+), 28 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs index a7c929f7ef..408564f855 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs @@ -1812,16 +1812,19 @@ internal void OnFedAuthInfo(SqlFedAuthInfo fedAuthInfo) // If the authentication context is expiring within next 10 minutes, lets // just re-create a token for this connection attempt. And on successful // login, try to update the cache with the new token. - SqlClientEventSource.Log.TryTraceEvent( - "SqlInternalConnectionTds.OnFedAuthInfo | " + - "Object ID {0}, " + - "The expiration time is less than 10 mins, trying to get new access " + - "token regardless of if an other thread is also trying to update it. " + - "The expiration time is {1:T}. " + - "Current Time is {2:T}.", - ObjectID, - dbConnectionPoolAuthenticationContext.ExpirationTime, - DateTime.UtcNow); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.OnFedAuthInfo | " + + "Object ID {0}, " + + "The expiration time is less than 10 mins, trying to get new access " + + "token regardless of if an other thread is also trying to update it. " + + "The expiration time is {1}. " + + "Current Time is {2}.", + ObjectID, + dbConnectionPoolAuthenticationContext.ExpirationTime.ToString("T"), + DateTime.UtcNow.ToString("T")); + } attemptRefreshTokenUnLocked = true; } #if DEBUG @@ -1843,15 +1846,18 @@ internal void OnFedAuthInfo(SqlFedAuthInfo fedAuthInfo) // If the token is expiring within the next 45 mins, try to fetch a new // token, if there is no thread already doing it. If a thread is already // doing the refresh, just use the existing token in the cache and proceed. - SqlClientEventSource.Log.TryAdvancedTraceEvent( - "SqlInternalConnectionTds.OnFedAuthInfo | ADV | " + - "Object ID {0}, " + - "The authentication context needs a refresh. " + - "The expiration time is {1:T}. " + - "Current Time is {2:T}.", - ObjectID, - dbConnectionPoolAuthenticationContext.ExpirationTime, - DateTime.UtcNow); + if (SqlClientEventSource.Log.IsAdvancedTraceOn()) + { + SqlClientEventSource.Log.TryAdvancedTraceEvent( + "SqlInternalConnectionTds.OnFedAuthInfo | ADV | " + + "Object ID {0}, " + + "The authentication context needs a refresh. " + + "The expiration time is {1}. " + + "Current Time is {2}.", + ObjectID, + dbConnectionPoolAuthenticationContext.ExpirationTime.ToString("T"), + DateTime.UtcNow.ToString("T")); + } // Call the function which tries to acquire a lock over the authentication // context before trying to update. If the lock could not be obtained, it @@ -4052,15 +4058,18 @@ private bool TryGetFedAuthTokenLocked( // proceed forward with the existing token in the cache. if (dbConnectionPoolAuthenticationContext.LockToUpdate()) { - SqlClientEventSource.Log.TryTraceEvent( - "SqlInternalConnectionTds.TryGetFedAuthTokenLocked | " + - "Object ID {0}, " + - "Acquired the lock to update the authentication context. " + - "The expiration time is {1:T}. " + - "Current Time is {2:T}.", - ObjectID, - dbConnectionPoolAuthenticationContext.ExpirationTime, - DateTime.UtcNow); + if (SqlClientEventSource.Log.IsTraceEnabled()) + { + SqlClientEventSource.Log.TryTraceEvent( + "SqlInternalConnectionTds.TryGetFedAuthTokenLocked | " + + "Object ID {0}, " + + "Acquired the lock to update the authentication context. " + + "The expiration time is {1}. " + + "Current Time is {2}.", + ObjectID, + dbConnectionPoolAuthenticationContext.ExpirationTime.ToString("T"), + DateTime.UtcNow.ToString("T")); + } authenticationContextLocked = true; }