Custom format for multi-line log entries with multiple patterns matches only one pattern #816

piotr-dobrogost · 2020-12-14T22:28:22Z

piotr-dobrogost
Dec 14, 2020
Sponsor

I defined custom format with three patterns (request, reply, generic). When opening a test log file (below) I see all lines are matched only by "generic" pattern although some of them should much "request" or "reply" patterns (tested at regex101.com).
What am I missing?

custom format:

{
    "appsrv_debug_log": {
        "title": "",
        "description": "",
        "regex": {
            "request": {
                "pattern": "^\\[(?<timestamp>\\d{4}-\\d{2}-\\d{2} \\d{2}:\\d{2}:\\d{2},\\d{3})\\]\\s+(?<level>\\w+)\\s+\\[(?<module>[^:]*):(?<line>\\d+)\\]\\s*(?<body>(?:.|\\n)*(?<head><head>(?:.|\\n)*<\\/head>)(?:.|\\n)*(?<source><source>(?:.|\\n)*<\\/source>)(?:.|\\n)*(?<message_type>request)>\\s+<(?<message_name>[^\\/>]+)\\/?>(.|\\n)*)?"
            },
            "reply": {
                "pattern": "^\\[(?<timestamp>\\d{4}-\\d{2}-\\d{2} \\d{2}:\\d{2}:\\d{2},\\d{3})\\]\\s+(?<level>\\w+)\\s+\\[(?<module>[^:]*):(?<line>\\d+)\\]\\s*(?<body>(?:.|\\n)*(?<head><head>(?:.|\\n)*<\\/head>)(?:.|\\n)*<(?<message_type>reply)>\\s*(?<status><status>(?:.|\\n)*<\\/status>\\s*\\s*<(?<message_name>[^\\/>]+)\\/?>)(?:.|\\n)*(?<technical_track><technical-track>(?:.|\\n)*<\\/technical-track>)(?:.|\\n)*)?"
            },
            "generic": {
                "pattern": "^\\[(?<timestamp>\\d{4}-\\d{2}-\\d{2} \\d{2}:\\d{2}:\\d{2},\\d{3})\\]\\s+(?<level>\\w+)\\s+\\[(?<module>[^:]*):(?<line>\\d+)\\]\\s*(?<body>(?:.|\\n)*)"
            }
        },
        "level": {
            "critical": "CRITICAL",
            "error": "ERROR",
            "warning": "WARNING",
            "info": "INFO",
            "debug": "DEBUG"
        },
        "value": {
            "module": {
                "kind": "string",
                "identifier": true,
                "description": "Python source module which emitted log entry"
            },
            "line": {
                "kind": "integer",
                "description": "Line number – in the module – where log entry was emitted"
            },
            "head": {
                "kind": "string",
                "description": "<head>",
                "hidden": true
            },
            "source": {
                "kind": "string",
                "description": "request <source>",
                "hidden": true
            },
            "technical_track": {
                "kind": "string",
                "description": "reply <technical-track>",
                "hidden": true
            },
            "message_name": {
                "kind": "string",
                "identifier": true,
                "description": "message name"
            },
            "message_type": {
                "kind": "string",
                "identifier": true,
                "description": "message type - request or reply"
            }
        },
        "highlights": {
            "client_id": {
              "pattern": "(?<=>)\\d+(?=<\/client>)",
              "color": "Orange1",
              "underline": true
            },
            "reply_error": {
              "pattern": "(?<=<result>)ERROR(?=</result>)",
              "color": "Red1"
            }
        },
        "sample": [
            {
                "line": "[2020-12-10 06:56:41,477] INFO [m:108] Calling 'x' with params:",
                "level": "info"
            },
            {
                "line": "[2020-12-10 06:56:41,092] DEBUG [m:69] Full request text:\n<?xml version='1.0' encoding='iso-8859-2'?>\n<a-request>\n  <head>\n    x\n  </head>\n  <source>\n    x\n  </source>\n  <request>\n    <name>\n      x\n    </name>\n  </request>\n</a-request>\n",
                "level": "debug"
            },
            {
                "line": "[2020-12-10 06:56:41,099] DEBUG [m:85] Full reply text:\n<?xml version='1.0' encoding='iso-8859-2'?>\n<a-reply>\n  <head>\n    x\n  </head>\n  <reply>\n    <status>\n      <result>OK</result>\n    </status>\n    <name>\n      x\n    </name>\n  </reply>\n  <technical-track>\n    x\n  </technical-track>\n</a-reply>\n",
                "level": "debug"
            }
        ]
    }
}

