locked
Test Run just stops, and eventually times out RRS feed

  • Question

  • I have an OrderedTest that consists of 13 codedui tests. The test solution is built and executed on a remote desktop through TeamBuild using a remote settings file.  Some days everything works fine.  Other times, the test just hangs and eventually times out.  Each of the 13 codedui tests open a web browser, performs a function and then closes the browser.  The test run fine for several of the tests, and then just fails to open the browser for the next test.  The test that fails is random -- it's rarely the same test that it gets stuck on.  Below is the log file for the Test agent around the time the agent just stalled:

    V, 3488, 22, 2011/01/28, 03:09:16.380, TSC-055L2\QTAgent32.exe, AutoSuiteResultSink.AddResult: starting.
    V, 3488, 22, 2011/01/28, 03:09:16.380, TSC-055L2\QTAgent32.exe, AutoSuiteResultSink.SendResult: sending 'smoketest'.InProgress to parent's sink: AgentExecution.
    V, 3488, 22, 2011/01/28, 03:09:16.380, TSC-055L2\QTAgent32.exe, BackgroundSpecialJobProcessor<Microsoft.VisualStudio.TestTools.Common.TestMessage>(AgentObject.TestMessageSender).TryEnqueueJob: invoking special job checker for job 'run id {7741f324-3568-495a-9b21-be9fd873cb26}, test 'smoketest' with id c19c1417-feec-4a4c-970e-143e7f141c59: MessageKind: Result, Outcome: InProgress'
    V, 3488, 22, 2011/01/28, 03:09:16.381, TSC-055L2\QTAgent32.exe, BackgroundSpecialJobProcessor<Microsoft.VisualStudio.TestTools.Common.TestMessage>(AgentObject.TestMessageSender).TryEnqueueJob: successfully invoked special job checker for job 'run id {7741f324-3568-495a-9b21-be9fd873cb26}, test 'smoketest' with id c19c1417-feec-4a4c-970e-143e7f141c59: MessageKind: Result, Outcome: InProgress'
    V, 3488, 22, 2011/01/28, 03:09:16.381, TSC-055L2\QTAgent32.exe, BackgroundSpecialJobProcessor<Microsoft.VisualStudio.TestTools.Common.TestMessage>(AgentObject.TestMessageSender).TryEnqueueJob: isSpecial = False
    V, 3488, 22, 2011/01/28, 03:09:16.381, TSC-055L2\QTAgent32.exe, BackgroundJobProcessor<Microsoft.VisualStudio.TestTools.Common.TestMessage>(AgentObject.TestMessageSender).TryEnqueueJob: Queuing job 'Type Microsoft.VisualStudio.TestTools.Common.TestResultAggregation: run id {7741f324-3568-495a-9b21-be9fd873cb26}, test 'smoketest' with id c19c1417-feec-4a4c-970e-143e7f141c59: MessageKind: Result, Outcome: InProgress'
    V, 3488, 22, 2011/01/28, 03:09:16.381, TSC-055L2\QTAgent32.exe, AutoSuiteResultSink.AddResult: finished.
    V, 3488, 22, 2011/01/28, 03:09:16.381, TSC-055L2\QTAgent32.exe, StateMachine(TestState): SetNextState Disposed called
    V, 3488, 29, 2011/01/28, 03:09:16.381, TSC-055L2\QTAgent32.exe, BackgroundJobProcessor<Microsoft.VisualStudio.TestTools.Common.TestMessage>(AgentObject.TestMessageSender)+ExternalJob.ProcessJob: invoking job processor for job 'run id {7741f324-3568-495a-9b21-be9fd873cb26}, test 'smoketest' with id c19c1417-feec-4a4c-970e-143e7f141c59: MessageKind: Result, Outcome: InProgress'
    V, 3488, 22, 2011/01/28, 03:09:16.381, TSC-055L2\QTAgent32.exe, StateMachine(TestState): In state Disposed. Waiting for state change...
    V, 3488, 22, 2011/01/28, 03:09:16.381, TSC-055L2\QTAgent32.exe, StateMachine(TestState): Exit wait for state change, current state is Disposed.
    V, 3488, 22, 2011/01/28, 03:09:16.381, TSC-055L2\QTAgent32.exe, AgentObject.OnExecutionTestCompleted: done for test PublishAccountsPage_CreateNewPublishAccountForSCTest_AccountCreatedInDatabase
    V, 3488, 14, 2011/01/28, 03:09:16.381, TSC-055L2\QTAgent32.exe, AgentObject: WaitForTestState: WaitAny returned 0
    I, 3488, 14, 2011/01/28, 03:09:16.381, TSC-055L2\QTAgent32.exe, AgentObject: ExecuteTest 'PublishAccountsPage_CreateNewPublishAccountForSCTest_AccountCreatedInDatabase' is complete.
    W, 3488, 29, 2011/01/28, 03:09:16.381, TSC-055L2\QTAgent32.exe, Performance warning: m_test should be null when TestResult is serialized. Please find the offending code and correct it.
    V, 3488, 23, 2011/01/28, 03:09:16.382, TSC-055L2\QTAgent32.exe, StateMachine(TestState): SetNextState Starting called
    V, 3488, 23, 2011/01/28, 03:09:16.382, TSC-055L2\QTAgent32.exe, StateMachine(TestState): In state Starting. Waiting for state change...
    V, 3488, 23, 2011/01/28, 03:09:16.382, TSC-055L2\QTAgent32.exe, StateMachine(TestState): Exit wait for state change, current state is Starting.
    V, 3488, 23, 2011/01/28, 03:09:16.382, TSC-055L2\QTAgent32.exe, StateMachine(TestState): calling state handler for Starting
    V, 3488, 23, 2011/01/28, 03:09:16.382, TSC-055L2\QTAgent32.exe, AgentObject.RaiseEventAndWait: Raising event 'Microsoft.VisualStudio.TestTools.Execution.TestCaseStartEventArgs' to the controller. Using data synchronization: False
    V, 3488, 14, 2011/01/28, 03:09:16.383, TSC-055L2\QTAgent32.exe, AgentObject: WaitForTestState waiting for test 'ProfilePage_CreateNewAutoTestProfileUsingRelayTestFSandSCTestDestinationsandAutoUser_EmptyDataBase_ProfileCreatedInDatabase' Completed, timeout is -1 current state is Starting
    V, 3488, 23, 2011/01/28, 03:09:16.393, TSC-055L2\QTAgent32.exe, AgentObject.RaiseEvent: got Microsoft.VisualStudio.TestTools.Execution.TestCaseStartEventArgs
    V, 3488, 23, 2011/01/28, 03:09:16.415, TSC-055L2\QTAgent32.exe, AgentObject.RaiseEvent: successfully returned from ExecutionPluginManager.RaiseEvent(Microsoft.VisualStudio.TestTools.Execution.TestCaseStartEventArgs)
    V, 3488, 29, 2011/01/28, 03:09:16.428, TSC-055L2\QTAgent32.exe, BackgroundJobProcessor<Microsoft.VisualStudio.TestTools.Common.TestMessage>(AgentObject.TestMessageSender)+ExternalJob.ProcessJob: successfully invoked job processor for job 'run id {7741f324-3568-495a-9b21-be9fd873cb26}, test 'smoketest' with id c19c1417-feec-4a4c-970e-143e7f141c59: MessageKind: Result, Outcome: InProgress'
    V, 3488, 23, 2011/01/28, 03:09:16.447, TSC-055L2\QTAgent32.exe, AgentObject.RaiseEventAndWait: Completed
    V, 3488, 23, 2011/01/28, 03:09:16.447, TSC-055L2\QTAgent32.exe, StateMachine(TestState): SetNextState Started called
    V, 3488, 23, 2011/01/28, 03:09:16.447, TSC-055L2\QTAgent32.exe, StateMachine(TestState): In state Started. Waiting for state change...
    V, 3488, 23, 2011/01/28, 03:09:16.447, TSC-055L2\QTAgent32.exe, StateMachine(TestState): Exit wait for state change, current state is Started.
    V, 3488, 23, 2011/01/28, 03:09:16.448, TSC-055L2\QTAgent32.exe, StateMachine(TestState): calling state handler for Started
    V, 3488, 23, 2011/01/28, 03:09:16.448, TSC-055L2\QTAgent32.exe, AutoSuiteResultSink.AddResult: starting.
    V, 3488, 23, 2011/01/28, 03:09:16.448, TSC-055L2\QTAgent32.exe, AutoSuiteResultSink.SendResult: sending 'smoketest'.InProgress to parent's sink: AgentExecution.
    V, 3488, 23, 2011/01/28, 03:09:16.448, TSC-055L2\QTAgent32.exe, BackgroundSpecialJobProcessor<Microsoft.VisualStudio.TestTools.Common.TestMessage>(AgentObject.TestMessageSender).TryEnqueueJob: invoking special job checker for job 'run id {7741f324-3568-495a-9b21-be9fd873cb26}, test 'smoketest' with id c19c1417-feec-4a4c-970e-143e7f141c59: MessageKind: Result, Outcome: InProgress'
    V, 3488, 23, 2011/01/28, 03:09:16.448, TSC-055L2\QTAgent32.exe, BackgroundSpecialJobProcessor<Microsoft.VisualStudio.TestTools.Common.TestMessage>(AgentObject.TestMessageSender).TryEnqueueJob: successfully invoked special job checker for job 'run id {7741f324-3568-495a-9b21-be9fd873cb26}, test 'smoketest' with id c19c1417-feec-4a4c-970e-143e7f141c59: MessageKind: Result, Outcome: InProgress'
    V, 3488, 23, 2011/01/28, 03:09:16.448, TSC-055L2\QTAgent32.exe, BackgroundSpecialJobProcessor<Microsoft.VisualStudio.TestTools.Common.TestMessage>(AgentObject.TestMessageSender).TryEnqueueJob: isSpecial = False
    V, 3488, 23, 2011/01/28, 03:09:16.448, TSC-055L2\QTAgent32.exe, BackgroundJobProcessor<Microsoft.VisualStudio.TestTools.Common.TestMessage>(AgentObject.TestMessageSender).TryEnqueueJob: Queuing job 'Type Microsoft.VisualStudio.TestTools.Common.TestResultAggregation: run id {7741f324-3568-495a-9b21-be9fd873cb26}, test 'smoketest' with id c19c1417-feec-4a4c-970e-143e7f141c59: MessageKind: Result, Outcome: InProgress'
    V, 3488, 23, 2011/01/28, 03:09:16.448, TSC-055L2\QTAgent32.exe, AutoSuiteResultSink.AddResult: finished.
    V, 3488, 29, 2011/01/28, 03:09:16.454, TSC-055L2\QTAgent32.exe, BackgroundJobProcessor<Microsoft.VisualStudio.TestTools.Common.TestMessage>(AgentObject.TestMessageSender)+ExternalJob.ProcessJob: invoking job processor for job 'run id {7741f324-3568-495a-9b21-be9fd873cb26}, test 'smoketest' with id c19c1417-feec-4a4c-970e-143e7f141c59: MessageKind: Result, Outcome: InProgress'
    V, 3488, 25, 2011/01/28, 03:09:16.459, TSC-055L2\QTAgent32.exe, AgentExectution.CallAdapterRunMethod: calling into test adapter.
    I, 3488, 25, 2011/01/28, 03:09:16.459, TSC-055L2\QTAgent32.exe, UnitTestAdapter executing test ProfilePage_CreateNewAutoTestProfileUsingRelayTestFSandSCTestDestinationsandAutoUser_EmptyDataBase_ProfileCreatedInDatabase ID={2b67a4b2-43ab-1812-0276-11cc438555d6}
    V, 3488, 25, 2011/01/28, 03:09:16.459, TSC-055L2\QTAgent32.exe, UnitTestAdapter: test: ProfilePage_CreateNewAutoTestProfileUsingRelayTestFSandSCTestDestinationsandAutoUser_EmptyDataBase_ProfileCreatedInDatabase, using code base: C:\Users\tscbuild\AppData\Local\VSEQT\QTAgent\7741f324-3568-495a-9b21-be9fd873cb26\TSC-055L2\Deployment\RelayServerUITests.DLL
    V, 3488, 29, 2011/01/28, 03:09:16.470, TSC-055L2\QTAgent32.exe, BackgroundJobProcessor<Microsoft.VisualStudio.TestTools.Common.TestMessage>(AgentObject.TestMessageSender)+ExternalJob.ProcessJob: successfully invoked job processor for job 'run id {7741f324-3568-495a-9b21-be9fd873cb26}, test 'smoketest' with id c19c1417-feec-4a4c-970e-143e7f141c59: MessageKind: Result, Outcome: InProgress'
    V, 3488, 23, 2011/01/28, 03:09:16.476, TSC-055L2\QTAgent32.exe, StateMachine(TestState): SetNextState Running called
    V, 3488, 23, 2011/01/28, 03:09:16.476, TSC-055L2\QTAgent32.exe, StateMachine(TestState): In state Running. Waiting for state change...
    V, 3488, 23, 2011/01/28, 03:09:16.476, TSC-055L2\QTAgent32.exe, StateMachine(TestState): Exit wait for state change, current state is Running.
    V, 3488, 23, 2011/01/28, 03:09:16.476, TSC-055L2\QTAgent32.exe, StateMachine(TestState): calling state handler for Running
    V, 3488, 23, 2011/01/28, 03:09:16.476, TSC-055L2\QTAgent32.exe, StateMachine(TestState): In state Running. Waiting for state change...
    V, 3488, 11, 2011/01/28, 03:09:22.067, TSC-055L2\QTAgent32.exe, AgentObject: Sending heartbeat to listeners
    V, 3488, 11, 2011/01/28, 03:09:22.074, TSC-055L2\QTAgent32.exe, AgentObject: Returned from sending heartbeat
    V, 3488, 11, 2011/01/28, 03:09:32.075, TSC-055L2\QTAgent32.exe, AgentObject: Sending heartbeat to listeners
    V, 3488, 11, 2011/01/28, 03:09:32.078, TSC-055L2\QTAgent32.exe, AgentObject: Returned from sending heartbeat
    V, 3488, 11, 2011/01/28, 03:09:42.079, TSC-055L2\QTAgent32.exe, AgentObject: Sending heartbeat to listeners
    V, 3488, 11, 2011/01/28, 03:09:42.082, TSC-055L2\QTAgent32.exe, AgentObject: Returned from sending heartbeat

     

    The rest of the log fileis the hearbeat messages.  Any help would be appreciated.

    Friday, January 28, 2011 4:08 PM

Answers

  • Well normally when this happens it is because it was looking for an object and couldn't find it. The test will continue to look for it and the Application under test will time out.  What I would propose doing is this :

    Ensure that anytime you are referencing a object in the application that it is in a try catch block and that you are catching the UITestControlNotFoundException.

    Edit some of your playback setting :

                Playback.PlaybackSettings.WaitForReadyTimeout = 500;
                Playback.PlaybackSettings.SearchTimeout = 500;
                Playback.PlaybackSettings.ShouldSearchFailFast = false;

     

    Now the randomness I would need to know more about the application but see if this helps you first.

    Monday, January 31, 2011 2:51 PM