fluent-bit config works as expected and yet it does not work in newrelic UI

[alcohol]

Description

I'm trying to use newrelic-infra logging configuration to forward logs to newrelic. Specifically, I am trying to use a custom fluent-bit configuration.

I can see the configuration is working exactly as expected when I output to a file on disk:

$ tail -1 /var/log/fluent-bit.out
caddy.proxy: [1704969865.913642137, {"log":{"level":"info","logger":"http.log.access.log3"},"bytes_read":0,"client":{"port":"38291","ip":"66.249.64.230"},"entity.guid.INFRA":"MzE3Mzg0M3xJTkZSQXxOQXw0NTA4NTc4NTg5MjM2MTgwMTc2","msg":"handled request","filePath":"/var/log/caddy/proxy.log","plugin.type":"nri-agent","fb.input":"tail","http":{"response":{"headers":{"Server":["Caddy"],"Alt-Svc":["h3=\":443\"; ma=2592000"],"Etag":["\"s6n2a3p2\""],"Content-Encoding":["gzip"],"Last-Modified":["Tue, 02 Jan 2024 14:44:27 GMT"],"Access-Control-Allow-Origin":["*"],"Cache-Control":["public, max-age=604800, s-maxage=86400, stale-while-revalidate=3600, must-revalidate"],"Content-Type":["text/javascript; charset=utf-8"],"Access-Control-Allow-Methods":["GET"],"Vary":["Accept-Encoding"]},"status_code":200},"request":{"host":"***","uri":"/assets/js/jquery.isonscreen.min.js?v1.4.38","headers":{"User-Agent":["Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)"],"From":["googlebot(at)googlebot.com"],"Accept-Encoding":["gzip, deflate, br"],"Connection":["keep-alive"],"Accept":["*/*"],"Cookie":{},"Referer":["***"],"Accept-Language":["en-US"]},"client_ip":"66.249.64.230","tls":{"proto":"","cipher_suite":4865,"resumed":false,"server_name":"***","version":772},"remote_ip":"66.249.64.230","proto":"HTTP/1.1","remote_port":"38291","method":"GET"}},"hostname":"***","service":"caddy.proxy","duration":0.000388375,"size":363,"message":"GET /assets/js/jquery.isonscreen.min.js?v1.4.38"}]

{
  "log": {
    "level": "info",
    "logger": "http.log.access.log3"
  },
  "bytes_read": 0,
  "client": {
    "port": "38291",
    "ip": "66.249.64.230"
  },
  "entity.guid.INFRA": "MzE3Mzg0M3xJTkZSQXxOQXw0NTA4NTc4NTg5MjM2MTgwMTc2",
  "msg": "handled request",
  "filePath": "/var/log/caddy/proxy.log",
  "plugin.type": "nri-agent",
  "fb.input": "tail",
  "http": {
    "response": {
      "headers": {
        "Server": [
          "Caddy"
        ],
        "Alt-Svc": [
          "h3=\":443\"; ma=2592000"
        ],
        "Etag": [
          "\"s6n2a3p2\""
        ],
        "Content-Encoding": [
          "gzip"
        ],
        "Last-Modified": [
          "Tue, 02 Jan 2024 14:44:27 GMT"
        ],
        "Access-Control-Allow-Origin": [
          "*"
        ],
        "Cache-Control": [
          "public, max-age=604800, s-maxage=86400, stale-while-revalidate=3600, must-revalidate"
        ],
        "Content-Type": [
          "text/javascript; charset=utf-8"
        ],
        "Access-Control-Allow-Methods": [
          "GET"
        ],
        "Vary": [
          "Accept-Encoding"
        ]
      },
      "status_code": 200
    },
    "request": {
      "host": "***",
      "uri": "/assets/js/jquery.isonscreen.min.js?v1.4.38",
      "headers": {
        "User-Agent": [
          "Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)"
        ],
        "From": [
          "googlebot(at)googlebot.com"
        ],
        "Accept-Encoding": [
          "gzip, deflate, br"
        ],
        "Connection": [
          "keep-alive"
        ],
        "Accept": [
          "*/*"
        ],
        "Cookie": {},
        "Referer": [
          "***"
        ],
        "Accept-Language": [
          "en-US"
        ]
      },
      "client_ip": "66.249.64.230",
      "tls": {
        "proto": "",
        "cipher_suite": 4865,
        "resumed": false,
        "server_name": "***",
        "version": 772
      },
      "remote_ip": "66.249.64.230",
      "proto": "HTTP/1.1",
      "remote_port": "38291",
      "method": "GET"
    }
  },
  "hostname": "***",
  "service": "caddy.proxy",
  "duration": 0.000388375,
  "size": 363,
  "message": "GET /assets/js/jquery.isonscreen.min.js?v1.4.38"
}

