Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

WindowsSerivceLifetime is broken #72590

Open
i-sinister opened this issue Jul 21, 2022 · 16 comments
Open

WindowsSerivceLifetime is broken #72590

i-sinister opened this issue Jul 21, 2022 · 16 comments

Comments

@i-sinister
Copy link

i-sinister commented Jul 21, 2022

Description

There are several bugs related to WindowsServiceLifetime implementation in 3.1:

  1. windows service hangs if there are errors during host initialization
  2. windows service is reported running until host is initialized.

#2 is can be a problem if the service is dependent by another windows service.

Reproduction Steps

Here is an example of what is roughly going on when application is started as windows service.

Create a new console application

dotnet new console --framework netcoreapp3.1 --output ServiceExitTest
dotnet add ServiceExitTest\ServiceExitTest.csproj package --version 3.1.3 Microsoft.Extensions.Hosting.WindowsServices

Replace Program.cs:

namespace ServiceExitTest
{
	using System;
	using System.IO;
	using System.ServiceProcess;
	using System.Threading;

	public class Program
	{
		private readonly static object logLock = new object();
		public static void Log(string name, string message)
		{
			lock (logLock)
			{
				message = $"{DateTime.Now} [{name}] {message}";
				File.AppendAllText("service_log.txt", message + Environment.NewLine);
			}
		}

		public static void Log(string message) => Log(nameof(Program), message);

		class StrangeService : ServiceBase
		{
			private static void Log(string message) => Program.Log(nameof(StrangeService), message);

			private readonly ManualResetEvent mre = new ManualResetEvent(false);

			public void StartService()
			{
				Log("starting service");
				new Thread(new ThreadStart(Run)).Start();
				Log("waiting for service to start");
				mre.WaitOne();
				Log("service started");
			}

			protected override void OnStart(string[] args)
			{
				Log("notifying started");
				mre.Set();
				Log("started notification complete");
				base.OnStart(args);
			}

			private void Run()
			{
				try
				{
					Log("calling ServiceBase.Run(this)");
					Run(this);
					Log("ServiceBase.Run(this) completed");
				}
				catch { }
				finally
				{
					Log("notifying completed");
					mre.Set();
					Log("completed notified");
				}
			}
		}

		public static int Main()
		{
			Directory.SetCurrentDirectory(AppDomain.CurrentDomain.BaseDirectory);
			using var service = new StrangeService();
			Log("starting strange service");
			service.StartService();
			Log("strange service started");
			Log("exiting application");
			return 1;
		}
	}
}

Create build.cmd with following content:

@echo off
sc.exe stop WINSERVICE_STOP_TEST
dotnet publish --self-contained true --configuration Release --runtime win10-x64 ServiceExitTest\ServiceExitTest.csproj
sc.exe delete WINSERVICE_STOP_TEST
sc.exe create WINSERVICE_STOP_TEST binPath= "%~dp0\ServiceExitTest\bin\Release\netcoreapp3.1\win10-x64\publish\ServiceExitTest.exe"
sc.exe start WINSERVICE_STOP_TEST

Execute build.cmd and check the current state:

C:\Repos>more ServiceExitTest\bin\Release\netcoreapp3.1\win10-x64\publish\service_log.txt
21.07.2022 11:37:25 [Program] starting strange service
21.07.2022 11:37:25 [StrangeService] starting service
21.07.2022 11:37:25 [StrangeService] waiting for service to start
21.07.2022 11:37:25 [StrangeService] calling ServiceBase.Run(this)
21.07.2022 11:37:25 [StrangeService] notifying started
21.07.2022 11:37:25 [StrangeService] started notification complete
21.07.2022 11:37:25 [StrangeService] service started
21.07.2022 11:37:25 [Program] strange service started
21.07.2022 11:37:25 [Program] exiting application

C:\Repos>sc.exe query WINSERVICE_STOP_TEST

SERVICE_NAME: WINSERVICE_STOP_TEST
        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:\Repos>tasklist /fi "IMAGENAME eq ServiceExitTest.exe"

Image Name                     PID Session Name        Session#    Mem Usage
========================= ======== ================ =========== ============
ServiceExitTest.exe          10928 Services                   0     18,800 K

So even though Main method has exited service and executable remain running. This happens because StrangeService.StartService starts new foreground thread which never completes (ServiceBase.Run does not return) because StrangeService.Stop is not called.

