.net 4.0 - MSTest hangs for seemingly no reason -
<tldr>
running mstest test command line hangs without errors or timeouts whilst "waiting runs/agents". reason might "there no runs in queue", why have no idea, because exact same test runs fine on machine.
</tldr>
we've moved evaluating teamcity on test machine, installing in our production environment. after migrating of our build configurations got problems our mstest tests: none run.
after debugging our way through can think of, think have ruled out teamcity. we're left believing directly mstest. simple way reproduce our issue, i've created test solution mstesttest(c# 4.0) in visual studio.
it has 1 project mstesttest single class class1:
namespace mstesttest { public static class class1 { public static string foo() { return "bar"; } } } it has project mstesttesttest single mstest test class unittest1:
using mstesttest; using microsoft.visualstudio.testtools.unittesting; namespace mstesttesttest { [testclass] public class unittest1 { [testmethod] public void testmethod1() { assert.areequal("bar", class1.foo()); } } } the solution compiled , copy 2 dlls (mstesttest.dll , mstesttesttest.dll) our old test server , our new production server. on both servers i've edited mstest.exe.config file write verbose logging information c:\temp\mstesttrace.log (as described here).
on both test server , production server run tests command line so:
mstest /testcontainer:mstesttesttest.dll /resultsfile:results.trx on test server successful test result straight away:
c:\temp\mstesttesttest>mstest /testcontainer:mstesttesttest.dll /resultsfile:results.trx microsoft (r) test execution command line tool version 10.0.30319.1 copyright (c) microsoft corporation. rights reserved. loading mstesttesttest.dll... starting execution... results top level tests ------- --------------- passed mstesttesttest.unittest1.testmethod1 1/1 test(s) passed summary ------- test run completed. passed 1 --------- total 1 results file: c:\temp\mstesttesttest\results.trx test settings: default test settings on production server however, this:
c:\temp\mstesttesttest>mstest /testcontainer:mstesttesttest.dll /resultsfile:results.trx microsoft (r) test execution command line tool version 10.0.30319.1 copyright (c) microsoft corporation. rights reserved. loading mstesttesttest.dll... starting execution... i've left server running hours, nothing happens. no timeout, no errors, no nothing. @ point i'm stuck continue.
here excerpt trace log on test server (full log can seen here (from different, identical run)):
15:02:39.525, testagentprocessready: total # of execution agents=1. 15:02:39.525, controllerexecution.testagentprocessready: areallagentprocessesready=true. 15:02:39.525, backgroundjobprocessor<microsoft.visualstudio.testtools.controller.receivedtestmessagewrapper>(controllerexecution.testmessagereceiver)+externaljob.processjob: invoked job processor job 'receivedtestmessagewrapper test message 'microsoft.visualstudio.testtools.execution.testagentprocessstartedmessage' agent 'trutvbygg01'' 15:02:39.634, controllerobject: runqueuethread waiting runs/agents... 15:02:39.744, agentprocessmanager.starttestagentrun_dowork: tests queued test agents. 15:02:39.744, controllerexecution.syncallexecutionagentsready: finished waiting on m_agentprocessesinitialized: signaledindex=0 15:02:39.744, statemachine(runstate): setnextstate started called 15:02:39.744, statemachine(runstate): in state started. waiting state change... 15:02:39.744, statemachine(runstate): exit wait state change, current state started. 15:02:39.744, statemachine(runstate): calling state handler started 15:02:39.744, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: invoking special job checker job 'trutvbygg01: run {9363144a-38a7-4ee1-a920-1e1a3584859b}: started' 15:02:39.744, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: invoked special job checker job 'trutvbygg01: run {9363144a-38a7-4ee1-a920-1e1a3584859b}: started' 15:02:39.744, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: isspecial = false 15:02:39.744, backgroundjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: queuing job 'type microsoft.visualstudio.testtools.common.runstateevent: trutvbygg01: run {9363144a-38a7-4ee1-a920-1e1a3584859b}: started' 15:02:39.744, controllerobject: runstartedhandler called run 9363144a-38a7-4ee1-a920-1e1a3584859b 15:02:39.744, backgroundjobprocessor<microsoft.visualstudio.testtools.execution.controllerqueueentry>(controllerobject.runqueuemessageprocessor).tryenqueuejob: queuing job 'type microsoft.visualstudio.testtools.execution.controllerqueueentry: microsoft.visualstudio.testtools.execution.controllerqueueentry' 15:02:39.744, statemachine(runstate): setnextstate running called 15:02:39.744, statemachine(runstate): in state running. waiting state change... 15:02:39.744, statemachine(runstate): exit wait state change, current state running. 15:02:39.744, statemachine(runstate): calling state handler running 15:02:39.744, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: invoking special job checker job 'trutvbygg01: run {9363144a-38a7-4ee1-a920-1e1a3584859b}: running' 15:02:39.744, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: invoked special job checker job 'trutvbygg01: run {9363144a-38a7-4ee1-a920-1e1a3584859b}: running' 15:02:39.744, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: isspecial = false 15:02:39.744, backgroundjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: queuing job 'type microsoft.visualstudio.testtools.common.runstateevent: trutvbygg01: run {9363144a-38a7-4ee1-a920-1e1a3584859b}: running' 15:02:39.744, statemachine(runstate): in state running. waiting state change... 15:02:39.744, backgroundjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender)+externaljob.processjob: invoking job processor job 'trutvbygg01: run {9363144a-38a7-4ee1-a920-1e1a3584859b}: started' 15:02:39.744, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(localrunmessagelistener.testmessagereceiver).tryenqueuejob: invoking special job checker job 'microsoft.visualstudio.testtools.common.testmessagebulk' 15:02:39.744, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(localrunmessagelistener.testmessagereceiver).tryenqueuejob: invoked special job checker job 'microsoft.visualstudio.testtools.common.testmessagebulk' 15:02:39.744, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(localrunmessagelistener.testmessagereceiver).tryenqueuejob: isspecial = false 15:02:39.744, backgroundjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(localrunmessagelistener.testmessagereceiver).tryenqueuejob: queuing job 'type microsoft.visualstudio.testtools.common.testmessagebulk: microsoft.visualstudio.testtools.common.testmessagebulk' 15:02:39.744, backgroundjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender)+externaljob.processjob: invoked job processor job 'trutvbygg01: run {9363144a-38a7-4ee1-a920-1e1a3584859b}: started' 15:02:39.744, backgroundjobprocessor<microsoft.visualstudio.testtools.execution.controllerqueueentry>(controllerobject.runqueuemessageprocessor)+externaljob.processjob: invoking job processor job 'microsoft.visualstudio.testtools.execution.controllerqueueentry' 15:02:39.744, backgroundjobprocessor<microsoft.visualstudio.testtools.execution.controllerqueueentry>(controllerobject.runqueuemessageprocessor)+externaljob.processjob: invoked job processor job 'microsoft.visualstudio.testtools.execution.controllerqueueentry' 15:02:39.744, backgroundjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(localrunmessagelistener.testmessagereceiver)+externaljob.processjob: invoking job processor job 'microsoft.visualstudio.testtools.common.testmessagebulk' 15:02:39.744, localrunmessagelistener.onprocessreceivedtestmessage: handling message 'trutvbygg01: run {9363144a-38a7-4ee1-a920-1e1a3584859b}: started' 15:02:39.744, localrunmessagelistener: restarttimer 15:02:39.744, localrunmessagelistener.onprocessreceivedtestmessage: handling message 'trutvbygg01: run {9363144a-38a7-4ee1-a920-1e1a3584859b}: running' 15:02:39.744, localrunmessagelistener: restarttimer 15:02:39.744, backgroundjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(localrunmessagelistener.testmessagereceiver)+externaljob.processjob: invoked job processor job 'microsoft.visualstudio.testtools.common.testmessagebulk' 15:02:39.900, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.controller.receivedtestmessagewrapper>(controllerexecution.testmessagereceiver).tryenqueuejob: invoking special job checker job 'receivedtestmessagewrapper test message 'run {9363144a-38a7-4ee1-a920-1e1a3584859b}, test {854d1b23-760d-4e32-a6c7-91b74b5f2409}: started' agent 'trutvbygg01'' 15:02:39.900, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.controller.receivedtestmessagewrapper>(controllerexecution.testmessagereceiver).tryenqueuejob: invoked special job checker job 'receivedtestmessagewrapper test message 'run {9363144a-38a7-4ee1-a920-1e1a3584859b}, test {854d1b23-760d-4e32-a6c7-91b74b5f2409}: started' agent 'trutvbygg01'' 15:02:39.900, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.controller.receivedtestmessagewrapper>(controllerexecution.testmessagereceiver).tryenqueuejob: isspecial = false 15:02:39.900, backgroundjobprocessor<microsoft.visualstudio.testtools.controller.receivedtestmessagewrapper>(controllerexecution.testmessagereceiver).tryenqueuejob: queuing job 'type microsoft.visualstudio.testtools.controller.receivedtestmessagewrapper: receivedtestmessagewrapper test message 'run {9363144a-38a7-4ee1-a920-1e1a3584859b}, test {854d1b23-760d-4e32-a6c7-91b74b5f2409}: started' agent 'trutvbygg01'' 15:02:39.900, backgroundjobprocessor<microsoft.visualstudio.testtools.controller.receivedtestmessagewrapper>(controllerexecution.testmessagereceiver)+externaljob.processjob: invoking job processor job 'receivedtestmessagewrapper test message 'run {9363144a-38a7-4ee1-a920-1e1a3584859b}, test {854d1b23-760d-4e32-a6c7-91b74b5f2409}: started' agent 'trutvbygg01'' 15:02:39.900, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: invoking special job checker job 'run {9363144a-38a7-4ee1-a920-1e1a3584859b}, test {854d1b23-760d-4e32-a6c7-91b74b5f2409}: started' 15:02:39.900, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: invoked special job checker job 'run {9363144a-38a7-4ee1-a920-1e1a3584859b}, test {854d1b23-760d-4e32-a6c7-91b74b5f2409}: started' 15:02:39.900, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: isspecial = false 15:02:39.900, backgroundjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: queuing job 'type microsoft.visualstudio.testtools.common.teststateevent: run {9363144a-38a7-4ee1-a920-1e1a3584859b}, test {854d1b23-760d-4e32-a6c7-91b74b5f2409}: started' 15:02:39.900, backgroundjobprocessor<microsoft.visualstudio.testtools.controller.receivedtestmessagewrapper>(controllerexecution.testmessagereceiver)+externaljob.processjob: invoked job processor job 'receivedtestmessagewrapper test message 'run {9363144a-38a7-4ee1-a920-1e1a3584859b}, test {854d1b23-760d-4e32-a6c7-91b74b5f2409}: started' agent 'trutvbygg01'' 15:02:39.900, backgroundjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender)+externaljob.processjob: invoking job processor job 'run {9363144a-38a7-4ee1-a920-1e1a3584859b}, test {854d1b23-760d-4e32-a6c7-91b74b5f2409}: started' 15:02:39.900, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(localrunmessagelistener.testmessagereceiver).tryenqueuejob: invoking special job checker job 'run {9363144a-38a7-4ee1-a920-1e1a3584859b}, test {854d1b23-760d-4e32-a6c7-91b74b5f2409}: started' and here similar excerpt production server (full log can seen here (from different, identical run)), showing things start hang:
16:33:50.260, testagentprocessready: total # of execution agents=1. 16:33:50.260, controllerexecution.testagentprocessready: areallagentprocessesready=true. 16:33:50.260, backgroundjobprocessor<microsoft.visualstudio.testtools.controller.receivedtestmessagewrapper>(controllerexecution.testmessagereceiver)+externaljob.processjob: invoked job processor job 'receivedtestmessagewrapper test message 'microsoft.visualstudio.testtools.execution.testagentprocessstartedmessage' agent 'trapputvtcp01'' 16:33:50.292, agentprocessmanager.starttestagentrun_dowork: tests queued test agents. 16:33:50.292, controllerexecution.syncallexecutionagentsready: finished waiting on m_agentprocessesinitialized: signaledindex=0 16:33:50.292, statemachine(runstate): setnextstate started called 16:33:50.292, statemachine(runstate): in state started. waiting state change... 16:33:50.292, statemachine(runstate): exit wait state change, current state started. 16:33:50.292, statemachine(runstate): calling state handler started 16:33:50.292, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: invoking special job checker job 'trapputvtcp01: run {453f4093-9409-40f3-9651-34caa1b8c92a}: started' 16:33:50.292, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: invoked special job checker job 'trapputvtcp01: run {453f4093-9409-40f3-9651-34caa1b8c92a}: started' 16:33:50.292, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: isspecial = false 16:33:50.292, backgroundjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: queuing job 'type microsoft.visualstudio.testtools.common.runstateevent: trapputvtcp01: run {453f4093-9409-40f3-9651-34caa1b8c92a}: started' 16:33:50.292, controllerobject: runstartedhandler called run 453f4093-9409-40f3-9651-34caa1b8c92a 16:33:50.292, backgroundjobprocessor<microsoft.visualstudio.testtools.execution.controllerqueueentry>(controllerobject.runqueuemessageprocessor).tryenqueuejob: queuing job 'type microsoft.visualstudio.testtools.execution.controllerqueueentry: microsoft.visualstudio.testtools.execution.controllerqueueentry' 16:33:50.292, statemachine(runstate): setnextstate running called 16:33:50.292, statemachine(runstate): in state running. waiting state change... 16:33:50.292, backgroundjobprocessor<microsoft.visualstudio.testtools.execution.controllerqueueentry>(controllerobject.runqueuemessageprocessor)+externaljob.processjob: invoking job processor job 'microsoft.visualstudio.testtools.execution.controllerqueueentry' 16:33:50.292, backgroundjobprocessor<microsoft.visualstudio.testtools.execution.controllerqueueentry>(controllerobject.runqueuemessageprocessor)+externaljob.processjob: invoked job processor job 'microsoft.visualstudio.testtools.execution.controllerqueueentry' 16:33:50.292, statemachine(runstate): exit wait state change, current state running. 16:33:50.292, statemachine(runstate): calling state handler running 16:33:50.292, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: invoking special job checker job 'trapputvtcp01: run {453f4093-9409-40f3-9651-34caa1b8c92a}: running' 16:33:50.292, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: invoked special job checker job 'trapputvtcp01: run {453f4093-9409-40f3-9651-34caa1b8c92a}: running' 16:33:50.292, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: isspecial = false 16:33:50.292, backgroundjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender).tryenqueuejob: queuing job 'type microsoft.visualstudio.testtools.common.runstateevent: trapputvtcp01: run {453f4093-9409-40f3-9651-34caa1b8c92a}: running' 16:33:50.292, statemachine(runstate): in state running. waiting state change... 16:33:50.292, backgroundjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender)+externaljob.processjob: invoking job processor job 'trapputvtcp01: run {453f4093-9409-40f3-9651-34caa1b8c92a}: started' 16:33:50.292, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(localrunmessagelistener.testmessagereceiver).tryenqueuejob: invoking special job checker job 'microsoft.visualstudio.testtools.common.testmessagebulk' 16:33:50.307, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(localrunmessagelistener.testmessagereceiver).tryenqueuejob: invoked special job checker job 'microsoft.visualstudio.testtools.common.testmessagebulk' 16:33:50.307, backgroundspecialjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(localrunmessagelistener.testmessagereceiver).tryenqueuejob: isspecial = false 16:33:50.307, backgroundjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(localrunmessagelistener.testmessagereceiver).tryenqueuejob: queuing job 'type microsoft.visualstudio.testtools.common.testmessagebulk: microsoft.visualstudio.testtools.common.testmessagebulk' 16:33:50.307, backgroundjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(controllerexecution.testmessagesender)+externaljob.processjob: invoked job processor job 'trapputvtcp01: run {453f4093-9409-40f3-9651-34caa1b8c92a}: started' 16:33:50.307, backgroundjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(localrunmessagelistener.testmessagereceiver)+externaljob.processjob: invoking job processor job 'microsoft.visualstudio.testtools.common.testmessagebulk' 16:33:50.307, localrunmessagelistener.onprocessreceivedtestmessage: handling message 'trapputvtcp01: run {453f4093-9409-40f3-9651-34caa1b8c92a}: started' 16:33:50.307, localrunmessagelistener: restarttimer 16:33:50.307, localrunmessagelistener.onprocessreceivedtestmessage: handling message 'trapputvtcp01: run {453f4093-9409-40f3-9651-34caa1b8c92a}: running' 16:33:50.307, localrunmessagelistener: restarttimer 16:33:50.307, backgroundjobprocessor<microsoft.visualstudio.testtools.common.testmessage>(localrunmessagelistener.testmessagereceiver)+externaljob.processjob: invoked job processor job 'microsoft.visualstudio.testtools.common.testmessagebulk' 16:33:50.401, controllerobject: runqueuethread there no runs in queue. 16:33:50.510, controllerobject: runqueuethread waiting runs/agents... 16:34:10.291, localrunmessagelistener: restarttimer 16:34:10.291, controllerexecution: sent heartbeat listeners 16:34:30.321, localrunmessagelistener: restarttimer 16:34:30.321, controllerexecution: sent heartbeat listeners 16:34:50.352, localrunmessagelistener: restarttimer 16:34:50.352, controllerexecution: sent heartbeat listeners 16:35:10.382, localrunmessagelistener: restarttimer 16:35:10.382, controllerexecution: sent heartbeat listeners 16:35:30.412, localrunmessagelistener: restarttimer 16:35:30.412, controllerexecution: sent heartbeat listeners 16:35:50.443, localrunmessagelistener: restarttimer i've tried running command prompt i'm running mstest administrator, didn't seem make difference.
any suggestion regarding next step should welcome!
the problem because of bug mstest when visual studio 2010 , visual studio 2012 installed side side. solution install service pack 1 visual studio 2010.
i came realize looking in windows logs > applications in event viewer. there found error source vsttagentprocess (which hadn't been present in of mstest trace logs had been looking through):
(qtagent32.exe, pid 6912, thread 9) agentobject.onbackgroundsendtestmessage: connection controller lost. system.runtime.remoting.remotingexception: argument type 'run {b816a0d9-50f3-490a-96b8-479555466167}, test {8a2710b4-3cf9-441c-bd5c-0efb0601e059}: started' cannot converted parameter type 'microsoft.visualstudio.testtools.common.testmessage'. ---> system.invalidcastexception: object must implement iconvertible. @ system.convert.changetype(object value, type conversiontype, iformatprovider provider) @ system.runtime.remoting.messaging.message.coercearg(object value, type pt) --- end of inner exception stack trace --- googling exception led me this post explaining vs 2010/2012 issue.
it worth mentioning had install microsoft office developer tools before able install vs2010 sp1.
Comments
Post a Comment