How to create separate log files per thread using nlog-CodePudding

I have a simple ASP.NET application which I would like create separate log files per request. The application creates the log files but I am having information from other threads in the log files. I created an nlog.config file which I would like all threads to use this file.Here is the content of the config file

<?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="Info">

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

    <!-- the targets to write to -->
    <targets async="true">
        <!-- write logs to file  -->
        <target
            xsi:type="File"
            name="allfile"
            fileName="c:/temp/nlog-Navigator-all-${shortdate}.log"
            layout="${longdate}|${event-properties:item=EventId_Id:whenEmpty=0}|${uppercase:${level}}|${logger}|TraceIdentifier: ${aspnet-TraceIdentifier}|SessionId: ${aspnet-sessionid}|${message} ${exception:format=tostring}" />
        <target
            xsi:type="Console"
            name="detailConsole"
            layout="${level:truncate=4:lowercase=true}: ${aspnet-sessionid} - ${logger}[0] ${newline}      ${message}${exception:format=tostring}" />
    </targets>

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

I using postman to send multiple requests to the application. The request body looks like the following

{
    "fileName": "testfileName1.txt"
}

I am currently sending 4 request and the log file name created is based on the fileName from the requets. So this means 4 log files are created with the name testfileName1.txt, testfileName2.txt, testfileName4.txt, testfileName4.txt . Here is my controller:

        [HttpPost]
        public async Task<IActionResult> Index([FromBody] JsonElement requestElement)
        {
            try
            {
                var myJsonString = JObject.Parse(requestElement.GetRawText());
                var fileName = myJsonString["fileName"].ToString();

                using (this._logger.BeginScope(fileName))
                {
                    for (int i = 0; i < 10; i  )
                    {
                        await this.StartJobLogger(fileName);

                        this._logger.LogInformation($"File: {fileName}");
                        await Task.Delay(1000);
                    }

                    return this.Ok("done");
                }
            }
            catch (Exception e)
            {
                throw;
            }
            finally
            {
            }
        }

        #region Private Methods

        private Task StartJobLogger( string fileName)
        {
            var target = new FileTarget();
            target.Name = fileName;
            target.FileName = $"c:\\temp\\{Path.GetFileNameWithoutExtension(fileName)}.log";
            target.Layout = "${longdate} ${threadid} ${callsite} ${level} ${message}";

            var config = LogManager.Configuration;
            config.AddTarget("testName", target);
            var rule = new LoggingRule("*", NLog.LogLevel.Info, target);
            
            config.LoggingRules.Add(rule);

            LogManager.Configuration = config;

            LogManager.GetLogger(fileName);

            return Task.CompletedTask;
        }

However, the following is being written in the first log file.

