Why some of vstest events aren't raised?

Question

I created simple vstestlogger by implementing ITestLogger interface from the Microsoft.VisualStudio.TestPlatform.ObjectModel.Client. But I can't handle some of events (for example TestRunMessage). This is my simple logger.

[ExtensionUri("logger://SimpleLogger")]
    [FriendlyName("SimpleLogger")]
    public class SimpleLogger : ITestLogger
    {
        public void Initialize(TestLoggerEvents events, string testRunDirectory)
        {
            events.TestRunMessage += TestRunMessageHandler;
            events.TestResult += TestResultHandler; 
            events.TestRunComplete += TestRunCompleteHandler; 
            events.TestRunStart += TestRunStartHandler; 
            events.DiscoveredTests += DiscoveredTestsHandler;
            events.DiscoveryMessage += DiscoveryMessageHandler;
            events.DiscoveryComplete += DiscoveryCompleteHandler;
            events.DiscoveryStart += DiscoveryStart;
        }

        private void TestRunStartHandler(object sender, TestRunStartEventArgs e)
        {
            Console.WriteLine("TestRunStartHandler");
        }

        private void DiscoveredTestsHandler(object sender, DiscoveredTestsEventArgs e)
        {
            Console.WriteLine("DiscoveredTests");
        }

        private void DiscoveryMessageHandler(object sender, TestRunMessageEventArgs e)
        {
            Console.WriteLine("DiscoveryMessage");
        }

        private void DiscoveryCompleteHandler(object sender, DiscoveryCompleteEventArgs e)
        {
            Console.WriteLine("DiscoveryComplete");
        }

        private void DiscoveryStart(object sender, DiscoveryStartEventArgs e)
        {
            Console.WriteLine("DiscoveryStart");
        }

        /// <summary>
        /// Called when a test message is received.
        /// </summary>
        private void TestRunMessageHandler(object sender, TestRunMessageEventArgs e)
        {
            Console.WriteLine("TestRunMessage");
        }

        /// <summary>
        /// Called when a test result is received.
        /// </summary>
        private void TestResultHandler(object sender, TestResultEventArgs e)
        {
            Console.WriteLine("TestResult");
        }

        /// <summary>
        /// Called when a test run is completed.
        /// </summary>
        private void TestRunCompleteHandler(object sender, TestRunCompleteEventArgs e)
        {
            Console.WriteLine("TestRunComplete");
        }
    }

I can catch only three events: TestRunStart (which raised once before running all tests), TestResult (which raised after each test), TestRunComplete (which raised after all tests). I can't handle anything else. I don't see the console output from other handlers. How can I handle the start of the test?

Answer 1

Not an expert here but I took a very quick glance over the sources of vstest on Github and guessing from the fact that vstest uses plugins or "agents" that discover and execute the tests, and from https://github.com/Microsoft/vstest/blob/21723abbc390609fd4f45853de32636d3830fe75/src/Microsoft.TestPlatform.Client/Execution/TestRunRequest.cs lines 163-166 I think that there is no direct clean way to it.

I think that "testRunCriteria" in line 166 are sent to the agent and that the accompaning event of started/pending/completed refer the the whole batch of the tests executed inside the agent. Later the agent returns summary with specific results and it's all to it.

You probably could work around it by chosing narrow criteria to eliminate batching and execute tests one by one. This way tracking agent job would be equal to tracking single test.. but probaby that would result in the tests being run much slower.

Another way I can think of is the Test-Message handler. Each 'message' sent bears a level (info/warning/error/..), and there's a high chance that starting each specific test from batch is reported as some kind of "Starting test xyz" message with level of i.e. 'Info'.

I searched for such a message and I think I found something related in the same file, in event hander for TestRunChangedEventArgs, lines 487-494:

// Do verbose check to save perf in iterating test cases
if (EqtTrace.IsVerboseEnabled)
{
    foreach (TestCase testCase in testRunChangedArgs.ActiveTests)
    {
        EqtTrace.Verbose("InProgress is {0}", testCase.DisplayName);
    }
}
// ....
this.LoggerManager.HandleTestRunStatsChange(testRunChangedArgs)

The TestRunChangedEventArgs hold ActiveTests and that seems to be the list of currently executed tests. testCase.DisplayName hints that. It seems the event is forwarder further via LoggerManager (ITestLoggerManager) which seems more-or-less related to the ITestLogger you're implementing.

Here's relevant file for the LoggerManager: https://github.com/Microsoft/vstest/blob/2cee46f833fc73304b6cb4952bf1ac1fc240a1a6/src/Microsoft.TestPlatform.CrossPlatEngine/Client/TestLoggerManager.cs lines 216-228:

    public void HandleTestRunStatsChange(TestRunChangedEventArgs e)
    {
        // ....
        foreach (TestResult result in e.NewTestResults)
        {
            this.loggerEvents.RaiseTestResult(new TestResultEventArgs(result));
        }
    }

loggerEvents seem to be wrapper around events you are now inspecting. So, well, uh, it seems that LoggerManager gets the complete information in form of that TestRunChangedEventArgs, but it seems to only care about completed tests. No other info is passed to loggerEvents.

Because of that, if you dont get any Message about starting test-cases via ITestLogger, maybe try to intercept ITestLoggerManager and HandleTestRunStatsChange by yourself? If you could get to that point, it could tell you something by ActiveTests, but I have a feeling that this HandleTestRunStatsChange event is not really guaranteed to be issued per each test entering into running state. Also probably it's really not synchronized with test execution (meaning: agent probalby sends the event and runs further, not waiting for the event to be completed), so if you want to catch that moment of time to do something before each test is ran .. then probably the running tests one-by-one is the only way.

All that being said, please keep in mind that I have no idea. I just look at the source code at random places that looked reasonable to look at. You may want to re-post this question as an issue on that GitHub project. You probably would get a more authoritative response :) (or just wait here a bit more for other people's answers)