AspNetCore 2.2 Unable to Write Logs (File & SQL)

[benwelker]

Type:

• Bug

NLog version: 4.5.11

NLog.Web/NLog.Web.AspNetCore version: 4.7.0

NLog.Extensions.Logging version: 1.3.0

Platform: .NET Core 2

Current NLog config (xml or C#, if relevant)

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      autoReload="true"
      internalLogLevel="trace"
      internalLogFile="c:\temp\internal-nlog.txt">

  <!-- enable asp.net core layout renderers -->
  <extensions>
    <add assembly="NLog.Web.AspNetCore"/>
  </extensions>

  <!-- the targets to write to -->
  <targets>
    <!-- write logs to file  -->
    <target xsi:type="File" name="allfile" fileName="c:\temp\nlog-all-${shortdate}.log"
            layout="${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}" />

    <!-- another file log, only own logs. Uses some ASP.NET core renderers -->
    <target xsi:type="File" name="ownFile-web" fileName="c:\temp\nlog-own-${shortdate}.log"
            layout="${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}|url: ${aspnet-request-url}|action: ${aspnet-mvc-action}" />
  </targets>

  <!-- rules to map from logger name to target -->
  <rules>
    <!--All logs, including from Microsoft-->
    <logger name="*" minlevel="Trace" writeTo="allfile" />

    <!--Skip non-critical Microsoft logs and so log only own logs-->
    <logger name="Microsoft.*" maxLevel="Info" final="true" /> <!-- BlackHole without writeTo -->
    <logger name="*" minlevel="Trace" writeTo="ownFile-web" />
  </rules>
</nlog>

In case of a BUG:

• What is the current result? Log file is created, but only the init debug is written to the log when initializing NLog.

• What is the expected result? Information is written to logs such as the API calls and times, plus any additional logging that's implemented be output to the log files.

• Did you checked the Internal log? Yes, I didn't find anything that I would consider an issue.

• Please post full exception details (message, stacktrace, inner exceptions) I'm unable to locate any messages or exceptions.

• Are there any workarounds? No

• Is there a version in which it did work? This previously worked with NLog.Web.AspNetCore 4.5.4 with .NetCore 2.0

• Can you help us by writing an unit test? I wouldn't know where to begin honestly.

I originally posted over here. I was told to create a small example. So I went through the basic instructions found here. I copied everything and have attempted to log things and it's not working as I'd expect. This is just file logging, my actual application doesn't seem to log to files or to a database anymore, but one thing at a time I suppose.

Attached is my example solution that I've made, where it doesn't seem to log anything from the ValuesController, no API related calls are logged like in the starter example. I get the "init main" debug line, but that's it, I don't get the output from the controller in the logs.

Example Solution: Test.zip *Updated test program, since I screwed it up the first time.

Please let me know if more information or anything is needed, first time opening an issue, and I try really hard not to, because I'm sure I've screwed something up some how.

[benwelker]

Think I found the issue, I'm not sure why it's an issue, maybe someone can answer that for me though.

Essentially, the way I set up the test program was based on my main project. In that project, I do the following:

var logger = NLog.Web.NLogBuilder.ConfigureNLog("nlog.config").GetCurrentClassLogger();
var host = CreateWebHostBuilder(args).Build();
try
{
    logger.Debug("init main");
}
catch (Exception ex)
{
    //NLog: catch setup errors
    logger.Error(ex, "Stopped program because of exception");
    throw;
}
finally
{
    // Ensure to flush and stop internal timers/threads before application-exit (Avoid segmentation fault on Linux)
    NLog.LogManager.Shutdown();
}

From there, before actually doing host.Run() I do this

using (var scope = host.Services.CreateScope())
{
    var services = scope.ServiceProvider;
    try
    {
        var serviceProvider = services.GetRequiredService<IServiceProvider>();
        var configuration = services.GetRequiredService<IConfiguration>();
        var env = services.GetRequiredService<IHostingEnvironment>();
        var context = services.GetRequiredService<DataContext>();
        SysStartup.Initiate(serviceProvider, configuration, env, context).Wait();
    }
    catch (Exception ex)
    {
        logger.Error(ex, "A problem occurred when attempting to load the necessary configurations on startup.");
    }
}

It's sort of weird to me, because it looks like the issue is me trying to assign the IWebHost to a variable and run Build() then do the logger, then do Run(). Regardless of the using statement, it doesn't seem to like that. So I have to drop the separation of host.Run() and combine it. I guess that was the only thing I changed to suite my needs, and didn't think it would be an issue, but yet, here I am.

This works:

var logger = NLog.Web.NLogBuilder.ConfigureNLog("nlog.config").GetCurrentClassLogger();
            try
            {
                logger.Debug("init main");
                CreateWebHostBuilder(args).Build().Run();
            }
            catch (Exception ex)
            {
                //NLog: catch setup errors
                logger.Error(ex, "Stopped program because of exception");
                throw;
            }
            finally
            {
                // Ensure to flush and stop internal timers/threads before application-exit (Avoid segmentation fault on Linux)
                NLog.LogManager.Shutdown();
            }

// Do some other random stuff here

This does not:

var logger = NLog.Web.NLogBuilder.ConfigureNLog("nlog.config").GetCurrentClassLogger();
var host = CreateWebHostBuilder(args).Build();
            try
            {
                logger.Debug("init main");
            }
            catch (Exception ex)
            {
                //NLog: catch setup errors
                logger.Error(ex, "Stopped program because of exception");
                throw;
            }
            finally
            {
                // Ensure to flush and stop internal timers/threads before application-exit (Avoid segmentation fault on Linux)
                NLog.LogManager.Shutdown();
            }
// Do some other random stuff here
host.Run();

Is there a reason why that's happening though?

[snakefoot]

@benwelker Think you have to ask Microsoft about their changes from NetCore2 to NetCore21. See also #329

Have now updated the wiki and the example-project to use NetCore21-style (Extracting the Build()-call)

The updated Wiki: https://github.com/NLog/NLog.Web/wiki/Getting-started-with-ASP.NET-Core-2#4-update-programcs

[benwelker]

@snakefoot Thanks, not sure why that didn't come up in my search for this particular issue. Of course, in NetCore3.0 they are changing it again, so happy days!

I managed to work around it, with the odd way I needed to grab the IServiceScope ultimately is the cause of this.

Here's what's currently working for me:

public static void Main(string[] args)
{
    CurrentDirectoryHelpers.SetCurrentDirectory();
    // NLog: setup the logger first to catch all errors
    var logger = NLog.Web.NLogBuilder.ConfigureNLog("nlog.config").GetCurrentClassLogger();
    try
    {
        logger.Debug("init main");
        CreateWebHostBuilder(args, logger).Run();
    }
    catch (Exception ex)
    {
        //NLog: catch setup errors
        logger.Error(ex, "Stopped program because of exception");
        throw;
    }
    finally
    {
        // Ensure to flush and stop internal timers/threads before application-exit (Avoid segmentation fault on Linux)
        NLog.LogManager.Shutdown();
    }
}

public static IWebHost CreateWebHostBuilder(string[] args, NLog.Logger logger)
{
    var host = WebHost.CreateDefaultBuilder(args)
        .UseStartup<Startup>()
        .UseIISIntegration()
        .ConfigureLogging(logging =>
        {
            logging.ClearProviders();
            logging.SetMinimumLevel(Microsoft.Extensions.Logging.LogLevel.Trace);
        })
        .UseNLog() // NLog: setup NLog for Dependency injection
        .Build();

    using (var scope = host.Services.CreateScope())
    {
        try
        {
            var serviceProvider = scope.ServiceProvider.GetRequiredService<IServiceProvider>();
            var configuration = scope.ServiceProvider.GetRequiredService<IConfiguration>();
            var env = scope.ServiceProvider.GetRequiredService<IHostingEnvironment>();
            var context = scope.ServiceProvider.GetRequiredService<DataContext>();
            SysStartup.Initiate(serviceProvider, configuration, env, context).Wait();
        }
        catch (Exception ex)
        {
        logger.Error(ex, "A problem occurred when attempting to load the necessary configurations on startup.");
        }
    }
    return host;
}

Really, no idea why, but I'm OK with this honestly, if it helps someone else, great, if not, at least it's some what interesting. The main reason for doing what I'm doing, was to move a lot of the startup I'm doing (db migration/update and comparing version #'s) away from the pipeline, which requires me to get information which I can't via dependency injection that early.

Either way, thanks for the response and information!