ConnectionOpenDisableRetry test deterministically fails locally #1196

Wraith2 · 2021-07-30T19:28:34Z

When running tests locally at the commandline I usually get 2 failures, one is TvpMain which is being reworked and the other is:

  Failed Microsoft.Data.SqlClient.ManualTesting.Tests.ConnectivityTest.ConnectionOpenDisableRetry [6 ms]
  Error Message:
   Connection Open() with retries took less time than expected. Expect > 5 sec with transient fault handling. Took 0.0024555 sec.
Expected: True
Actual:   False
  Stack Trace:
     at Microsoft.Data.SqlClient.ManualTesting.Tests.ConnectivityTest.ConnectionOpenDisableRetry() in E:\Programming\csharp7\SqlClient\src\Microsoft.Data.SqlClient\tests\ManualTests\SQL\ConnectivityTests\ConnectivityTest.cs:line 378

the build batch file I use is:

set netcore=netcoreapp3.1
set netfx=net461
set config=Release

msbuild /t:clean
msbuild /p:Configuration=%config%
msbuild /t:BuildTestsNetCore /p:TargetNetCoreVersion=%netcore% /p:Configuration=%config%

call :pauseOnError dotnet test "src\Microsoft.Data.SqlClient\tests\ManualTests\Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" /p:Platform="AnyCPU" /p:Configuration="%config%" /p:TestTargetOS="Windowsnetcoreapp" /p:TargetNetCoreVersion=%netcore% --no-build -v n --filter "category!=nonnetcoreapptests&category!=failing&category!=nonwindowstests"

The text was updated successfully, but these errors were encountered:

JRahnama · 2021-07-30T20:45:34Z

I looked into the test, I also tested with VS 2019. The test caught an actual exception ( which is expected, the next line should not be reached). On my try all values were captured as we expected. Can you try without pauseOnError and see how it works?
I will try to improve the test and omit the part that goes inside catch block next week.

JRahnama · 2021-07-30T21:05:27Z

on some other notes, can you capture logs when that happens?

Wraith2 · 2021-07-30T23:23:11Z

Exactly the same result without the pauseOnError. What logs do you want gathering and how?

JRahnama · 2021-08-03T17:39:46Z

@Wraith2 there are two possible ways to do so. Option one is to use PerfView and look for traces from Microsoft.Data.SqlClient.EventSource. This by default captures all added EventSource calls (you can filter by event type or keywords or name and etc....) you can start to collect and stop the process when the test is finished. steps:

Download PerfView from here.
Click on Collect tab and click on Collect and click on Start Collection button. an etl file will be created when you stop it. The name is PerfViewData.etl.zip. ( this will take some time)
click on Events and you can filter by name at the top right beside Filter box.

(Tests running by XUnit may not show any logs using perfview or at least I was not able to capture them. You can add that test as a new project and try to run that.)

The other way is to add a listener. In this case, you can wrap the test with a listener and print them all on a desired output. you can look into EventSourceTest in the driver. The change you can make is inside TraceEventListener class on OnEventWritten part.

here is how I use that when I use listener:

public class Listener : EventListener
    {
        private TextWriter Out = Console.Out;
        protected override void OnEventSourceCreated(EventSource eventsource)
        {
            if (eventsource.Name.Equals("Microsoft.Data.SqlClient.EventSource"))
            {
                EnableEvents(eventSource, EventLevel.Informational, EventKeywords.All);
            }
        }

        protected override void OnEventWritten(EventWrittenEventArgs eventData)
        {

            // report all event information 

            Out.Write(" Event {0} ", eventData.EventName);



           

            // Out.Write(" (activity {0}{1}) ", ShortGuid(eventData.ActivityId),  

            // eventData.RelatedActivityId != Guid.Empty ? "->" + ShortGuid(eventData.RelatedActivityId) : ""); 



            // Events can have formatting strings 'the Message property on the 'Event' attribute.  

            // If the event has a formatted message, print that, otherwise print out argument values.  

            if (eventData.Message != null)

                Out.WriteLine(eventData.Message, eventData.Payload.ToArray());

            else

            {

                string[] sargs = eventData.Payload != null ? eventData.Payload.Select(o => o.ToString()).ToArray() : null;

                Out.WriteLine("({0}).", sargs != null ? string.Join(", ", sargs) : "");


            }
        }
    }

