feat(json): multiple line-format in json logs

[s0nik42]

Description

Would be great to have lnav able to handle different line-formats within the same json formatted file.

context
Apps usually integrate multiple components that have different json schema.
All components usually log to the same file or STDOUT usually merged in one uniq logfile by systemd.

proposition

We could use the module-field as identifier to distinguish message from one component to another.

[tstack]

Can you provide some sample inputs and expected outputs. Does the existing line-format work for producing the output? Is it mostly a matter of having multiple line-format configurations that are keyed off of a single field?

[crc-smcleod]

I have a similar use case. The error messages in the log provide a few fields and the regular messages are more detailed. I would want different line-formats or a way to make portions of the format conditional to not waste so much screen space.

{"timestamp":"2022-10-13T14:51:09.088Z","status":"update","image":"C30379-v3","image_date":"2022-10-13T21:51:07.000Z","size":70270,"mime":"image/jpeg"}
{"timestamp":"2022-10-13T14:51:09.244Z","status":"error","image":"C30382-v4","message":"Response code 404 (Not Found)"}

This is the line-format I use with it currently.

    "line-format": [
      { "field": "timestamp" },
      " ",
      { "field": "status", "min-width": 6 },
      " ",
      { "field": "image", "min-width": 9, "default-value": "-" },
      " ",
      { "field": "image_date", "min-width": 24, "default-value": "-" },
      " ",
      { "field": "mime", "min-width": 10, "default-value": "-" },
      " ",
      { "field": "size", "min-width": 6, "default-value": "-" },
      " ",
      { "field": "message", "default-value": " " }
    ]

[VimCommando]

Kibana 7.x used this format:

