dasMulli / dotnet-win32-service

Helper classes to set up and run as windows services directly on .net core. A ServiceBase alternative.
MIT License
451 stars 57 forks source link

An error ocurred: The service did not respond to the start or control request in a timely fashion #54

Closed DercioGaspar closed 6 years ago

DercioGaspar commented 6 years ago

Hello, I've been banging with my head on the wall with this one.

When I try to register the service with "c:\Services\KBBService_PT>dotnet.exe C:\Services\KBBService_PT\KBBService.dll --register-service", it just wont start, but creates it. If I open a cmd (always admin mode) and run it as "c:\Services\KBBService_PT>dotnet.exe C:\Services\KBBService_PT\KBBService.dll --interactive" it runs the service in the console as suposed. If I manually call the service with "--run-as-service" happens the same as when I call the "--register-service". I'm running the latest version of the code, on a windows 10 LTSB, and also tried on a Windows Server 2012 R2.

Bellow is a call stack and error message:

C:\Services\KBBService_PT>dotnet.exe C:\Services\KBBService_PT\KBBService.dll --register-service 2017-12-05 17:36:22.174 - An error ocurred: The service did not respond to the start or control request in a timely fashion

------ STACK TRACE: ------ at DasMulli.Win32.ServiceUtils.ServiceHandle.Start(Boolean throwIfAlreadyRunning) in E:_Git\KBB_MVC\DasMulli.Win32.ServiceUtils\ServiceHandle.cs:line 44

at DasMulli.Win32.ServiceUtils.Win32ServiceManager.DoUpdateService(ServiceHandle existingService, ServiceDefinition serviceDefinition, Boolean startIfNotRunning) in E:_Git\KBB_MVC\DasMulli.Win32.ServiceUtils\Win32ServiceManager.cs:line 193

at DasMulli.Win32.ServiceUtils.Win32ServiceManager.CreateOrUpdateService(ServiceDefinition serviceDefinition, Boolean startImmediately) in E:_Git\KBB_MVC\DasMulli.Win32.ServiceUtils\Win32ServiceManager.cs:line 165

at KBBService.Program.RegisterService() in E:_Git\KBB_MVC\KBBService\Program.cs:line 122

at KBBService.Program.Main(String[] args) in E:_Git\KBB_MVC\KBBService\Program.cs:line 37System.ComponentModel.Win32Exception (0x80004005): The service did not respond to the start or control request in a timely fashion at DasMulli.Win32.ServiceUtils.ServiceHandle.Start(Boolean throwIfAlreadyRunning) in E:_Git\KBB_MVC\DasMulli.Win32.ServiceUtils\ServiceHandle.cs:line 44 at DasMulli.Win32.ServiceUtils.Win32ServiceManager.DoUpdateService(ServiceHandle existingService, ServiceDefinition serviceDefinition, Boolean startIfNotRunning) in E:_Git\KBB_MVC\DasMulli.Win32.ServiceUtils\Win32ServiceManager.cs:line 193 at DasMulli.Win32.ServiceUtils.Win32ServiceManager.CreateOrUpdateService(ServiceDefinition serviceDefinition, Boolean startImmediately) in E:_Git\KBB_MVC\DasMulli.Win32.ServiceUtils\Win32ServiceManager.cs:line 165 at KBBService.Program.RegisterService() in E:_Git\KBB_MVC\KBBService\Program.cs:line 122 at KBBService.Program.Main(String[] args) in E:_Git\KBB_MVC\KBBService\Program.cs:line 37

And bellow my Program.cs (Configs appear to be loading correctly):

using DasMulli.Win32.ServiceUtils;
using System;
using System.Diagnostics;
using System.IO;
using System.Linq;
using System.Reflection;
using System.Text.RegularExpressions;

using static System.Console;

namespace KBBService
{
    public class Program
    {
        private const string RunAsServiceFlag = "--run-as-service";
        private const string ServiceWorkingDirectoryFlag = "--working-directory";
        private const string RegisterServiceFlag = "--register-service";
        private const string PreserveWorkingDirectoryFlag = "--preserve-working-directory";
        private const string UnregisterServiceFlag = "--unregister-service";
        private const string InteractiveFlag = "--interactive";
        private const string HelpFlag = "--help";

