Reproduce for issue #708

[RomanSoloweow]

Reproduce for issue #708

[codecov-commenter]

Codecov Report

All modified and coverable lines are covered by tests ✅

Comparison is base (a72df32) 81.00% compared to head (bf9aea6) 80.71%.

❗ Your organization needs to install the Codecov GitHub app to enable full functionality.

Additional details and impacted files

@@            Coverage Diff             @@
##           master     #709      +/-   ##
==========================================
- Coverage   81.00%   80.71%   -0.29%     
==========================================
  Files          19       19              
  Lines        1732     1732              
  Branches      295      295              
==========================================
- Hits         1403     1398       -5     
- Misses        193      198       +5     
  Partials      136      136              

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[snakefoot]

Have the following output in console-example.log after starting the HostingExample two times, and there is a single "header" for every startup.

Header
2023/12/02 12:48:13.303|INFO|Message before configure host builder |HostingExample.Program|
2023/12/02 12:48:13.469|DEBUG|Hosting starting |Microsoft.Extensions.Hosting.Internal.Host|EventId=1, EventName=Starting
2023/12/02 12:48:13.492|INFO|ConsoleHostedService instance created... |HostingExample.Program.ConsoleHostedService|
2023/12/02 12:48:13.492|INFO|Hello from your hosted service thread! |HostingExample.Program.ConsoleHostedService|
2023/12/02 12:48:13.492|TRACE|I may or may not return for a long time depending on what I do. |HostingExample.Program.ConsoleHostedService|
2023/12/02 12:48:13.492|DEBUG|In this example, I return right away, but my host will continue to run until |HostingExample.Program.ConsoleHostedService|
2023/12/02 12:48:13.492|INFO|its CancellationToken is Cancelled (SIGTERM(Ctrl-C) or a Lifetime Event ) |HostingExample.Program.ConsoleHostedService|
2023/12/02 12:48:13.499|INFO|Application started. Press Ctrl+C to shut down. |Microsoft.Hosting.Lifetime|
2023/12/02 12:48:13.499|INFO|Hosting environment: Production |Microsoft.Hosting.Lifetime|EnvName=Production
2023/12/02 12:48:13.499|INFO|Content root path: C:\Users\snakefoot\source\repos\NLog.Extensions.Logging\examples\NetCore2\HostingExample\bin\Debug\net7.0\ |Microsoft.Hosting.Lifetime|ContentRoot=C:\Users\snakefoot\source\repos\NLog.Extensions.Logging\examples\NetCore2\HostingExample\bin\Debug\net7.0\
2023/12/02 12:48:13.499|DEBUG|Hosting started |Microsoft.Extensions.Hosting.Internal.Host|EventId=2, EventName=Started
Header
2023/12/02 12:48:26.252|INFO|Message before configure host builder |HostingExample.Program|
2023/12/02 12:48:26.463|DEBUG|Hosting starting |Microsoft.Extensions.Hosting.Internal.Host|EventId=1, EventName=Starting
2023/12/02 12:48:26.547|INFO|ConsoleHostedService instance created... |HostingExample.Program.ConsoleHostedService|
2023/12/02 12:48:26.580|INFO|Hello from your hosted service thread! |HostingExample.Program.ConsoleHostedService|
2023/12/02 12:48:26.605|TRACE|I may or may not return for a long time depending on what I do. |HostingExample.Program.ConsoleHostedService|
2023/12/02 12:48:26.636|DEBUG|In this example, I return right away, but my host will continue to run until |HostingExample.Program.ConsoleHostedService|
2023/12/02 12:48:26.653|INFO|its CancellationToken is Cancelled (SIGTERM(Ctrl-C) or a Lifetime Event ) |HostingExample.Program.ConsoleHostedService|
2023/12/02 12:48:26.660|INFO|Application started. Press Ctrl+C to shut down. |Microsoft.Hosting.Lifetime|
2023/12/02 12:48:26.681|INFO|Hosting environment: Production |Microsoft.Hosting.Lifetime|EnvName=Production
2023/12/02 12:48:26.717|INFO|Content root path: C:\Users\snakefoot\source\repos\NLog.Extensions.Logging\examples\NetCore2\HostingExample\bin\Debug\net7.0\ |Microsoft.Hosting.Lifetime|ContentRoot=C:\Users\snakefoot\source\repos\NLog.Extensions.Logging\examples\NetCore2\HostingExample\bin\Debug\net7.0\
2023/12/02 12:48:26.744|DEBUG|Hosting started |Microsoft.Extensions.Hosting.Internal.Host|EventId=2, EventName=Started

