Capturing output written to TestContext

Jun 20, 2011 at 6:47 PM

I'd like to be able to capture the output written to the TestContext using TextContext.WriteLine.  I looked at the source, but I had some trouble building (we need to use the self-hosted browser, but the self-hosted browser opens IE 64, and IE 64 can't seem to handle Silverlight...).  TestContext is abstract class and it looks like at one point Statlight instantiated a UnitTestContext (StatLight.Client.Harness.MSTest\UnitTestProviders\MSTest\TestMethod.cs), but doesn't anymore.

Is there any way to use a TestContext that I've written?

(Essentially I want to be able to capture all the output and do some processing on it.  Statlight currently prints the output to the console like this:


Message=My output text here, which could be multiple lines

So, can I use my own TestContext / how do I get the output as it is sent to TestContext.WriteLine?

- Mike

Jun 20, 2011 at 8:13 PM

Hello MikeBenza,

To Build: You need to make sure VS has selected the x86 platform when you try to do a build of StatLight. Also, due to the complexities of the StatLight build process, most/all builds are done through the psake powershell builds (use build-debug.bat or build-full-release.bat).

I rarely use MSTest myself and wasn't aware of the TestContext.WriteLine. Do you need to be able to tie the message written to a specific test? (i'm guessing so)... I have some thoughts, but need to dig in a bit and look at some things. Will get back to you. Or if you can get a build yourself, feel free to splunk through the code.

Jun 20, 2011 at 10:41 PM

Yes, we do need to tie the message to a specific for digging into the code myself, I'm trying to see where the test context is created, but I can't seem to find it.

Jun 21, 2011 at 4:01 AM
Edited Jun 21, 2011 at 4:03 AM

Go checkout a change I made and pushed to

The output of the TestContext.WriteLine() will append it to the "metadata" collection in the StatLight xml file.





    <test name="StatLight.IntegrationTests.Silverlight.MSTestTests.Should_be_able_to_write_to_the_TestContext" resulttype="Passed" timeToComplete="00:00:00.0290017">
        <metaData classification="TestContextWriteMethod" name="TestContextWriteMethod">Hello From a Test 1</metaData>
        <metaData classification="TestContextWriteMethod" name="TestContextWriteMethod">Hello From a Test 2</metaData>
        <metaData classification="TestContextWriteMethod" name="TestContextWriteMethod">Hello From a Test 3</metaData>



How does this look? (FYI: I have some integration tests to cleanup before this can become completely buildable - but you can use the build-full-skip tests bat file)

Jun 22, 2011 at 4:56 AM
Edited Jun 22, 2011 at 4:59 AM

It looks great!  The only catch is that it doesn't seem to be ordering them correctly.  Although it seems like the ClientEventOrder should sequence it correctly, it doesn't.  I wish I could tell you why, but I didn't look into it.  I added my own Sequence field to TestContextMessageClientEvent and sorted on that in TestResultAggregator.OnTestCaseResultCreated().  The sequence stored in TestMethod and is incremented using Interlocked.Increment.  At the call to AppendTestContextMetaData in TestResultAggregator.cs, I wrote out to the console a line to document the discrepancy.  I've highlighted the out of order ones.

Appending data for sequence number 0, ClientEventOrder 94
Appending data for sequence number 1, ClientEventOrder 95
Appending data for sequence number 2, ClientEventOrder 96
Appending data for sequence number 3, ClientEventOrder 97
Appending data for sequence number 4, ClientEventOrder 98
Appending data for sequence number 5, ClientEventOrder 99
Appending data for sequence number 6, ClientEventOrder 100
Appending data for sequence number 7, ClientEventOrder 101
Appending data for sequence number 8, ClientEventOrder 102
Appending data for sequence number 9, ClientEventOrder 103
Appending data for sequence number 10, ClientEventOrder 104
Appending data for sequence number 11, ClientEventOrder 106
Appending data for sequence number 12, ClientEventOrder 105
Appending data for sequence number 13, ClientEventOrder 107
Appending data for sequence number 14, ClientEventOrder 108
Appending data for sequence number 15, ClientEventOrder 110
Appending data for sequence number 16, ClientEventOrder 109
Appending data for sequence number 17, ClientEventOrder 112
Appending data for sequence number 18, ClientEventOrder 119
Appending data for sequence number 19, ClientEventOrder 111
Appending data for sequence number 20, ClientEventOrder 113
Appending data for sequence number 21, ClientEventOrder 114
Appending data for sequence number 22, ClientEventOrder 141
Appending data for sequence number 23, ClientEventOrder 139
Appending data for sequence number 24, ClientEventOrder 140

