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

s0nik42 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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.

tstack / lnav

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