Runtime: [Regression] Test failed: System.ServiceProcess.Tests.ServiceBaseTests / TestOnExecuteCustomCommand

[karelz]

Failure:

Assert.Equal() Failure
                                   ↓ (pos 44)
Expected: ···ommand command=128\\r\
OnStop\\r\

Actual:   ···ommand command=128\\r\

                                   ↑ (pos 44)

History of failures

Day | Build | OS | Details
--- | --- | --- | ---
8/14 | 20170814.02 | Win8.1 | pos 2
11/1 | 20171101.01 | Win10 | pos 17
11/4 | 20171104.02 | Win10 | pos 46
11/9 | 20171109.05 | Win8.1 | pos 17
11/21 | 20171121.02 | WIn7 | pos 46
12/10 | 20171210.03 | Win8.1 | pos 17
12/12 | 20171212.03 | Win7 | pos 46
1/9 | 20180109.01 | Win10 | 2x failures (pos 44) - link
1/9 | 20180109.02 | Win10 | pos 44 - link
1/11 | 20180111.01 | Win7 | pos 44 - link
1/11 | 20180111.03 | Win10 | 2x pos 44 - link
1/12 | 20180112.02 | Win10 | pos 44 - link
1/13 | 20180113.03 | Win7 | pos 44 - link
1/15 | 20180115.04 | Win10 | pos 44 - link
1/16 | 20180116.01 | Win10 | pos 44 - link
1/16 | 20180116.06 | Win7 & Win10 | 3x pos 44 - link
1/17 | 20180117.03 | Win10 | pos 44 - link
1/19 | 20180119.02 | Win10 | pos 44 - link
1/21 | 20180121.01 | Win8.1 | pos 44 - link
1/21 | 20180121.02 | Win10 | pos 44 - link
1/22 | 20180122.02 | Win10 | pos 44 - link
1/23 | 20180123.01 | Win10 | pos 44 - link
1/24 | 20180124.02 | Win8 + 3x Win10 | 4x pos 44 - link
1/24 | 20180124.06 | Win10 | pos 44 - link
1/25 | 20180125.01 | Win10 | pos 44 - link
1/25 | 20180125.06 | Win10 | pos 44 - link
1/26 | 20180126.03 | Win7 | pos 44 - link
1/27 | 20180127.01 | Win7 | pos 44 - link
1/30 | 20180130.01 | Win10 | pos 44 - link

[karelz]

Still some issue with the tests - cc @danmosemsft @wtgodbe

[danmosemsft]

Yeah, this is an older issue I think -- apparent flakiness in the service infra.
https://github.com/dotnet/corefx/issues/24993

[karelz]

Is it possible that the recent changes made it more common? I updated history of the failure above ...

[danmosemsft]

Unlikely.

ServiceBase has a bunch of calls to WriteLogEntry that only go to Debug.Write right now. In NETFX they go to the event log. We should probably make them do that, and perhaps the tests should read any such events and log them also.

Or we can do code inspection or add a sleep.

[danmosemsft]

We should make it write to the event log regardless. @Anipik could you please fix ServiceBase WriteLogEntry to match Desktop, which writes to the event log. LMK if you need a pointer to the desktop sources.

[danmosemsft]

BTW @weshaggard any particular reason you removed the EventLog logging?

[weshaggard]

Because they didn't exist when we ported it. See https://github.com/dotnet/corefx/issues/23864.

[Anipik]

@danmosemsft src\NDP\fx\src\Services\ServProc\System\ServiceProcess\ServiceBse.cs is this the correct pointer ?. Do I need to write any tests for it also ?

[danmosemsft]

@Anipik yes correct place. I don't know why it seems it's not on reference source. Yes, minimal test please. Note that the events written by a test service can be found because "source" in the event log is the service name.

[danmosemsft]

Meanwhile as for the cause of this issue and dotnet/runtime#24016.

OnStart, OnStop, and OnCustomCommand etc handlers are not called synchronously. This is not the case. ServiceBase invokes all of them on the threadpool and does not mutually sync them. The tests try to use controller.WaitForStatus(ServiceControllerStatus.Running); to avoid problems but it isn't sufficient.

TestOnExecuteCustomCommand does start, custom command, wait for running, stop, wait for stop. There is no wait after the start, so custom command and start might get reversed in the log. Also stop might happen before custom command (and the service actually stop before custom command got logged). That explains one repro. The Stop missing is because WaitForStatus waits on the stopped status, not on the stop message, so the test can read the file before it gets written. The doubled up custom command on NETFX I cannot explain.

[danmosemsft]

One way to fix this could be a named pipe between test and service, the service would send whatever handler it was processing, and the test could wait on whatever handler it expected. This would eliminate the need for the log file. This would need a bunch of reworking of the tests.

[danmosemsft]

A lesser way to fix it could be to disregard the order of the log (to solve the ordering problem) and use a sleep (to "solve" the cropped log problem)

[karelz]

BTW: This issue seems to be happening much more often recently - see updated history in top post

[Anipik]

@karelz yeah I am working on it to get it fixed using named pipe. Is any other test is also failing from this class ?

[karelz]

Thank you for the fix!