datalust / nlog-targets-seq

An NLog target that writes events to Seq. Built for NLog 4.5+.
https://getseq.net
Apache License 2.0
21 stars 11 forks source link

Structured data being ToString'd rather than recorder as raw JSON #61

Closed Strandedpirate closed 2 years ago

Strandedpirate commented 2 years ago

I'm trying to use ILogger.BeginScope to record structured object data, and have it recorded in Seq in JSON format so it can be queried, but it's consistently showing up as just strings, which is doesn't allow me to query it. I posted some of the issue here stackoverflow, and also tried one of the viable suggestions, but it doesn't work either.

I'm not sure if this is an issue in NLog or NLog.Targets.Seq.

I made an example web api controller in my .net 6 c# app for testing this, and the output in Seq is below after running it.

In the following test, only the first row (ObjectsOp2) generates the desired JSON format in Seq that is actually searchable as structured data.

I tried one of the viable stackoverflow suggestions of using a scope level layout ${scopenested:format=@}, but that produces JSON in string format rather than raw JSON in Seq, so it's not searchable or a workable solution. It gets output in each log as the Scope property.

Is there a bug in NLog.Targets.Seq specifically for the layout ${scopenested:format=@}? Seems like that should work.

NlogController

    [ApiController]
    [Route("[controller]")]
    public class NlogController : Controller
    {
        private readonly ILogger<NlogController> _logger;

        public NlogController(ILogger<NlogController> logger)
        {
            _logger = logger;
        }

        public class Test1Class
        {
            public class Test1InnerClass
            {
                public string Name { get; set; } = "";
                public string Description { get; set; } = "";
            }
            public int Id { get; set; }
            public List<Test1InnerClass> Tags { get; set; } = new List<Test1InnerClass>();
        }

        [HttpPost(nameof(Test1))]
        public Task Test1()
        {
            var objects = new Test1Class
            {
                Id = 1,
                Tags =
                {
                    new Test1Class.Test1InnerClass
                    {
                        Name = "global",
                        Description = "global tag"
                    },
                    new Test1Class.Test1InnerClass
                    {
                        Name = "exactMatch",
                        Description = "exactMatch tag"
                    }
                }
            };

            using (_logger.BeginScope(new Dictionary<string, object>
            {
                ["OrderId"] = 3456,
                ["ObjectsScope1"] = objects,
                ["@ObjectsScope2"] = objects,
                ["{@ObjectsScope3}"] = objects
            }))
            {
                _logger.LogInformation("String message with no additional parameters tied to it.");
                _logger.LogInformation("String message with a parameter tied to it using format: {{ObjectsOp1}}. {ObjectsOp1}", objects);
                _logger.LogInformation("String message with a parameter tied to it using format: {{@ObjectsOp2}}. {@ObjectsOp2}", objects);
            }

            return Task.CompletedTask;
        }
    }

