Multiline source won't include java stacktrace in message #13654

jonathanderham-streamotion · 2022-07-21T05:49:14Z

jonathanderham-streamotion
Jul 21, 2022

We need some help using the multiline feature.

We're using a log like the following:

[2022-07-18T11:46:25,410+1000] DEBUG [java.class] - first line
[2022-07-18T11:46:25,418+1000] ERROR [java.class] - Begin event threw exception java.lang.Exception: class name
        at stacktrace.info(javaClass.java:77)
        at stacktrace.info(javaClass.java:276)
        at stacktrace.info(javaClass.java:1350)
        stacktrace.info(javaClass.java:377)
        at net.sf.saxon.event.ProxyReceiver.startElement(ProxyReceiver.java:140)
        ...
Error on line 304 column 11 of filename.xsl:
  SXCH0003  org.xml.sax.SAXParseException; systemId:
  file:/filepath/filename.xsl;
[2022-07-18T11:46:25,418+1000] ERROR [java.class] - Content parsing failed - see exception
[2022-07-18T11:46:27,240+1000] DEBUG [java.class] - Logging Provider: org.jboss.logging.Slf4jLoggerProvider

In our /etc/vector/vector.toml, we have the following for our transforms which successfully groups the timestamp, the log severity, the class name and the message for when the application is working properly:

[transforms.parse_logs]
type = "remap"
inputs = ["logs"]
source = '''
. = parse_regex!(.message,r'\[(?P<timestamp>\d+-\d+-\d+T\d+:\d+:\d+),\d+\+\d+\].(?P<severity>\w+)\s+\[(?P<class>(?:.*))\]...(?P<message>(?:.*))')
.timestamp = .timestamp + "Z"
.application_id = "applications"
.log_type = "schedule-loader"
.platform = "bookable-promos"
'''

However this does not handle the stacktrace, so in the 'sources' section, we added a 'multiline' configuration as follows:

[sources.logs]
type = "file"
include = ["/tmp/schedule-loader-2022-07-18.log"]
read_from = "beginning"
ignore_checkpoints = true

  [sources.logs.multiline]
  mode = "halt_before"
  start_pattern = "^\\["
  condition_pattern = "^\\["
  timeout_ms = 1000

We've been reading the documentation here:
https://vector.dev/docs/reference/configuration/sources/file/#multiline-messages

According to that documentation, using the config we have, the 'halt_before' setting should parse the line beginning with a stacktrace (ie, starting with a '[' character), and continue aggregating the lines until it reaches the condition line, the next line beginning with a '[' character.

However, no aggregation occurs, and only the lines with the timestamps appear in the output:

{"application_id":"applications","class":"java.class","log_type":"schedule-loader","message":"first line","platform":"bookable-promos","severity":"DEBUG","timestamp":"2022-07-18T11:46:25Z"}
{"application_id":"applications","class":"java.class","log_type":"schedule-loader","message":"Begin event threw exception java.lang.Exception: class name","platform":"bookable-promos","severity":"ERROR","timestamp":"2022-07-18T11:46:25Z"}
{"application_id":"applications","class":"java.class","log_type":"schedule-loader","message":"Content parsing failed - see exception","platform":"bookable-promos","severity":"ERROR","timestamp":"2022-07-18T11:46:25Z"}
{"application_id":"applications","class":"java.class","log_type":"schedule-loader","message":"Logging Provider: org.jboss.logging.Slf4jLoggerProvider","platform":"bookable-promos","severity":"DEBUG","timestamp":"2022-07-18T11:46:27Z"}

What are we missing here? Is there some setting that we have misconfigured? or does the multiline not work as documented?

