I need to capture some standard fields from a log line, but if new fields show up I don't want it included in the capture, just treat it as text

[hiro5id]

I am using the following regex:

^{((\"level\"\:\")(?<level>.*?)(?<!\\)").?(?:(\"message\"\:\")(?<message>.*?)(?<!\\)")?.?(?:(\"\@filename\"\:\")(?<filename>.*?)(?<!\\)")?.?(?:(\"\@logCallStack\"\:\")(?<logCallStack>.*?)(?<!\\)")?.?(?:(\"errCallStack\"\:\")(?<errCallStack>.*?)(?<!\\)")?.?((\"\@timestamp\"\:\")(?<timestamp>.*?)(?<!\\)")}$

to capture messages in the following format:

{"level":"info","message":"Error running main:   - connect ECONNREFUS\"ED ::1:27017","@errorObjectName":"MongoServerSelectionError","@filename":"/data-scraper/dist/src/main.js","@logCallStack":" /data-scraper/src/main.ts:20:13","@packageName":"starter-project","errCallStack":"Error: connect ECONNREFUSED ::1:27017\n    at /data-scraper/src/main.ts:20:13Caused By: MongoServerSelectionError: connect ECONNREFUSED ::1:27017\n    at Timeout._onTimeout (/data-scraper/node_modules/mongodb/src/sdam/topology.ts:591:30)\n    at listOnTimeout (node:internal/timers:564:17)\n    at processTimers (node:internal/timers:507:7)","@timestamp":"2023-01-16T14:52:31.874Z"}

That works fine, except some fields that show up that are not in the regex, like for example the @errorObjectName field above, it gets captured together as <message> rather than being ignored.

So I tried the following regex to achieve that desired behaviour which uses OR to capture the different fields that I want to parse out.

^{((\"level\"\:\")(?<level>.*?)(?<!\\)")|(?:(\"message\"\:\")(?<message>.*?)(?<!\\)")|(?:(\"\@filename\"\:\")(?<filename>.*?)(?<!\\)")|(?:(\"\@logCallStack\"\:\")(?<logCallStack>.*?)(?<!\\)")|(?:(\"errCallStack\"\:\")(?<errCallStack>.*?)(?<!\\)")|((\"\@timestamp\"\:\")(?<timestamp>.*?)(?<!\\)")}$

The problem is with the above when I run lnav I get the following error:

error: invalid pattern: “base”
 reason: pattern does not match entire message
 --> /Users/roberto/.lnav/formats/installed/console_log_json.json:43
 | {"level":"info","message":"Error running main:   - connect ECONNREFUS\"ED ::1:27017","@errorObjectName":"MongoServerSelectionError","@filename":"/data-scraper/dist/src/main.js","@logCallStack":" /data-scraper/src/main.ts:20:13","@packageName":"starter-project","errCallStack":"Error: connect ECONNREFUSED ::1:27017\n    at /data-scraper/src/main.ts:20:13Caused By: MongoServerSelectionError: connect ECONNREFUSED ::1:27017\n    at Timeout._onTimeout (/data-scraper/node_modules/mongodb/src/sdam/topology.ts:591:30)\n    at listOnTimeout (node:internal/timers:564:17)\n    at processTimers (node:internal/timers:507:7)","@timestamp":"2023-01-16T14:52:31.874Z"}
 |                ^ matched up to here
 = note: base = ^{((\"level\"\:\")(?<level>.*?)(?<!\\)")|(?:(\"message\"\:\")(?<message>.*?)(?<!\\)")|(?:(\"\@filename\"\:\")(?<filename>.*?)(?<!\\)")|(?:(\"\@logCallStack\"\:\")(?<logCallStack>.*?)(?<!\\)")|(?:(\"errCallStack\"\:\")(?<errCallStack>.*?)(?<!\\)")|((\"\@timestamp\"\:\")(?<timestamp>.*?)(?<!\\)")}$
 = help: update the regular expression to fully capture the sample message

So lnav won't allow me to load this formatter unless it fully matches everything......

Is there a way to achieve the behavior that I want? Or is it impossible with lnav ?

[tstack]

It looks like your log file is in JSON-lines form, which is directly supported by lnav. You shouldn't have to use a regex to parse it out. The log format reference covers the details of how to write a log format file for a JSON-lines log. Unfortunately, the docs don't have an actual example, but there are some tests you can look at. For this log file:

lnav/test/logfile_json.json

Lines 1 to 13 in 8d17561

	{"ts": "2013-09-06T20:00:48.124817Z", "lvl": "TRACE", "msg": "trace test"}
	{"ts": "2013-09-06T20:00:49.124817Z", "lvl": "INFO", "msg": "Starting up service"}
	{"ts": "2013-09-06T22:00:49.124817Z", "lvl": "INFO", "msg": "Shutting down service", "user": "[email protected]"}
	{"ts": "2013-09-06T22:00:59.124817Z", "lvl": "DEBUG5", "msg": "Details..."}
	{"ts": "2013-09-06T22:00:59.124817Z", "lvl": "DEBUG4", "msg": "Details..."}
	{"ts": "2013-09-06T22:00:59.124817Z", "lvl": "DEBUG3", "msg": "Details..."}
	{"ts": "2013-09-06T22:00:59.124817Z", "lvl": "DEBUG2", "msg": "Details..."}
	{"ts": "2013-09-06T22:00:59.124817Z", "lvl": "DEBUG", "msg": "Details..."}
	{"ts": "2013-09-06T22:01:49.124817Z", "lvl": "STATS", "msg": "1 beat per second"}
	{"ts": "2013-09-06T22:01:49.124817Z", "lvl": "WARNING", "msg": "not looking good"}
	{"ts": "2013-09-06T22:01:49.124817Z", "lvl": "ERROR", "msg": "looking bad"}
	{"ts": "2013-09-06T22:01:49.124817Z", "lvl": "CRITICAL", "msg": "sooo bad"}
	{"ts": "2013-09-06T22:01:49.124817Z", "lvl": "FATAL", "msg": "shoot", "obj": { "field1" : "hi", "field2": 2 }, "arr" : ["hi", {"sub1": true}]}

The log format file looks like this:

lnav/test/formats/jsontest/format.json

Lines 1 to 36 in 8d17561

	{
	"$schema": "https://lnav.org/schemas/format-v1.schema.json",
	"test_log" : {
	"title" : "Test JSON Log",
	"json" : true,
	"file-pattern" : "logfile_json\\.json",
	"description" : "Test config",
	"line-format" : [
	"\n[",
	{ "field" : "ts" },
	"] ",
	{ "field" : "lvl" },
	" ",
	{ "field" : "msg" }
	],
	"level-field" : "lvl",
	"timestamp-field": "ts",
	"body-field" : "msg",
	"value" : {
	"msg" : {
	"rewriter" : ";SELECT :msg || 'bork bork bork'"
	},
	"arr" : {
	"kind" : "json"
	},
	"obj" : {
	"kind" : "json"
	},
	"user" : {
	"kind" : "string",
	"identifier" : true,
	"rewriter" : "|rewrite-user"
	}
	}
	}
	}

The rendered output then looks like this:

lnav/test/expected/test_json_format.sh_469f005b0708d629bc95f0c48a5e390f440c1fef.out

Lines 1 to 29 in 8d17561

	[2013-09-06T20:00:48.124] TRACE trace test
	[2013-09-06T20:00:49.124] INFO Starting up service
	[2013-09-06T22:00:49.124] INFO Shutting down service
	user: [email protected]
	[2013-09-06T22:00:59.124] DEBUG5 Details...
	[2013-09-06T22:00:59.124] DEBUG4 Details...
	[2013-09-06T22:00:59.124] DEBUG3 Details...
	[2013-09-06T22:00:59.124] DEBUG2 Details...
	[2013-09-06T22:00:59.124] DEBUG Details...
	[2013-09-06T22:01:49.124] STATS 1 beat per second
	�[33m[2013-09-06T22:01:49.124] WARNING not looking good�[0m
	�[31m[2013-09-06T22:01:49.124] ERROR looking bad�[0m
	�[31m[2013-09-06T22:01:49.124] CRITICAL sooo bad�[0m
	�[31m[2013-09-06T22:01:49.124] FATAL shoot�[0m
	�[31m obj: { "field1" : "hi", "field2": 2 }�[0m
	�[31m arr: ["hi", {"sub1": true}]�[0m

(Note that the extra spacing is due to the leading \n in the line-format that was added for testing purposes. Your format won't have that.)

Let me know if you need additional help in creating your format file.

[tstack]

It does not work if I'm piping logs directly to lnav.

Ah, sorry. Yes, JSON-lines logs need to be in a file at the moment.

For those extra fields, I would still like to print them out on the screen, even if they are not parsed and picked up by the JSON parser with known fields.

This behavior should work already. Any fields found that are not mentioned in line-format will be printed below the text generated by the line-format. You can see this in the test example above with the last message:

{"ts": "2013-09-06T22:01:49.124817Z", "lvl": "FATAL", "msg": "shoot", "obj": { "field1" : "hi", "field2": 2 }, "arr" : ["hi", {"sub1": true}]}

The obj and arr fields are not mentioned in the line-format, so they are added just below the main message:

There is a flag in the format definition, hide-extra, that actually controls whether or not undefined fields will be displayed on their own lines.

[stewartshea]

Totally new user (found lnav yesterday) - I'm trying to do something sort of similar, but with a few differences.

1. I'm passing in a json file (not using regex etc)
2. The json fields are slightly inconsisent across lines
3. lnav possibly appears to auto-identify the fields from the first couple of logs, but then ignores the rest - so if the field I want to search on itsn't in the first few lines, it's not possible
4. Ideally, I'd like lnav to only load the lines that match the fields in the custom format and drop the rest.
5. With my limited experience, but many hours of use, the best solution I can come up with is to pre-filter the log to generate a new logfile that includes the mandatory fields.

Is my final approach the right way to handle this scenario?

By example, here are a few sample log entries:

{"http.req.id":"a525bbef-c9e0-414a-99d7-8eaafaa08bb0","http.req.method":"POST","http.req.path":"/setCurrency","message":"request started","session":"6d33a840-a794-4dfe-b1cc-481a35b1b70c","severity":"debug","timestamp":"2023-09-09T09:40:33.963230061Z"}
{"curr.new":"CAD","curr.old":"CAD","http.req.id":"a525bbef-c9e0-414a-99d7-8eaafaa08bb0","http.req.method":"POST","http.req.path":"/setCurrency","message":"setting currency","session":"6d33a840-a794-4dfe-b1cc-481a35b1b70c","severity":"debug","timestamp":"2023-09-09T09:40:33.963381439Z"}
{"http.req.id":"a525bbef-c9e0-414a-99d7-8eaafaa08bb0","http.req.method":"POST","http.req.path":"/setCurrency","http.resp.bytes":0,"http.resp.status":302,"http.resp.took_ms":0,"message":"request complete","session":"6d33a840-a794-4dfe-b1cc-481a35b1b70c","severity":"debug","timestamp":"2023-09-09T09:40:33.963469391Z"}
{"http.req.id":"0f8627b0-e523-4d24-95d6-5c50afc28a40","http.req.method":"GET","http.req.path":"/","message":"request started","session":"6d33a840-a794-4dfe-b1cc-481a35b1b70c","severity":"debug","timestamp":"2023-09-09T09:40:33.965102419Z"}
{"currency":"CAD","http.req.id":"0f8627b0-e523-4d24-95d6-5c50afc28a40","http.req.method":"GET","http.req.path":"/","message":"home","session":"6d33a840-a794-4dfe-b1cc-481a35b1b70c","severity":"info","timestamp":"2023-09-09T09:40:33.965219675Z"}
{"error":"could not retrieve products: rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.107.248.32:3550: connect: connection refused\"","http.req.id":"0f8627b0-e523-4d24-95d6-5c50afc28a40","http.req.method":"GET","http.req.path":"/","message":"request error","session":"6d33a840-a794-4dfe-b1cc-481a35b1b70c","severity":"error","timestamp":"2023-09-09T09:40:33.967523152Z"}

With the custom format;

{
   "http_logrus_custom": {
        "title": "HTTP Logrus Custom (used in online-boutique)",
        "description": "A custom format for specific http router logs from logrus with online-boutique.",
        "json": true,
        "file-pattern": ".*\\.json$",
        "timestamp-format": ["%Y-%m-%dT%H:%M:%S"],
	"timestamp-field": "timestamp",
        "level-field": "severity",
	"require": ["http.resp.status", "http.req.path"], 
	"severity" : 
	{
      	    "debug" : "debug",
      	    "info": "info",
      	    "warning" : "warning",
      	    "error" : "error",
      	    "fatal" : "fatal"
	},

	"opid-field": "http.req.id",
        "convert-to-local-time": true,
        "multiline": false,
	"body-field": "message",
	"line-format":[
	{ 
		"field": "__timestamp__"
	},
        " ",	
	{ 
		"field": "message"
	},
	" ",
	{
		"field": "severity"
	},
	"http_req_method: ",
	{
		"field": "http.req.method"
	}
	],
	"value": {
            "http.req.id": {
                "kind": "string"
            },
            "http.req.method": {
                "kind": "string"
            },
            "http.req.path": {
                "kind": "json",
                "identifier": "true"
            },
            "http.resp.bytes": {
                "kind": "integer",
                "identifier": "true"
            },
            "http.resp.status": {
                "kind": "integer",
                "identifier": "true"
            },
            "http.resp.took.ms": {
                "kind": "integer"
            },
            "session": {
                "kind": "string"
            },
            "currency": {
                "kind": "string",
                "identifier": "false"
            },
            "product.id": {
                "kind": "string"
            },
            "error": {
                "kind": "string",
		"identifier": true
            }
        }
    }
}

When running lnav against the file, I see the following when typing p:

 Received Time: 2023-09-09T06:11:25.977 -- 3 hours ago  Format: %Y-%m-%dT%H:%M:%S                                                                                        │
 Known message fields for table http_logrus_custom:                                                                                                                      │
 ├ http.req.id     = b71c7065-22bb-462a-aebf-5ea6292e61b7                                                                                                                │
 ├ http.req.method = GET                                                                                                                                                 │
 ├ http.req.path   = /product/2ZYFJ3GM2N                                                                                                                                 │
 ├ body            = request started                                                                                                                                     │
 ├ log_body        = request started                                                                                                                                     │
 ├ session         = 570730fe-ade9-412e-ae34-08fd523965bb                                                                                                                │
 ├ severity        = debug                                                                                                                                               │
 ├ log_time        = 2023-09-09T06:11:25.977 
 

The ultimate goal here (in this example) is to query the number of 500's by path so that a user can identify which path is having issues. so the field http.resp.status is mandatory.

Oddly, I just scrolled through the lines and sometimes I get a hit for that as a field and sometimes not;

Known message fields for table http_logrus_custom:                                                                                                                      │
 ├ http.req.id       = 4fe5496e-f676-4deb-8cf8-c64f55949646                                                                                                              │
 ├ http.req.method   = GET                                                                                                                                               │
 ├ http.req.path     = /product/9SIQT8TOJO                                                                                                                               │
 ├ http.resp.bytes   = 4742                                                                                                                                              │
 ├ http.resp.status  = 500                                                                                                                                               │
 ├ http.resp.took_ms = 0                                                                                                                                                 │
 ├ body              = request complete                                                                                                                                  │
 ├ log_body          = request complete                                                                                                                                  │
 ├ session           = 1072f05e-4ac0-446e-a5aa-3a5230da8fa9                                                                                                              │
 ├ severity          = debug                                                                                                                                             │
 ├ log_time          = 2023-09-09T06:10:19.876   

This is interesting, but even that message doesn't seem to return a result when querying, so I guess the easiest path is to just grep / pre-filter the file?

[tstack]

lnav possibly appears to auto-identify the fields from the first couple of logs, but then ignores the rest - so if the field I want to search on isn't in the first few lines, it's not possible

Hmm, I'm not sure what you mean by this. Can you give an example?

The ultimate goal here (in this example) is to query the number of 500's by path so that a user can identify which path is having issues. so the field http.resp.status is mandatory.

With your format, I am able to run the following query and it returns a reasonable result for the sample log messages you provided:

;SELECT count(*), "http.req.path", "http.resp.status" FROM http_logrus_custom GROUP BY "http.req.path", "http.resp.status"

To limit the query to cases where the status is 500, you can do:

;SELECT count(*), "http.req.path", "http.resp.status" from http_logrus_custom WHERE "http.resp.status" = 500 GROUP BY "http.req.path"

I think that is doing what you want or are you looking for something else?

Oddly, I just scrolled through the lines and sometimes I get a hit for that as a field and sometimes not;

The display is only showing the fields actually in the message. All fields are still available as columns in the http_logrus_custom SQL table.

Your format had some errors/warnings (pass -W to lnav see them), so I tweaked it a bit:

{
    "$schema": "https://lnav.org/schemas/format-v1.schema.json",
    "http_logrus_custom": {
        "title": "HTTP Logrus Custom (used in online-boutique)",
        "description": "A custom format for specific http router logs from logrus with online-boutique.",
        "json": true,
        "timestamp-format": [
            "%Y-%m-%dT%H:%M:%S"
        ],
        "timestamp-field": "timestamp",
        "level-field": "severity",
        "opid-field": "http.req.id",
        "convert-to-local-time": true,
        "multiline": false,
        "body-field": "message",
        "line-format": [
            {
                "field": "__timestamp__"
            },
            " ",
            {
                "field": "severity",
                "auto-width": true
            },
            " ",
            {
                "field": "message"
            },
            " ",
            {
                "field": "http.req.method"
            },
            " ",
            {
                "field": "http.req.path",
                "default-value": ""
            }
        ],
        "value": {
            "http.req.id": {
                "kind": "string",
                "identifier": true
            },
            "http.req.method": {
                "kind": "string",
                "identifier": true
            },
            "http.req.path": {
                "kind": "json",
                "identifier": true
            },
            "http.resp.bytes": {
                "kind": "integer"
            },
            "http.resp.status": {
                "kind": "integer",
                "identifier": true
            },
            "http.resp.took.ms": {
                "kind": "integer"
            },
            "session": {
                "kind": "string"
            },
            "currency": {
                "kind": "string",
                "identifier": false
            },
            "product.id": {
                "kind": "string",
                "identifier": true
            },
            "error": {
                "kind": "string"
            }
        }
    }
}

Adding the $schema property at the root lets an editor, like VSCode, highlight any errors.

[stewartshea]

Oh wow, so I was really just getting caught up in poor SQL statement issue - I just had a look at yours and those examples are super helpful this removes the entire pre-filter requirement.

I'll definitely add the schema and changes you've provided - I'm just now moving it from vim to vscode as we build up a repository of formats for use.

@tstack you're amazing, this is a huge help - I appreciate the guidance, pointers, and patience :)

[tstack]

so I was really just getting caught up in SQL statement issue

Note that the column names need to be in double-quotes (e.g. "http.resp.status") since they have dots in their name.