Test failure: System.ServiceProcess.Tests.ServiceBaseTests.TestOnStartWithArgsThenStop (expected: 6, Actual: 0)

[antonfirsov]

Build

https://dev.azure.com/dnceng/public/_build/results?buildId=720801&view=ms.vss-test-web.build-test-results-tab&runId=22327000

Message

System.AggregateException : One or more errors occurred. (Assert.Equal() Failure\r\nExpected: 6\r\nActual: 0) (The operation requested for service '6d2e6215-600a-4f31-a5a8-e6ab01a20de9' has not been completed within the specified time interval.)\r\n---- Assert.Equal() Failure\r\nExpected: 6\r\nActual: 0\r\n---- System.ServiceProcess.TimeoutException : The operation requested for service '6d2e6215-600a-4f31-a5a8-e6ab01a20de9' has not been completed within the specified time interval.

Stack trace

----- Inner Stack Trace #1 (Xunit.Sdk.EqualException) -----
   at System.ServiceProcess.Tests.ServiceBaseTests.TestOnStartWithArgsThenStop() in /_/src/libraries/System.ServiceProcess.ServiceController/tests/ServiceBaseTests.cs:line 96
----- Inner Stack Trace #2 (System.ServiceProcess.TimeoutException) -----
   at System.ServiceProcess.ServiceController.WaitForStatus(ServiceControllerStatus desiredStatus, TimeSpan timeout) in /_/src/libraries/System.ServiceProcess.ServiceController/src/System/ServiceProcess/ServiceController.cs:line 905
   at System.ServiceProcess.Tests.TestServiceInstaller.StopService() in /_/src/libraries/System.ServiceProcess.ServiceController/tests/System.ServiceProcess.ServiceController.TestService/TestServiceInstaller.cs:line 154
   at System.ServiceProcess.Tests.TestServiceInstaller.RemoveService() in /_/src/libraries/System.ServiceProcess.ServiceController/tests/System.ServiceProcess.ServiceController.TestService/TestServiceInstaller.cs:line 119
   at System.ServiceProcess.Tests.TestServiceProvider.DeleteTestServices() in /_/src/libraries/System.ServiceProcess.ServiceController/tests/TestServiceProvider.cs:line 135
   at System.ServiceProcess.Tests.ServiceBaseTests.Dispose() in /_/src/libraries/System.ServiceProcess.ServiceController/tests/ServiceBaseTests.cs:line 218
   at ReflectionAbstractionExtensions.DisposeTestClass(ITest test, Object testClass, IMessageBus messageBus, ExecutionTimer timer, CancellationTokenSource cancellationTokenSource) in C:\Dev\xunit\xunit\src\xunit.execution\Extensions\ReflectionAbstractionExtensions.cs:line 79

[danmoseley]

Test service apparently returned PipeMessageByteCode.Start when PipeMessageByteCode.Connected was expected. It expects Start to be transmitted after Connected. Apparently it's then in a bad state as subsequently it did not respond to a stop message.

There is some asynchrony in the test service writes.

constructor:

            _waitClientConnect = this._serverStream.WaitForConnectionAsync();
            _waitClientConnect.ContinueWith((t) => WriteStreamAsync(PipeMessageByteCode.Connected));

OnStart() - called directly after

                WriteStreamAsync(PipeMessageByteCode.Start).Wait();

        public async Task WriteStreamAsync(PipeMessageByteCode code, int command = 0)
        {
            if (_waitClientConnect.IsCompleted)
            {
                Task writeCompleted;
                const int WriteTimeout = 60000;
                ...
                    writeCompleted = _serverStream.WriteAsync(new byte[] { (byte)code }, 0, 1);
...
                await writeCompleted.TimeoutAfter(WriteTimeout).ConfigureAwait(false);

@stephentoub is the code above written such that Start will reliably only be written after Connected?

@dotnet/dnceng when I go to the link above, the "Helix Test Logs (Beta)" tab just says "Unable to Load Helix Data". Is that expected?

[antonfirsov]

Sorry, realized this is a duplicate of #37540 and #36207.

I used the filter is:issue System.ServiceProcess when I first tried finding existing issues, but it does not list those two for some reason.

Feel free to close this one.

[alexperovich]

when I go to the link above, the "Helix Test Logs (Beta)" tab just says "Unable to Load Helix Data". Is that expected?

The test logs tab isn't supported for a specific run. If you click on one of the tests in the run it does work.

[danmoseley]

@alexperovich I see -- maybe it should say that ..

[ericstj]

I'll dupe the other issues to this one since this is where the party is happening. Interested to hear from @stephentoub. 🍿

My read of that code is that _WaitForConnectionAsync will happen on threadpool thread. OnStart will also happen on another threadpool thread as it is queued by native callback

runtime/src/libraries/System.ServiceProcess.ServiceController/src/System/ServiceProcess/ServiceBase.cs

Line 928 in 6072e4d

ThreadPool.QueueUserWorkItem(new WaitCallback(this.ServiceQueuedMainCallback!), args);

. This is triggered by Program.Main which serially constructs the service then invokes run, which PInvokes to Windows and triggers this callback. I don't see any connection between the startup and the pipe connection.

[ericstj]

I bet you could force this to happen by doing

            _waitClientConnect.ContinueWith(Task.Delay(5000)).ContinueWith((t) => WriteStreamAsync(PipeMessageByteCode.Connected));

Then you could fix it by making _waitClientConnect be the task returned from all continuations, then Wait() that task in OnStart.

[stephentoub]

@stephentoub is the code above written such that Start will reliably only be written after Connected?

The only thing related to that this guarantees:

            _waitClientConnect = this._serverStream.WaitForConnectionAsync();
            _waitClientConnect.ContinueWith((t) => WriteStreamAsync(PipeMessageByteCode.Connected));

is that the WriteStreamAsync(PipeMessageByteCode.Connected) will happen at some point and on some thread after the WaitForConnectionAsync completes. It could be anywhere from immediately to much longer, as the ContinueWith is just scheduling that call to the thread pool. So if something else in the interim caused OnStart to be invoked once the connection was established, there's a race condition where that OnStart could be invoked concurrently with or well before the WriteStreamAsync(Connected).

[danmoseley]

OK, so there's a bug. Should the constructor instead be

            _waitClientConnect = this._serverStream.WaitForConnectionAsync().ContinueWith((t) => WriteStreamAsync(PipeMessageByteCode.Connected));

I'll go re-read the async documentation as I need to understand this better.

[ericstj]

Yeah. You do that and make sure OnStart waits on that task before sending start message.

[danmoseley]

I'll fix it..assuming I remember the magic to make these tests actually run for me