If you'll squint your eyes you can see that StrangeService is a WindowsServiceLifetime. The same behavior is observed in "real project" when error happens during IHostedService.StartAsync. There are couple ways to solve/workaround it:

  1. start thread as background - it will cause thread running ServiceBase.Run to be torn down when Main exists
  2. implement startup error handling to call ServiceBase.Stop if error occurred
  3. dont report service as started until ApplicationStarted is raised (my fav)

About #3 - unlike SystemdLifetime, WindowsServiceLifetime reports service is up and running inside WaitForStartAsync before IHostApplicationLifetime.ApplicationStarted is raised which is completely wrong because service is not running. This can cause problems when the service is dependent by other services.

Expected behavior

  1. windows service should stop when main method exists
  2. windows service should not be reported as started until ApplicationStarted event is raised

Actual behavior

  1. windows service does not stop if execution happens during IHostedService.Start method
  2. windows service is reported as started before ApplicationStarted event is raised

Regression?

No response

Known Workarounds

No response

Configuration

No response

Other information

No response

@ghost ghost added the untriaged New issue has not been triaged by the area owner label Jul 21, 2022
@ghost
Copy link

ghost commented Jul 21, 2022

Tagging subscribers to this area: @dotnet/area-system-serviceprocess
See info in area-owners.md if you want to be subscribed.

Issue Details

Description

There are several bugs related to WindowsServiceLifetime implementation in 3.1:

  1. windows service to hangs if there are errors during host initialization
  2. windows service is reported running until host is initialized.

#2 is can be a problem if the service is dependent by another windows service.

Reproduction Steps

Here is an example of what is roughly going on when application is started as windows service.

Create a new console application

dotnet new console --framework netcoreapp3.1 --output ServiceExitTest
dotnet add ServiceExitTest\ServiceExitTest.csproj package --version 3.1.3 Microsoft.Extensions.Hosting.WindowsServices

Replace Program.cs:

namespace ServiceExitTest
{
	using System;
	using System.IO;
	using System.ServiceProcess;
	using System.Threading;

	public class Program
	{
		private readonly static object logLock = new object();
		public static void Log(string name, string message)
		{
			lock (logLock)
			{
				message = $"{DateTime.Now} [{name}] {message}";
				File.AppendAllText("service_log.txt", message + Environment.NewLine);
			}
		}

		public static void Log(string message) => Log(nameof(Program), message);

		class StrangeService : ServiceBase
		{
			private static void Log(string message) => Program.Log(nameof(StrangeService), message);

			private readonly ManualResetEvent mre = new ManualResetEvent(false);

			public void StartService()
			{
				Log("starting service");
				new Thread(new ThreadStart(Run)).Start();
				Log("waiting for service to start");
				mre.WaitOne();
				Log("service started");
			}

			protected override void OnStart(string[] args)
			{
				Log("notifying started");
				mre.Set();
				Log("started notification complete");
				base.OnStart(args);
			}

			private void Run()
			{
				try
				{
					Log("calling ServiceBase.Run(this)");
					Run(this);
					Log("ServiceBase.Run(this) completed");
				}
				catch { }
				finally
				{
					Log("notifying completed");
					mre.Set();
					Log("completed notified");
				}
			}
		}

		public static int Main()
		{
			Directory.SetCurrentDirectory(AppDomain.CurrentDomain.BaseDirectory);
			using var service = new StrangeService();
			Log("starting strange service");
			service.StartService();
			Log("strange service started");
			Log("exiting application");
			return 1;
		}
	}
}

Create build.cmd with following content:

@echo off
sc.exe stop WINSERVICE_STOP_TEST
dotnet publish --self-contained true --configuration Release --runtime win10-x64 ServiceExitTest\ServiceExitTest.csproj
sc.exe delete WINSERVICE_STOP_TEST
sc.exe create WINSERVICE_STOP_TEST binPath= "%~dp0\ServiceExitTest\bin\Release\netcoreapp3.1\win10-x64\publish\ServiceExitTest.exe"
sc.exe start WINSERVICE_STOP_TEST

Execute build.cmd and check the current state:

C:\Repos>more ServiceExitTest\bin\Release\netcoreapp3.1\win10-x64\publish\service_log.txt
21.07.2022 11:37:25 [Program] starting strange service
21.07.2022 11:37:25 [StrangeService] starting service
21.07.2022 11:37:25 [StrangeService] waiting for service to start
21.07.2022 11:37:25 [StrangeService] calling ServiceBase.Run(this)
21.07.2022 11:37:25 [StrangeService] notifying started
21.07.2022 11:37:25 [StrangeService] started notification complete
21.07.2022 11:37:25 [StrangeService] service started
21.07.2022 11:37:25 [Program] strange service started
21.07.2022 11:37:25 [Program] exiting application

C:\Repos>sc.exe query WINSERVICE_STOP_TEST

SERVICE_NAME: WINSERVICE_STOP_TEST
        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:\Repos>tasklist /fi "IMAGENAME eq ServiceExitTest.exe"

Image Name                     PID Session Name        Session#    Mem Usage
========================= ======== ================ =========== ============
ServiceExitTest.exe          10928 Services                   0     18,800 K

So even though Main method has exited service and executable remain running. This happens because StrangeService.StartService starts new foreground thread which never completes (ServiceBase.Run does not return) because StrangeService.Stop is not called.

If you'll squint your eyes you can see that StrangeService is a WindowsServiceLifetime. The same behavior is observed in "real project" when error happens during IHostedService.StartAsync. There are couple ways to solve/workaround it:

  1. start thread as background - it will cause thread running ServiceBase.Run to be teared down when Main exists
  2. implement startup error handling to call ServiceBase.Stop if error occurred
  3. dont report service as started until ApplicationStarted is raised (my fav)

About #3 - unlike SystemdLifetime, WindowsServiceLifetime reports service is up and running inside WaitForStartAsync before IHostApplicationLifetime.ApplicationStarted is raised which is completely wrong because service is not running. This can cause problems when the service is dependent by other services.

Expected behavior

  1. windows service should stop when main method exists
  2. windows service should not be reported as started until ApplicationStarted event is raised

Actual behavior

  1. windows service does not stop if execution happens during IHostedService.Start method
  2. windows service is reported as started before ApplicationStarted event is raised

Regression?

No response

Known Workarounds

No response

Configuration

No response

Other information

No response

Author: i-sinister
Assignees: -
Labels:

area-System.ServiceProcess

Milestone: -

@i-sinister
Copy link
Author

I would also like to note that having separate thread just to call ServiceBase.Run is a clear indication that "running an application" was an afterthought when making dotnet core host design decisions (old windows service api is not compatible with new Host/Lifetime api).

For full framework I've been using following approach that does not require separate thread since forever (aka .net 1.1):

//  error handling logic omitted

interface IApp // host+hostlifetime
{
  int Run(string[] args);
}

interface IDaemon // hosted service
{
  void Start();
  void Stop();
}

class ConsoleApp : IApp
{
  private readonly IDaemon daemon:
  public ConsoleApp(IDaemon daemon)
  {
    this.daemon = daemon;
  }
  public int Run(string[] args)
  {
       daemon.Start();
       Console.ReadLine();// or wait for Ctrl+C
       daemon.Stop();
       return 0;
  }
}

class ServiceApp : ServiceBase, IApp
{
  private readonly IDaemon daemon:
  public ServiceApp (IDaemon daemon)
  {
    this.daemon = daemon;
  }
  public int Run(string args[])
  {
     Run(this);
     return 0;
  }
  protected override void OnStart(string[] args)
  {
     base.OnStart(args);
     daemon.Start();
  }
  protected override void OnShutdown()
  {
    daemon.Stop();
    base.OnShutdown();
  }
  protected override void OnStop()
  {
      daemon.Stop();
      base.OnStop();
  }
}

public static int Main(string[] args)
{
  var daemon = CreateDaemon(args);
  var app = IsWindowsService ? new ServiceApp(daemon) : new ConsoleApp(daemon);
  return app.Run(args);
}

@ghost
Copy link

ghost commented Jul 27, 2022

Tagging subscribers to this area: @dotnet/area-extensions-hosting
See info in area-owners.md if you want to be subscribed.

Issue Details

Description

There are several bugs related to WindowsServiceLifetime implementation in 3.1:

  1. windows service hangs if there are errors during host initialization
  2. windows service is reported running until host is initialized.

#2 is can be a problem if the service is dependent by another windows service.