{"type":"log","@timestamp":"2022-11-15T01:55:25+00:00","tags":["info","status"],"pid":8,"message":"Kibana is now degraded (was available)"}
{"type":"response","@timestamp":"2022-11-15T01:55:28+00:00","tags":["access:console"],"pid":8,"method":"post","statusCode":200,"req":{"url":"/api/console/proxy?path=_aliases%3Fpretty%3Dfalse&method=GET","method":"post","headers":{"host":"localhost:5642","user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:106.0) Gecko/20100101 Firefox/106.0","accept":"text/plain, */*; q=0.01","accept-language":"en-US,en;q=0.5","accept-encoding":"gzip, deflate, br","referer":"http://localhost:5642/app/dev_tools","kbn-xsrf":"kibana","origin":"http://localhost:5642","connection":"keep-alive","sec-fetch-dest":"empty","sec-fetch-mode":"cors","sec-fetch-site":"same-origin","content-length":"0"},"remoteAddress":"172.18.0.1","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:106.0) Gecko/20100101 Firefox/106.0","referer":"http://localhost:5642/app/dev_tools"},"res":{"statusCode":200,"responseTime":35},"message":"POST /api/console/proxy?path=_aliases%3Fpretty%3Dfalse&method=GET 200 35ms"}
{"type":"response","@timestamp":"2022-11-15T01:55:28+00:00","tags":["access:console"],"pid":8,"method":"post","statusCode":200,"req":{"url":"/api/console/proxy?path=_template%3Fpretty%3Dfalse&method=GET","method":"post","headers":{"host":"localhost:5642","user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:106.0) Gecko/20100101 Firefox/106.0","accept":"text/plain, */*; q=0.01","accept-language":"en-US,en;q=0.5","accept-encoding":"gzip, deflate, br","referer":"http://localhost:5642/app/dev_tools","kbn-xsrf":"kibana","origin":"http://localhost:5642","connection":"keep-alive","sec-fetch-dest":"empty","sec-fetch-mode":"cors","sec-fetch-site":"same-origin","content-length":"0"},"remoteAddress":"172.18.0.1","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:106.0) Gecko/20100101 Firefox/106.0","referer":"http://localhost:5642/app/dev_tools"},"res":{"statusCode":200,"responseTime":61},"message":"POST /api/console/proxy?path=_template%3Fpretty%3Dfalse&method=GET 200 61ms"}
{"type":"response","@timestamp":"2022-11-15T01:55:28+00:00","tags":["access:console"],"pid":8,"method":"post","statusCode":200,"req":{"url":"/api/console/proxy?path=_mapping%3Fpretty%3Dfalse&method=GET","method":"post","headers":{"host":"localhost:5642","user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:106.0) Gecko/20100101 Firefox/106.0","accept":"text/plain, */*; q=0.01","accept-language":"en-US,en;q=0.5","accept-encoding":"gzip, deflate, br","referer":"http://localhost:5642/app/dev_tools","kbn-xsrf":"kibana","origin":"http://localhost:5642","connection":"keep-alive","sec-fetch-dest":"empty","sec-fetch-mode":"cors","sec-fetch-site":"same-origin","content-length":"0"},"remoteAddress":"172.18.0.1","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:106.0) Gecko/20100101 Firefox/106.0","referer":"http://localhost:5642/app/dev_tools"},"res":{"statusCode":200,"responseTime":59},"message":"POST /api/console/proxy?path=_mapping%3Fpretty%3Dfalse&method=GET 200 59ms"}
{"type":"log","@timestamp":"2022-11-15T01:56:13+00:00","tags":["info","status"],"pid":8,"message":"Kibana is now available (was degraded)"}
{"type":"log","@timestamp":"2022-11-15T02:09:43+00:00","tags":["info","status"],"pid":8,"message":"Kibana is now degraded (was available)"}
{"type":"response","@timestamp":"2022-11-15T02:09:48+00:00","tags":["access:console"],"pid":8,"method":"post","statusCode":200,"req":{"url":"/api/console/proxy?path=_aliases%3Fpretty%3Dfalse&method=GET","method":"post","headers":{"host":"localhost:5642","user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:106.0) Gecko/20100101 Firefox/106.0","accept":"text/plain, */*; q=0.01","accept-language":"en-US,en;q=0.5","accept-encoding":"gzip, deflate, br","referer":"http://localhost:5642/app/dev_tools","kbn-xsrf":"kibana","origin":"http://localhost:5642","connection":"keep-alive","sec-fetch-dest":"empty","sec-fetch-mode":"cors","sec-fetch-site":"same-origin","content-length":"0"},"remoteAddress":"172.18.0.1","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:106.0) Gecko/20100101 Firefox/106.0","referer":"http://localhost:5642/app/dev_tools"},"res":{"statusCode":200,"responseTime":34},"message":"POST /api/console/proxy?path=_aliases%3Fpretty%3Dfalse&method=GET 200 34ms"}
{"type":"response","@timestamp":"2022-11-15T02:09:48+00:00","tags":["access:console"],"pid":8,"method":"post","statusCode":200,"req":{"url":"/api/console/proxy?path=_template%3Fpretty%3Dfalse&method=GET","method":"post","headers":{"host":"localhost:5642","user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:106.0) Gecko/20100101 Firefox/106.0","accept":"text/plain, */*; q=0.01","accept-language":"en-US,en;q=0.5","accept-encoding":"gzip, deflate, br","referer":"http://localhost:5642/app/dev_tools","kbn-xsrf":"kibana","origin":"http://localhost:5642","connection":"keep-alive","sec-fetch-dest":"empty","sec-fetch-mode":"cors","sec-fetch-site":"same-origin","content-length":"0"},"remoteAddress":"172.18.0.1","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:106.0) Gecko/20100101 Firefox/106.0","referer":"http://localhost:5642/app/dev_tools"},"res":{"statusCode":200,"responseTime":43},"message":"POST /api/console/proxy?path=_template%3Fpretty%3Dfalse&method=GET 200 43ms"}
{"type":"response","@timestamp":"2022-11-15T02:09:48+00:00","tags":["access:console"],"pid":8,"method":"post","statusCode":200,"req":{"url":"/api/console/proxy?path=_mapping%3Fpretty%3Dfalse&method=GET","method":"post","headers":{"host":"localhost:5642","user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:106.0) Gecko/20100101 Firefox/106.0","accept":"text/plain, */*; q=0.01","accept-language":"en-US,en;q=0.5","accept-encoding":"gzip, deflate, br","referer":"http://localhost:5642/app/dev_tools","kbn-xsrf":"kibana","origin":"http://localhost:5642","connection":"keep-alive","sec-fetch-dest":"empty","sec-fetch-mode":"cors","sec-fetch-site":"same-origin","content-length":"0"},"remoteAddress":"172.18.0.1","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:106.0) Gecko/20100101 Firefox/106.0","referer":"http://localhost:5642/app/dev_tools"},"res":{"statusCode":200,"responseTime":103},"message":"POST /api/console/proxy?path=_mapping%3Fpretty%3Dfalse&method=GET 200 103ms"}
{"type":"log","@timestamp":"2022-11-15T02:10:32+00:00","tags":["info","status"],"pid":8,"message":"Kibana is now available (was degraded)"}
{"type":"log","@timestamp":"2022-11-15T02:11:59+00:00","tags":["info","status"],"pid":8,"message":"Kibana is now degraded (was available)"}
{"type":"log","@timestamp":"2022-11-15T02:15:14+00:00","tags":["info","status"],"pid":8,"message":"Kibana is now available (was degraded)"}
{"type":"log","@timestamp":"2022-11-15T02:19:08+00:00","tags":["info","status"],"pid":8,"message":"Kibana is now degraded (was available)"}