Expected Behavior

I expect the above values to also appear in newrelic logging UI.

However, in newrelic logs UI, I see that msg is used as message for some reason unknown to me. But if I remove msg from the record entirely using a FILTER, message is still not used as message in the UI. Instead I end up with an empty message in newrelic logging UI then.

The same goes for the nested log entry. In newrelic UI I only see the root level and logger, not the nested values.

Steps to Reproduce

/etc/newrelic-infra/logging.d $ tail -n +1 caddy*

==> caddy.fluentbit.conf <==

[INPUT]
  Name tail
  Path /var/log/caddy/proxy.log
  Path_Key filePath
  DB /var/db/newrelic-infra/newrelic-integrations/logging/fb.db
  Parser json_parser
  Tag caddy.proxy

[INPUT]
  Name tail
  Path /var/log/caddy/backend.log
  Path_Key filePath
  DB /var/db/newrelic-infra/newrelic-integrations/logging/fb.db
  Parser json_parser
  Tag caddy.backend

[INPUT]
  Name tail
  Path /var/log/caddy/development.log
  Path_Key filePath
  DB /var/db/newrelic-infra/newrelic-integrations/logging/fb.db
  Parser json_parser
  Tag caddy.development

[FILTER]
  Name record_modifier
  Match caddy.*
  Record fb.input tail

[FILTER]
  Name lua
  Match caddy.*
  Call callback
  Script /etc/newrelic-infra/logging.d/caddy.lua

[OUTPUT]
  Name file
  Match *
  Path /var/log
  File fluent-bit.out

==> caddy.lua <==

function callback(tag, timestamp, record)

  -- set some basic keys and cleanup redundant keys
  record["service"] = tag
  record["user_id"] = nil
  record["ts"] = nil
  record["message"] = record.request.method .. ' ' .. record.request.uri
  --record["msg"] = nil

  -- create nested log and cleanup redundant keys
  record["log"] = {}
  record["log"]["level"] = record.level
  record["log"]["logger"] = record.logger
  record["level"] = nil
  record["logger"] = nil

  -- create nested response and cleanup redundant keys
  record["response"] = {}
  record["response"]["status_code"] = record.status
  record["response"]["headers"] = record.resp_headers
  record["status"] = nil
  record["resp_headers"] = nil

  -- create nested client
  record["client"] = {}
  record["client"]["ip"] = record.request.remote_ip
  record["client"]["port"] = record.request.remote_port

  -- nest request and response under http and cleanup redundant keys
  record["http"] = {}
  record["http"]["response"] = record.response
  record["http"]["request"] = record.request
  record["response"] = nil
  record["request"] = nil

  return 2, timestamp, record
end

==> caddy.parser.conf <==

[PARSER]
  Name json_parser
  Format json
  Time_Key ts
  Time_Format %s.%L

==> caddy.yml <==

logs:
  - name: caddy
    fluentbit:
      config_file: /etc/newrelic-infra/logging.d/caddy.fluentbit.conf
      parsers_file: /etc/newrelic-infra/logging.d/caddy.parser.conf

[workato-integration[bot]]

https://new-relic.atlassian.net/browse/NR-214377

[jdearana-nr]

@alcohol This is an expected behaviour, msg attribute is a reserved attribute that is automatically mapped to the message, but, unfortunately, it was not explicitly mentioned in our documentation. We have filed a PR in our documentation to explicitly mention this in our public documentation (https://github.com/newrelic/docs-website/pull/17532). Sorry for the inconveniences.

[workato-integration[bot]]

Work has been completed on this issue.

[alcohol]

@jdearana-nr but that does not entirely answer my question? What I understand from your comment is that msg is mapped to message upon ingest (so on your end -- or do I get this wrong?). But if I remove msg using LUA in my pipeline before the data is send to newrelic, message (also present in my data) was not used as message, instead message on your end ended up as an empty property. Is this because previously msg was mapped to message and so now the ingest point or index always expects msg to be present?