2022-01-03 10:34:20.0592 12 MultiThreadLogging.Controllers.HomeController.Index Info File: testfileName1.txt
2022-01-03 10:34:20.0592 12 MultiThreadLogging.Controllers.HomeController.Index Info File: testfileName1.txt
2022-01-03 10:34:20.0592 12 MultiThreadLogging.Controllers.HomeController.Index Info File: testfileName1.txt
2022-01-03 10:34:20.0592 12 MultiThreadLogging.Controllers.HomeController.Index Info File: testfileName1.txt
2022-01-03 10:34:20.0592 12 MultiThreadLogging.Controllers.HomeController.Index Info File: testfileName1.txt
2022-01-03 10:34:20.0592 12 MultiThreadLogging.Controllers.HomeController.Index Info File: testfileName1.txt
2022-01-03 10:34:20.0592 12 MultiThreadLogging.Controllers.HomeController.Index Info File: testfileName1.txt
2022-01-03 10:34:20.0592 12 MultiThreadLogging.Controllers.HomeController.Index Info File: testfileName1.txt
2022-01-03 10:34:20.0592 12 MultiThreadLogging.Controllers.HomeController.Index Info File: testfileName1.txt
2022-01-03 10:34:20.0592 12 MultiThreadLogging.Controllers.HomeController.Index Info File: testfileName1.txt
2022-01-03 10:34:20.0592 12 MultiThreadLogging.Controllers.HomeController.Index Info File: testfileName1.txt
2022-01-03 10:34:21.0805 12 MultiThreadLogging.Controllers.HomeController <Index>d__2.MoveNext Info File: testfileName1.txt
2022-01-03 10:34:21.0805 12 MultiThreadLogging.Controllers.HomeController <Index>d__2.MoveNext Info File: testfileName1.txt
2022-01-03 10:34:21.0805 12 MultiThreadLogging.Controllers.HomeController <Index>d__2.MoveNext Info File: testfileName1.txt
2022-01-03 10:34:21.0805 12 MultiThreadLogging.Controllers.HomeController <Index>d__2.MoveNext Info File: testfileName1.txt
2022-01-03 10:34:21.0805 12 MultiThreadLogging.Controllers.HomeController <Index>d__2.MoveNext Info File: testfileName1.txt
2022-01-03 10:34:21.0805 12 MultiThreadLogging.Controllers.HomeController <Index>d__2.MoveNext Info File: testfileName1.txt
2022-01-03 10:34:21.0805 12 MultiThreadLogging.Controllers.HomeController <Index>d__2.MoveNext Info File: testfileName1.txt
2022-01-03 10:34:21.0805 12 MultiThreadLogging.Controllers.HomeController <Index>d__2.MoveNext Info File: testfileName1.txt
2022-01-03 10:34:21.0805 12 MultiThreadLogging.Controllers.HomeController <Index>d__2.MoveNext Info File: testfileName1.txt
2022-01-03 10:34:21.0805 12 MultiThreadLogging.Controllers.HomeController <Index>d__2.MoveNext Info File: testfileName1.txt
2022-01-03 10:34:21.0805 12 MultiThreadLogging.Controllers.HomeController <Index>d__2.MoveNext Info File: testfileName1.txt
2022-01-03 10:34:21.0805 12 MultiThreadLogging.Controllers.HomeController <Index>d__2.MoveNext Info File: testfileName1.txt
2022-01-03 10:34:21.6422 12 MultiThreadLogging.Controllers.HomeController.Index Info File: testfileName2.txt
2022-01-03 10:34:21.6422 12 MultiThreadLogging.Controllers.HomeController.Index Info File: testfileName2.txt
2022-01-03 10:34:21.6422 12 MultiThreadLogging.Controllers.HomeController.Index Info File: testfileName2.txt
2022-01-03 10:34:21.6422 12 MultiThreadLogging.Controllers.HomeController.Index Info File: testfileName2.txt

I wanted to have just information related to the first request to be logged in the first log file, and information related to the second request to be logged in the second file and so on. But this currently creates files with mixed information.

CodePudding user response：

Try doing this instead (Using BeginScope to inject ScopeFileName-property into NLog MDLC):

[HttpPost]
public async Task<IActionResult> Index([FromBody] JsonElement requestElement)
{
    try
    {
        var myJsonString = JObject.Parse(requestElement.GetRawText());
        var fileName = myJsonString["fileName"].ToString();

        // Pushing input-filename as scope-property, accessible from MDLC
        using (this._logger.BeginScope(new [] { new KeyValuePair<string, object>("ScopeFileName", fileName) }))
        {
            for (int i = 0; i < 10; i  )
            {
                // REMOVED AS BROKEN -> await this.StartJobLogger(fileName);

                this._logger.LogInformation($"File: {fileName}");
                await Task.Delay(1000);
            }

            return this.Ok("done");
        }
    }
    catch (Exception e)
    {
        throw;
    }
    finally
    {
    }
}

But notice that taking user-input and using as filename, can be used as an attack-vector.

<?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="Info">

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

    <variable name="ScopeFileName" value="${mdlc:ScopeFileName:whenEmpty=Navigator}" />

    <!-- the targets to write to -->
    <targets async="true">
        <!-- write logs to file  -->
        <target
            xsi:type="File"
            name="allfile"
            fileName="c:/temp/${ScopeFileName}-${shortdate}.log"
            layout="${longdate}|${event-properties:item=EventId_Id:whenEmpty=0}|${uppercase:${level}}|${logger}|TraceIdentifier: ${aspnet-TraceIdentifier}|SessionId: ${aspnet-sessionid}|${message} ${exception:format=tostring}" />
        <target
            xsi:type="Console"
            name="detailConsole"
            layout="${level:truncate=4:lowercase=true}: ${aspnet-sessionid} - ${logger}[0] ${newline}      ${message}${exception:format=tostring}" />
    </targets>

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