test log file:

[2020-12-10 06:56:41,061] INFO [m:108] Calling 'x' with params:

[2020-12-10 06:56:41,092] DEBUG [connect.client:69] Full request text:
<?xml version='1.0' encoding='iso-8859-2'?>
<a-request>
  <head>
    x
  </head>
  <source>
    x
  </source>
  <request>
    <name>
      x
    </name>
  </request>
</a-request>

[2020-12-10 06:56:41,099] DEBUG [m:85] Full reply text:
<?xml version='1.0' encoding='iso-8859-2'?>
<a-reply>
  <head>
    x
  </head>
  <reply>
    <status>
      <result>OK</result>
    </status>
    <name>
      x
    </name>
  </reply>
  <technical-track>
    x
  </technical-track>
</a-reply>

piotr-dobrogost · 2020-12-17T20:05:38Z

piotr-dobrogost
Dec 17, 2020
Author Sponsor

Anyone?

0 replies

tstack · 2020-12-19T21:37:32Z

tstack
Dec 19, 2020
Maintainer

lnav will only match the first line of the log message when picking a pattern. Since it looks like your patterns all have the same pattern for the first line, it's not going to figure out which one to use. I would suggest combining the patterns into a single one using an alternate (e.g. |) for the lines after the first.

3 replies

piotr-dobrogost Dec 20, 2020
Author Sponsor

lnav will only match the first line of the log message when picking a pattern

Did I miss this or is this information missing from the docs?

How can I reconcile this with the following information from docs?

When lnav loads a file, it tries each log format against the first ~1000 lines of the file trying to find a match.

As to your suggestion:

I would suggest combining the patterns into a single one using an alternate (e.g. |) for the lines after the first.

I have already tried combing them using alternative as you suggest but still had a trouble getting it to match.
In addition when patterns are combined there is a problem as there are "common" (the same) fields in each pattern thus after combining them in one pattern there are name collisions (more than one named group with the same name).

In my comment #410 (comment) I suggested using separate patterns for the first line and the rest of log entry. What do you think? Maybe more precise would be to say the header of the log entry (which usually is some kind of a timestamp and additional level and source) and the body. Then this would handle both one line and multi-line log entries (provided body was matched multi-line). This could help separate concerns and potentially have performance benefits as the body regexes would be matched against slices of the whole file obtained by matching the header regexp first (technically both could be run simultaneously, one process trailing the other in the pipeline). Having log file sliced to log entries by matching header regex would also allow more natural approach to matching body. Body could be matched against a series of regexes which do not need to match whole body but can much any specific part of a body (similar to how highlight regexes work now). This way each body regex would add additional fields without having to specify the order among fields (like current approach of body matching forces).

tstack Dec 20, 2020
Maintainer

lnav will only match the first line of the log message when picking a pattern

Did I miss this or is this information missing from the docs?

Looks like It might be missing from the docs.

How can I reconcile this with the following information from docs?

When lnav loads a file, it tries each log format against the first ~1000 lines of the file trying to find a match.

This behavior is to prevent lnav from checking every line of a really big file. It's not really related to the actual matching logic.

As to your suggestion:

I would suggest combining the patterns into a single one using an alternate (e.g. |) for the lines after the first.

I have already tried combing them using alternative as you suggest but still had a trouble getting it to match.
In addition when patterns are combined there is a problem as there are "common" (the same) fields in each pattern thus after combining them in one pattern there are name collisions (more than one named group with the same name).

It looks like there is a feature in PCRE that can be used to allow this to work:

https://www.pcre.org/current/doc/html/pcre2pattern.html#SEC15

I didn't try it out in a real format, but using (?| in a test regex and log file seems to produce the expected results.

However, I would say that using a regex to parse XML is ... not great. I would suggest that this use-case is better served by incorporating XML/XPATH into lnav's SQLite extensions. Then, if you wanted to write some SQL that accessed portions of an XML document that were in a log message, you write something like:

;SELECT * FROM xpath(msg_xml, '/a-request/source');

In my comment #410 (comment) I suggested using separate patterns for the first line and the rest of log entry. What do you think? Maybe more precise would be to say the header of the log entry (which usually is some kind of a timestamp and additional level and source) and the body. Then this would handle both one line and multi-line log entries (provided body was matched multi-line). This could help separate concerns and potentially have performance benefits as the body regexes would be matched against slices of the whole file obtained by matching the header regexp first (technically both could be run simultaneously, one process trailing the other in the pipeline). Having log file sliced to log entries by matching header regex would also allow more natural approach to matching body. Body could be matched against a series of regexes which do not need to match whole body but can much any specific part of a body (similar to how highlight regexes work now). This way each body regex would add additional fields without having to specify the order among fields (like current approach of body matching forces).