Reproduction Steps

Here is an example of what is roughly going on when application is started as windows service.

Create a new console application

dotnet new console --framework netcoreapp3.1 --output ServiceExitTest
dotnet add ServiceExitTest\ServiceExitTest.csproj package --version 3.1.3 Microsoft.Extensions.Hosting.WindowsServices

Replace Program.cs:

namespace ServiceExitTest
{
	using System;
	using System.IO;
	using System.ServiceProcess;
	using System.Threading;

	public class Program
	{
		private readonly static object logLock = new object();
		public static void Log(string name, string message)
		{
			lock (logLock)
			{
				message = $"{DateTime.Now} [{name}] {message}";
				File.AppendAllText("service_log.txt", message + Environment.NewLine);
			}
		}

		public static void Log(string message) => Log(nameof(Program), message);

		class StrangeService : ServiceBase
		{
			private static void Log(string message) => Program.Log(nameof(StrangeService), message);

			private readonly ManualResetEvent mre = new ManualResetEvent(false);

			public void StartService()
			{
				Log("starting service");
				new Thread(new ThreadStart(Run)).Start();
				Log("waiting for service to start");
				mre.WaitOne();
				Log("service started");
			}

			protected override void OnStart(string[] args)
			{
				Log("notifying started");
				mre.Set();
				Log("started notification complete");
				base.OnStart(args);
			}

			private void Run()
			{
				try
				{
					Log("calling ServiceBase.Run(this)");
					Run(this);
					Log("ServiceBase.Run(this) completed");
				}
				catch { }
				finally
				{
					Log("notifying completed");
					mre.Set();
					Log("completed notified");
				}
			}
		}

		public static int Main()
		{
			Directory.SetCurrentDirectory(AppDomain.CurrentDomain.BaseDirectory);
			using var service = new StrangeService();
			Log("starting strange service");
			service.StartService();
			Log("strange service started");
			Log("exiting application");
			return 1;
		}
	}
}

Create build.cmd with following content:

@echo off
sc.exe stop WINSERVICE_STOP_TEST
dotnet publish --self-contained true --configuration Release --runtime win10-x64 ServiceExitTest\ServiceExitTest.csproj
sc.exe delete WINSERVICE_STOP_TEST
sc.exe create WINSERVICE_STOP_TEST binPath= "%~dp0\ServiceExitTest\bin\Release\netcoreapp3.1\win10-x64\publish\ServiceExitTest.exe"
sc.exe start WINSERVICE_STOP_TEST

Execute build.cmd and check the current state:

C:\Repos>more ServiceExitTest\bin\Release\netcoreapp3.1\win10-x64\publish\service_log.txt
21.07.2022 11:37:25 [Program] starting strange service
21.07.2022 11:37:25 [StrangeService] starting service
21.07.2022 11:37:25 [StrangeService] waiting for service to start
21.07.2022 11:37:25 [StrangeService] calling ServiceBase.Run(this)
21.07.2022 11:37:25 [StrangeService] notifying started
21.07.2022 11:37:25 [StrangeService] started notification complete
21.07.2022 11:37:25 [StrangeService] service started
21.07.2022 11:37:25 [Program] strange service started
21.07.2022 11:37:25 [Program] exiting application

C:\Repos>sc.exe query WINSERVICE_STOP_TEST

SERVICE_NAME: WINSERVICE_STOP_TEST
        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:\Repos>tasklist /fi "IMAGENAME eq ServiceExitTest.exe"

Image Name                     PID Session Name        Session#    Mem Usage
========================= ======== ================ =========== ============
ServiceExitTest.exe          10928 Services                   0     18,800 K

So even though Main method has exited service and executable remain running. This happens because StrangeService.StartService starts new foreground thread which never completes (ServiceBase.Run does not return) because StrangeService.Stop is not called.

If you'll squint your eyes you can see that StrangeService is a WindowsServiceLifetime. The same behavior is observed in "real project" when error happens during IHostedService.StartAsync. There are couple ways to solve/workaround it:

  1. start thread as background - it will cause thread running ServiceBase.Run to be torn down when Main exists
  2. implement startup error handling to call ServiceBase.Stop if error occurred
  3. dont report service as started until ApplicationStarted is raised (my fav)