appsettings.json

  "NLog": {
    "autoReload": true,
    "throwConfigExceptions": true,
    "internalLogLevel": "Info",
    "internalLogFile": "${basedir}/internal-nlog.txt",
    "extensions": [
      { "assembly": "NLog.Extensions.Logging" },
      { "assembly": "NLog.Web.AspNetCore" },
      { "assembly": "Microsoft.Data.SqlClient" },
      { "assembly": "NLog.Targets.Seq" }
    ],
    "default-wrapper": {
      "type": "AsyncWrapper",
      "overflowAction": "Block"
    },
    "targets": {
      "async": true,
      "logconsole": {
        "type": "Console"
      },
      "seq": {
        "type": "BufferingWrapper",
        "bufferSize": 200,
        "flushTimeout": 2000,
        "slidingTimeout": false,
        "target": {
          "type": "Seq",
          "serverUrl": "http://localhost:4005",
          "apiKey": "",
          "properties": [
            {
              "name": "Level",
              "value": "${level}"
            },
            {
              "name": "Scope",
              "value": "${scopenested:format=@}"
            },
            {
              "name": "CacheValueTest",
              "value": "${scopeproperty:CacheValue:format=@}"
            },
            {
              "name": "MachineName",
              "value": "${machinename}"
            },
            {
              "name": "Logger",
              "value": "${logger}"
            },
            {
              "name": "Callsite",
              "value": "${callsite}"
            },
            {
              "name": "Exception",
              "value": "${exception:tostring}"
            },
            {
              "name": "TraceId",
              "value": "${aspnet-TraceIdentifier}"
            },
            {
              "name": "Url",
              "value": "${aspnet-request-url}${aspnet-request-querystring}"
            },
            {
              "name": "Referer",
              "value": "${aspnet-request-referrer}"
            },
            {
              "name": "RequestMethod",
              "value": "${aspnet-request-method}"
            },
            {
              "name": "UserAgent",
              "value": "${aspnet-request-useragent}"
            },
            {
              "name": "ClientIpAddress",
              "value": "${aspnet-request-ip:CheckForwardedForHeader=true}"
            }
          ]
        }
      },
    "rules": [
      {
        "logger": "*",
        "minLevel": "Debug",
        "writeTo": "logconsole"
      },
      {
        "logger": "Ripple.*",
        "minLevel": "Debug",
        "writeTo": "seq"
      },
      {
        "logger": "Microsoft.*",
        "minLevel": "Off",
        "final": true
      }
    ]

row 1

{
  "@t": "2022-05-31T21:11:07.7751772Z",
  "@mt": "String message with a parameter tied to it using format: {{@ObjectsOp2}}. {@ObjectsOp2}",
  "@m": "String message with a parameter tied to it using format: {@ObjectsOp2}. {\n  \"Id\": 1,\n  \"Tags\": [\n    {\n      \"Name\": \"global\",\n      \"Description\": \"global tag\"\n    },\n    {\n      \"Name\": \"exactMatch\",\n      \"Description\": \"exactMatch tag\"\n    }\n  ]\n}",
  "@i": "11088dc7",
  "Level": "Info",
  "Scope": "[ { \"ConnectionId\": \"0HMI3987KKG0L\" }, { \"RequestId\": \"0HMI3987KKG0L:00000009\", \"RequestPath\": \"/Nlog/Test1\" }, { \"ActionId\": \"bd4fb72b-ea24-43d6-8960-5211ec8dbaae\", \"ActionName\": \"Ripple.Rest.Controllers.NlogController.Test1 (Ripple.Rest)\" }, { \"UserName\": \"Unknown User\", \"UserId\": 0 }, { \"OrderId\": 3456, \"ObjectsScope1\": {\"Id\":1, \"Tags\":[{\"Name\":\"global\", \"Description\":\"global tag\"},{\"Name\":\"exactMatch\", \"Description\":\"exactMatch tag\"}]}, \"@ObjectsScope2\": {\"Id\":1, \"Tags\":[{\"Name\":\"global\", \"Description\":\"global tag\"},{\"Name\":\"exactMatch\", \"Description\":\"exactMatch tag\"}]}, \"{@ObjectsScope3}\": {\"Id\":1, \"Tags\":[{\"Name\":\"global\", \"Description\":\"global tag\"},{\"Name\":\"exactMatch\", \"Description\":\"exactMatch tag\"}]} } ]",
  "CacheValueTest": "null",
  "MachineName": "DESKTOP-QVMC0TS",
  "Logger": "Ripple.Rest.Controllers.NlogController",
  "Callsite": "Ripple.Rest.Controllers.NlogController.Test1",
  "TraceId": "00-8c95b52c3ee70d8cadd18547a13d9816-56e4d8037b71839f-00",
  "Url": "https://localhost/Nlog/Test1",
  "Referer": "https://localhost:7165/swagger/index.html",
  "RequestMethod": "POST",
  "UserAgent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/102.0.0.0 Safari/537.36",
  "ClientIpAddress": "::1",
  "ConnectionId": "0HMI3987KKG0L",
  "RequestId": "0HMI3987KKG0L:00000009",
  "RequestPath": "/Nlog/Test1",
  "ActionId": "bd4fb72b-ea24-43d6-8960-5211ec8dbaae",
  "ActionName": "Ripple.Rest.Controllers.NlogController.Test1 (Ripple.Rest)",
  "UserName": "Unknown User",
  "UserId": 0,
  "OrderId": 3456,
  "ObjectsScope1": "Ripple.Rest.Controllers.NlogController+Test1Class",
  "@@ObjectsScope2": "Ripple.Rest.Controllers.NlogController+Test1Class",
  "{@ObjectsScope3}": "Ripple.Rest.Controllers.NlogController+Test1Class",
  "ObjectsOp2": {
    "Id": 1,
    "Tags": [
      {
        "Name": "global",
        "Description": "global tag"
      },
      {
        "Name": "exactMatch",
        "Description": "exactMatch tag"
      }
    ]
  }
}

row 2

{
  "@t": "2022-05-31T21:11:07.7717526Z",
  "@mt": "String message with a parameter tied to it using format: {{ObjectsOp1}}. {ObjectsOp1}",
  "@m": "String message with a parameter tied to it using format: {ObjectsOp1}. Ripple.Rest.Controllers.NlogController+Test1Class",
  "@i": "a4227fe6",
  "Level": "Info",
  "Scope": "[ { \"ConnectionId\": \"0HMI3987KKG0L\" }, { \"RequestId\": \"0HMI3987KKG0L:00000009\", \"RequestPath\": \"/Nlog/Test1\" }, { \"ActionId\": \"bd4fb72b-ea24-43d6-8960-5211ec8dbaae\", \"ActionName\": \"Ripple.Rest.Controllers.NlogController.Test1 (Ripple.Rest)\" }, { \"UserName\": \"Unknown User\", \"UserId\": 0 }, { \"OrderId\": 3456, \"ObjectsScope1\": {\"Id\":1, \"Tags\":[{\"Name\":\"global\", \"Description\":\"global tag\"},{\"Name\":\"exactMatch\", \"Description\":\"exactMatch tag\"}]}, \"@ObjectsScope2\": {\"Id\":1, \"Tags\":[{\"Name\":\"global\", \"Description\":\"global tag\"},{\"Name\":\"exactMatch\", \"Description\":\"exactMatch tag\"}]}, \"{@ObjectsScope3}\": {\"Id\":1, \"Tags\":[{\"Name\":\"global\", \"Description\":\"global tag\"},{\"Name\":\"exactMatch\", \"Description\":\"exactMatch tag\"}]} } ]",
  "CacheValueTest": "null",
  "MachineName": "DESKTOP-QVMC0TS",
  "Logger": "Ripple.Rest.Controllers.NlogController",
  "Callsite": "Ripple.Rest.Controllers.NlogController.Test1",
  "TraceId": "00-8c95b52c3ee70d8cadd18547a13d9816-56e4d8037b71839f-00",
  "Url": "https://localhost/Nlog/Test1",
  "Referer": "https://localhost:7165/swagger/index.html",
  "RequestMethod": "POST",
  "UserAgent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/102.0.0.0 Safari/537.36",
  "ClientIpAddress": "::1",
  "ConnectionId": "0HMI3987KKG0L",
  "RequestId": "0HMI3987KKG0L:00000009",
  "RequestPath": "/Nlog/Test1",
  "ActionId": "bd4fb72b-ea24-43d6-8960-5211ec8dbaae",
  "ActionName": "Ripple.Rest.Controllers.NlogController.Test1 (Ripple.Rest)",
  "UserName": "Unknown User",
  "UserId": 0,
  "OrderId": 3456,
  "ObjectsScope1": "Ripple.Rest.Controllers.NlogController+Test1Class",
  "@@ObjectsScope2": "Ripple.Rest.Controllers.NlogController+Test1Class",
  "{@ObjectsScope3}": "Ripple.Rest.Controllers.NlogController+Test1Class",
  "ObjectsOp1": "Ripple.Rest.Controllers.NlogController+Test1Class"
}

row 3

{
  "@t": "2022-05-31T21:11:07.7717526Z",
  "@mt": "String message with a parameter tied to it using format: {{ObjectsOp1}}. {ObjectsOp1}",
  "@m": "String message with a parameter tied to it using format: {ObjectsOp1}. Ripple.Rest.Controllers.NlogController+Test1Class",
  "@i": "a4227fe6",
  "Level": "Info",
  "Scope": "[ { \"ConnectionId\": \"0HMI3987KKG0L\" }, { \"RequestId\": \"0HMI3987KKG0L:00000009\", \"RequestPath\": \"/Nlog/Test1\" }, { \"ActionId\": \"bd4fb72b-ea24-43d6-8960-5211ec8dbaae\", \"ActionName\": \"Ripple.Rest.Controllers.NlogController.Test1 (Ripple.Rest)\" }, { \"UserName\": \"Unknown User\", \"UserId\": 0 }, { \"OrderId\": 3456, \"ObjectsScope1\": {\"Id\":1, \"Tags\":[{\"Name\":\"global\", \"Description\":\"global tag\"},{\"Name\":\"exactMatch\", \"Description\":\"exactMatch tag\"}]}, \"@ObjectsScope2\": {\"Id\":1, \"Tags\":[{\"Name\":\"global\", \"Description\":\"global tag\"},{\"Name\":\"exactMatch\", \"Description\":\"exactMatch tag\"}]}, \"{@ObjectsScope3}\": {\"Id\":1, \"Tags\":[{\"Name\":\"global\", \"Description\":\"global tag\"},{\"Name\":\"exactMatch\", \"Description\":\"exactMatch tag\"}]} } ]",
  "CacheValueTest": "null",
  "MachineName": "DESKTOP-QVMC0TS",
  "Logger": "Ripple.Rest.Controllers.NlogController",
  "Callsite": "Ripple.Rest.Controllers.NlogController.Test1",
  "TraceId": "00-8c95b52c3ee70d8cadd18547a13d9816-56e4d8037b71839f-00",
  "Url": "https://localhost/Nlog/Test1",
  "Referer": "https://localhost:7165/swagger/index.html",
  "RequestMethod": "POST",
  "UserAgent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/102.0.0.0 Safari/537.36",
  "ClientIpAddress": "::1",
  "ConnectionId": "0HMI3987KKG0L",
  "RequestId": "0HMI3987KKG0L:00000009",
  "RequestPath": "/Nlog/Test1",
  "ActionId": "bd4fb72b-ea24-43d6-8960-5211ec8dbaae",
  "ActionName": "Ripple.Rest.Controllers.NlogController.Test1 (Ripple.Rest)",
  "UserName": "Unknown User",
  "UserId": 0,
  "OrderId": 3456,
  "ObjectsScope1": "Ripple.Rest.Controllers.NlogController+Test1Class",
  "@@ObjectsScope2": "Ripple.Rest.Controllers.NlogController+Test1Class",
  "{@ObjectsScope3}": "Ripple.Rest.Controllers.NlogController+Test1Class",
  "ObjectsOp1": "Ripple.Rest.Controllers.NlogController+Test1Class"
}
nblumhardt commented 2 years ago

Hi! Thanks for the note. I don't think there's any bug here - you're using Microsoft.Extensions.Logging's ILogger<T>, which doesn't really have any native way to mark objects as being serialized except through message templates with @ (even though NLog supports more structured data handling behind the scenes).

I suspect that the @ObjectsScope2 approach could be made to work via NLog's adapter for Microsoft.Extensions.Logging, but I'm not sure whether it fits with the design goals of that library.

This library just accepts whatever structured data NLog passes into it, so I don't think it's the place to make changes in support of this, but I could be wrong (I'm not deeply familiar with NLog - one of the other watchers of this repo may be able to chime in and correct me if so).

Hope this at least provides some more info on why things are as they are :-)

Strandedpirate commented 2 years ago

Thanks, I submitted a feature request for ILogger.BeginScope on NLog's repo to add support for template message syntax.

Specifically for this project though, any idea why using ${scopenested:format=@} doesn't get inserted into Seq as raw JSON? It's getting pumped in as a JSON string, but its not searchable as structured data because its not the raw JSON object.

Current:

{
    "Scope": "[ { \"ConnectionId\": \"0HMI3987KKG0L\" }, { \"RequestId\": \"0HMI3987KKG0L:00000009\", \"RequestPath\": \"/Nlog/Test1\" }, { \"ActionId\": \"bd4fb72b-ea24-43d6-8960-5211ec8dbaae\", \"ActionName\": \"Ripple.Rest.Controllers.NlogController.Test1 (Ripple.Rest)\" }, { \"UserName\": \"Unknown User\", \"UserId\": 0 }, { \"OrderId\": 3456, \"ObjectsScope1\": {\"Id\":1, \"Tags\":[{\"Name\":\"global\", \"Description\":\"global tag\"},{\"Name\":\"exactMatch\", \"Description\":\"exactMatch tag\"}]}, \"@ObjectsScope2\": {\"Id\":1, \"Tags\":[{\"Name\":\"global\", \"Description\":\"global tag\"},{\"Name\":\"exactMatch\", \"Description\":\"exactMatch tag\"}]}, \"{@ObjectsScope3}\": {\"Id\":1, \"Tags\":[{\"Name\":\"global\", \"Description\":\"global tag\"},{\"Name\":\"exactMatch\", \"Description\":\"exactMatch tag\"}]} } ]",
}

Versus expected:

{
     "Scope": [
      {
        "ConnectionId":"0HMI3987KKG0L"
      },
      {
        "RequestId":"0HMI3987KKG0L:00000009",
        "RequestPath":"/Nlog/Test1"
      },
      {
        "ActionId":"bd4fb72b-ea24-43d6-8960-5211ec8dbaae",
        "ActionName":"Ripple.Rest.Controllers.NlogController.Test1 (Ripple.Rest)"
      },
      {
        "UserName":"Unknown User",
        "UserId":0
      },
      {
        "OrderId":3456,
        "ObjectsScope1":{
          "Id":1,
          "Tags":[
            {
              "Name":"global",
              "Description":"global tag"
            },
            {
              "Name":"exactMatch",
              "Description":"exactMatch tag"
            }
          ]
        },
        "@ObjectsScope2":{
          "Id":1,
          "Tags":[
            {
              "Name":"global",
              "Description":"global tag"
            },
            {
              "Name":"exactMatch",
              "Description":"exactMatch tag"
            }
          ]
        },
        "{@ObjectsScope3}":{
          "Id":1,
          "Tags":[
            {
              "Name":"global",
              "Description":"global tag"
            },
            {
              "Name":"exactMatch",
              "Description":"exactMatch tag"
            }
          ]
        }
      }
    ]
}
nblumhardt commented 2 years ago

Thanks for the update. The target/Seq don't try to automatically determine whether a value in a string is valid JSON; the value needs to reach the target as structured data before it will be inlined into the payload as an object with properties and values. If the value is pre-formatted as a string, even a JSON string, it will remain a string through the whole pipeline.

nblumhardt commented 2 years ago

BTW using NLog directly is likely to have better support for structured data in its API than MEL does; it might be worth asking how to achieve what you're after using an NLog ILogger directly, if the MEL wrapper doesn't have the features you need. HTH!

Strandedpirate commented 2 years ago

Thanks, I actually wound up ditching NLog. The bare bones MS ILogger interface by itself, does precisely what I'm after, and allows message template syntax in the ILogger.BeginScope overloads.

snakefoot commented 2 years ago

NLog.Targets.Seq uses NLog JsonLayout, so you can do this:

          "type": "Seq",
          "serverUrl": "http://localhost:4005",
          "apiKey": "",
          "properties": [
            {
              "name": "Level",
              "value": "${level}"
            },
            {
              "name": "Scope",
              "value": "${scopenested:format=@}",
               "As": "number"
            },
            {
              "name": "CacheValueTest",
              "value": "${scopeproperty:CacheValue:format=@}",
              "As": "number"
            }
          ]

Little weird with this magic-value for "As" in SeqPropertyItem. It would probably be more logical if the property was called "AsString" (default=true).