I'll think about this option as I work on moving lnav to a message-oriented model instead of line-oriented.

piotr-dobrogost Dec 20, 2020
Author Sponsor

I would suggest combining the patterns into a single one using an alternate (e.g. |) for the lines after the first.

I combined the three patterns from the original format description using alternative into the one below. To better see the structure I placed each of them in the named matching group with names REQUEST, REPLY, GENERIC respectively. With this modification and the original log file the third entry ("reply") in the log is not being matched and I have no idea why as it's being matched with this pattern at regex101.com. For comparison the second entry of the log file ("request") is matched.

"regex": {
    "combined": {
      "pattern": "^\\[(?<timestamp>\\d{4}-\\d{2}-\\d{2} \\d{2}:\\d{2}:\\d{2},\\d{3})\\]\\s+(?<level>\\w+)\\s+\\[(?<module>[^:]*):(?<line>\\d+)\\]\\s*((?<REQUEST>(?:.|\\n)*(?<head><head>(?:.|\\n)*<\\/head>)(?:.|\\n)*(?<source><source>(?:.|\\n)*<\\/source>)(?:.|\\n)*(?<message_type>request)>\\s+<(?<message_name>[^\\/>]+)\\/?>(.|\\n)*)?|(?<REPLY>(?:.|\\n)*(?<head2><head>(?:.|\\n)*<\\/head>)(?:.|\\n)*<(?<message_type2>reply)>\\s*(?<status><status>(?:.|\\n)*<\\/status>\\s*\\s*<(?<message_name2>[^\\/>]+)\\/?>)(?:.|\\n)*(?<technical_track><technical-track>(?:.|\\n)*<\\/technical-track>)(?:.|\\n)*)?|(?<GENERIC>(?:.|\\n)*))"
    }
}

It looks like there is a feature in PCRE that can be used to allow this to work:

I've seen it and I tried to use it but with no success as it seems to work only for match groups on the same level and my common fields are on different levels in each of the pattern.

However, I would say that using a regex to parse XML is ... not great.

Of course it's the wrong tool and I'm perfectly aware of this :) Never the less it does not keep people from trying and it seems I came up with the ones catching exactly what I need from these xml documents. By the way please do not allow the fact I'm working with xml documents embedded in the log entries mislead you as the problems I'm describing are generic and are perfectly valid outside of this specific case of xml content too.

I would suggest that this use-case is better served by incorporating XML/XPATH into lnav's SQLite extensions.

This sounds interesting. Could you please elaborate? Is this possible currently in lnav and if so then how? It seems I would first need to match the entire xml document and mark it as such so that it could be subsequently parsed by this extension, yes?

By the way, it seems even when I manage to match some field it's not being hidden in spite of it being marked as hidden in the format description. Is this because the field's content is multi-line?

tstack · 2020-12-23T23:26:49Z

tstack
Dec 23, 2020
Maintainer

I've pushed a change that adds an xpath() table-valued function that you can call like:

;SELECT * FROM xpath('/a-request/source', msg_data);

I added your test log file and a format to the source and it seems to work. (I still have to write a test that uses that stuff)

0 replies

alan-taylor · 2021-03-24T13:13:07Z

alan-taylor
Mar 24, 2021

I thought I understood things, but this discussion indicates that I don’t.
Are you saying that lnav can only match one regex format per file ? If so, what’s the point of having more than one ?

BRgds/Alan

1 reply

tstack Mar 24, 2021
Maintainer

Are you saying that lnav can only match one regex format per file ?

lnav can match more than one regex per file. But, the regex has only the first line of the message to match against, so the regexes need to be unique in that respect.

Here's the steps lnav takes when reading files:

Read in a line
Match the line against the regexes
a. If the line matches a regex, add a new log message to the index
b. If the line did not match a regex, add the line to the previous log message

In order for lnav to figure out where messages start and stop, it needs to be able to test a single line against a regex. (There may be a better way to do this, but this is the way it works now.)

If so, what’s the point of having more than one ?

A log file format can vary slightly over different versions of the software, so multiple regexes were initially supported for this case. Later, support was expanded to allow multiple regexes within a single file.

alan-taylor · 2021-03-25T00:02:31Z