[RomanSoloweow]

Which OS you use? It's windows 10 and 11 for me (reproduced for both)

[snakefoot]

I'm running on Windows 10, this the output from console-example-internal.log:

2023-12-02 15:15:14.3960 Debug Message Template Auto Format enabled
2023-12-02 15:15:14.5367 Debug Adding target NLog.Targets.FileTarget(Name=fileTarget)
2023-12-02 15:15:14.5367 Info Registered target NLog.Targets.FileTarget(Name=fileTarget)
2023-12-02 15:15:14.5367 Debug Adding target NLog.Targets.ConsoleTarget(Name=consoleTarget)
2023-12-02 15:15:14.5367 Info Registered target NLog.Targets.ConsoleTarget(Name=consoleTarget)
2023-12-02 15:15:14.5673 Info NLog, Version=5.0.0.0, Culture=neutral, PublicKeyToken=5120e14c03d0593c. File version: 5.2.7.2287. Product version: 5.2.7+a1ef7cd83b5a6a172142a6850f0ced4e759a4b3b. GlobalAssemblyCache: False
2023-12-02 15:15:14.5952 Debug Start watching file-filter 'NLog.config' in directory: C:\Users\snakefoot\source\repos\NLog.Extensions.Logging\examples\NetCore2\HostingExample\bin\Debug\net7.0
2023-12-02 15:15:14.5952 Debug --- NLog configuration dump ---
2023-12-02 15:15:14.5952 Debug Targets:
2023-12-02 15:15:14.5952 Debug FileTarget(Name=fileTarget)
2023-12-02 15:15:14.5952 Debug ConsoleTarget(Name=consoleTarget)
2023-12-02 15:15:14.5952 Debug Rules:
2023-12-02 15:15:14.5952 Debug logNamePattern: (:All) levels: [ Trace Debug Info Warn Error Fatal ] writeTo: [ fileTarget consoleTarget ]
2023-12-02 15:15:14.5952 Debug --- End of NLog configuration dump ---
2023-12-02 15:15:14.6342 Info Validating config: TargetNames=fileTarget, consoleTarget, ConfigItems=31, FilePath=C:\Users\snakefoot\source\repos\NLog.Extensions.Logging\examples\NetCore2\HostingExample\bin\Debug\net7.0\NLog.config
2023-12-02 15:15:14.6342 Debug Unused target checking is started... Rule Count: 1, Target Count: 2
2023-12-02 15:15:14.6342 Debug Unused target checking is completed. Total Rule Count: 1, Total Target Count: 2, Unused Target Count: 0
2023-12-02 15:15:14.6495 Info Configuration initialized.
2023-12-02 15:15:14.6495 Debug Targets configured when LogLevel >= Trace for Logger: HostingExample.Program
2023-12-02 15:15:14.6495 Debug Logger HostingExample.Program [Trace] => fileTarget consoleTarget
2023-12-02 15:15:14.6495 Debug Logger HostingExample.Program [Debug] => fileTarget consoleTarget
2023-12-02 15:15:14.6495 Debug Logger HostingExample.Program [Info] => fileTarget consoleTarget
2023-12-02 15:15:14.6495 Debug Logger HostingExample.Program [Warn] => fileTarget consoleTarget
2023-12-02 15:15:14.6495 Debug Logger HostingExample.Program [Error] => fileTarget consoleTarget
2023-12-02 15:15:14.6495 Debug Logger HostingExample.Program [Fatal] => fileTarget consoleTarget
2023-12-02 15:15:14.6631 Debug FileTarget(Name=fileTarget): Preparing for new file: 'c:\temp\console-example.log'
2023-12-02 15:15:14.6631 Debug FileTarget(Name=fileTarget): Creating file appender: 'c:\temp\console-example.log'
2023-12-02 15:15:14.7859 Debug Hide assemblies for callsite
2023-12-02 15:15:14.7859 Debug Skip loading NLogLoggingConfiguration from empty config section: NLog
2023-12-02 15:15:14.8044 Debug Targets configured when LogLevel >= Trace for Logger: Microsoft.Extensions.Hosting.Internal.ApplicationLifetime
2023-12-02 15:15:14.8044 Debug Logger Microsoft.Extensions.Hosting.Internal.ApplicationLifetime [Trace] => fileTarget consoleTarget
2023-12-02 15:15:14.8044 Debug Logger Microsoft.Extensions.Hosting.Internal.ApplicationLifetime [Debug] => fileTarget consoleTarget
2023-12-02 15:15:14.8044 Debug Logger Microsoft.Extensions.Hosting.Internal.ApplicationLifetime [Info] => fileTarget consoleTarget
2023-12-02 15:15:14.8044 Debug Logger Microsoft.Extensions.Hosting.Internal.ApplicationLifetime [Warn] => fileTarget consoleTarget
2023-12-02 15:15:14.8044 Debug Logger Microsoft.Extensions.Hosting.Internal.ApplicationLifetime [Error] => fileTarget consoleTarget
2023-12-02 15:15:14.8044 Debug Logger Microsoft.Extensions.Hosting.Internal.ApplicationLifetime [Fatal] => fileTarget consoleTarget
2023-12-02 15:15:14.8126 Debug Targets configured when LogLevel >= Trace for Logger: Microsoft.Extensions.Hosting.Internal.Host
2023-12-02 15:15:14.8126 Debug Logger Microsoft.Extensions.Hosting.Internal.Host [Trace] => fileTarget consoleTarget
2023-12-02 15:15:14.8126 Debug Logger Microsoft.Extensions.Hosting.Internal.Host [Debug] => fileTarget consoleTarget
2023-12-02 15:15:14.8126 Debug Logger Microsoft.Extensions.Hosting.Internal.Host [Info] => fileTarget consoleTarget
2023-12-02 15:15:14.8126 Debug Logger Microsoft.Extensions.Hosting.Internal.Host [Warn] => fileTarget consoleTarget
2023-12-02 15:15:14.8126 Debug Logger Microsoft.Extensions.Hosting.Internal.Host [Error] => fileTarget consoleTarget
2023-12-02 15:15:14.8126 Debug Logger Microsoft.Extensions.Hosting.Internal.Host [Fatal] => fileTarget consoleTarget
2023-12-02 15:15:14.8126 Debug Targets configured when LogLevel >= Trace for Logger: Microsoft.Hosting.Lifetime
2023-12-02 15:15:14.8126 Debug Logger Microsoft.Hosting.Lifetime [Trace] => fileTarget consoleTarget
2023-12-02 15:15:14.8126 Debug Logger Microsoft.Hosting.Lifetime [Debug] => fileTarget consoleTarget
2023-12-02 15:15:14.8126 Debug Logger Microsoft.Hosting.Lifetime [Info] => fileTarget consoleTarget
2023-12-02 15:15:14.8126 Debug Logger Microsoft.Hosting.Lifetime [Warn] => fileTarget consoleTarget
2023-12-02 15:15:14.8126 Debug Logger Microsoft.Hosting.Lifetime [Error] => fileTarget consoleTarget
2023-12-02 15:15:14.8126 Debug Logger Microsoft.Hosting.Lifetime [Fatal] => fileTarget consoleTarget
2023-12-02 15:15:14.8354 Debug Targets configured when LogLevel >= Trace for Logger: HostingExample.Program.ConsoleHostedService
2023-12-02 15:15:14.8354 Debug Logger HostingExample.Program.ConsoleHostedService [Trace] => fileTarget consoleTarget
2023-12-02 15:15:14.8354 Debug Logger HostingExample.Program.ConsoleHostedService [Debug] => fileTarget consoleTarget
2023-12-02 15:15:14.8354 Debug Logger HostingExample.Program.ConsoleHostedService [Info] => fileTarget consoleTarget
2023-12-02 15:15:14.8354 Debug Logger HostingExample.Program.ConsoleHostedService [Warn] => fileTarget consoleTarget
2023-12-02 15:15:14.8354 Debug Logger HostingExample.Program.ConsoleHostedService [Error] => fileTarget consoleTarget
2023-12-02 15:15:14.8354 Debug Logger HostingExample.Program.ConsoleHostedService [Fatal] => fileTarget consoleTarget