basically modify the class in DataTestUtility and wrap the test in a using block of that class.

All the logs from here are the steps that driver has taken to get to the point of the issue or success.

Wraith2 · 2021-08-03T19:25:49Z

The console out didn't work do i piped it to a file instead which did:

 Event Trace (<prov.DbConnectionHelper.ConnectionString_Set|API> 7, 'Data Source=tcp:WRAITH\SQL2017;Initial Catalog=DoesNotExist0982532435423;Integrated Security=True;Pooling=False;Connect Timeout=1').
 Event ScopeEnter (SqlConnection.Open | API | Correlation | Object Id 7, Activity Id 757c1855-09bb-470c-bea8-df21efa7af5e:1).
 Event CorrelationTrace (SqlConnection.Open | API | Correlation | Object Id 7, Activity Id 757c1855-09bb-470c-bea8-df21efa7af5e:1).
 Event Trace (<sc.SqlConfigurableRetryLogicManager.ConnectionProvider|INFO> Requested the ConnectionProvider value.).
 Event Trace (TdsParserStateObjectFactory.CreateTdsParserStateObject | Info | AppContext switch 'Switch.Microsoft.Data.SqlClient.UseManagedNetworkingOnWindows' not enabled, native networking implementation will be used.).
 Event Trace (TdsParser.Connect | SEC | Connection Object Id 8, Authentication Mode: SqlPassword).
 Event Trace (TdsParser.Connect | SEC | SSPI or Active Directory Authentication Library loaded for SQL Server based integrated authentication).
 Event Trace (<sc.TdsParser.Connect|SEC> Sending prelogin handshake).
 Event Trace (<sc.TdsParser.SendPreLoginHandshake|INFO> ClientConnectionID 756bbdd1-5e83-4642-a175-3db406a95de8, ActivityID 3e64d969-8b0d-46c1-9e16-5b3f551511e2:2).
 Event Trace (<sc.TdsParser.Connect|SEC> Consuming prelogin handshake).
 Event Trace (SqlError.ctor | ERR | Info Number 4060, Error State 1, Error Class 11, Error Message 'Cannot open database "DoesNotExist0982532435423" requested by the login. The login failed.', Procedure '', Line Number 1).
 Event Trace (SqlError.ctor | ERR | Info Number 18456, Error State 1, Error Class 14, Error Message 'Login failed for user 'WRAITH\Wraith2'.', Procedure '', Line Number 1).
 Event Trace (<sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|GetCachedToken|Info>Retrieved cached token null.).
 Event Trace (<sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|CheckCanRetry|Error>Cannot retry when cached token is null.).
 Event Trace (<sc.SqlInternalConnectionTds.LoginFailure|RES|CPOOL> 8).
 Event ScopeLeave (Exit Scope 1).
 Event ScopeEnter (SqlConnection.Open | API | Correlation | Object Id 7, Activity Id 3e64d969-8b0d-46c1-9e16-5b3f551511e2:2).
 Event CorrelationTrace (SqlConnection.Open | API | Correlation | Object Id 7, Activity Id 3e64d969-8b0d-46c1-9e16-5b3f551511e2:2).
 Event Trace (TdsParserStateObjectFactory.CreateTdsParserStateObject | Info | AppContext switch 'Switch.Microsoft.Data.SqlClient.UseManagedNetworkingOnWindows' not enabled, native networking implementation will be used.).
 Event Trace (TdsParser.Connect | SEC | Connection Object Id 9, Authentication Mode: SqlPassword).
 Event Trace (TdsParser.Connect | SEC | SSPI or Active Directory Authentication Library loaded for SQL Server based integrated authentication).
 Event Trace (<sc.TdsParser.Connect|SEC> Sending prelogin handshake).
 Event Trace (<sc.TdsParser.SendPreLoginHandshake|INFO> ClientConnectionID b34537f6-ca28-4001-96a4-5194a55789a8, ActivityID f6f3ab9d-8259-45b5-af94-3a757661d4fd:3).
 Event Trace (<sc.TdsParser.Connect|SEC> Consuming prelogin handshake).
 Event Trace (SqlError.ctor | ERR | Info Number 4060, Error State 1, Error Class 11, Error Message 'Cannot open database "DoesNotExist0982532435423" requested by the login. The login failed.', Procedure '', Line Number 1).
 Event Trace (SqlError.ctor | ERR | Info Number 18456, Error State 1, Error Class 14, Error Message 'Login failed for user 'WRAITH\Wraith2'.', Procedure '', Line Number 1).
 Event Trace (<sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|GetCachedToken|Info>Retrieved cached token null.).
 Event Trace (<sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|CheckCanRetry|Error>Cannot retry when cached token is null.).
 Event Trace (<sc.SqlInternalConnectionTds.LoginFailure|RES|CPOOL> 9).
 Event ScopeLeave (Exit Scope 2).
 Event ScopeEnter (SqlConnection.Close | API | Object Id 7).
 Event CorrelationTrace (SqlConnection.Close | API | Correlation | Object Id 7, Activity Id f6f3ab9d-8259-45b5-af94-3a757661d4fd:3, Client Connection Id 00000000-0000-0000-0000-000000000000).
 Event ScopeLeave (Exit Scope 3).