alan-taylor
Mar 25, 2021

Thanks Tim ...

"regex has only the first line of the message to match" ... do you mean carriage return delineated lines ? I am dealing with a pfSense firewall log and every message in the log is a single line long, separated by the normal end-of-line for OS. So every message line should be unique and matched against one of the unique regex ? In my case it doesn't seem to work like this, it picks one regex to match and then seems to ignore the others. Examples of the possible (I think) message formats given below (everything within the quotes is a single line in the log file).

"Mar 18 10:51:53 computer.domain.tld filterlog: 5,,,1000000103,igb0,match,block,in,4,0x0,,41,4812,0,none,6,tcp,44,111.22.33.1,224.22.11.1,39248,10443,0,S,980905229,,1024,,mss"
"Mar 18 10:51:54 computer.domain.tld filterlog: 145,,,100000101,igb1.8,match,pass,in,4,0x0,,64,43408,0,DF,6,tcp,52,111.22.33.1,224.22.11.1,56840,443,0,S,3960455768,,64240,,mss;nop;nop;sackOK;nop;wscale"
"Mar 18 10:51:53 computer.domain.tld filterlog: 145,,,100000101,igb1.8,match,pass,in,4,0x0,,64,26055,0,DF,17,udp,86,111.22.33.1,224.22.11.1,37347,53,66"
"Dec 19 17:30:22 computer.domain.tld filterlog: 7,,,1000000105,lagg0.9,match,block,in,6,0x00,0x30dbe,255,UDP,17,147,fe00::1c11:7f5c:b111:71d2,fc23::bc,5353,5353,147"
"Mar 18 10:52:26 computer.domain.tld filterlog: 7,,,1000000105,lagg0.9,match,block,in,6,0x00,0x00000,1,Options,0,32,fe00::1c11:7f5c:b111:71d2,ee23::5,HBH,PADN,RTALERT,0x0000,"
"Mar 18 10:52:21 computer.domain.tld filterlog: 136,,,1615175071,igb1.8,match,pass,in,4,0x0,,64,47615,0,DF,1,icmp,84,111.22.33.1,224.22.11.1,request,7717,164"
Mar 12 02:53:34 computer.domain.tld filterlog: 5,,,1000000103,lagg0.9,match,block,in,4,0x0,,1,1918,0,none,2,igmp,32,111.22.33.1,224.22.11.1,datalength=8"

BRgds/Alan

2 replies

tstack Mar 27, 2021
Maintainer

it picks one regex to match and then seems to ignore the others.

So long as the regex matches the lines, it will continue to be used. The regexes needs to be specific enough so that it will only match a particular type of line. For example, in your format you have (?<ip_ver>[4|6]) for the IPv4 and IPv6 patterns. But, I would think you would only want (?<ip_ver>4) in the v4 pattern and (?<ip_ver>6) in the v6 pattern.

alan-taylor Mar 28, 2021

Thanks Tim,

Absolutely right. I did that and also simplified and reduced the numbers of regex - seems to be working well now.

BRgds/Alan

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Custom format for multi-line log entries with multiple patterns matches only one pattern #816

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 5 comments 6 replies

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

Select a reply

Custom format for multi-line log entries with multiple patterns matches only one pattern #816

piotr-dobrogost Dec 14, 2020 Sponsor

Replies: 5 comments · 6 replies

piotr-dobrogost Dec 17, 2020 Author Sponsor

tstack Dec 19, 2020 Maintainer

piotr-dobrogost Dec 20, 2020 Author Sponsor

tstack Dec 20, 2020 Maintainer

piotr-dobrogost Dec 20, 2020 Author Sponsor

tstack Dec 23, 2020 Maintainer

alan-taylor Mar 24, 2021

tstack Mar 24, 2021 Maintainer

alan-taylor Mar 25, 2021

tstack Mar 27, 2021 Maintainer

alan-taylor Mar 28, 2021

piotr-dobrogost
Dec 14, 2020
Sponsor

Replies: 5 comments 6 replies

piotr-dobrogost
Dec 17, 2020
Author Sponsor

tstack
Dec 19, 2020
Maintainer

piotr-dobrogost Dec 20, 2020
Author Sponsor

tstack Dec 20, 2020
Maintainer

piotr-dobrogost Dec 20, 2020
Author Sponsor

tstack
Dec 23, 2020
Maintainer

alan-taylor
Mar 24, 2021

tstack Mar 24, 2021
Maintainer

alan-taylor
Mar 25, 2021

tstack Mar 27, 2021
Maintainer