[RomanSoloweow]

console-example-internal.log:

2023-12-02 13:10:05.1947 Debug FileTarget(Name=fileTarget): Recreating FileStream because no longer File.Exists: 'c:\temp\console-example.log'
2023-12-02 13:10:05.2010 Debug LogFactory Flush with timeout=15 secs
2023-12-02 13:10:05.2010 Debug Flush completed
2023-12-02 13:10:08.6685 Debug Message Template Auto Format enabled
2023-12-02 13:10:08.7008 Debug Adding target NLog.Targets.FileTarget(Name=fileTarget)
2023-12-02 13:10:08.7008 Info Registered target NLog.Targets.FileTarget(Name=fileTarget)
2023-12-02 13:10:08.7008 Debug Adding target NLog.Targets.ConsoleTarget(Name=consoleTarget)
2023-12-02 13:10:08.7008 Info Registered target NLog.Targets.ConsoleTarget(Name=consoleTarget)
2023-12-02 13:10:08.7008 Info NLog, Version=5.0.0.0, Culture=neutral, PublicKeyToken=5120e14c03d0593c. File version: 5.2.7.2287. Product version: 5.2.7+a1ef7cd83b5a6a172142a6850f0ced4e759a4b3b. GlobalAssemblyCache: False
2023-12-02 13:10:08.7008 Debug Start watching file-filter 'NLog.config' in directory: C:\git\NLog.Extensions.Logging\examples\NetCore2\HostingExample\bin\Debug\net7.0
2023-12-02 13:10:08.7008 Debug --- NLog configuration dump ---
2023-12-02 13:10:08.7008 Debug Targets:
2023-12-02 13:10:08.7008 Debug FileTarget(Name=fileTarget)
2023-12-02 13:10:08.7008 Debug ConsoleTarget(Name=consoleTarget)
2023-12-02 13:10:08.7008 Debug Rules:
2023-12-02 13:10:08.7008 Debug logNamePattern: (:All) levels: [ Trace Debug Info Warn Error Fatal ] writeTo: [ fileTarget consoleTarget ]
2023-12-02 13:10:08.7008 Debug --- End of NLog configuration dump ---
2023-12-02 13:10:08.7165 Info Validating config: TargetNames=fileTarget, consoleTarget, ConfigItems=31, FilePath=C:\git\NLog.Extensions.Logging\examples\NetCore2\HostingExample\bin\Debug\net7.0\NLog.config
2023-12-02 13:10:08.7165 Debug Unused target checking is started... Rule Count: 1, Target Count: 2
2023-12-02 13:10:08.7165 Debug Unused target checking is completed. Total Rule Count: 1, Total Target Count: 2, Unused Target Count: 0
2023-12-02 13:10:08.7165 Info Configuration initialized.
2023-12-02 13:10:08.7165 Debug Targets configured when LogLevel >= Trace for Logger: HostingExample.Program
2023-12-02 13:10:08.7165 Debug Logger HostingExample.Program [Trace] => fileTarget consoleTarget
2023-12-02 13:10:08.7165 Debug Logger HostingExample.Program [Debug] => fileTarget consoleTarget
2023-12-02 13:10:08.7165 Debug Logger HostingExample.Program [Info] => fileTarget consoleTarget
2023-12-02 13:10:08.7165 Debug Logger HostingExample.Program [Warn] => fileTarget consoleTarget
2023-12-02 13:10:08.7165 Debug Logger HostingExample.Program [Error] => fileTarget consoleTarget
2023-12-02 13:10:08.7165 Debug Logger HostingExample.Program [Fatal] => fileTarget consoleTarget
2023-12-02 13:10:08.7306 Debug FileTarget(Name=fileTarget): Preparing for new file: 'c:\temp\console-example.log'
2023-12-02 13:10:08.7306 Debug FileTarget(Name=fileTarget): Creating file appender: 'c:\temp\console-example.log'
2023-12-02 13:10:08.7807 Debug Hide assemblies for callsite
2023-12-02 13:10:08.7807 Debug Skip loading NLogLoggingConfiguration from empty config section: NLog
2023-12-02 13:10:08.7807 Info Closing old configuration.
2023-12-02 13:10:08.7807 Debug LogFactory Flush with timeout=15 secs
2023-12-02 13:10:08.7807 Debug Flush completed
2023-12-02 13:10:08.7807 Debug Closing logging configuration...
2023-12-02 13:10:08.7807 Debug FileTarget(Name=fileTarget): Closing...
2023-12-02 13:10:08.7807 Debug FileTarget(Name=fileTarget): FileAppender Invalidate Closing File: 'c:\temp\console-example.log'
2023-12-02 13:10:08.7807 Debug FileTarget(Name=fileTarget): Closed.
2023-12-02 13:10:08.7807 Debug ConsoleTarget(Name=consoleTarget): Closing...
2023-12-02 13:10:08.7807 Debug ConsoleTarget(Name=consoleTarget): Closed.
2023-12-02 13:10:08.7807 Debug Finished closing logging configuration.
2023-12-02 13:10:08.7926 Debug Stop watching file-filter 'NLog.config' in directory: C:\git\NLog.Extensions.Logging\examples\NetCore2\HostingExample\bin\Debug\net7.0
2023-12-02 13:10:08.7926 Debug Start watching file-filter 'NLog.config' in directory: C:\git\NLog.Extensions.Logging\examples\NetCore2\HostingExample\bin\Debug\net7.0
2023-12-02 13:10:08.7926 Debug --- NLog configuration dump ---
2023-12-02 13:10:08.7926 Debug Targets:
2023-12-02 13:10:08.7926 Debug FileTarget(Name=fileTarget)
2023-12-02 13:10:08.7926 Debug ConsoleTarget(Name=consoleTarget)
2023-12-02 13:10:08.7926 Debug Rules:
2023-12-02 13:10:08.7926 Debug logNamePattern: (:All) levels: [ Trace Debug Info Warn Error Fatal ] writeTo: [ fileTarget consoleTarget ]
2023-12-02 13:10:08.7926 Debug --- End of NLog configuration dump ---
2023-12-02 13:10:08.7926 Info Validating config: TargetNames=fileTarget, consoleTarget, ConfigItems=31, FilePath=C:\git\NLog.Extensions.Logging\examples\NetCore2\HostingExample\bin\Debug\net7.0\NLog.config
2023-12-02 13:10:08.7926 Debug Targets configured when LogLevel >= Trace for Logger: HostingExample.Program
2023-12-02 13:10:08.7926 Debug Logger HostingExample.Program [Trace] => fileTarget consoleTarget
2023-12-02 13:10:08.7926 Debug Logger HostingExample.Program [Debug] => fileTarget consoleTarget
2023-12-02 13:10:08.7926 Debug Logger HostingExample.Program [Info] => fileTarget consoleTarget
2023-12-02 13:10:08.7926 Debug Logger HostingExample.Program [Warn] => fileTarget consoleTarget
2023-12-02 13:10:08.7926 Debug Logger HostingExample.Program [Error] => fileTarget consoleTarget
2023-12-02 13:10:08.7926 Debug Logger HostingExample.Program [Fatal] => fileTarget consoleTarget
2023-12-02 13:10:08.7926 Info Configuration initialized.
2023-12-02 13:10:08.7926 Debug Targets configured when LogLevel >= Trace for Logger: Microsoft.Extensions.Hosting.Internal.ApplicationLifetime
2023-12-02 13:10:08.7926 Debug Logger Microsoft.Extensions.Hosting.Internal.ApplicationLifetime [Trace] => fileTarget consoleTarget
2023-12-02 13:10:08.7926 Debug Logger Microsoft.Extensions.Hosting.Internal.ApplicationLifetime [Debug] => fileTarget consoleTarget
2023-12-02 13:10:08.7926 Debug Logger Microsoft.Extensions.Hosting.Internal.ApplicationLifetime [Info] => fileTarget consoleTarget
2023-12-02 13:10:08.7926 Debug Logger Microsoft.Extensions.Hosting.Internal.ApplicationLifetime [Warn] => fileTarget consoleTarget
2023-12-02 13:10:08.7926 Debug Logger Microsoft.Extensions.Hosting.Internal.ApplicationLifetime [Error] => fileTarget consoleTarget
2023-12-02 13:10:08.7926 Debug Logger Microsoft.Extensions.Hosting.Internal.ApplicationLifetime [Fatal] => fileTarget consoleTarget
2023-12-02 13:10:08.7926 Debug Targets configured when LogLevel >= Trace for Logger: Microsoft.Extensions.Hosting.Internal.Host
2023-12-02 13:10:08.7926 Debug Logger Microsoft.Extensions.Hosting.Internal.Host [Trace] => fileTarget consoleTarget
2023-12-02 13:10:08.8084 Debug Logger Microsoft.Extensions.Hosting.Internal.Host [Debug] => fileTarget consoleTarget
2023-12-02 13:10:08.8084 Debug Logger Microsoft.Extensions.Hosting.Internal.Host [Info] => fileTarget consoleTarget
2023-12-02 13:10:08.8084 Debug Logger Microsoft.Extensions.Hosting.Internal.Host [Warn] => fileTarget consoleTarget
2023-12-02 13:10:08.8084 Debug Logger Microsoft.Extensions.Hosting.Internal.Host [Error] => fileTarget consoleTarget
2023-12-02 13:10:08.8084 Debug Logger Microsoft.Extensions.Hosting.Internal.Host [Fatal] => fileTarget consoleTarget
2023-12-02 13:10:08.8084 Debug Targets configured when LogLevel >= Trace for Logger: Microsoft.Hosting.Lifetime
2023-12-02 13:10:08.8084 Debug Logger Microsoft.Hosting.Lifetime [Trace] => fileTarget consoleTarget
2023-12-02 13:10:08.8084 Debug Logger Microsoft.Hosting.Lifetime [Debug] => fileTarget consoleTarget
2023-12-02 13:10:08.8084 Debug Logger Microsoft.Hosting.Lifetime [Info] => fileTarget consoleTarget
2023-12-02 13:10:08.8084 Debug Logger Microsoft.Hosting.Lifetime [Warn] => fileTarget consoleTarget
2023-12-02 13:10:08.8084 Debug Logger Microsoft.Hosting.Lifetime [Error] => fileTarget consoleTarget
2023-12-02 13:10:08.8084 Debug Logger Microsoft.Hosting.Lifetime [Fatal] => fileTarget consoleTarget
2023-12-02 13:10:08.8245 Debug FileTarget(Name=fileTarget): Preparing for new file: 'c:\temp\console-example.log'
2023-12-02 13:10:08.8245 Debug FileTarget(Name=fileTarget): Creating file appender: 'c:\temp\console-example.log'
2023-12-02 13:10:08.8245 Debug Targets configured when LogLevel >= Trace for Logger: HostingExample.Program.ConsoleHostedService
2023-12-02 13:10:08.8245 Debug Logger HostingExample.Program.ConsoleHostedService [Trace] => fileTarget consoleTarget
2023-12-02 13:10:08.8245 Debug Logger HostingExample.Program.ConsoleHostedService [Debug] => fileTarget consoleTarget
2023-12-02 13:10:08.8245 Debug Logger HostingExample.Program.ConsoleHostedService [Info] => fileTarget consoleTarget
2023-12-02 13:10:08.8245 Debug Logger HostingExample.Program.ConsoleHostedService [Warn] => fileTarget consoleTarget
2023-12-02 13:10:08.8245 Debug Logger HostingExample.Program.ConsoleHostedService [Error] => fileTarget consoleTarget
2023-12-02 13:10:08.8245 Debug Logger HostingExample.Program.ConsoleHostedService [Fatal] => fileTarget consoleTarget
2023-12-02 13:10:14.6836 Debug LogFactory Flush with timeout=15 secs
2023-12-02 13:10:14.6836 Debug Flush completed

[snakefoot]

Ahh sorry can see you are calling builder.AddNLog(logger.Factory.Configuration); which forces AddNLog to re-assign the configuration (thus closing file-target and all filehandles, followed by re-initializing it)

Try just using builder.AddNLog()

[snakefoot]

Closing pull-request, since the issue has been found.