.net core 2.2 writes to NLog from Main, but not from controllers

Question

I'm writing a .net core 2.2 MVC app, using NLog. from the Main function, the app writes to all levels of NLog, but from the controllers, nothing is being written.

Logging section in appsettings.json:

 "Logging": {
        "LogLevel": {
            "Default": "Trace",
            "Microsoft": "Information"
        }
    }

Nlog Config:

public static class NlogConfig
{
    public static LoggingConfiguration GetLoggingConfiguration()
    {
        var logConfig = new LoggingConfiguration();

        var consoleTarget = new ColoredConsoleTarget("consoleTarget")
        {
            Layout = @"${date:format=HH\:mm\:ss} ${level} ${message} ${exception}"
        };
        logConfig.AddTarget(consoleTarget);
        logConfig.AddRuleForAllLevels(consoleTarget);

        var fatalTarget = new FileTarget("fatal")
        {
            FileName = "${basedir}/logs/${shortdate}/fatal-${shortdate}.log",
            Layout = "${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}|url: ${aspnet-request-url}|action: ${aspnet-mvc-action}"
        };
        logConfig.AddTarget(fatalTarget);
        logConfig.AddRuleForOneLevel(LogLevel.Fatal, fatalTarget);

        var errorTarget = new FileTarget("error")
        {
            FileName = "${basedir}/logs/${shortdate}/error-${shortdate}.log",
            Layout = "${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}|url: ${aspnet-request-url}|action: ${aspnet-mvc-action}"
        };
        logConfig.AddTarget(errorTarget);
        logConfig.AddRuleForOneLevel(LogLevel.Error, errorTarget);

        var warningTarget = new FileTarget("warning")
        {
            FileName = "${basedir}/logs/${shortdate}/warning-${shortdate}.log",
            Layout = "${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}|url: ${aspnet-request-url}|action: ${aspnet-mvc-action}"
        };
        logConfig.AddTarget(warningTarget);
        logConfig.AddRuleForOneLevel(LogLevel.Warn, warningTarget);

        var infoTarget = new FileTarget("info")
        {
            FileName = "${basedir}/logs/${shortdate}/info-${shortdate}.log",
            Layout = "${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}|url: ${aspnet-request-url}|action: ${aspnet-mvc-action}"
        };
        logConfig.AddTarget(infoTarget);
        logConfig.AddRuleForOneLevel(LogLevel.Info, infoTarget);

        var debugTarget = new FileTarget("debug")
        {
            FileName = "${basedir}/logs/${shortdate}/debug-${shortdate}.log",
            Layout = "${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}|url: ${aspnet-request-url}|action: ${aspnet-mvc-action}"
        };
        logConfig.AddTarget(debugTarget);
        logConfig.AddRuleForOneLevel(LogLevel.Debug, debugTarget);

        var traceTarget = new FileTarget("trace")
        {
            FileName = "${basedir}/logs/${shortdate}/trace-${shortdate}.log",
            Layout = "${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}|url: ${aspnet-request-url}|action: ${aspnet-mvc-action}"
        };
        logConfig.AddTarget(traceTarget);
        logConfig.AddRuleForOneLevel(LogLevel.Trace, traceTarget);

        var allTarget = new FileTarget("all")
        {
            FileName = "${basedir}/logs/${shortdate}/all-${shortdate}.log",
            Layout = "${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}|url: ${aspnet-request-url}|action: ${aspnet-mvc-action}"
        };
        logConfig.AddTarget(allTarget);
        logConfig.AddRuleForAllLevels(allTarget);

        return logConfig;
    }

---

my main function: public static void Main(string[] args) {

        // NLog: setup the logger first to catch all errors
        var logConfig = NlogConfig.GetLoggingConfiguration();
        var logger = NLog.Web.NLogBuilder.ConfigureNLog(logConfig).GetCurrentClassLogger();
        try
        {
            logger.Debug("init main");
            logger.Trace("startup - trace logging test");
            logger.Info("startup - info logging test");
            logger.Warn("startup - warn logging test");
            logger.Error("startup - error logging test");
            logger.Fatal("startup - fatal logging test");

            CreateWebHostBuilder(args).Build().Run();
        }
        catch (Exception ex)
        {
            logger.Fatal(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 IWebHostBuilder CreateWebHostBuilder(string[] args) =>
        WebHost.CreateDefaultBuilder(args)
            .UseStartup<Startup>()
        .ConfigureLogging(logging =>
        {
            logging.ClearProviders();
            logging.SetMinimumLevel(Microsoft.Extensions.Logging.LogLevel.Trace);
        }).UseNLog(); // NLog: setup NLog for Dependency injection
}

---

and a sample controller:

[ApiController]
[Route("/api/app/parts")]
public class AppPartsController : ControllerBase
{
    private readonly ILogger<AppPartsController> _logger;
    private IPartsRepository _partsRepo;

    public AppPartsController(ILogger<AppPartsController> logger, IPartsRepository repo)
    {
        _logger = logger;
        _partsRepo = repo;
    }


    [HttpGet]
    public async Task<ActionResult> Get()
    {
        _logger.LogInformation("/api/app/parts has been reached");
        try
        {
            var partsDb = await _partsRepo.GetAllParts();
            var parts = Mapper.Map<IEnumerable<AppPartDto>>(partsDb);
            return Ok(parts);
        }
        catch (Exception ex)
        {
            _logger.LogError(ex, "error in AppPartsController, get all parts ");
            return StatusCode(500);
        }
    }
}

no matter what i do, all the log entries in the 'Main' are written, but the controller entries are not.

afaik, NLog is configured as per their instructions, but obviously I'm missing something here...

Thanks,

Nir

Answer 1

well, there has been a confusion of configs.

when I've looked deeper in the debug folder, I suddenly saw that log files are generated in a place where they shouldn't, with a different naming convention that was in my NLog code config.

this led me on a wide file hunt for a rouge config file - which was subsequently found lurking in the project folder, after being removed from the project, but not deleted from the file system.

I then continued to search for the usages for said config file in my code and found them in all of my repositories.

once the repositories had been converted to use the proper code config, all was fixed, and peace & order had been restored.

I've also updated the logging section in the appsettings.json to look like this (but I'm not really sure if it had any effect):

 "Logging": {
        "LogLevel": {
            "Default": "Trace",
            "Microsoft": "Trace"
        }
    }