Extensions: WebHostService does not log service state changes

[Erikvl87]

Describe the bug

The WebHostService (AspNetCore) inherits from ServiceBase (corefx) which has a public property called AutoLog that is documented as follows: Indicates whether to report Start, Stop, Pause, and Continue commands in the event. This doesn't seem to work for the application (netcoreapp2.2) I am developing. I am following the guide Host ASP.NET Core in a Windows Service to accomplish this. One of my requirements is that I log state changes to the event viewer.

The documentation shows how to run as a custom service so I can handle starting and stopping events myself, but my understanding is that these event logs should already been covered by the ServiceBase using the AutoLog property. I cannot find any logs of the service being started or stopped in the event viewer (running Windows 10).

I have managed to accomplish logging to the event viewer by using the .AddEventLog() in the ConfigureLogging on the WebHostBuilder and creating a CustomWebHostService as documented, but should I? Is the documentation / implementation of AutoLog on the ServiceBase (or any other relevant code) bugged?

To Reproduce

Follow the guide Host ASP.NET Core in a Windows Service. Install and start the service and observe that the event viewer does not contain any start/stop/pause events on Windows 10.

Edit: I did find that Windows Server 2019 does log start/stopped events under id 7036. I guess this somehow does respect the AutoLog property.

Edit2: Reproducible sample: https://github.com/Erikvl87/AspNetCore-issue-12352

[anurse]

AutoLog uses an EventSource named after ServiceName value. Are you running as an admin or have you previously registered that source? If you're using a custom source name (as AutoLog does), the name has to first be registered by a user with Admin permissions. If your service is running as an Admin, it will be auto-registered, but if not you need to manually register it by running as Admin and calling an API like EventLog.CreateEventSource

[anurse]

Edit: I did find that Windows Server 2019 does log start/stopped events under id 7036. I guess this somehow does respect the AutoLog property.

Do you mean that it only works on Windows Server 2019 but still isn't working on other OS versions?

[Erikvl87]

Do you mean that it only works on Windows Server 2019 but still isn't working on other OS versions?

Yes, that is what I ment. In Windows Server 2019 the Service Control Manager is logging eventId 7036 which describes that The <service name> service entered the <running/stopped> state.

<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Name="Service Control Manager" Guid="{555908d1-a6d7-4695-8e1e-26931d2012f4}" EventSourceName="Service Control Manager" />
        <EventID Qualifiers="16384">7036</EventID>
        <Version>0</Version>
        <Level>4</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x8080000000000000</Keywords>
        <TimeCreated SystemTime="2019-07-19T13:34:31.812574400Z" />
        <EventRecordID>605</EventRecordID>
        <Correlation />
        <Execution ProcessID="696" ThreadID="4928" />
        <Channel>System</Channel>
        <Computer>MY_SERVER</Computer>
        <Security />
    </System>
    <EventData>
        <Data Name="param1">MY_APP</Data>
        <Data Name="param2">running</Data>
        <Binary>46006F006E0074006F005200650076006900650077002F0034000000</Binary>
    </EventData>
</Event>

I did not get this on Windows 10. I was assuming that these events are created somewhere internally based on the AutoLog property since its documentation is literally Indicates whether to report Start, Stop, Pause, and Continue commands in the event (log). But I think my assumption is incorrect, since the documentation of AutoLog that you mentioned states that it uses the Application event log while I am looking at logs from the Service Control Manager .

If you're using a custom source name (as AutoLog does), the name has to first be registered by a user with Admin permissions. If your service is running as an Admin, it will be auto-registered, but if not you need to manually register it by running as Admin and calling an API like EventLog.CreateEventSource

I followed the guide Service user account to create the Service user account, Log on as a service rights and Create and manage the Windows Service.

I just changed the permissions of the concerning account to be part of the Administrators group but still no service start/stopped events from the Service Control Manager event source nor the Application event source on my Windows 10 machine.

AutoLog uses an EventSource named after ServiceName value. Are you running as an admin or have you previously registered that source?

Just to make sure we are on the same page; I was expecting event logs (like the one above, 7036) for service started/stopped events without the need of AddEventLog, nor following the guide on how to Handle starting and stopping events nor applying any custom configuration for the event logger whatsoever. And that expectation was indeed met on Windows Server 2019 (by the logs from the Service Control Manager) but not on our Windows 10 development machines.

I was expecting the WebHostService : ServiceBase to log that the Service started successfully.

