Skip to content

Log meaningful job names and use template based log messages#15307

Merged
Migaroez merged 2 commits intorelease/13.0from
v13/fix/background-service-runner-logging
Nov 29, 2023
Merged

Log meaningful job names and use template based log messages#15307
Migaroez merged 2 commits intorelease/13.0from
v13/fix/background-service-runner-logging

Conversation

@kjac
Copy link
Copy Markdown
Contributor

@kjac kjac commented Nov 28, 2023

Prerequisites

  • I have added steps to test this contribution in the description below

If there's an existing issue for this PR then this fixes #15302

Description

As described in the linked issue, the new RecurringBackgroundJobHostedServiceRunner has a little flaw in its logging: It doesn't log the actual names of the jobs it's starting, but the generic type of the hosted service instead:

image

This PR makes the logging a little bit more verbose, in order to log both the creation and the start-up of each individual hosted service - this time using the job names:

image

While I was here, I also changed all logging to use template based log messages.

Testing this PR

All recurring jobs (hosted services) should start and run as per usual. The log should display the names of the jobs rather than the generic type of the hosted service.

{
_logger.LogInformation($"Starting background hosted service for {hostedService.GetType().Name}");

_logger.LogInformation("Creating background hosted service for {job}", jobName);
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this is a bit too much spam, there's already a "Starting ...", and if it fails a "Failed to start ..." message, there are no other possibilities.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Creating a job and starting it can have 2 different failure reasons.
With the current code flow, if you see a failed to start message it might be because of the factory failing or the created service not actually starting.

A way to resolve this and reduce messages being logged is to Log a message right after getting the jobName Booting/Initializing/Hosting background job {Jobname}
And wrapping the factory and the start in separate try catches with each having a distinct message template
For Completnes, you could leave the Creating/Starting messages but change their level to debug.

private readonly List<IRecurringBackgroundJob> _jobs;
private readonly Func<IRecurringBackgroundJob, IHostedService> _jobFactory;
private IList<IHostedService> _hostedServices = new List<IHostedService>();
private readonly List<(IHostedService HostedService, string JobName)> _hostedServices = new();
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please create a private sub class in the same file to model this data to improve readability
Name suggestion: NamedServiceJob

{
_logger.LogInformation($"Starting background hosted service for {hostedService.GetType().Name}");

_logger.LogInformation("Creating background hosted service for {job}", jobName);
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Creating a job and starting it can have 2 different failure reasons.
With the current code flow, if you see a failed to start message it might be because of the factory failing or the created service not actually starting.

A way to resolve this and reduce messages being logged is to Log a message right after getting the jobName Booting/Initializing/Hosting background job {Jobname}
And wrapping the factory and the start in separate try catches with each having a distinct message template
For Completnes, you could leave the Creating/Starting messages but change their level to debug.

@kjac
Copy link
Copy Markdown
Contributor Author

kjac commented Nov 29, 2023

Makes sense - thanks for chiming in, @Nuklon 😄

I have changed the "Creating..." message to use log level "Debug", so it won't be visible unless one is really looking for it. And @Migaroez is spot on why we need both messages 😆

image

Also added the class, thanks for the suggestion 👍

@Migaroez Migaroez merged commit b596900 into release/13.0 Nov 29, 2023
@Migaroez Migaroez deleted the v13/fix/background-service-runner-logging branch November 29, 2023 14:35
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants