Coded UI Test run aborts on exception after timeout
-
Tuesday, December 13, 2011 10:00 AM
I have a bunch of test cases automated to test our plug-in for Outlook. Sometimes a test case times out and the next test case aborts with the error "The test adapter 'UnitTestAdapter' threw an exception while running test '<testcasename>'. Exception has been thrown by the target of an invocation.Attempted to read or write protected memory. This is often an indication that other memory is corrupt."
I do not know why the test case times out in the first place, and why the next test case aborts.
I set a static variable in my TestCleanup to store the current test outcome to be used in the next test case TestInitialize
private static UnitTestOutcome PreviousTestOutcome;
PreviousTestOutcome = TestContext.CurrentTestOutcome;
and when the next test case starts it checks if the previous test case was timed out, if so re-launch the application. I have this piece of code in my TestInitialize
if (PreviousTestOutcome == UnitTestOutcome.Timeout) { Playback.StopSession(); KillOutlookAndDMProcesses(); System.Threading.Thread.Sleep(TimeSpan.FromSeconds(5)); Playback.StartSession(); Playback.Wait(5000); LaunchOutlookAndLoginToDM(); }The logs are too huge to upload here. Is there a way to upload them as attachment?
Madhu
All Replies
-
Tuesday, December 13, 2011 11:43 AM
I can't help you with the crash, but the following are best practices for improving the performance of Coded UI Tests that might help you with your timeout:
http://blogs.msdn.com/b/vstsqualitytools/archive/2009/08/10/configuring-playback-in-vstt-2010.aspx
Probably the most useful thing to turn off is Smart Matching:
Playback.PlaybackSettings.SmartMatchOptions = SmartMatchOptions.None;
With Smart Matching on, I found my tests always passed locally (fast machine) but failed intermittently on a virtual machine when running against the Test Agents. When I turned off the Smart Matching, and fixed up the search criteria (without the Smart Matching heuristics, many of my tests failed to find the controls), everything passed 100% of the time.
Grey Ham
Blog: http://www.havecomputerwillcode.com/blog -
Tuesday, December 13, 2011 2:44 PM
Madhu G Umapathy,
Are your tests executing for longer than 30 minutes? By default, there is a limit of 30 minutes for test execution, unless that limit is lifted in either the .testsettings file or with an explicit test attribute.
See:
How to: Set Time Limits for Running Tests
http://msdn.microsoft.com/en-us/library/ms243175.aspx
Cheers,
Paul
-
Wednesday, December 14, 2011 5:45 AM
I have set the test timeout to 10 minutes and tough the controls are seen on the screen, the application is not hung and it is responding, the WaitThread keeps waiting forever until it is aborted by the application on crossing 10 minutes. I have pasted the trx log towards the end of the test case. I do not know why, but the therad waits for the control infinitely. I do not have any infinite loops in my code.
4088, 28, 2011/12/13, 12:08:21.579, 10009971218, QTAgent32.exe, Msaa:WindowHandleGetter: MTA Thread returned valid Window handle [262932]
I, 4088, 28, 2011/12/13, 12:08:21.680, 10010247199, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [262932]
V, 4088, 28, 2011/12/13, 12:08:21.783, 10010527864, QTAgent32.exe, MsaaElement.IsWin32 = False for Element = Name [UnitializedBB839B89-49D2-4923-9F10-3C00A9902878], ControlType [Client], NativeControlType [client], ClassName [NUIPane], RuntimeId []
W, 4088, 28, 2011/12/13, 12:08:21.885, 10010805444, QTAgent32.exe, Msaa.MsaaElement() took more time. Total time taken 305 ms for element 262932_0_[MSAA]ControlType='Client' && ClassName='NUIPane'
I, 4088, 28, 2011/12/13, 12:08:21.885, 10010805917, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [197474]
I, 4088, 28, 2011/12/13, 12:08:21.987, 10011084804, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [197474]
W, 4088, 28, 2011/12/13, 12:08:23.312, 10014697181, QTAgent32.exe, Msaa.WindowInstanceGetter: Timeout
V, 4088, 28, 2011/12/13, 12:08:24.790, 10018725714, QTAgent32.exe, Msaa:WindowHandleGetter: MTA Thread returned valid Window handle [262938]
V, 4088, 28, 2011/12/13, 12:08:26.315, 10022886417, QTAgent32.exe, Msaa.ControlTypeName: No mapping found for MSAA role [PropertyPage]
I, 4088, 28, 2011/12/13, 12:08:26.417, 10023162307, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [262938]
V, 4088, 28, 2011/12/13, 12:08:26.519, 10023440030, QTAgent32.exe, MsaaElement.IsWin32 = False for Element = Name [UnitializedBB839B89-49D2-4923-9F10-3C00A9902878], ControlType [PropertyPage], NativeControlType [property page], ClassName [NetUIHWND], RuntimeId []
W, 4088, 28, 2011/12/13, 12:08:26.570, 10023579918, QTAgent32.exe, Msaa.MsaaElement() took more time. Total time taken 253 ms for element 262938_0_[MSAA]Name='Status Bar' && ControlType='PropertyPage'
V, 4088, 28, 2011/12/13, 12:08:26.621, 10023719120, QTAgent32.exe, AL: Setting search timeout to 120000 ms
V, 4088, 28, 2011/12/13, 12:08:26.621, 10023719388, QTAgent32.exe, PERF: AL : SearchHelper.Search: took 21516 ms.
V, 4088, 28, 2011/12/13, 12:08:26.621, 10023719530, QTAgent32.exe, AL : GetProperty, propertyName: Name
V, 4088, 28, 2011/12/13, 12:08:26.621, 10023719706, QTAgent32.exe, AL : EnsureValid()
V, 4088, 28, 2011/12/13, 12:08:26.621, 10023719841, QTAgent32.exe, AL : UITestControl.WaitForControlReady - 60000
I, 4088, 28, 2011/12/13, 12:08:26.723, 10023997904, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 4088, 28, 2011/12/13, 12:08:26.726, 10024006729, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
V, 4088, 28, 2011/12/13, 12:08:26.825, 10024275843, QTAgent32.exe, AL : GetPropertyValue, propertyName: Name, ControlType: Button
V, 4088, 28, 2011/12/13, 12:08:26.877, 10024416089, QTAgent32.exe, ManagedWrapper : Utility : RestoreWindowForSearching
V, 4088, 28, 2011/12/13, 12:08:26.877, 10024416427, QTAgent32.exe, AL : EnsureValid()
V, 4088, 28, 2011/12/13, 12:08:26.877, 10024416912, QTAgent32.exe, AL : GetProperty, propertyName: Expanded
V, 4088, 28, 2011/12/13, 12:08:26.877, 10024417071, QTAgent32.exe, AL : EnsureValid()
V, 4088, 28, 2011/12/13, 12:08:26.877, 10024417218, QTAgent32.exe, AL : UITestControl.WaitForControlReady - 60000
I, 4088, 28, 2011/12/13, 12:08:26.978, 10024692209, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 4088, 28, 2011/12/13, 12:08:26.980, 10024699441, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
V, 4088, 28, 2011/12/13, 12:08:26.980, 10024699933, QTAgent32.exe, AL : GetPropertyValue, propertyName: Expanded, ControlType: TreeItem
V, 4088, 28, 2011/12/13, 12:08:26.980, 10024700269, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 4088, 28, 2011/12/13, 12:08:26.980, 10024700415, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: TreeItem
V, 4088, 28, 2011/12/13, 12:08:26.981, 10024701005, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 4088, 28, 2011/12/13, 12:08:26.981, 10024701165, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: TreeItem
V, 4088, 28, 2011/12/13, 12:08:26.981, 10024701324, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 4088, 28, 2011/12/13, 12:08:26.981, 10024701471, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: TreeItem
V, 4088, 28, 2011/12/13, 12:08:26.981, 10024701628, QTAgent32.exe, AL : GetTreeNodeProperty, propertyName: Expanded
V, 4088, 28, 2011/12/13, 12:08:26.981, 10024701764, QTAgent32.exe, AL : GetProperty, propertyName: State
V, 4088, 28, 2011/12/13, 12:08:26.981, 10024701904, QTAgent32.exe, AL : EnsureValid()
V, 4088, 28, 2011/12/13, 12:08:26.981, 10024702035, QTAgent32.exe, AL : UITestControl.WaitForControlReady - 60000
I, 4088, 28, 2011/12/13, 12:08:27.079, 10024967479, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 4088, 28, 2011/12/13, 12:08:27.082, 10024976049, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
V, 4088, 28, 2011/12/13, 12:08:27.082, 10024976531, QTAgent32.exe, AL : GetPropertyValue, propertyName: State, ControlType: TreeItem
V, 4088, 28, 2011/12/13, 12:08:27.130, 10025106198, QTAgent32.exe, AL : GetProperty, propertyName: Expanded
V, 4088, 28, 2011/12/13, 12:08:27.130, 10025106565, QTAgent32.exe, AL : EnsureValid()
V, 4088, 28, 2011/12/13, 12:08:27.130, 10025106714, QTAgent32.exe, AL : UITestControl.WaitForControlReady - 60000
I, 4088, 28, 2011/12/13, 12:08:27.231, 10025382670, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 4088, 28, 2011/12/13, 12:08:27.234, 10025389508, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
V, 4088, 28, 2011/12/13, 12:08:27.234, 10025390005, QTAgent32.exe, AL : GetPropertyValue, propertyName: Expanded, ControlType: TreeItem
V, 4088, 28, 2011/12/13, 12:08:27.234, 10025390348, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 4088, 28, 2011/12/13, 12:08:27.234, 10025390498, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: TreeItem
V, 4088, 28, 2011/12/13, 12:08:27.234, 10025390666, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 4088, 28, 2011/12/13, 12:08:27.234, 10025390810, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: TreeItem
V, 4088, 28, 2011/12/13, 12:08:27.234, 10025390954, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 4088, 28, 2011/12/13, 12:08:27.234, 10025391123, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: TreeItem
V, 4088, 28, 2011/12/13, 12:08:27.234, 10025391284, QTAgent32.exe, AL : GetTreeNodeProperty, propertyName: Expanded
V, 4088, 28, 2011/12/13, 12:08:27.234, 10025391425, QTAgent32.exe, AL : GetProperty, propertyName: State
V, 4088, 28, 2011/12/13, 12:08:27.234, 10025391555, QTAgent32.exe, AL : EnsureValid()
V, 4088, 28, 2011/12/13, 12:08:27.234, 10025391619, QTAgent32.exe, AL : UITestControl.WaitForControlReady - 60000
I, 4088, 28, 2011/12/13, 12:08:27.334, 10025661634, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 4088, 28, 2011/12/13, 12:08:27.336, 10025669067, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
V, 4088, 28, 2011/12/13, 12:08:27.336, 10025669564, QTAgent32.exe, AL : GetPropertyValue, propertyName: State, ControlType: TreeItem
V, 4088, 28, 2011/12/13, 12:08:27.385, 10025801727, QTAgent32.exe, AL : GetProperty, propertyName: Name
V, 4088, 28, 2011/12/13, 12:08:27.385, 10025802094, QTAgent32.exe, AL : EnsureValid()
V, 4088, 28, 2011/12/13, 12:08:27.385, 10025802252, QTAgent32.exe, AL : UITestControl.WaitForControlReady - 60000
I, 4088, 28, 2011/12/13, 12:08:27.486, 10026078199, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 4088, 28, 2011/12/13, 12:08:27.489, 10026085658, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
V, 4088, 28, 2011/12/13, 12:08:27.489, 10026086145, QTAgent32.exe, AL : GetPropertyValue, propertyName: Name, ControlType: TreeItem
V, 4088, 28, 2011/12/13, 12:08:27.538, 10026218203, QTAgent32.exe, ManagedWrapper : Utility : RestoreWindowForSearching
V, 4088, 28, 2011/12/13, 12:08:27.538, 10026218634, QTAgent32.exe, AL : EnsureValid()
I, 4088, 28, 2011/12/13, 12:11:10.206, 10469985674, QTAgent32.exe, Playback - < No Scrollable containers found for the current UI element. The immediate parent "eDOCS DM" "TreeItem" will be used as a scrollable container >
\0
I, 4088, 28, 2011/12/13, 12:11:15.802, 10485282467, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 4088, 28, 2011/12/13, 12:11:15.818, 10485326913, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.430, 10489730960, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 4088, 28, 2011/12/13, 12:11:17.481, 10489873635, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.566, 10490105492, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.568, 10490111244, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3168, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.571, 10490118242, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1060, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.582, 10490148323, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3332, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.583, 10490152325, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.586, 10490159145, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3208, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.588, 10490164490, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2108, ThreadState = Wait, ThreadWaitReason = ExecutionDelay
I, 4088, 28, 2011/12/13, 12:11:17.591, 10490171913, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3612, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.593, 10490178274, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 4092, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.594, 10490181697, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 352, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.597, 10490189547, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2168, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.599, 10490195084, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2528, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.602, 10490202331, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1176, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.606, 10490214902, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 956, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.608, 10490220211, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1672, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.611, 10490226757, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3740, ThreadState = Wait, ThreadWaitReason = ExecutionDelay
I, 4088, 28, 2011/12/13, 12:11:17.612, 10490231361, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 628, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:17.614, 10490235364, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3880, ThreadState = Wait, ThreadWaitReason = ExecutionDelay
I, 4088, 28, 2011/12/13, 12:11:17.616, 10490240243, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3360, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.618, 10490245593, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 4004, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.619, 10490249921, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3204, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.622, 10490257591, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3876, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.624, 10490264131, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3856, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.626, 10490269662, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2188, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.629, 10490276151, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.631, 10490281833, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2252, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.633, 10490286977, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3832, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.636, 10490295962, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1212, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.638, 10490301660, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3288, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.641, 10490308889, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3524, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.644, 10490316273, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3172, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.645, 10490321741, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2088, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.648, 10490328044, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3368, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.650, 10490335043, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 4012, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:17.652, 10490339443, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3648, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:17.654, 10490345472, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1140, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:17.658, 10490356012, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3604, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:18.059, 10491452817, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
W, 4088, 28, 2011/12/13, 12:11:18.493, 10492637731, QTAgent32.exe, Playback - [WARNING] Internal warning: Vertical programmatic scroll failed\0
I, 4088, 28, 2011/12/13, 12:11:18.593, 10492911938, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 4088, 28, 2011/12/13, 12:11:18.654, 10493079361, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.734, 10493297753, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.736, 10493301909, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3168, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.737, 10493305921, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1060, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.739, 10493311013, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3332, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.741, 10493316363, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.743, 10493320625, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3208, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.745, 10493326959, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2108, ThreadState = Wait, ThreadWaitReason = ExecutionDelay
I, 4088, 28, 2011/12/13, 12:11:18.747, 10493331295, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3612, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.748, 10493336089, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 4092, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.750, 10493340518, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 352, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.752, 10493345750, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2168, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.754, 10493351103, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2528, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.755, 10493355313, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1176, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.757, 10493360318, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 956, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.759, 10493364729, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1672, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.760, 10493368868, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3740, ThreadState = Wait, ThreadWaitReason = ExecutionDelay
I, 4088, 28, 2011/12/13, 12:11:18.763, 10493374743, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 628, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:18.765, 10493381607, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3880, ThreadState = Wait, ThreadWaitReason = ExecutionDelay
I, 4088, 28, 2011/12/13, 12:11:18.768, 10493389498, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3360, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.769, 10493394387, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 4004, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.771, 10493398422, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3204, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.772, 10493402316, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3876, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.774, 10493406194, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3856, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.777, 10493413984, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2188, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.788, 10493445128, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.790, 10493449303, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2252, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.791, 10493453106, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3832, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.792, 10493457271, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1212, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.794, 10493461190, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3288, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.795, 10493465087, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3524, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.797, 10493469101, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3172, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.799, 10493474109, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2088, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.801, 10493479166, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3368, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.802, 10493484039, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 4012, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:18.805, 10493489733, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3648, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:18.807, 10493496394, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1140, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:18.809, 10493501894, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3604, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:19.162, 10494466617, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.248, 10494701726, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 4088, 28, 2011/12/13, 12:11:19.300, 10494845509, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.384, 10495072443, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.385, 10495077650, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3168, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.387, 10495083724, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1060, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.389, 10495088315, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3332, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.391, 10495092628, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.393, 10495097387, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3208, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.395, 10495103718, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2108, ThreadState = Wait, ThreadWaitReason = ExecutionDelay
I, 4088, 28, 2011/12/13, 12:11:19.397, 10495108361, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3612, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.398, 10495112565, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 4092, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.400, 10495116612, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 352, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.402, 10495121449, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2168, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.403, 10495125464, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2528, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.405, 10495129710, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1176, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.407, 10495134867, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 956, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.408, 10495140174, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1672, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.410, 10495146098, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3740, ThreadState = Wait, ThreadWaitReason = ExecutionDelay
I, 4088, 28, 2011/12/13, 12:11:19.412, 10495151397, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 628, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:19.414, 10495156720, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3880, ThreadState = Wait, ThreadWaitReason = ExecutionDelay
I, 4088, 28, 2011/12/13, 12:11:19.416, 10495160622, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3360, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.418, 10495165515, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 4004, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.420, 10495171896, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3204, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.423, 10495178832, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3876, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.425, 10495184135, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3856, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.435, 10495214253, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2188, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.437, 10495218959, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.439, 10495223164, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2252, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.440, 10495227178, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3832, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.443, 10495234593, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1212, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.446, 10495241340, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3288, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.448, 10495247096, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3524, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.449, 10495252372, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3172, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.451, 10495257670, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2088, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.453, 10495261886, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3368, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.455, 10495267008, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 4012, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:19.456, 10495271246, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3648, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:19.458, 10495275091, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1140, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:19.459, 10495279562, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3604, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:19.870, 10496402310, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.458, 10506209588, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 4088, 28, 2011/12/13, 12:11:23.461, 10506216770, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.560, 10506487559, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 4088, 28, 2011/12/13, 12:11:23.614, 10506636023, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.699, 10506868577, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.701, 10506873466, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3168, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.703, 10506878746, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1060, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.705, 10506885172, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3332, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.708, 10506891851, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.710, 10506897392, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3208, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.712, 10506904589, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2108, ThreadState = Wait, ThreadWaitReason = ExecutionDelay
I, 4088, 28, 2011/12/13, 12:11:23.717, 10506915410, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3612, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.727, 10506944716, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 4092, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.728, 10506948696, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 352, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.730, 10506952405, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2168, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.732, 10506959377, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2528, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.734, 10506963334, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1176, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.735, 10506967358, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 956, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.737, 10506971344, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1672, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.739, 10506978648, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3740, ThreadState = Wait, ThreadWaitReason = ExecutionDelay
I, 4088, 28, 2011/12/13, 12:11:23.742, 10506985458, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 628, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:23.745, 10506993238, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3880, ThreadState = Wait, ThreadWaitReason = ExecutionDelay
I, 4088, 28, 2011/12/13, 12:11:23.746, 10506998169, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3360, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.749, 10507004067, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 4004, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.751, 10507009730, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3204, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.753, 10507014894, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3876, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.754, 10507019454, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3856, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.756, 10507024465, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2188, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.758, 10507028782, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.760, 10507034548, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2252, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.762, 10507040859, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3832, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.764, 10507045783, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1212, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.767, 10507054571, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3288, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.770, 10507062625, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3524, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.772, 10507067562, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3172, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.773, 10507071527, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2088, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.777, 10507081455, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3368, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.788, 10507111518, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 4012, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:11:23.790, 10507116341, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3648, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:23.791, 10507120879, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1140, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:23.794, 10507128689, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 3604, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:23.796, 10507132777, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 1156, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:23.797, 10507136719, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 2740, ThreadState = Wait, ThreadWaitReason = EventPairLow
I, 4088, 28, 2011/12/13, 12:11:24.231, 10508322449, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 692, ThreadId = 872, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 4088, 28, 2011/12/13, 12:13:32.634, 10859274209, QTAgent32.exe, Playback - < No visible child has been found - updating the collection in the container. Could be an Accessibility performance issue or incorrect GetBoundingRectangle implementation >
\0
W, 4088, 28, 2011/12/13, 12:15:54.197, 11246252754, QTAgent32.exe, Playback - [WARNING] Internal warning: Can't find anchor child after updating the collection
\0
I, 4088, 28, 2011/12/13, 12:15:57.394, 11255000193, QTAgent32.exe, Playback - < No visible child has been found - updating the collection in the container. Could be an Accessibility performance issue or incorrect GetBoundingRectangle implementation >
\0
I, 4088, 16, 2011/12/13, 12:17:08.782, CU12\QTAgent32.exe, UnitTestRunner.StopTestRun was called with 'Timeout'.
V, 4088, 16, 2011/12/13, 12:17:08.784, 11450322771, QTAgent32.exe, AL : Playback.Cancel
I, 4088, 16, 2011/12/13, 12:17:08.784, 11450324183, QTAgent32.exe, ManagedWrapper : SkipStep()
Madhu -
Wednesday, December 14, 2011 6:39 AM
Yet another trace for a timeout where the controls are available and responding, but Coded UI waits infinitely
2688, 44, 2011/12/13, 12:24:02.565, 21580898878, QTAgent32.exe, ManagedWrapper : Utility : RestoreWindowForSearching
I, 2688, 44, 2011/12/13, 12:24:02.565, 21580905508, QTAgent32.exe, GetElementFromNativeElement() : MSAA, System.Object[]
V, 2688, 44, 2011/12/13, 12:24:02.565, 21580909012, QTAgent32.exe, Msaa : GetElementFromNativeElement
V, 2688, 44, 2011/12/13, 12:24:02.565, 21580912937, QTAgent32.exe, Msaa:WindowHandleGetter: MTA Thread returned valid Window handle [7210454]
V, 2688, 44, 2011/12/13, 12:24:02.581, 21580934755, QTAgent32.exe, Msaa:WindowHandleGetter: MTA Thread returned valid Window handle [65556]
I, 2688, 44, 2011/12/13, 12:24:02.581, 21580946792, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
I, 2688, 44, 2011/12/13, 12:24:02.581, 21580968230, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
V, 2688, 44, 2011/12/13, 12:24:02.596, 21580988338, QTAgent32.exe, ManagedWrapper : Utility : RestoreWindowForSearching
I, 2688, 44, 2011/12/13, 12:24:02.596, 21580993030, QTAgent32.exe, GetElementFromNativeElement() : MSAA, System.Object[]
V, 2688, 44, 2011/12/13, 12:24:02.596, 21580996411, QTAgent32.exe, Msaa : GetElementFromNativeElement
V, 2688, 44, 2011/12/13, 12:24:02.596, 21581003652, QTAgent32.exe, Msaa:WindowHandleGetter: MTA Thread returned valid Window handle [7210454]
V, 2688, 44, 2011/12/13, 12:24:02.596, 21581023698, QTAgent32.exe, Msaa:WindowHandleGetter: MTA Thread returned valid Window handle [65556]
I, 2688, 44, 2011/12/13, 12:24:02.596, 21581033138, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
I, 2688, 44, 2011/12/13, 12:24:02.612, 21581061843, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
I, 2688, 44, 2011/12/13, 12:24:02.612, 21581085684, QTAgent32.exe, ManagedWrapper : FindScreenElement with QID:;[MSAA, VisibleOnly]ControlType='Client' && Name='Matter';[MSAA, VisibleOnly]ControlType='Edit' && Name='&Matter'
I, 2688, 44, 2011/12/13, 12:24:02.612, 21581085994, QTAgent32.exe, ManagedWrapper : ResetSkipStep()
V, 2688, 44, 2011/12/13, 12:24:02.612, 21581087326, QTAgent32.exe, QueryId : Creating QueryId from: ;[MSAA, VisibleOnly]ControlType='Client' && Name='Matter';[MSAA, VisibleOnly]ControlType='Edit' && Name='&Matter'
V, 2688, 44, 2011/12/13, 12:24:02.628, 21581094210, QTAgent32.exe, QueryId : Creating SingleQueryId from: [MSAA, VisibleOnly]ControlType='Client' && Name='Matter'
V, 2688, 44, 2011/12/13, 12:24:02.628, 21581101297, QTAgent32.exe, QueryId : Creating SingleQueryId from: [MSAA, VisibleOnly]ControlType='Edit' && Name='&Matter'
I, 2688, 44, 2011/12/13, 12:24:02.628, 21581105534, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 2688, 44, 2011/12/13, 12:24:02.628, 21581133539, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 3116, ThreadId = 2844, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 2688, 44, 2011/12/13, 12:24:03.878, 21585615392, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 2688, 44, 2011/12/13, 12:24:03.893, 21585621754, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 3116, ThreadId = 2844, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 2688, 44, 2011/12/13, 12:24:03.971, 21585946816, QTAgent32.exe, Playback - Element Found: ;[MSAA, VisibleOnly]ControlType='Client' && Name='Matter';[MSAA, VisibleOnly]ControlType='Edit' && Name='&Matter'
\0
W, 2688, 44, 2011/12/13, 12:24:03.971, 21585947517, QTAgent32.exe, PERF WARNING: FindAllDescendents: took 1357 ms. Expected it to take maximum 500 ms.
V, 2688, 44, 2011/12/13, 12:24:03.971, 21585955553, QTAgent32.exe, AL : Constructing UITestControl from screenElement: Microsoft.VisualStudio.TestTools.UITest.Playback.ScreenElement QueryId: ;[MSAA, VisibleOnly]ControlType='Client' && Name='Matter';[MSAA, VisibleOnly]ControlType='Edit' && Name='&Matter'
I, 2688, 44, 2011/12/13, 12:24:03.971, 21585956744, QTAgent32.exe, GetElementFromNativeElement() : MSAA, System.Object[]
V, 2688, 44, 2011/12/13, 12:24:03.987, 21585957029, QTAgent32.exe, Msaa : GetElementFromNativeElement
V, 2688, 44, 2011/12/13, 12:24:03.987, 21585958042, QTAgent32.exe, Msaa:WindowHandleGetter: MTA Thread returned valid Window handle [1181076]
I, 2688, 44, 2011/12/13, 12:24:03.987, 21585959396, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [1181076]
V, 2688, 44, 2011/12/13, 12:24:03.987, 21585980294, QTAgent32.exe, MsaaElement.IsWin32 = False for Element = Name [UnitializedBB839B89-49D2-4923-9F10-3C00A9902878], ControlType [Edit], NativeControlType [editable text], ClassName [WindowsForms10.Window.b.app.0.378734a], RuntimeId []
I, 2688, 44, 2011/12/13, 12:24:03.987, 21585981645, QTAgent32.exe, ConvertToMappedPluginElement
V, 2688, 44, 2011/12/13, 12:24:03.987, 21585982038, QTAgent32.exe, AL : CacheQueryId(queryId=;[MSAA, VisibleOnly]ControlType='Client' && Name='Matter';[MSAA, VisibleOnly]ControlType='Edit' && Name='&Matter')
V, 2688, 44, 2011/12/13, 12:24:03.987, 21585994760, QTAgent32.exe, Msaa:WindowHandleGetter: MTA Thread returned valid Window handle [1181076]
I, 2688, 44, 2011/12/13, 12:24:03.987, 21586004677, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [1181076]
V, 2688, 44, 2011/12/13, 12:24:04.003, 21586027630, QTAgent32.exe, MsaaElement.IsWin32 = False for Element = Name [UnitializedBB839B89-49D2-4923-9F10-3C00A9902878], ControlType [Client], NativeControlType [client], ClassName [WindowsForms10.Window.b.app.0.378734a], RuntimeId []
I, 2688, 44, 2011/12/13, 12:24:04.003, 21586028623, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
I, 2688, 44, 2011/12/13, 12:24:04.003, 21586046181, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
I, 2688, 44, 2011/12/13, 12:24:04.003, 21586065870, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [1181076]
V, 2688, 44, 2011/12/13, 12:24:04.018, 21586087706, QTAgent32.exe, MsaaElement.IsWin32 = False for Element = Name [UnitializedBB839B89-49D2-4923-9F10-3C00A9902878], ControlType [Client], NativeControlType [client], ClassName [WindowsForms10.Window.b.app.0.378734a], RuntimeId []
V, 2688, 44, 2011/12/13, 12:24:04.018, 21586100224, QTAgent32.exe, Msaa:WindowHandleGetter: MTA Thread returned valid Window handle [9569808]
I, 2688, 44, 2011/12/13, 12:24:04.018, 21586113367, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [9569808]
V, 2688, 44, 2011/12/13, 12:24:04.034, 21586134981, QTAgent32.exe, MsaaElement.IsWin32 = False for Element = Name [UnitializedBB839B89-49D2-4923-9F10-3C00A9902878], ControlType [Client], NativeControlType [client], ClassName [WindowsForms10.Window.8.app.0.378734a], RuntimeId []
I, 2688, 44, 2011/12/13, 12:24:04.034, 21586136178, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
I, 2688, 44, 2011/12/13, 12:24:04.034, 21586153619, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
I, 2688, 44, 2011/12/13, 12:24:04.034, 21586173576, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [9569808]
I, 2688, 44, 2011/12/13, 12:24:04.049, 21586195483, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [2098676]
I, 2688, 44, 2011/12/13, 12:24:04.049, 21586217913, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [8979802]
I, 2688, 44, 2011/12/13, 12:24:04.065, 21586246081, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [9963170]
I, 2688, 44, 2011/12/13, 12:24:04.065, 21586268861, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
V, 2688, 44, 2011/12/13, 12:24:04.081, 21586314451, QTAgent32.exe, AL: Setting search timeout to 120000 ms
V, 2688, 44, 2011/12/13, 12:24:04.081, 21586314794, QTAgent32.exe, PERF: AL : SearchHelper.Search: took 1516 ms.
V, 2688, 44, 2011/12/13, 12:24:04.081, 21586315064, QTAgent32.exe, AL : GetProperty, propertyName: Text
V, 2688, 44, 2011/12/13, 12:24:04.081, 21586315282, QTAgent32.exe, AL : EnsureValid()
V, 2688, 44, 2011/12/13, 12:24:04.081, 21586315647, QTAgent32.exe, AL : UITestControl.WaitForControlReady - 60000
I, 2688, 44, 2011/12/13, 12:24:04.081, 21586316380, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 2688, 44, 2011/12/13, 12:24:04.081, 21586327860, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 3116, ThreadId = 2844, ThreadState = Wait, ThreadWaitReason = UserRequest
V, 2688, 44, 2011/12/13, 12:24:04.081, 21586339539, QTAgent32.exe, AL : GetPropertyValue, propertyName: Text, ControlType: Edit
V, 2688, 44, 2011/12/13, 12:24:04.081, 21586341290, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 2688, 44, 2011/12/13, 12:24:04.081, 21586344738, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: Edit
V, 2688, 44, 2011/12/13, 12:24:04.096, 21586348182, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 2688, 44, 2011/12/13, 12:24:04.096, 21586351661, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: Edit
V, 2688, 44, 2011/12/13, 12:24:04.096, 21586355117, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 2688, 44, 2011/12/13, 12:24:04.096, 21586355379, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: Edit
V, 2688, 44, 2011/12/13, 12:24:04.096, 21586358881, QTAgent32.exe, AL : GetEditProperty, propertyName: Text
V, 2688, 44, 2011/12/13, 12:24:04.096, 21586366897, QTAgent32.exe, AL : Playback.Wait
V, 2688, 44, 2011/12/13, 12:24:05.096, 21589972556, QTAgent32.exe, AL : GetProperty, propertyName: Text
V, 2688, 44, 2011/12/13, 12:24:05.096, 21589973466, QTAgent32.exe, AL : EnsureValid()
V, 2688, 44, 2011/12/13, 12:24:05.096, 21589976808, QTAgent32.exe, AL : UITestControl.WaitForControlReady - 60000
I, 2688, 44, 2011/12/13, 12:24:05.096, 21589981003, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 2688, 44, 2011/12/13, 12:24:05.112, 21590015753, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 3116, ThreadId = 2844, ThreadState = Wait, ThreadWaitReason = UserRequest
V, 2688, 44, 2011/12/13, 12:24:05.112, 21590022194, QTAgent32.exe, AL : GetPropertyValue, propertyName: Text, ControlType: Edit
V, 2688, 44, 2011/12/13, 12:24:05.112, 21590025837, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 2688, 44, 2011/12/13, 12:24:05.112, 21590029222, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: Edit
V, 2688, 44, 2011/12/13, 12:24:05.112, 21590033452, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 2688, 44, 2011/12/13, 12:24:05.112, 21590038384, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: Edit
V, 2688, 44, 2011/12/13, 12:24:05.112, 21590039058, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 2688, 44, 2011/12/13, 12:24:05.128, 21590040992, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: Edit
V, 2688, 44, 2011/12/13, 12:24:05.128, 21590041290, QTAgent32.exe, AL : GetEditProperty, propertyName: Text
V, 2688, 44, 2011/12/13, 12:24:05.128, 21590048524, QTAgent32.exe, AL : Playback.Wait
I, 2688, 44, 2011/12/13, 12:24:06.128, 21593657681, QTAgent32.exe, GetUITestControl UIObject: ;[MSAA, VisibleOnly]ControlType='Client' && Name='Document Type';[MSAA, VisibleOnly]ControlType='Edit' && Name='Document &Type'
V, 2688, 44, 2011/12/13, 12:24:06.128, 21593661273, QTAgent32.exe, AL : FindFirstInDescendants with Qid=;[MSAA, VisibleOnly]ControlType='Client' && Name='Document Type';[MSAA, VisibleOnly]ControlType='Edit' && Name='Document &Type'
V, 2688, 44, 2011/12/13, 12:24:06.128, 21593661498, QTAgent32.exe, AL : EnsureValid()
I, 2688, 44, 2011/12/13, 12:24:06.128, 21593668143, QTAgent32.exe, ManagedWrapper : FindScreenElement with QID:;[MSAA, VisibleOnly]ControlType='Client' && Name='Document Type';[MSAA, VisibleOnly]ControlType='Edit' && Name='Document &Type'
V, 2688, 44, 2011/12/13, 12:24:06.128, 21593668416, QTAgent32.exe, ManagedWrapper : Utility : RestoreWindowForSearching
I, 2688, 44, 2011/12/13, 12:24:06.128, 21593671869, QTAgent32.exe, GetElementFromNativeElement() : MSAA, System.Object[]
V, 2688, 44, 2011/12/13, 12:24:06.143, 21593678354, QTAgent32.exe, Msaa : GetElementFromNativeElement
V, 2688, 44, 2011/12/13, 12:24:06.143, 21593682376, QTAgent32.exe, Msaa:WindowHandleGetter: MTA Thread returned valid Window handle [7210454]
V, 2688, 44, 2011/12/13, 12:24:06.143, 21593702415, QTAgent32.exe, Msaa:WindowHandleGetter: MTA Thread returned valid Window handle [65556]
I, 2688, 44, 2011/12/13, 12:24:06.143, 21593708006, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
I, 2688, 44, 2011/12/13, 12:24:06.143, 21593730045, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
V, 2688, 44, 2011/12/13, 12:24:06.159, 21593747857, QTAgent32.exe, ManagedWrapper : Utility : RestoreWindowForSearching
I, 2688, 44, 2011/12/13, 12:24:06.159, 21593751351, QTAgent32.exe, GetElementFromNativeElement() : MSAA, System.Object[]
V, 2688, 44, 2011/12/13, 12:24:06.159, 21593751351, QTAgent32.exe, Msaa : GetElementFromNativeElement
V, 2688, 44, 2011/12/13, 12:24:06.159, 21593751351, QTAgent32.exe, Msaa:WindowHandleGetter: MTA Thread returned valid Window handle [7210454]
V, 2688, 44, 2011/12/13, 12:24:06.159, 21593763990, QTAgent32.exe, Msaa:WindowHandleGetter: MTA Thread returned valid Window handle [65556]
I, 2688, 44, 2011/12/13, 12:24:06.159, 21593775039, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
I, 2688, 44, 2011/12/13, 12:24:06.174, 21593795361, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
I, 2688, 44, 2011/12/13, 12:24:06.174, 21593823753, QTAgent32.exe, ManagedWrapper : FindScreenElement with QID:;[MSAA, VisibleOnly]ControlType='Client' && Name='Document Type';[MSAA, VisibleOnly]ControlType='Edit' && Name='Document &Type'
I, 2688, 44, 2011/12/13, 12:24:06.174, 21593824037, QTAgent32.exe, ManagedWrapper : ResetSkipStep()
V, 2688, 44, 2011/12/13, 12:24:06.174, 21593828729, QTAgent32.exe, QueryId : Creating QueryId from: ;[MSAA, VisibleOnly]ControlType='Client' && Name='Document Type';[MSAA, VisibleOnly]ControlType='Edit' && Name='Document &Type'
V, 2688, 44, 2011/12/13, 12:24:06.174, 21593835630, QTAgent32.exe, QueryId : Creating SingleQueryId from: [MSAA, VisibleOnly]ControlType='Client' && Name='Document Type'
V, 2688, 44, 2011/12/13, 12:24:06.174, 21593839435, QTAgent32.exe, QueryId : Creating SingleQueryId from: [MSAA, VisibleOnly]ControlType='Edit' && Name='Document &Type'
I, 2688, 44, 2011/12/13, 12:24:06.190, 21593846806, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 2688, 44, 2011/12/13, 12:24:06.190, 21593885084, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 3116, ThreadId = 2844, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 2688, 44, 2011/12/13, 12:24:07.674, 21599156807, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 2688, 44, 2011/12/13, 12:24:07.674, 21599161348, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 3116, ThreadId = 2844, ThreadState = Wait, ThreadWaitReason = UserRequest
I, 2688, 44, 2011/12/13, 12:24:07.768, 21599492340, QTAgent32.exe, Playback - Element Found: ;[MSAA, VisibleOnly]ControlType='Client' && Name='Document Type';[MSAA, VisibleOnly]ControlType='Edit' && Name='Document &Type'
\0
W, 2688, 44, 2011/12/13, 12:24:07.768, 21599492879, QTAgent32.exe, PERF WARNING: FindAllDescendents: took 1583 ms. Expected it to take maximum 500 ms.
V, 2688, 44, 2011/12/13, 12:24:07.768, 21599500838, QTAgent32.exe, AL : Constructing UITestControl from screenElement: Microsoft.VisualStudio.TestTools.UITest.Playback.ScreenElement QueryId: ;[MSAA, VisibleOnly]ControlType='Client' && Name='Document Type';[MSAA, VisibleOnly]ControlType='Edit' && Name='Document &Type'
I, 2688, 44, 2011/12/13, 12:24:07.768, 21599501988, QTAgent32.exe, GetElementFromNativeElement() : MSAA, System.Object[]
V, 2688, 44, 2011/12/13, 12:24:07.768, 21599502272, QTAgent32.exe, Msaa : GetElementFromNativeElement
V, 2688, 44, 2011/12/13, 12:24:07.768, 21599503049, QTAgent32.exe, Msaa:WindowHandleGetter: MTA Thread returned valid Window handle [8979890]
I, 2688, 44, 2011/12/13, 12:24:07.768, 21599504260, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [8979890]
V, 2688, 44, 2011/12/13, 12:24:07.768, 21599525830, QTAgent32.exe, MsaaElement.IsWin32 = False for Element = Name [UnitializedBB839B89-49D2-4923-9F10-3C00A9902878], ControlType [Edit], NativeControlType [editable text], ClassName [WindowsForms10.Window.b.app.0.378734a], RuntimeId []
I, 2688, 44, 2011/12/13, 12:24:07.768, 21599526575, QTAgent32.exe, ConvertToMappedPluginElement
V, 2688, 44, 2011/12/13, 12:24:07.768, 21599526899, QTAgent32.exe, AL : CacheQueryId(queryId=;[MSAA, VisibleOnly]ControlType='Client' && Name='Document Type';[MSAA, VisibleOnly]ControlType='Edit' && Name='Document &Type')
V, 2688, 44, 2011/12/13, 12:24:07.768, 21599538510, QTAgent32.exe, Msaa:WindowHandleGetter: MTA Thread returned valid Window handle [8979890]
I, 2688, 44, 2011/12/13, 12:24:07.784, 21599548462, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [8979890]
V, 2688, 44, 2011/12/13, 12:24:07.784, 21599570151, QTAgent32.exe, MsaaElement.IsWin32 = False for Element = Name [UnitializedBB839B89-49D2-4923-9F10-3C00A9902878], ControlType [Client], NativeControlType [client], ClassName [WindowsForms10.Window.b.app.0.378734a], RuntimeId []
I, 2688, 44, 2011/12/13, 12:24:07.784, 21599570751, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
I, 2688, 44, 2011/12/13, 12:24:07.784, 21599588222, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
I, 2688, 44, 2011/12/13, 12:24:07.799, 21599606378, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [8979890]
V, 2688, 44, 2011/12/13, 12:24:07.799, 21599627137, QTAgent32.exe, MsaaElement.IsWin32 = False for Element = Name [UnitializedBB839B89-49D2-4923-9F10-3C00A9902878], ControlType [Client], NativeControlType [client], ClassName [WindowsForms10.Window.b.app.0.378734a], RuntimeId []
V, 2688, 44, 2011/12/13, 12:24:07.799, 21599638888, QTAgent32.exe, Msaa:WindowHandleGetter: MTA Thread returned valid Window handle [918988]
I, 2688, 44, 2011/12/13, 12:24:07.799, 21599650640, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [918988]
V, 2688, 44, 2011/12/13, 12:24:07.815, 21599671654, QTAgent32.exe, MsaaElement.IsWin32 = False for Element = Name [UnitializedBB839B89-49D2-4923-9F10-3C00A9902878], ControlType [Client], NativeControlType [client], ClassName [WindowsForms10.Window.8.app.0.378734a], RuntimeId []
I, 2688, 44, 2011/12/13, 12:24:07.815, 21599672349, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
I, 2688, 44, 2011/12/13, 12:24:07.815, 21599689907, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
I, 2688, 44, 2011/12/13, 12:24:07.815, 21599708739, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [918988]
I, 2688, 44, 2011/12/13, 12:24:07.831, 21599729500, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [2098676]
I, 2688, 44, 2011/12/13, 12:24:07.831, 21599750235, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [8979802]
I, 2688, 44, 2011/12/13, 12:24:07.846, 21599771786, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [9963170]
I, 2688, 44, 2011/12/13, 12:24:07.846, 21599792870, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [7210454]
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599836565, QTAgent32.exe, AL: Setting search timeout to 120000 ms
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599836859, QTAgent32.exe, PERF: AL : SearchHelper.Search: took 1726 ms.
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599837072, QTAgent32.exe, AL : GetProperty, propertyName: Text
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599837286, QTAgent32.exe, AL : EnsureValid()
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599837575, QTAgent32.exe, AL : UITestControl.WaitForControlReady - 60000
I, 2688, 44, 2011/12/13, 12:24:07.862, 21599838344, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 2688, 44, 2011/12/13, 12:24:07.862, 21599842774, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 3116, ThreadId = 2844, ThreadState = Wait, ThreadWaitReason = UserRequest
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599844194, QTAgent32.exe, AL : GetPropertyValue, propertyName: Text, ControlType: Edit
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599844582, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599844902, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: Edit
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599845141, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599845359, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: Edit
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599845575, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599845792, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: Edit
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599846011, QTAgent32.exe, AL : GetEditProperty, propertyName: Text
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599847681, QTAgent32.exe, AL : GetProperty, propertyName: Text
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599847902, QTAgent32.exe, AL : EnsureValid()
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599848159, QTAgent32.exe, AL : UITestControl.WaitForControlReady - 60000
I, 2688, 44, 2011/12/13, 12:24:07.862, 21599848939, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 2688, 44, 2011/12/13, 12:24:07.862, 21599852800, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 3116, ThreadId = 2844, ThreadState = Wait, ThreadWaitReason = UserRequest
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599853211, QTAgent32.exe, AL : GetPropertyValue, propertyName: Text, ControlType: Edit
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599853586, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599853856, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: Edit
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599854089, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599854300, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: Edit
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599854524, QTAgent32.exe, AL : GetProperty, propertyName: ControlType
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599854732, QTAgent32.exe, AL : GetPropertyValue, propertyName: ControlType, ControlType: Edit
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599854956, QTAgent32.exe, AL : GetEditProperty, propertyName: Text
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599856704, QTAgent32.exe, AL : GetProperty, propertyName: HasFocus
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599856933, QTAgent32.exe, AL : EnsureValid()
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599857147, QTAgent32.exe, AL : UITestControl.WaitForControlReady - 60000
I, 2688, 44, 2011/12/13, 12:24:07.862, 21599857814, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >\0
I, 2688, 44, 2011/12/13, 12:24:07.862, 21599861570, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 3116, ThreadId = 2844, ThreadState = Wait, ThreadWaitReason = UserRequest
V, 2688, 44, 2011/12/13, 12:24:07.862, 21599862020, QTAgent32.exe, AL : GetPropertyValue, propertyName: HasFocus, ControlType: Edit
I, 2688, 44, 2011/12/13, 12:24:07.862, 21599862568, QTAgent32.exe, GetFocusedElement()
I, 2688, 44, 2011/12/13, 12:24:07.862, 21599862789, QTAgent32.exe, Msaa.GetFocusedElement
I, 2688, 44, 2011/12/13, 12:24:07.862, 21599863013, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [0]
E, 2688, 44, 2011/12/13, 12:24:07.862, 21599863312, QTAgent32.exe, Msaa.GetFocusedElement: could not find accessible object of foreground window
I, 2688, 44, 2011/12/13, 12:24:07.862, 21599863536, QTAgent32.exe, Msaa.GetFocusedElement - Returning element from GetFocus().
I, 2688, 44, 2011/12/13, 12:24:07.862, 21599863742, QTAgent32.exe, Calling GetFocusedElementUsingThread() as WinEvent failed to get focused element
I, 2688, 44, 2011/12/13, 12:24:07.862, 21599863973, QTAgent32.exe, GetFocusedElementUsingThread()
I, 2688, 44, 2011/12/13, 12:24:07.862, 21599864337, QTAgent32.exe, Msaa.GetFocusedElement
I, 2688, 44, 2011/12/13, 12:24:07.862, 21599864552, QTAgent32.exe, Msaa.AccWrapperFromWindow: window handle [1640056]
I, 2688, 45, 2011/12/13, 12:32:14.715, WINXP-VIJAY2010\QTAgent32.exe, UnitTestRunner.StopTestRun was called with 'Timeout'.
V, 2688, 45, 2011/12/13, 12:32:14.731, 23342598328, QTAgent32.exe, AL : Playback.Cancel
I, 2688, 45, 2011/12/13, 12:32:14.731, 23342599410, QTAgent32.exe, ManagedWrapper : SkipStep()
Madhu -
Monday, January 16, 2012 4:52 AM
I have a couple of more questions related to this. If a test case times out will the TestCleanup be executed? I set a static variable of type UnitTestOutcome in the test cleanup and check for it in the test setup so that the next test case would know if the previous test case was a time out. And if it is a timeout, I do the following
if (PreviousTestOutcome == UnitTestOutcome.Timeout) { Playback.StopSession(); KillOutlookAndDMProcesses(); System.Threading.Thread.Sleep(TimeSpan.FromSeconds(5)); Playback.StartSession(); Playback.Wait(5000); LaunchOutlookAndLoginToDM(); }
But the control comes into this block only for the 3rd or 4th test case after the timed out test case. The reason I am doing this is because after a timed out test case the following test cases fail saying that "The Coded UI Test is running in Single Thread Apartment (STA) mode of COM. In this mode, all the playback calls should happen from the TestMethod thread only and UITestControl should not be shared across TestMethods." Can someone please help me on this. I have been facing this issue for quite some time and haven't received any solution or workarounds yet.
Madhu