We have also tried using the 'continue_through' setting and changing the 'condition_pattern' to be `^[\s]+' to at least catch the indented lines, but that did not work either. Given the stacktraces also have lines beginning with 'Caused by' it made more sense to use the 'halt_before' setting.

Any help would be much appreciated.

We are using vector versions 0.23.0 and 0.22.3

Answered by jonathanderham-streamotion

Jul 27, 2022

@jszwedko huzzah we have a winner.
Thanks so much for your help!

View full answer

jszwedko · 2022-07-21T14:33:25Z

jszwedko
Jul 21, 2022
Maintainer

Hi @jonathanderham-streamotion !

The multiline configuration you are using seems to work for me. With the below config:

data_dir = "/tmp/vector/"

[sources.source0]
type = "file"
include = ["/tmp/tmp.log"]
[sources.source0.multiline]
  mode = "halt_before"
  start_pattern = "^\\["
  condition_pattern = "^\\["
  timeout_ms = 1000

[sinks.sink0]
type = "console"
inputs = ["source0"]

[sinks.sink0.encoding]
codec = "json"

In the output I see:

{"file":"/tmp/tmp.log","host":"COMP-J4C4P27K9Q","message":"[2022-07-18T11:46:25,410+1000] DEBUG [java.class] - first line","source_type":"file","timestamp":"2022-07-21T14:31:59.838198Z"}
{"file":"/tmp/tmp.log","host":"COMP-J4C4P27K9Q","message":"[2022-07-18T11:46:25,418+1000] ERROR [java.class] - Begin event threw exception java.lang.Exception: class name\n        at stacktrace.info(javaClass.java:77)\n        at stacktrace.info(javaClass.java:276)\n        at stacktrace.info(javaClass.java:1350)\n        stacktrace.info(javaClass.java:377)\n        at net.sf.saxon.event.ProxyReceiver.startElement(ProxyReceiver.java:140)\n        ...\nError on line 304 column 11 of filename.xsl:\n  SXCH0003  org.xml.sax.SAXParseException; systemId:\n  file:/filepath/filename.xsl;","source_type":"file","timestamp":"2022-07-21T14:31:59.838258Z"}
{"file":"/tmp/tmp.log","host":"COMP-J4C4P27K9Q","message":"[2022-07-18T11:46:25,418+1000] ERROR [java.class] - Content parsing failed - see exception","source_type":"file","timestamp":"2022-07-21T14:31:59.838263Z"}
{"file":"/tmp/tmp.log","host":"COMP-J4C4P27K9Q","message":"[2022-07-18T11:46:27,240+1000] DEBUG [java.class] - Logging Provider: org.jboss.logging.Slf4jLoggerProvider","source_type":"file","timestamp":"2022-07-21T14:32:00.839232Z"}

Which seems to have correctly handled the multi-line log events.

Could you share your whole Vector configuration? I'm guessing these is something else amiss.

0 replies

jonathanderham-streamotion · 2022-07-22T00:05:57Z

jonathanderham-streamotion
Jul 22, 2022
Author

Hi @jszwedko,

Here is my whole config:

[sources.logs]
type = "file"
include = ["/tmp/schedule-loader-2022-07-18.log"]
read_from = "beginning"
ignore_checkpoints = true

  [sources.logs.multiline]
  mode = "halt_before"
  start_pattern = "^\\["
  condition_pattern = "^\\["
  timeout_ms = 1000

[transforms.parse_logs]
type = "remap"
inputs = ["logs"]
source = '''
. = parse_regex!(.message,r'\[(?P<timestamp>\d+-\d+-\d+T\d+:\d+:\d+),\d+\+\d+\].(?P<severity>\w+)\s+\[(?P<class>(?:.*))\]...(?P<message>(?:.*))')
.timestamp = .timestamp + "Z"
.application_id = "applications"
.log_type = "schedule-loader"
.platform = "bookable-promos"
'''

[sinks.print]
type = "console"
inputs = ["parse_logs"]
encoding.codec = "json"

You will notice that the 'input' value for my sink is the toml key of my transform, not the toml key of my source, as I want to print the tranformed output. This seems to be the only difference.

When I change the input value in the sink to the source ('logs' in my case, 'source0' in yours) like you have done, I do in fact get the stacktrace multiline output, but you will also notice that the rest of the output is different, which we do not want - ie, the json has 'file' and host' keys, rather than 'application_id', 'log_type', and 'class' for example, so the transform has not worked properly. Our output is being sent to ElasticSearch and needs to have the right keys to be indexed properly.

We need the log to include the multline output and be transformed, not one or the other.

1 reply

jszwedko Jul 26, 2022
Maintainer

Hi @jonathanderham-streamotion ! I think the issue here is that parse_regex isn't multline by default (meaning . won't match newline characters). You can enable multiline mode by prefixing the regex with (?m) like:

. = parse_regex!(.message,r'(?m)\[(?P<timestamp>\d+-\d+-\d+T\d+:\d+:\d+),\d+\+\d+\].(?P<severity>\w+)\s+\[(?P<class>(?:.*))\]...(?P<message>(?:.*))')

jonathanderham-streamotion · 2022-07-26T07:22:13Z

jonathanderham-streamotion
Jul 26, 2022
Author

Hi @jszwedko,

Would adding a reduce transform in between the source and the remap transform help achieve my goals? I have tried this but was unsuccessful.

0 replies

jonathanderham-streamotion · 2022-07-27T01:03:39Z

jonathanderham-streamotion
Jul 27, 2022
Author

Hi @jszwedko,

When I added the (?m) in the regex (I just copied the whole regex you had above), I get the following output, which shows all the correct groupings but none of the stacktrace lines:

{"application_id":"applications","class":"java.class","log_type":"schedule-loader","message":"first line","platform":"bookable-promos","severity":"DEBUG","timestamp":"2022-07-18T11:46:25Z"}
{"application_id":"applications","class":"java.class","log_type":"schedule-loader","message":"Begin event threw exception java.lang.Exception: class name","platform":"bookable-promos","severity":"ERROR","timestamp":"2022-07-18T11:46:25Z"}
{"application_id":"applications","class":"java.class","log_type":"schedule-loader","message":"Content parsing failed - see exception","platform":"bookable-promos","severity":"ERROR","timestamp":"2022-07-18T11:46:25Z"}
{"application_id":"applications","class":"java.class","log_type":"schedule-loader","message":"Logging Provider: org.jboss.logging.Slf4jLoggerProvider","platform":"bookable-promos","severity":"DEBUG","timestamp":"2022-07-18T11:46:27Z"}

My config now looks like the following:

[sources.logs]
type = "file"
include = ["/tmp/test.log"]
read_from = "beginning"
ignore_checkpoints = true

  [sources.logs.multiline]
  mode = "halt_before"
  start_pattern = "^\\["
  condition_pattern = "^\\["
  timeout_ms = 1000

[transforms.parse_logs]
type = "remap"
inputs = ["logs"]
source = '''
. = parse_regex!(.message,r'(?m)\[(?P<timestamp>\d+-\d+-\d+T\d+:\d+:\d+),\d+\+\d+\].(?P<severity>\w+)\s+\[(?P<class>(?:.*))\]...(?P<message>(?:.*))')
.timestamp = .timestamp + "Z"
.application_id = "applications"
.log_type = "schedule-loader"
.platform = "bookable-promos"
'''

[sinks.print]
type = "console"
inputs = ["parse_logs"]
encoding.codec = "json"

1 reply

jszwedko Jul 27, 2022
Maintainer

Oops, sorry @jonathanderham-streamotion . We actually need to disable multiline mode so you need to pass (?-m). This seemed to work for me with your input:

. = parse_regex!(.message,r'(?-m)^\[(?P<timestamp>\d+-\d+-\d+T\d+:\d+:\d+),\d+\+\d+\].(?P<severity>\w+)\s+\[(?P<class>(?:.*))\] - (?P<message>(?:.*))$')

See https://docs.rs/regex/1.6.0/regex/#grouping-and-flags for more details on regex flag support.

jonathanderham-streamotion · 2022-07-27T01:22:12Z

jonathanderham-streamotion
Jul 27, 2022
Author

@jszwedko can you show me your output?
When I make the same change it doesn't seem to make any difference, I still don't receive the stacktrace output as part of the message

1 reply

jszwedko Jul 27, 2022
Maintainer

@jonathanderham-streamotion ah, yeah, I misread the output. The regex I used didn't actually match. That's what I get for working too late. We actually need to set the s flag to have . match newline characters. This seems to work:

(?s)\[(?P<timestamp>\d+-\d+-\d+T\d+:\d+:\d+),\d+\+\d+\].(?P<severity>\w+)\s+\[(?P<class>(?:.*))\]...(?P<message>(?:.*))

The output looks like:

{"application_id":"applications","class":"java.class","log_type":"schedule-loader","message":"first line","platform":"bookable-promos","severity":"DEBUG","timestamp":"2022-07-18T11:46:25Z"}
{"application_id":"applications","class":"java.class","log_type":"schedule-loader","message":"Begin event threw exception java.lang.Exception: class name\n        at stacktrace.info(javaClass.java:77)\n        at stacktrace.info(javaClass.java:276)\n        at stacktrace.info(javaClass.java:1350)\n        stacktrace.info(javaClass.java:377)\n        at net.sf.saxon.event.ProxyReceiver.startElement(ProxyReceiver.java:140)\n        ...\nError on line 304 column 11 of filename.xsl:\n  SXCH0003  org.xml.sax.SAXParseException; systemId:\n  file:/filepath/filename.xsl;","platform":"bookable-promos","severity":"ERROR","timestamp":"2022-07-18T11:46:25Z"}
{"application_id":"applications","class":"java.class","log_type":"schedule-loader","message":"Content parsing failed - see exception","platform":"bookable-promos","severity":"ERROR","timestamp":"2022-07-18T11:46:25Z"}
{"application_id":"applications","class":"java.class","log_type":"schedule-loader","message":"Logging Provider: org.jboss.logging.Slf4jLoggerProvider","platform":"bookable-promos","severity":"DEBUG","timestamp":"2022-07-18T11:46:27Z"}

jonathanderham-streamotion · 2022-07-27T01:39:40Z

jonathanderham-streamotion
Jul 27, 2022
Author

@jszwedko huzzah we have a winner.
Thanks so much for your help!

0 replies

Multiline source won't include java stacktrace in message #13654

Uh oh!

jonathanderham-streamotion Jul 21, 2022

Replies: 6 comments · 3 replies

Uh oh!

jszwedko Jul 21, 2022 Maintainer

Uh oh!

Uh oh!

jonathanderham-streamotion Jul 22, 2022 Author

Uh oh!

jszwedko Jul 26, 2022 Maintainer

Uh oh!

jonathanderham-streamotion Jul 26, 2022 Author

Uh oh!

jonathanderham-streamotion Jul 27, 2022 Author

Uh oh!

jszwedko Jul 27, 2022 Maintainer

Uh oh!

jonathanderham-streamotion Jul 27, 2022 Author

Uh oh!

jszwedko Jul 27, 2022 Maintainer

Uh oh!

jonathanderham-streamotion Jul 27, 2022 Author

jonathanderham-streamotion
Jul 21, 2022

Replies: 6 comments 3 replies

jszwedko
Jul 21, 2022
Maintainer

jonathanderham-streamotion
Jul 22, 2022
Author

jszwedko Jul 26, 2022
Maintainer

jonathanderham-streamotion
Jul 26, 2022
Author

jonathanderham-streamotion
Jul 27, 2022
Author

jszwedko Jul 27, 2022
Maintainer

jonathanderham-streamotion
Jul 27, 2022
Author

jszwedko Jul 27, 2022
Maintainer

jonathanderham-streamotion
Jul 27, 2022
Author