From 5ddb446936df4255dc1748942591561c3e39a2b6 Mon Sep 17 00:00:00 2001 From: Cheena Malhotra Date: Tue, 21 Jul 2026 23:36:53 -0700 Subject: [PATCH] Add env-gated login-timeout diagnostics for post-login timeout investigation Investigating intermittent CI failures of the form: Connection Timeout Expired. The timeout period elapsed during the post-login phase. ... [Post-Login] complete=89010 These occur during connection OPEN (post-login CompleteLogin read), not bulk copy. To determine whether the ~89s budget comes from a large configured ConnectTimeout (environment/server stall) or from an inflated / mis-propagated timer budget (driver bug), this adds temporary instrumentation that correlates the configured ConnectTimeout with the actual timer budget handed to the SNI read. Instrumentation (LoginTimeoutDiagnostics, gated behind the MDS_LOGIN_TIMEOUT_DIAG environment variable; default OFF so normal builds and tests are unaffected): * LoginTimerSetup - logs configured ConnectTimeout, resolved login-timer budget, caller (pool) timer state, and the relevant AppContext switches at login start. * LoginAttemptBudget- logs the timeout (seconds) actually handed to the SNI read for each login attempt. * TimeoutMessageBuilt - logs phase durations and diagnostic context when the timeout error message is built, and appends a compact [MDS-TIMEOUT-DIAG ...] suffix directly to the SqlException message so it is captured in test output. The CI-SqlClient pipeline (dotnet-sqlclient-ci-core.yml) sets MDS_LOGIN_TIMEOUT_DIAG=1 so scheduled/CI runs emit these lines automatically. This is temporary diagnostic tooling and should be reverted once the root cause is identified. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: 47316e67-7fb7-405b-9eea-1b5d075b0f49 --- eng/pipelines/dotnet-sqlclient-ci-core.yml | 8 ++ .../Connection/SqlConnectionInternal.cs | 43 ++++++++++ .../Data/SqlClient/LoginTimeoutDiagnostics.cs | 83 +++++++++++++++++++ .../SqlConnectionTimeoutErrorInternal.cs | 53 ++++++++++++ 4 files changed, 187 insertions(+) create mode 100644 src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/LoginTimeoutDiagnostics.cs diff --git a/eng/pipelines/dotnet-sqlclient-ci-core.yml b/eng/pipelines/dotnet-sqlclient-ci-core.yml index a51bbee3f5..86c1012b61 100644 --- a/eng/pipelines/dotnet-sqlclient-ci-core.yml +++ b/eng/pipelines/dotnet-sqlclient-ci-core.yml @@ -107,6 +107,14 @@ parameters: variables: - template: /eng/pipelines/libraries/ci-build-variables.yml@self + # TEMPORARY diagnostics for investigating intermittent post-login connection + # timeouts (see LoginTimeoutDiagnostics in the driver). When set, the driver + # emits '[MDS-TIMEOUT-DIAG]' lines to stderr correlating the configured + # ConnectTimeout with the actual timer budget handed to the SNI read. Remove + # this variable once the investigation concludes. + - name: MDS_LOGIN_TIMEOUT_DIAG + value: 1 + - name: abstractionsArtifactsName value: Abstractions.Artifacts 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..403277f036 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 @@ -383,6 +383,35 @@ internal SqlConnectionInternal( // connect timeout. _timeout = ResolveLoginTimeout(timeout, connectionOptions.ConnectTimeout); + if (LoginTimeoutDiagnostics.Enabled) + { + _timeoutErrorInternal.SetDiagnosticContext( + connectionOptions.DataSource, + connectionOptions.ConnectTimeout, + _timeout.IsInfinite ? -1 : _timeout.MillisecondsRemaining, + _timeout.IsInfinite, + LocalAppContextSwitches.UseOverallConnectTimeoutForPoolWait); + + LoginTimeoutDiagnostics.Log(string.Format( + System.Globalization.CultureInfo.InvariantCulture, + "LoginTimerSetup: DataSource='{0}'; ConnectTimeoutConfig={1}s; " + + "ResolvedLoginBudgetMs={2}; LoginTimerInfinite={3}; " + + "CallerTimerInfinite={4}; CallerTimerRemainingMs={5}; " + + "OverallPoolWaitSwitch={6}; UseMinimumLoginTimeout={7}; " + + "Pooling={8}; MultiSubnetFailover={9}; TransientFaultHandling={10}", + connectionOptions.DataSource, + connectionOptions.ConnectTimeout, + _timeout.IsInfinite ? -1 : _timeout.MillisecondsRemaining, + _timeout.IsInfinite, + timeout is null ? (object)"null" : timeout.IsInfinite, + timeout is null ? -1 : (timeout.IsInfinite ? -1 : timeout.MillisecondsRemaining), + LocalAppContextSwitches.UseOverallConnectTimeoutForPoolWait, + LocalAppContextSwitches.UseMinimumLoginTimeout, + connectionOptions.Pooling, + connectionOptions.MultiSubnetFailover, + applyTransientFaultHandling)); + } + // If transient fault handling is enabled then we can retry the login up to the // ConnectRetryCount. int connectionEstablishCount = applyTransientFaultHandling @@ -2950,6 +2979,20 @@ private void Login( // @TODO: How about we define all the easy ones in one block, then have the conditional ones below that login.authentication = ConnectionOptions.Authentication; login.timeout = timeoutInSeconds; + + if (LoginTimeoutDiagnostics.Enabled) + { + LoginTimeoutDiagnostics.Log(string.Format( + System.Globalization.CultureInfo.InvariantCulture, + "LoginAttemptBudget: server='{0}'; loginTimeoutSecondsToSni={1}; " + + "timerInfinite={2}; timerRemainingMs={3}; overallConnectTimeoutConfig={4}s", + server?.ExtendedServerName, + timeoutInSeconds, + timeout.IsInfinite, + timeout.IsInfinite ? -1 : timeout.MillisecondsRemaining, + ConnectionOptions.ConnectTimeout)); + } + login.userInstance = ConnectionOptions.UserInstance; login.hostName = ConnectionOptions.ObtainWorkstationId(); login.userName = ConnectionOptions.UserID; diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/LoginTimeoutDiagnostics.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/LoginTimeoutDiagnostics.cs new file mode 100644 index 0000000000..642a5d526b --- /dev/null +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/LoginTimeoutDiagnostics.cs @@ -0,0 +1,83 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System; +using System.Globalization; + +namespace Microsoft.Data.SqlClient +{ + /// + /// TEMPORARY CI diagnostic instrumentation for investigating the intermittent + /// "Connection Timeout Expired ... during the post-login phase" failures. + /// + /// This is intentionally NOT shipped behavior. Every emission is gated behind the + /// MDS_LOGIN_TIMEOUT_DIAG environment variable (default OFF), so a normal + /// build/test run is completely unaffected. When the variable is set to + /// 1/true the driver prints greppable lines prefixed with + /// [MDS-TIMEOUT-DIAG] to stderr (captured by ADO/CI logs). + /// + /// The goal is to capture, at the moment a connection open times out, both the + /// configured ConnectTimeout and the actual timer budget handed to + /// the SNI read, so we can prove whether an ~89s post-login timeout comes from a large + /// configured ConnectTimeout (environment) or from an inflated/mis-propagated budget + /// (driver bug). + /// + internal static class LoginTimeoutDiagnostics + { + internal const string EnvVarName = "MDS_LOGIN_TIMEOUT_DIAG"; + + private static readonly bool s_enabled = ComputeEnabled(); + + internal static bool Enabled => s_enabled; + + private static bool ComputeEnabled() + { + try + { + string value = Environment.GetEnvironmentVariable(EnvVarName); + if (string.IsNullOrEmpty(value)) + { + return false; + } + + value = value.Trim(); + return value == "1" + || string.Equals(value, "true", StringComparison.OrdinalIgnoreCase) + || string.Equals(value, "yes", StringComparison.OrdinalIgnoreCase) + || string.Equals(value, "on", StringComparison.OrdinalIgnoreCase); + } + catch + { + // Environment access can throw under partial trust; never let diagnostics + // interfere with normal operation. + return false; + } + } + + internal static void Log(string message) + { + if (!s_enabled) + { + return; + } + + string line = string.Format( + CultureInfo.InvariantCulture, + "[MDS-TIMEOUT-DIAG] {0:O} tid={1} {2}", + DateTime.UtcNow, + Environment.CurrentManagedThreadId, + message); + + try + { + Console.Error.WriteLine(line); + Console.Error.Flush(); + } + catch + { + // Ignore - diagnostics must never affect connection behavior. + } + } + } +} diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlConnectionTimeoutErrorInternal.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlConnectionTimeoutErrorInternal.cs index 4e950a564c..5329c8e702 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlConnectionTimeoutErrorInternal.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlConnectionTimeoutErrorInternal.cs @@ -66,8 +66,31 @@ internal class SqlConnectionTimeoutErrorInternal private SqlConnectionInternalSourceType _currentSourceType; private bool _isFailoverScenario; + // TEMPORARY CI diagnostics context (see LoginTimeoutDiagnostics). Populated when the + // owning SqlConnectionInternal sets up the login timer so the timeout message emission + // can correlate the configured ConnectTimeout with the actual timer budget. + private int _diagConnectTimeoutSeconds = -1; + private long _diagLoginBudgetMs = -1; + private bool _diagLoginTimerInfinite; + private bool _diagOverallPoolWaitSwitch; + private string _diagDataSource; + internal SqlConnectionTimeoutErrorPhase CurrentPhase => _currentPhase; + internal void SetDiagnosticContext( + string dataSource, + int connectTimeoutSeconds, + long loginBudgetMs, + bool loginTimerInfinite, + bool overallPoolWaitSwitch) + { + _diagDataSource = dataSource; + _diagConnectTimeoutSeconds = connectTimeoutSeconds; + _diagLoginBudgetMs = loginBudgetMs; + _diagLoginTimerInfinite = loginTimerInfinite; + _diagOverallPoolWaitSwitch = overallPoolWaitSwitch; + } + public SqlConnectionTimeoutErrorInternal() { _phaseDurations = new SqlConnectionTimeoutPhaseDuration[(int)SqlConnectionTimeoutErrorPhase.Count]; @@ -233,6 +256,36 @@ internal string GetErrorMessage() errorBuilder.Append(durationString); } + if (LoginTimeoutDiagnostics.Enabled) + { + long postLoginMs = _phaseDurations[(int)SqlConnectionTimeoutErrorPhase.PostLogin]?.GetMilliSecondDuration() ?? -1; + long preLoginMs = _phaseDurations[(int)SqlConnectionTimeoutErrorPhase.PreLoginBegin]?.GetMilliSecondDuration() ?? -1; + string diag = string.Format( + System.Globalization.CultureInfo.InvariantCulture, + "TimeoutMessageBuilt: phase={0}; failover={1}; sourceType={2}; " + + "DataSource='{3}'; ConnectTimeoutConfig={4}s; LoginBudgetMs={5}; " + + "LoginTimerInfinite={6}; OverallPoolWaitSwitch={7}; " + + "PreLoginPhaseMs={8}; PostLoginPhaseMs={9}", + _currentPhase, + _isFailoverScenario, + _currentSourceType, + _diagDataSource, + _diagConnectTimeoutSeconds, + _diagLoginBudgetMs, + _diagLoginTimerInfinite, + _diagOverallPoolWaitSwitch, + preLoginMs, + postLoginMs); + + LoginTimeoutDiagnostics.Log(diag); + + // Also append a compact, greppable suffix directly to the timeout + // exception message so it is captured in the test failure output + // (xunit surfaces exception messages even when it does not surface + // driver stderr). Env-gated, append-only, timeout-path-only. + errorBuilder.Append(" [MDS-TIMEOUT-DIAG ").Append(diag).Append("]"); + } + return errorBuilder.ToString(); } }