About #3 - unlike SystemdLifetime, WindowsServiceLifetime reports service is up and running inside WaitForStartAsync before IHostApplicationLifetime.ApplicationStarted is raised which is completely wrong because service is not running. This can cause problems when the service is dependent by other services.

Expected behavior

  1. windows service should stop when main method exists
  2. windows service should not be reported as started until ApplicationStarted event is raised

Actual behavior

  1. windows service does not stop if execution happens during IHostedService.Start method
  2. windows service is reported as started before ApplicationStarted event is raised

Regression?

No response

Known Workarounds

No response

Configuration

No response

Other information

No response

Author: i-sinister
Assignees: -
Labels:

untriaged, area-Extensions-Hosting

Milestone: -

@ericstj
Copy link
Member

ericstj commented Jul 27, 2022

Changed the area path - I believe this issue is reporting a problem with Microsoft.Extensions.Hosting.WindowsServices. It's more evidence like #62579 that the hosting model and windows services aren't playing well together.

@eerhardt
Copy link
Member

@i-sinister - can you describe the issue(s) in terms of using Microsoft.Extensions.Hosting.WindowsServices, and not how WindowsServices is implemented? For example, can you give a repro project that uses Microsoft.Extensions.Hosting.WindowsServices and what the expected and actual behavior in the project is. See https://github.com/dotnet/runtime/blob/main/CONTRIBUTING.md#writing-a-good-bug-report.

@i-sinister
Copy link
Author

@eerhardt, here you are:

namespace ServiceExitTest
{
	using Microsoft.Extensions.DependencyInjection;
	using Microsoft.Extensions.Hosting;
	using System;
	using System.IO;
	using System.Threading;
	using System.Threading.Tasks;

	public class Program
	{
		private readonly static object logLock = new object();
		public static void Log(string name, string message)
		{
			lock (logLock)
			{
				message = $"{DateTime.Now} [{name}] {message}";
				File.AppendAllText("service_log.txt", message + Environment.NewLine);
			}
		}

		public static void Log(string message) => Log(nameof(Program), message);

		public class BadService : IHostedService
		{
			public Task StartAsync(CancellationToken cancellationToken)
			{
				Log("starting bad service");
				throw new Exception("kaboom");
			}

			public Task StopAsync(CancellationToken cancellationToken)
			{
				Log("stopping bad service");
				return Task.CompletedTask;
			}
		}

		public static async Task<int> Main()
		{
			Directory.SetCurrentDirectory(AppDomain.CurrentDomain.BaseDirectory);
			try
			{
				Log("building host");
				var host = Host.CreateDefaultBuilder()
					.ConfigureServices(services => services.AddHostedService<BadService>())
					.UseWindowsService()
					.Build();
				Log("running host");
				await host.RunAsync();
				Log("application completed");
				return 0;
			}
			catch (Exception ex)
			{
				Log($"error: {ex}");
				return 1;
			}
		}
	}
}

Starting windows service generates log similar to following:

C:\>more ServiceExitTest\bin\Release\netcoreapp3.1\win10-x64\publish\service_log.txt
28.07.2022 16:27:18 [Program] building host
28.07.2022 16:27:18 [Program] running host
28.07.2022 16:27:18 [Program] starting bad service
28.07.2022 16:27:18 [Program] error: System.Exception: kaboom
   at ServiceExitTest.Program.BadService.StartAsync(CancellationToken cancellationToken) in C:\ServiceExitTest\Program.cs:line 71
   at Microsoft.Extensions.Hosting.Internal.Host.StartAsync(CancellationToken cancellationToken)
   at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.RunAsync(IHost host, CancellationToken token)
   at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.RunAsync(IHost host, CancellationToken token)
   at ServiceExitTest.Program.Main() in C:\ServiceExitTest\Program.cs:line 101

After 'error ...' log line main function exits and host and all related services are disposed. However executable remains running, as well as windows service.

@eerhardt
Copy link
Member

However executable remains running, as well as windows service.

I see above it appears you are using netcoreapp3.1. Have you tried this with the latest? When I use net6.0 and the 6.0.0 version of Microsoft.Extensions.Hosting.WindowsServices, the service is stopped after the exception is thrown.

So even though Main method has exited service and executable remain running. This happens because StrangeService.StartService starts new foreground thread which never completes

The latest code uses a background thread:

Thread thread = new Thread(Run);
thread.IsBackground = true;
thread.Start(); // Otherwise this would block and prevent IHost.StartAsync from finishing.

@i-sinister
Copy link
Author

i-sinister commented Jul 29, 2022

I see above it appears you are using netcoreapp3.1. Have you tried this with the latest?

Nope, as we are using 3.1 - there are multiple services that were written even before 6.0 was a thing.

The latest code uses a background thread: ...

This should not be happening then. I only wonder is it the correct way to handle this scenario.

However the issue with reporting windows service as started while it is actually starting and apis are not available is still present

@eerhardt
Copy link
Member

However the issue with reporting windows service as started while it is actually starting and apis are not available is still present

can you describe the issue(s) with a repro project that uses Microsoft.Extensions.Hosting.WindowsServices and what the expected and actual behavior in the project is? See https://github.com/dotnet/runtime/blob/main/CONTRIBUTING.md#writing-a-good-bug-report.

@i-sinister
Copy link
Author

I dont understand what is unclear in the first post but anyway here is it:

Replace Program.cs with:

namespace ServiceExitTest
{
	using Microsoft.Extensions.DependencyInjection;
	using Microsoft.Extensions.Hosting;
	using System;
	using System.IO;
	using System.Threading;
	using System.Threading.Tasks;

	public class Program
	{
		private readonly static object logLock = new object();
		public static void Log(string name, string message)
		{
			lock (logLock)
			{
				message = $"{DateTime.Now} [{name}] {message}";
				File.AppendAllText("service_log.txt", message + Environment.NewLine);
			}
		}

		public static void Log(string message) => Log(nameof(Program), message);

		public class BadService : IHostedService
		{
			public async Task StartAsync(CancellationToken cancellationToken)
			{
				Log("starting bad service");
				await Task.Delay(55000);
				throw new Exception("kaboom");
			}


			public Task StopAsync(CancellationToken cancellationToken)
			{
				Log("stopping bad service");
				return Task.CompletedTask;
			}
		}

		public static async Task<int> Main()
		{
			Directory.SetCurrentDirectory(AppDomain.CurrentDomain.BaseDirectory);
			try
			{
				Log("building host");
				var host = Host.CreateDefaultBuilder()
					.ConfigureServices(services => services.AddHostedService<BadService>())
					.UseWindowsService()
					.Build();
				Log("running host");
				await host.RunAsync();
				Log("application completed");
				return 0;
			}
			catch (Exception ex)
			{
				Log($"error: {ex}");
				return 1;
			}
		}
	}
}

Starting windows service, observe logs and status:

c:\>more ServiceExitTest\bin\Release\netcoreapp3.1\win10-x64\publish\service_log.txt
30.07.2022 11:50:05 [Program] building host
30.07.2022 11:50:05 [Program] running host
30.07.2022 11:50:05 [Program] starting bad service

c:\>sc.exe query WINSERVICE_STOP_TEST

SERVICE_NAME: WINSERVICE_STOP_TEST
        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

As you can see service startup is in process but service reported as running which is not correct.

If you'll use UseSystemd instead of broken UseWindowsService the service will not be reported as running until 'starting sequence' completes.

@eerhardt
Copy link
Member

eerhardt commented Aug 9, 2022

It looks like the issue is that the ServiceBase.Run method is kicked off from WaitForStartAsync, which is called before calling each IHostService.StartAsync.

The main Host logic StartAsync:

public async Task StartAsync(CancellationToken cancellationToken = default)
{
_logger.Starting();
using var combinedCancellationTokenSource = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken, _applicationLifetime.ApplicationStopping);
CancellationToken combinedCancellationToken = combinedCancellationTokenSource.Token;
await _hostLifetime.WaitForStartAsync(combinedCancellationToken).ConfigureAwait(false);
combinedCancellationToken.ThrowIfCancellationRequested();
_hostedServices = Services.GetRequiredService<IEnumerable<IHostedService>>();
foreach (IHostedService hostedService in _hostedServices)
{
// Fire IHostedService.Start
await hostedService.StartAsync(combinedCancellationToken).ConfigureAwait(false);
if (hostedService is BackgroundService backgroundService)
{
_ = TryExecuteBackgroundServiceAsync(backgroundService);
}
}
// Fire IHostApplicationLifetime.Started
_applicationLifetime.NotifyStarted();