So basically I have an app that uses the default RunAsService method, which creates a WebHostService and runs that service. Here is a simplified version of my code:

public static void Main(string[] args)
{
    var pathToExe = Process.GetCurrentProcess().MainModule?.FileName;
    var pathToContentRoot = Path.GetDirectoryName(pathToExe);
    Directory.SetCurrentDirectory(pathToContentRoot);
    var host = CreateWebHostBuilder().Build();
    host.RunAsService();
}

private static IWebHostBuilder CreateWebHostBuilder()
{
    var builder = new WebHostBuilder()
        .UseContentRoot(Directory.GetCurrentDirectory())
        .ConfigureAppConfiguration((hostingContext, config) =>
            config.AddEnvironmentVariables())
        .UseStartup<Startup>()
        .UseKestrel();
    return builder;
}

As an alternative approach I can follow the guide Handle starting and stopping events but I don't know if I should, because it seems that these logs should have been working "out of the box".

[anurse]

Just to make sure we are on the same page; I was expecting event logs (like the one above, 7036) for service started/stopped events without the need of AddEventLog

Yep, we're on the same page. That's what I'm talking about, the built-in logging to EventLog provided by ServiceBase.

Honestly, we haven't really validated what AutoLog does in the WebHostService scenario because our general recommendation has been to just use the built-in logging functionality in ASP.NET Core (since the host should be logging lifetime events like start and stop to ILogger automatically). For example, WebHostService never sets ServiceName which may affect how AutoLog works.

[anurse]

I think the best thing here to help move forward is if you can provide a runnable sample that reproduces the problem. That way we can see the whole project and get the full context.

[Erikvl87]

I've created a runnable sample at https://github.com/Erikvl87/AspNetCore-issue-12352.

And while doing so, I've found that you are right: The ServiceName is not being set and that is the cause of the logs not being written. Logging state changes works after hard-coding ServiceName to Application. I've added the workaround to the sample as well.

Should the WebHostService be responsible to set a fall back to Application for the ServiceName? If not, that would mean we cannot be using the default RunAsService() extension method since we cannot access the ServiceName using that.

I also made a video showing both the error scenario and the working solution which you can find here: https://github.com/Erikvl87/AspNetCore-issue-12352/blob/master/aspnetcore-12352.mp4.

[anurse]

Setting the ServiceName to Application isn't really appropriate. Maybe we could set it to the assembly name.

[Erikvl87]

You've explained to me the AutoLog uses an EventSource named after ServiceName. I tested a different ServiceName in my sample repository (just changing the ServiceName to something else than application) and noticed that I do not see the service start/stopped logs anymore.

So that would mean that the assembly name first has to be registered by a user with Admin permissions. Would that be sensible default behavior? Maybe add configuration options to be able to explicitly set the name when using the RunAsService() extension method instead. That could be documented with the instruction to register the appropriate event source name in case of event logging.

Something like:

host.RunAsService(options => {
    options.ServiceName = "MyAppServiceName";
});

[anurse]

So that would mean that the assembly name first has to be registered by a user with Admin permissions.

Yep, either you need to run the app itself as an Admin (not generally desirable) or run some other application/tool as an Admin to register the source (I don't have a specific suggestion for one, if one exists).

Maybe add configuration options to be able to explicitly set the name when using the RunAsService() extension method instead.

That's a pretty reasonable suggestion. Honestly, an API like this would seem OK to me:

public static class WebHostWindowsServiceExtensions
{
    // Exiting method
    public static void RunAsService(this IWebHost host);

    // New overload
    public static void RunAsService(this IWebHost host, string serviceName);
}

Defaulting the service name to the assembly name makes sense, but so too does allowing the app to override that. I suspect we'd take a PR with that change (or we can consider it while planning for future releases), though I'd need some other folks on the team to take a look and see what they thing (cc @Tratcher @davidfowl @rynowak).

[Tratcher]

Note this functionality has moved to the generic IHost and any improvement should be made there instead. (And this issue should be moved to Extensions).

There were some design changes in the move and RunAsService no longer exists there. We would use the normal options pattern to provide a name.
https://github.com/aspnet/Extensions/blob/master/src/Hosting/WindowsServices/src/WindowsServiceLifetimeHostBuilderExtensions.cs

[anurse]

Reviving this. I'll open a more specific issue describing that proposal: Allow setting the ServiceName property in UseWindowsService (via Options). https://github.com/aspnet/Extensions/issues/2612

Closing this in lieu of that one.