        public static void Main(string[] args)
        {
            //cd to the directory where the project files are
            //dotnet.exe C:\Program Files\dotnet\dotnet.exe C:\Services\KBBService_PT\KBBService.dll --register-service
            ////sc.exe create KBBService_PT DisplayName= "KBBService_PT" binpath= "C:\Program Files\dotnet\dotnet.exe C:\Services\KBBService_PT\KBBService.dll --run-as-service"
            Configs.Load();

            try
            {
                if (args.Contains(RunAsServiceFlag))
                {
                    RunAsService(args);
                }
                else if (args.Contains(RegisterServiceFlag))
                {
                    RegisterService();
                }
                else if (args.Contains(UnregisterServiceFlag))
                {
                    UnregisterService();
                }
                else if (args.Contains(HelpFlag))
                {
                    DisplayHelp();
                }
                else
                {
                    RunInteractive(args);
                }
            }
            catch (Exception ex)
            {
                Service.Log(true, $"An error ocurred: {ex.Message}", ex);
            }
        }

        private static void RunAsService(string[] args)
        {
            // easy fix to allow using default web host builder without changes
            var wdFlagIndex = Array.IndexOf(args, ServiceWorkingDirectoryFlag);
            if (wdFlagIndex >= 0 && wdFlagIndex < args.Length - 1)
            {
                var workingDirectory = args[wdFlagIndex + 1];
                Directory.SetCurrentDirectory(workingDirectory);
            }
            else
            {
                Directory.SetCurrentDirectory(Path.GetDirectoryName(Assembly.GetEntryAssembly().Location));
            }
            var mvcService = new Service(args.Where(a => a != RunAsServiceFlag).ToArray());
            var serviceHost = new Win32ServiceHost(mvcService);
            serviceHost.Run();
        }

        private static void RunInteractive(string[] args)
        {
            var mvcService = new Service(args.Where(a => a != InteractiveFlag).ToArray());
            mvcService.Start(new string[0], () => { });
            WriteLine("Running interactively, press enter to stop.");
            ReadLine();
            mvcService.Stop();
        }

        private static void RegisterService()
        {
            // Environment.GetCommandLineArgs() includes the current DLL from a "dotnet my.dll --register-service" call, which is not passed to Main()
            var commandLineArgs = Environment.GetCommandLineArgs();

            var serviceArgs = commandLineArgs
                .Where(arg => arg != RegisterServiceFlag && arg != PreserveWorkingDirectoryFlag)
                .Select(EscapeCommandLineArgument)
                .Append(RunAsServiceFlag);

            var host = Process.GetCurrentProcess().MainModule.FileName;

            if (!host.EndsWith("dotnet.exe", StringComparison.OrdinalIgnoreCase))
            {
                // For self-contained apps, skip the dll path
                serviceArgs = serviceArgs.Skip(1);
            }

            if (commandLineArgs.Contains(PreserveWorkingDirectoryFlag))
            {
                serviceArgs = serviceArgs
                    .Append(ServiceWorkingDirectoryFlag)
                    .Append(EscapeCommandLineArgument(Directory.GetCurrentDirectory()));
            }

            var fullServiceCommand = host + " " + string.Join(" ", serviceArgs);

            // Do not use LocalSystem in production.. but this is good for demos as LocalSystem will have access to some random git-clone path
            // Note that when the service is already registered and running, it will be reconfigured but not restarted
            var serviceDefinition = new ServiceDefinitionBuilder(Configs.ServiceName)
                .WithDisplayName(Configs.ServiceDisplayName)
                .WithDescription(Configs.ServiceDescription)
                .WithBinaryPath(fullServiceCommand)
                .WithCredentials(Win32ServiceCredentials.LocalSystem)
                .WithAutoStart(true)
                .Build();

            new Win32ServiceManager().CreateOrUpdateService(serviceDefinition, startImmediately: true);

            WriteLine($@"Successfully registered and started service ""{Configs.ServiceDisplayName}"" (""{Configs.ServiceDescription}"")");
        }

        private static void UnregisterService()
        {
            new Win32ServiceManager()
                .DeleteService(Configs.ServiceName);

            WriteLine($@"Successfully unregistered service ""{Configs.ServiceDisplayName}"" (""{Configs.ServiceDescription}"")");
        }

        private static void DisplayHelp()
        {
            WriteLine(Configs.ServiceDescription);
            WriteLine();
            WriteLine("This demo application is intened to be run as windows service. Use one of the following options:");
            WriteLine();
            WriteLine("  --register-service            Registers and starts this program as a windows service named \"" + Configs.ServiceDisplayName + "\"");
            WriteLine("                                All additional arguments will be passed to ASP.NET Core's WebHostBuilder.");
            WriteLine();
            WriteLine("  --preserve-working-directory  Saves the current working directory to the service configuration.");
            WriteLine("                                Set this wenn running via 'dotnet run' or when the application content");
            WriteLine("                                is not located nex to the application.");
            WriteLine();
            WriteLine("  --unregister-service          Removes the windows service creatd by --register-service.");
            WriteLine();
            WriteLine("  --interactive                 Runs the underlying asp.net core app. Useful to test arguments.");
        }