The sequence goes:

  • await _hostLifetime.WaitForStartAsync
  • Call each IHostedService.StartAsync
  • Raise _applicationLifetime.Started

And here is the WindowsServiceLifetime.WaitForStartAsync, which kicks off a separate thread to call ServiceBase.Run:

public Task WaitForStartAsync(CancellationToken cancellationToken)
{
cancellationToken.Register(() => _delayStart.TrySetCanceled());
ApplicationLifetime.ApplicationStarted.Register(() =>
{
Logger.LogInformation("Application started. Hosting environment: {EnvName}; Content root path: {ContentRoot}",
Environment.EnvironmentName, Environment.ContentRootPath);
});
ApplicationLifetime.ApplicationStopping.Register(() =>
{
Logger.LogInformation("Application is shutting down...");
});
ApplicationLifetime.ApplicationStopped.Register(_delayStop.Set);
Thread thread = new Thread(Run);
thread.IsBackground = true;
thread.Start(); // Otherwise this would block and prevent IHost.StartAsync from finishing.
return _delayStart.Task;
}
private void Run()
{
try
{
Run(this); // This blocks until the service is stopped.

This means the "Windows Service" side thinks the service is up and running before the IHostService.StartAsync methods get to run.

One potential fix for this would be to move the code that kicks off a thread to call ServiceBase.Run into the ApplicationLifetime.Started handler. That way it occurs after each service has started.

@Tratcher - do you know why it was done this way originally?

@i-sinister - one potential workaround for now would be to subscribe to ApplicationLifetime.ApplicationStarted yourself and log some message to indicate to dependent services that the service is now started.

@eerhardt eerhardt added this to the Future milestone Aug 9, 2022
@ghost ghost removed the untriaged New issue has not been triaged by the area owner label Aug 9, 2022
@davidfowl
Copy link
Member

One potential fix for this would be to move the code that kicks off a thread to call ServiceBase.Run into the ApplicationLifetime.Started handler. That way it occurs after each service has started.

That seems like a reasonable change but I don't know what else it impacts. It means hosted services run before ServiceBase does anything right? Systemd has a lighter weight communication model where the application just sends signals over a unix domain socket signaling (started, or stopped).

@davidfowl
Copy link
Member

I think I remember why it was done this way. We use OnStart to signal that the service is starting up. Basically we let the windows service tell us when it has started before we start running user code. For that to be the case we needed to Run the service.

It seems like instead we'd want to either:

  • Run the windows service after the hosted services run. I'm don't think failures would propagate, it would just never start the service if any of those fail.
  • Run the startup sequence from OnStart. This is a bit inverted because the IHostLifetime APIs don't have a way to run the startup sequence of the host. It's just one of the things the host uses before it starts the sequence.

@eerhardt
Copy link
Member

eerhardt commented Aug 10, 2022

This seems to be a common theme with Hosting.WindowsServices. Which app model is "in charge"? I wrote about this in #63284 (comment) w.r.t. exiting the app. There it was basically decided that the Extensions.Hosting app model "sits on top of" ServiceBase, and Extensions.Hosting is the owner/controller of the process.

What if we add a wait both ways in OnStart? We do the same sequence we do today and wait for ServiceBase.OnStart to get called before running user code. But then the new change is to block the ServiceBase.OnStart waiting for the _applicationLifetime.Started event to be raised (basically all of the IHostedService.StartAsync methods have completed).

The sequence would be:

  • await _hostLifetime.WaitForStartAsync
    • Spin up a thread for ServiceBase.Run to be called
    • Wait for ServiceBase.OnStart to be invoked. When it is invoked, it sets the _delayStart flag indicating that it was called, and then it waits for the "started" flag to be set.
  • Call each IHostedService.StartAsync
  • Raise _applicationLifetime.Started
    • Unblock ServiceBase.OnStart thread by setting the "started" flag, which tells Windows that the service is now running

Thoughts?

@Tratcher
Copy link
Member

The main complaint above seems to be that the service reports as "running" before IHostedService's are called. Run is needed to tell the service we're ready to start and wait for the service host to actually start us. Does the service report "running" before or after OnStart is called?

@davidfowl
Copy link
Member

Right as long as we can also propagate failures so if Started never fires, we want OnStart to throw or fail or something.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

5 participants