cheenamalhotra · 2021-08-03T19:42:06Z

Do you also get this error when you specify "User Id" and "Password" in connection string?

Wraith2 · 2021-08-03T20:28:38Z

Yup:

 Event Trace (<prov.DbConnectionHelper.ConnectionString_Set|API> 31, 'Data Source=tcp:WRAITH\SQL2017;Initial Catalog=DoesNotExist0982532435423;Integrated Security=False;User ID=testuser;Pooling=False;Connect Timeout=1').
 Event ScopeEnter (SqlConnection.Open | API | Correlation | Object Id 31, Activity Id 1b046208-094d-4d0d-8ee8-3628e1c82f45:1).
 Event CorrelationTrace (SqlConnection.Open | API | Correlation | Object Id 31, Activity Id 1b046208-094d-4d0d-8ee8-3628e1c82f45:1).
 Event Trace (<sc.SqlConfigurableRetryLogicManager.ConnectionProvider|INFO> Requested the ConnectionProvider value.).
 Event Trace (TdsParserStateObjectFactory.CreateTdsParserStateObject | Info | AppContext switch 'Switch.Microsoft.Data.SqlClient.UseManagedNetworkingOnWindows' not enabled, native networking implementation will be used.).
 Event Trace (TdsParser.Connect | SEC | Connection Object Id 6, Authentication Mode: SqlPassword).
 Event Trace (<sc.TdsParser.Connect|SEC> Sending prelogin handshake).
 Event Trace (<sc.TdsParser.SendPreLoginHandshake|INFO> ClientConnectionID ffa40229-c3d1-4845-a3e9-5d3f1213cf13, ActivityID 85b2fe91-3661-44e4-a35a-2ba71685ed6a:2).
 Event Trace (<sc.TdsParser.Connect|SEC> Consuming prelogin handshake).
 Event Trace (SqlError.ctor | ERR | Info Number 4060, Error State 1, Error Class 11, Error Message 'Cannot open database "DoesNotExist0982532435423" requested by the login. The login failed.', Procedure '', Line Number 1).
 Event Trace (SqlError.ctor | ERR | Info Number 18456, Error State 1, Error Class 14, Error Message 'Login failed for user 'testuser'.', Procedure '', Line Number 1).
 Event Trace (<sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|GetCachedToken|Info>Retrieved cached token null.).
 Event Trace (<sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|CheckCanRetry|Error>Cannot retry when cached token is null.).
 Event Trace (<sc.SqlInternalConnectionTds.LoginFailure|RES|CPOOL> 6).
 Event ScopeLeave (Exit Scope 1).
 Event ScopeEnter (SqlConnection.Open | API | Correlation | Object Id 31, Activity Id 85b2fe91-3661-44e4-a35a-2ba71685ed6a:2).
 Event CorrelationTrace (SqlConnection.Open | API | Correlation | Object Id 31, Activity Id 85b2fe91-3661-44e4-a35a-2ba71685ed6a:2).
 Event Trace (TdsParserStateObjectFactory.CreateTdsParserStateObject | Info | AppContext switch 'Switch.Microsoft.Data.SqlClient.UseManagedNetworkingOnWindows' not enabled, native networking implementation will be used.).
 Event Trace (TdsParser.Connect | SEC | Connection Object Id 7, Authentication Mode: SqlPassword).
 Event Trace (<sc.TdsParser.Connect|SEC> Sending prelogin handshake).
 Event Trace (<sc.TdsParser.SendPreLoginHandshake|INFO> ClientConnectionID 7c5e2086-5dcb-4655-823c-122f4cca613d, ActivityID 508b3f83-2517-4a0d-8cb9-40a371e4f39f:3).
 Event Trace (<sc.TdsParser.Connect|SEC> Consuming prelogin handshake).
 Event Trace (SqlError.ctor | ERR | Info Number 4060, Error State 1, Error Class 11, Error Message 'Cannot open database "DoesNotExist0982532435423" requested by the login. The login failed.', Procedure '', Line Number 1).
 Event Trace (SqlError.ctor | ERR | Info Number 18456, Error State 1, Error Class 14, Error Message 'Login failed for user 'testuser'.', Procedure '', Line Number 1).
 Event Trace (<sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|GetCachedToken|Info>Retrieved cached token null.).
 Event Trace (<sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|CheckCanRetry|Error>Cannot retry when cached token is null.).
 Event Trace (<sc.SqlInternalConnectionTds.LoginFailure|RES|CPOOL> 7).
 Event ScopeLeave (Exit Scope 2).
 Event ScopeEnter (SqlConnection.Close | API | Object Id 31).
 Event CorrelationTrace (SqlConnection.Close | API | Correlation | Object Id 31, Activity Id 508b3f83-2517-4a0d-8cb9-40a371e4f39f:3, Client Connection Id 00000000-0000-0000-0000-000000000000).
 Event ScopeLeave (Exit Scope 3).