        private static string EscapeCommandLineArgument(string arg)
        {
            // http://stackoverflow.com/a/6040946/784387
            arg = Regex.Replace(arg, @"(\\*)" + "\"", @"$1$1\" + "\"");
            arg = "\"" + Regex.Replace(arg, @"(\\+)$", @"$1$1") + "\"";
            return arg;
        }
    }

    public class Service : IWin32Service
    {
        private readonly string[] commandLineArguments;

        public string ServiceName => Configs.ServiceName;

        public Service(string[] commandLineArguments)
        {
            this.commandLineArguments = commandLineArguments;
        }

        public void Start(string[] startupArguments, ServiceStoppedCallback serviceStoppedCallback)
        {
            Log(false, $"Service {ServiceName} Started");
            ErrorHandler.Log($"Service {ServiceName} Started", ExceptionLevel.Warning);
            ThreadManager.Start();//aka Do Stuff
        }

        public void Stop()
        {
            Log(false, $"Service {ServiceName} Stopped");
            ErrorHandler.Log($"Service {ServiceName} Stopped", ExceptionLevel.Warning);
            ThreadManager.Stop();//aka Stop Stuff
        }

        public static void Log(bool error, string message = null, Exception ex = null, ExceptionLevel exceptionLevel = ExceptionLevel.Regular)
        {
            if (message == null)
            {
                message = string.Empty;
            }

            lock (typeof(Service))
            {
                if (error)
                {
                    if (ex == null)
                    {
                        ErrorHandler.Log(message, exceptionLevel);
                    }
                    else
                    {
                        ErrorHandler.Log(ex, message, exceptionLevel);
                        message += "\r\n--------------------------\r\n";
                        message += GetStack(ex);
                    }
                }

                DateTime dtNow = DateTime.UtcNow;
                message += (ex == null ? string.Empty : ex.ToString());

                Console.WriteLine(dtNow.ToString("yyyy-MM-dd HH:mm:ss.fff") + " - " + message);

                string sFileName = dtNow.Year + "_" + dtNow.Month + "_" + dtNow.Day + ".txt";

                if (!Directory.Exists(Configs.LogPath))
                {
                    Directory.CreateDirectory(Configs.LogPath);
                }

                File.AppendAllText(Configs.LogPath + "\\" + sFileName, dtNow.ToString("yyyy-MM-dd HH:mm:ss.fff") + " - " + message + Environment.NewLine + Environment.NewLine + Environment.NewLine);
            }
        }
        private static string GetStack(Exception ex)
        {
            if (ex == null)
            {
                return string.Empty;
            }

            string stacktrace = "\r\n------ STACK TRACE: ------";

            if (ex.StackTrace != null)
            {
                stacktrace += ex.StackTrace.ToString();
                stacktrace = stacktrace.Replace("at ", "\r\nat ");
            }

            return stacktrace;
        }
    }
}

If you need any more info, just let me know.

dasMulli commented 6 years ago

Do any of these log messages end up on disk? it may also help to put a try/catch around the contents of the RunAsService method and log any exception.

Also, does ThreadManager.Start() block the method or does it return immediately after kicking off some background work? The IWin32Service.Start method is required to exit when startup is completed. This exit (without exception) will cause the service host to report the "Started" state of the service. The error message you are seeing usually indicates that this state (or any other state) is not being reported.

DercioGaspar commented 6 years ago

Indeed the ThreadManaget.Start() would block the method, I've changed that to:

Thread thread = new Thread(new ThreadStart(ThreadManager.Start));
thread.Start();

Still the problem persists. The stack I wrote is the result of try/catch right after the Configs.Load(); I tried to debug calling the RunAsService method and the breakpoint I put in the Start method is never reached, went to the Event Viewer and found this:

<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Name=".NET Runtime" /> 
        <EventID Qualifiers="0">1022</EventID> 
        <Level>2</Level> 
        <Task>0</Task> 
        <Keywords>0x80000000000000</Keywords> 
        <TimeCreated SystemTime="2017-12-06T09:48:52.000000000Z" /> 
        <EventRecordID>50378</EventRecordID> 
        <Channel>Application</Channel> 
        <Computer>DGaspar</Computer> 
        <Security UserID="S-1-5-21-1078081533-436374069-1202660629-9033" /> 
    </System>
    <EventData>
        <Data>.NET Runtime version 4.0.30319.0 - Loading profiler failed during CoCreateInstance. Profiler CLSID: '{de70e25c-02b5-4556-a837-8aa6fe502668}'. HRESULT: 0x8007007e. Process ID (decimal): 7736. Message ID: [0x2504].</Data> 
    </EventData>
