I have a problem with a windows service. Sometimes service can't be stopped and hangs with a running status) after the start command with the message:
The service cannot accept control messages at this time
The simplified service implementation:
using System.ServiceProcess;
using System.Threading;
using System.Threading.Tasks;
namespace ConsoleApp1
{
public class Service : ServiceBase
{
protected object SyncRoot { get; } = new object();
protected override void OnStart(string[] args)
{
lock (SyncRoot)
{
var task = PerformHealthCheck();
while (!task.Wait(10000))
{
RequestAdditionalTime(10000);
}
Task.Factory.StartNew(() =>
{
//Some logic to start worker threads and initialize some startup processes
//All workers threads actually successfully executed.
}, CancellationToken.None, TaskCreationOptions.LongRunning, TaskScheduler.Default);
}
}
protected override void OnStop()
{
//Code is not reachable sometimes
lock (SyncRoot)
{
//Some stop logic
}
}
private static async Task PerformHealthCheck()
{
int status = 0;
do
{
status = CheckStatus();
if (status == 0)
{
await Task.Delay(20000);
}
}
while (status == 0);
}
private static int CheckStatus()
{
//Calculating HealthCheck status
return 0;
}
}
}
Creation logic:
internal static class Program
{
private static void Main(string[] args)
{
ServiceBase.Run(new Service());
}
}
OnStart method is successfully executed till the end and OnStop method is not even hit. I can see the service status as following in WinDbg:
16 serviceType
4 currentState
5 controlsAccepted
0 win32ExitCode
0 serviceSpecificExitCode
0 checkPoint
0 waitHint
So apparently as far as I understand the service is in the Running state and has received the stop command but didn't execute it (I can see it from logs). I don't understand what could possibly stop the service from executing the OnStop method. Start command can be seen in windows event view but Stop command is not there.
Other information:
In your example PerformHealthCheck() will run indefinitively. Thus your OnStart does never finishes. Don't know if that's only because of your simplified example.
However, do you actually log something when it happens? As in, log the end of the OnStart method and confirm that when the problem happens, the OnStart was actually finished. In your code-comment you write //Code is not reachabl.. do you log something there as well? Or within the lock?
BTW, locking the startup and stop might seem like a good idea to synchronize, but as a user if i want to stop a service, i really want to stop it. Regardless of it still being in the state of starting up. In fact, if a service does not respond to the stop command, i suspect that 90% of the time, task manager is the next stop anyway... Is it not better if you try to rewrite the stop logic in such a way that it will always just executes and breaks off everything it can? This would probably solve your issue and also improves the experience imo.
Edit, it seems that the locks in fact don't do anything anyway (at least, if they are used only here and not to lock something elsewhere) The OS won't pass the OnStop command if its still StartPending..:
Is it possible that this happens when the startup just takes LONG and stop is called once BEFORE the start has finished? See this example:
class logger
{
static readonly object _logSync = new object();
public void Log(string message)
{
var m = $"{DateTime.Now.ToString("HH:mm:ss")}; {message}{Environment.NewLine}";
lock(_logSync)
{
File.AppendAllText(@"C:\temp\test.txt", m);
}
}
}
class Program
{
static void Main(string[] args)
{
ServiceBase.Run(new TestHangService());
}
}
class TestHangService : ServiceBase
{
private logger _log;
public TestHangService()
{
_log = new logger();
}
protected override void OnStart(string[] args)
{
_log.Log("OnStart");
Thread.Sleep(30 * 1000);
_log.Log("OnStart exit");
}
protected override void OnStop()
{
_log.Log("OnStop");
}
}
Then
C:\WINDOWS\system32>sc create DeleteMe binpath="C:\testprojects\TestService\TestService\bin\Debug\TestService.exe"
[SC] CreateService SUCCESS
C:\WINDOWS\system32>sc start deleteMe
SERVICE_NAME: deleteMe
TYPE : 10 WIN32_OWN_PROCESS
STATE : 2 START_PENDING
(NOT_STOPPABLE, NOT_PAUSABLE, IGNORES_SHUTDOWN)
WIN32_EXIT_CODE : 0 (0x0)
SERVICE_EXIT_CODE : 0 (0x0)
CHECKPOINT : 0x0
WAIT_HINT : 0x7d0
PID : 27376
FLAGS :
C:\WINDOWS\system32>echo "executed directly after starting"
"executed directly after starting"
C:\WINDOWS\system32>sc stop deleteMe
SERVICE_NAME: deleteMe
TYPE : 10 WIN32_OWN_PROCESS
STATE : 2 START_PENDING
(STOPPABLE, NOT_PAUSABLE, ACCEPTS_SHUTDOWN)
WIN32_EXIT_CODE : 0 (0x0)
SERVICE_EXIT_CODE : 0 (0x0)
CHECKPOINT : 0x0
WAIT_HINT : 0x0
C:\WINDOWS\system32>echo "waiting for 30 sec"
"waiting for 30 sec"
C:\WINDOWS\system32>sc stop deleteMe
[SC] ControlService FAILED 1061:
The service cannot accept control messages at this time.
which logs:
18:32:20; OnStart
18:32:50; OnStart exit
note not onstop
It will not recover from this it seems (which suprised me btw) even after 10 min:
C:\WINDOWS\system32>sc query deleteme
SERVICE_NAME: deleteme
TYPE : 10 WIN32_OWN_PROCESS
STATE : 4 RUNNING
(STOPPABLE, NOT_PAUSABLE, ACCEPTS_SHUTDOWN)
WIN32_EXIT_CODE : 0 (0x0)
SERVICE_EXIT_CODE : 0 (0x0)
CHECKPOINT : 0x0
WAIT_HINT : 0x0
C:\WINDOWS\system32>sc stop deleteme
[SC] ControlService FAILED 1061:
The service cannot accept control messages at this time.