JRahnama · 2021-08-04T04:40:15Z

I think the issue happens in your case because of Connect Timeout=1. Let it be default or something more than 5 seconds and test should run ok.

Wraith2 · 2021-08-04T14:36:05Z

That's it. Connect Timeout must be >= 11 for the test to succeed, it's probably worth forcing that in the test.

JRahnama · 2021-08-04T16:15:44Z

I will adjust the PR to address the issue.

JRahnama added the ✔️ Tests Identifier for test related changes label Jul 30, 2021

JRahnama mentioned this issue Aug 3, 2021

Tests | Improve ConnectivityTest #1203

Merged

cheenamalhotra linked a pull request Aug 4, 2021 that will close this issue

Tests | Improve ConnectivityTest #1203

Merged

cheenamalhotra closed this as completed in #1203 Aug 20, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ConnectionOpenDisableRetry test deterministically fails locally #1196

ConnectionOpenDisableRetry test deterministically fails locally #1196

Wraith2 commented Jul 30, 2021

JRahnama commented Jul 30, 2021

JRahnama commented Jul 30, 2021

Wraith2 commented Jul 30, 2021

JRahnama commented Aug 3, 2021 •

edited

Loading

Wraith2 commented Aug 3, 2021 •

edited

Loading

cheenamalhotra commented Aug 3, 2021

Wraith2 commented Aug 3, 2021

JRahnama commented Aug 4, 2021

Wraith2 commented Aug 4, 2021

JRahnama commented Aug 4, 2021

ConnectionOpenDisableRetry test deterministically fails locally #1196

ConnectionOpenDisableRetry test deterministically fails locally #1196

Comments

Wraith2 commented Jul 30, 2021

JRahnama commented Jul 30, 2021

JRahnama commented Jul 30, 2021

Wraith2 commented Jul 30, 2021

JRahnama commented Aug 3, 2021 • edited Loading

Wraith2 commented Aug 3, 2021 • edited Loading

cheenamalhotra commented Aug 3, 2021

Wraith2 commented Aug 3, 2021

JRahnama commented Aug 4, 2021

Wraith2 commented Aug 4, 2021

JRahnama commented Aug 4, 2021

JRahnama commented Aug 3, 2021 •

edited

Loading

Wraith2 commented Aug 3, 2021 •

edited

Loading