With a type field to differentiate between response (http) entries and log (everything else) entries.

In Kibana 8.x this type field was removed for a more standardized Elastic Common Schema (ECS) format. This means we have to rely on the existence of an http property to know if it is response or not.

{"kibana":{"usageCounters":{"results":[{"id":"uiCounter:01062022:count:index_management:index_delete","type":"usage-counters","updated_at":"2022-06-01T16:52:44.190Z","references":[],"version":"WzE5NDQ3OCw2XQ==","attributes":{"domainId":"uiCounter","counterName":"index_management:index_delete","counterType":"count","count":5}}]}},"ecs":{"version":"8.0.0"},"@timestamp":"2022-06-01T16:52:45.172+00:00","message":"StorecountersintosavedObjects","log":{"level":"DEBUG","logger":"plugins.usageCollection.usage-collection.usage-counters-service"},"process":{"pid":20},"trace":{"id":"REDACTED"},"transaction":{"id":"REDACTED"}}
{"http":{"request":{"id":"unknownId","method":"POST","headers":{"REDACTED":true}},"response":{"body":{"bytes":228},"status_code":200,"headers":{"REDACTED":true}}},"url":{"path":"/.kibana_task_manager/_update_by_query","query":"ignore_unavailable=true&refresh=true"},"ecs":{"version":"8.0.0"},"@timestamp":"2022-06-01T16:52:45.350+00:00","message":"200-228.0B\nPOST/.kibana_task_manager/_update_by_query?ignore_unavailable=true&refresh=true\\n{\"query\":{\"REDACTED\":true}}","log":{"level":"DEBUG","logger":"elasticsearch.query.data"},"process":{"pid":20},"trace":{"id":"redacted"},"transaction":{"id":"redacted"}}

To add to the confusion here, both the 7.x and 8.x standards match the same kibana.*log filename pattern. So even if I defined separate kibana7 and kibana8 formats, the filenames collide.

[tstack]

I've made a couple of minor tweaks recently that might help this situation. The format elements can now have a prefix and a suffix that will prepend/append text to the value. If the value does not exist or is empty (the default-value must be empty as well), then nothing will be printed out. This allows for some conditional behavior.

Using the example from @crc-smcleod, I've created this format:

{
    "$schema": "https://lnav.org/schemas/format-v1.schema.json",
    "issue1065_log": {
        "json": true,
        "title": "format for issue #1065",
        "level": {
            "error": "error",
            "info": "update"
        },
        "level-field": "status",
        "body-field": "message",
        "line-format": [
            {
                "field": "timestamp"
            },
            " ",
            {
                "field": "status",
                "auto-width": true
            },
            " ",
            {
                "field": "image",
                "min-width": 9,
                "default-value": "-"
            },
            " ",
            {
                "field": "image_date",
                "min-width": 24,
                "default-value": "",
                "suffix": " "
            },
            {
                "field": "mime",
                "auto-width": true,
                "default-value": "",
                "suffix": " "
            },
            {
                "field": "size",
                "auto-width": true,
                "default-value": ""
            },
            {
                "field": "message",
                "default-value": ""
            }
        ],
        "timestamp-field": "timestamp",
        "value": {
            "timestamp": {
                "kind": "string"
            },
            "status": {
                "kind": "string"
            },
            "image": {
                "kind": "string"
            },
            "image_date": {
                "kind": "string"
            },
            "mime": {
                "kind": "string",
                "identifier": true
            },
            "size": {
                "kind": "integer"
            },
            "message": {
                "kind": "string"
            }
        }
    }
}

The following screenshot shows what things look like with this format and the above example log messages:

Here's what it looked like before:

To add to the confusion here, both the 7.x and 8.x standards match the same kibana.*log filename pattern. So even if I defined separate kibana7 and kibana8 formats, the filenames collide.

@VimCommando The format detection for JSON-lines files has been also been improved, so I think you can write two different format files that will separately recognize kibana7 and kibana8 even though the filenames are the same. The detection now tries to find a format that matches the most fields in the line-format.

[tstack]

I think the conditional field functionality is good enough for now, going to close this out. Open a new feature request for improvements to that.