I double checked that the lines sequenced with my Sequence field is correct and the lines sequenced with CilentEventOrder are actually out of order.  Any idea why the ClientEventOrder isn't sequencing correctly, but mine is (they both use Interlocked.Increment). 

Jun 23, 2011 at 5:57 AM

I've reproduced your event ordering issue. The base class event order property was something I put in there when I originally designed the base event structure, but never actually used the order property (which is why I never saw the mis-ordering issue).

I was able to get a version to work where I can print 100 lines successfully (in order).

Take a look and let me know...

Jun 23, 2011 at 3:09 PM

I don't see your changes...just one to fix up tests.

Jun 23, 2011 at 4:13 PM

Hmmm... I'll have to double check this evening - my git push must not have worked.

Jun 23, 2011 at 7:30 PM

Ok, NOW I've pushed the code up... (if you're a git user - fyi: I rebased a small change so co a clean pull of code to try it)

Jun 23, 2011 at 10:53 PM

Looks good!  Thank you so much.

I'm not a git user.  I've used Perforce, TFS, and Subversion.  No git yet, but I'm sure I'll get to it eventually.

- Mike

Jun 25, 2011 at 3:52 PM

I've merged the branch into master. You should be able to download a build from the teamcity server (if you wish). There's a link to teamcity on the StatLight home page.

Jul 8, 2011 at 6:03 PM

I've found a bug in StatLight.Client.Harness.MSTest\UnitTestProviders\MSTest\TestMethod.cs.  The getter for StatlightTestContext.Properties should have a null check on _testMethod.Properties.  I've fixed it in my local build, but I can't get the build scripts to produce the output on the bleeding edge build.  How do I do that?

Jul 8, 2011 at 7:22 PM

You should be able to run the release build bat files. Are you seeing errors there?

Jul 8, 2011 at 8:30 PM

I ran those, but it produced a lot of extra files (Microsoft.Silverlight.Testing.dll, Microsoft.VisiaulStudio.QualityTools.UnitTesting.Silverlight.dll, nunit.framework.dll, Statlight.Client.For.______.Integration-SL3/4.xap, Statlight.Client.Harness.MSTEst.dll, Statlight.Core.dll.config, and Statlight.exe.config)

I wasn't sure if the Integration XAPs were integration tests or something else.  Also, I was confused by there being a Statlight.Client.Harness.MSTest.dll when there wasn't before.

Jul 8, 2011 at 9:40 PM

The XML output is ordered correctly now, but the console output is still not ordered correctly. Could you get both to be in order?

Jul 8, 2011 at 10:38 PM
Edited Jul 8, 2011 at 10:40 PM

MikeBenza - When you do a release build a .\Release\** folder is created - that has all the goodies (without the integration stuff).

AdamKemp - why do you care what the console output looks like? If you're not looking to read it out of the XML and only want to see it during development (possibly doing printf style debugging) just use Console.WriteLine(...).  (P.S. I'm not trying to be difficult - just trying to understand the use-case)

Hope this helps.

Jul 9, 2011 at 8:34 AM

The console output is easier to quickly munge in a text editor or script to pull out useful information. Parsing XML is much more difficult. I'm talking about cases where I just want some one-off test run and pull some data into Excel. I'm not going to write an XML parser just for that, and I don't want to have to modify my tests either if I can help it. If there's useful output on the console already, and all the data I want is there, then I want to just use that. Unfortunately, it's not in a reliable order, and it also doesn't even tell me which test each piece of output belongs to, so that console output is practically useless right now. If it included the test name and was output in the right order then it would actually be useful.


While I'm at it, it would also be nice if the tests ran in the order listed in the --MethodsToTest command line option.

Jul 11, 2011 at 9:07 PM

- AdamKemp

The console output is not really intended to be scraped. Not that I'm against you doing it, there are a number of issues with this. For one, the SL testing framework runs many work items asynchronously, and therefore timing/order are a difficult to truly get right with this. On top of that the even messages sent from the browser host down to the StatLight server is another set of asynchronous events, making the order/timing just that much harder to get things together.

The fact that you see the output of a context.WriteLine(...) call is actually an inherit leftover from when I designed the messaging. When a message was unknown to the server it would dump it to the console. Which is why you see the messages being dumped to the console (out of order in some cases).

There are a couple options for you.

1. Fork the project, and see if you can re-order how these are printed to the console

2. Write a plugin that does what you need -

3. Write something to read the xml (I'd recommend powershell - it's fantastic at reading xml).

4. Try using Console.WriteLine instead as it will be less prone to the async issues.

Hope this helps,