</Event>

For what I can see it fails on if (!nativeInterop.StartServiceCtrlDispatcherW(serviceTable)) in Win32ServiceHost class, when I call serviceHost.Run();

If you need any more info, just let me know.

dasMulli commented 6 years ago

if you start and debug the RunAsService method, it is expected to fail at this point because the native method called here expects that it can connect to the windows service management system, which only works when the process is started by it (== when the process is started because the windows service is started).

As stated in https://github.com/dasMulli/dotnet-win32-service/issues/18#issuecomment-267798630, you could try adding a

while (!Debugger.IsAttached)
{
    Thread.Sleep(100);
}

loop to the process, start the windows service via the service management console and attach to it via VS (you'd have to be quick though. this is the only way to really debug a windows service when actually running as service, even with ServiceBase).

The event looks a bit strange - a .NET Core service shouldn't try to load the full .NET Runtimee.

DercioGaspar commented 6 years ago

Found out the problem, I was trying to load configs with:

        var builder = new ConfigurationBuilder()
            .SetBasePath(Directory.GetCurrentDirectory())
            .AddJsonFile("appsettings.json", false, true);

        var root = builder.Build();

But apparently it doesn't like those nuggets (Microsoft.Extensions.Configuration, Microsoft.Extensions.Configuration.FileExtensions and Microsoft.Extensions.Configuration.Json). Guess I'll have to find another way to load my configs without using the IWebHost builder (this service is not gonna do anything related to Web so in my head it doesn't make sense to use it, I may be wrong in my theory tho)

dasMulli commented 6 years ago

You may want to take a look at the MVC sample which has a feature to preserve the working directory from where the register call is made. A windows service always starts with the working directory being the system32 directory. So your application was likely looking for a C:\Windows\system32\appsettings.json file.

dasMulli commented 6 years ago

Closing since you found the issue(s) specific to your application. Reopen if necessary.

DercioGaspar commented 6 years ago

@dasMulli Just in case you know. Is there a good way to load configs?

dasMulli commented 6 years ago

I do like the configuration system that comes with asp.net core. Using the Microsoft.Extensions.Configuration NuGet package is useful even in non-asp.net core scenario. In case of windows services, you'll have too look for the config files next to your application. E.g. get the directory part from typeof(Program).Assembly.Location and use it for new ConfigurationBuilder().SetBasePath(…)…. I've even used this configuration system in combination with .NET Framework 4.7.1's now ConfigBuilders system to determine resolved values from multiple json files when loading a config for a classic ASP.NET app.

DercioGaspar commented 6 years ago

@dasMulli Would you imagine that, that last message was what unlocked everything?

Reinstalled the Microsoft.Extensions.Configuration.Json nugget and tried the ConfigurationBuilder().SetBasePath(typeof(Program).Assembly.Location); and it said "invalid path" (ofc it was duhh), then tried hammering down the path just to see if it worked, IT DID. I think tears were seen in my eyes :) All of this was only because of the Directory.GetCurrentDirectory() Ended up loading the configs (as suggested by you) with:

System.Reflection.Assembly assembly = typeof(Program).Assembly;
var builder = new ConfigurationBuilder()
    .SetBasePath(assembly.Location.Replace(assembly.ManifestModule.Name, string.Empty))
    .AddJsonFile("appsettings.json", false, true);

Thank you very much!

I would suggest adding an example loading the configs with way, because the internet is all over the Directory.GetCurrentDirectory() and never the typeof(Program).Assembly.Location

dasMulli commented 6 years ago

Glad you figured it out! I think we all wasted weeks of our lives figuring out such config stuff..

The problem is that even .SetBasePath(Path.GetDirectoryName(typeof(Program).Assembly.Location)) doesn't work in all cases. For example an asp.net core app is run with the project directory as working directory and this line would cause it to look int ..\bin\Debug\netcoreapp2.0\ where there is no config file by default. Only the published output will include one. That's why I chose to pursue the "preserve current working directory" strategy which works saving a config that works from dotnet run during development and dotnet my.dll on the published output both incases where running interactively would also work from the same setup.

DercioGaspar commented 6 years ago

@dasMulli In my case this code will be more idiot prof (the idiot probably would be me in a few moths), this way there is no need for the --preserve-working-directory:

string assemblyPath = Path.GetDirectoryName(typeof(Program).Assembly.Location);
string path = assemblyPath.Contains(@"\bin\") ? Directory.GetCurrentDirectory() : assemblyPath;

var builder = new ConfigurationBuilder()
    .SetBasePath(path)
    .AddJsonFile("appsettings.json", false, true);

var root = builder.Build();

As far as I've tested it works both ways