Add tag "multiline" to "log.flags" if event consists of multiple lines. #7997

kvch · 2018-08-17T11:39:24Z

Add "multiline" tag to "log.status" if the event contains multiple lines. This way users can filter for multiline messages using "multiline" in [log.status].

Example event

{
  "@timestamp": "2018-08-17T11:35:21.813Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "7.0.0-alpha1"
  },
  "source": "/home/n/test.log",
  "offset": 0,
  "log": {
    "status": ["multiline"],
  },
  "message": "[test line\ntest line]",
  "prospector": {
    "type": "log"
  },
  "input": {
    "type": "log"
  },
  "beat": {
    "hostname": "sleipnir",
    "version": "7.0.0-alpha1",
    "name": "sleipnir"
  },
  "host": {
    "name": "sleipnir"
  }
}

Depends on #7991
Closes #957

andrewvc

LGTM.

Tested manually as well for good measure

andrewvc

Spoke too soon. Looks like there are some test failures:


07:04:43 ======================================================================
07:04:43 FAIL: Should be able to do multiline on docker logs.
07:04:43 ----------------------------------------------------------------------
07:04:43 Traceback (most recent call last):
07:04:43   File "/private/var/lib/jenkins/workspace/elastic+beats+pull-request+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/tests/system/test_json.py", line 95, in test_docker_logs_multiline
07:04:43     assert all("log" in o for o in output)
07:04:43 AssertionError
07:04:43

urso · 2018-08-17T16:43:05Z

filebeat/reader/multiline/multiline.go

+				"multiline": mlr.numLines,
+			},
+		})
+	}


Why don't report log.multiline: 1 ?

Can a multiline event contain only 1 line? Reason I'm asking is because I was thinking what if someone wants to see all mutiline events. So far I assumed it would be exists:log.multiline.

But your idea below kind of also answers this. If we call it log.lines we should probably add it to all events, not only mutiline events?

The original request in the issue I am trying to close states "This is to mimic the behaviour the logstash multiline filter performs by adding 'multiline' to tags.". As logstash only tags events which contain more than one lines. See: https://www.elastic.co/guide/en/logstash/current/plugins-codecs-multiline.html#plugins-codecs-multiline-multiline_tag

urso · 2018-08-17T16:44:23Z

Personally I like log.lines better :)

ruflin · 2018-08-20T07:37:55Z

+1 on the idea from @urso to call it log.lines. Reasoning on my end is that log.multiline I would expect to be a bool.

webmat · 2018-08-20T15:33:24Z

I also prefer log.lines. And to @ruflin's question about searching for multiline events, I think I'd rather have log.lines always be populated with either a 1 or greater. Then if someone's looking for multiline events, they search for log.lines:[2 TO *].

I personally prefer the consistency of always having the field present.

andrewvc · 2018-08-20T18:06:01Z

Many people never touch multi-line events, so it's hard to imagine why we would start always setting this value. What's the use case? Every field we add increases the cognitive overhead of using the product.

The only use case for this value I've encountered is indicating the operation of the multiline option. If there are more use cases, that would be great to hear about. Without those however, keeping the naming multiline makes sense.

Using this value beyond the specific use of the multiline feature raises a number of questions. You could have a JSON input source creating 'multiline' values for the message field, yet this value would remain. What happens with a JSON value with no message field, but other fields with multiple newline characters?

If we really want to start counting the number of lines in every message, then an enumeration of the use cases for this new feature would be useful to this discussion.

WRT whether it should be only values >1 or >=1 I'm very slightly in favor of >=1. The reason being that since the main value here is in checking the operation of the multiline option. It will confirm that multiline was enabled, but only a single line was processed.

Ideally this field wouldn't even exist in the mapping unless a multiline filter was enabled. This is beyond the scope of this ticket, but is relevant to #7972

urso · 2018-08-20T18:09:15Z

Many people never touch multi-line events, so it's hard to imagine why we would start always setting this value. What's the use case? Every field we add increases the cognitive overhead of using the product.

The way the reader works, the count field would only be added if multiline is configured. No multiline, not extra-field.

andrewvc · 2018-08-20T18:14:11Z

@urso Ah, my misunderstanding, I had thought we were considering expanding the scope. Glad to hear that's not on the table.

kvch · 2018-08-21T07:58:41Z

@ruflin For the record log.lines is my idea. :P :D
However, this does not seem like a viable name. In Docker JSON log format, the message is under the key log. Thus, if I change message_key to msg in the test, the messages are never parsed, because Docker log messages are under the key "log". (Example log from our codebase: "{"log":"1:M 09 Nov 13:27:36.276 # User requested shutdown...\n","stream":"stdout"}"). So the test fails.

I propose event.lines instead of log.lines. event is already part of the top level fields, so we would not introduce anything new there. WDYT?

ruflin · 2018-08-21T10:49:17Z

As for the docker case: The docker input "should" already solve the issue by renaming it to message. And if log is an object, I would expect that log.lines just gets added to it? I would definitively prefer to go with log.line as the log.* object will contain meta information about log events: https://github.com/elastic/ecs#log

@kvch Sorry about the log.lines, should read PR messages better :-(

kvch · 2018-08-21T11:37:39Z

I think I might be made a mistake with my previous explanation. Let me check again. But still my statement that if I change message_key option in that test, nothing is parsed.

kvch · 2018-08-21T12:25:53Z

No, my description is correct.

ruflin · 2018-08-21T12:30:25Z

Did you use the docker input for this test? Because then I would expect a different result.

Which test are you referring to? In general I think that docker write to log is a problem and will cause other problems down the road and is why the docker input writes it to message instead (I hope).

kvch · 2018-08-21T13:00:11Z

The failing test is not relevant anymore, because for Docker JSON logs, docker is the correct input to use, not log. I deleted that test and named the field log.lines.

I still have one more question. Do we want to mimic Logstash's behaviour or add log.lines all multiline messages?

ruflin · 2018-08-22T07:22:03Z

Both options work for me.

@exekias For the docker prospector if we have this partial lines, should we also use the multiline count or is this a different kind of multiline?

exekias · 2018-08-22T09:51:35Z

Docker partials are just something internal to the format, it's still a single line in source and should be a single line in output. So would say it should not include this field in that case.

If you do common multiline on top it should contain this field, but I think that's covered by this change already.

ruflin

Let's get the other PR and then rebase this on top which will be very little changes left like it seems.

ruflin · 2018-08-29T08:03:05Z

filebeat/_meta/fields.common.yml

@@ -108,6 +108,10 @@
      description: >
        Logging level.

+    - name: log.status


See comment about naming in the other thread.

ruflin · 2018-08-29T08:04:45Z

filebeat/reader/multiline/multiline_test.go

@@ -150,6 +151,25 @@ func TestMultilineBeforeNegateOKWithEmptyLine(t *testing.T) {
 	)
 }

+func TestMultilineAfterTruncated(t *testing.T) {


Would be nice to have a test for a multiline event that also gets truncated and then check for both flags.

Closes elastic#957

kvch · 2018-08-30T14:26:26Z

Rebased.

ruflin · 2018-08-31T11:46:46Z

filebeat/tests/system/test_json.py

-        """
-        Should be able to do multiline on docker logs.
-        """
-        self.render_config_template(


@kvch

I think this test is still valuable to make sure we support multiline logs in docker. What we should change is to set keys_under_root=False and then check for the fields accordingly

If we remove the test, we should also remove the test file as it's not used anywhere else.

For docker we have a dedicated input type in Filebeat. Do users prefer to read Docker files using log and use json.* options? What is the "official" way read Docker logs?

The "official" was has become the docker input I would say. This doesn't mean users do not still use the old behaviour and I'm not even sure if we have such a multiline test for the docker input.

@timestamp

…s. (elastic#7997) Add "multiline" tag to "log.status" if the event contains multiple lines. This way users can filter for multiline messages using "multiline" in [log.status]. Example event { "@timestamp": "2018-08-17T11:35:21.813Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1" }, "source": "/home/n/test.log", "offset": 0, "log": { "status": [ "multiline" ], }, "message": "[test line\ntest line]", "prospector": { "type": "log" }, "input": { "type": "log" }, "beat": { "hostname": "sleipnir", "version": "7.0.0-alpha1", "name": "sleipnir" }, "host": { "name": "sleipnir" } } Closes elastic#957 (cherry picked from commit 6da83e8)

@timestamp

…s. (#7997) (#8207) Add "multiline" tag to "log.status" if the event contains multiple lines. This way users can filter for multiline messages using "multiline" in [log.status]. Example event { "@timestamp": "2018-08-17T11:35:21.813Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1" }, "source": "/home/n/test.log", "offset": 0, "log": { "status": [ "multiline" ], }, "message": "[test line\ntest line]", "prospector": { "type": "log" }, "input": { "type": "log" }, "beat": { "hostname": "sleipnir", "version": "7.0.0-alpha1", "name": "sleipnir" }, "host": { "name": "sleipnir" } } Closes #957 (cherry picked from commit 6da83e8)

kvch requested review from urso and ruflin August 17, 2018 11:39

kvch added review Filebeat Filebeat needs_backport PR is waiting to be backported to other branches. labels Aug 17, 2018

andrewvc approved these changes Aug 17, 2018

View reviewed changes

andrewvc requested changes Aug 17, 2018

View reviewed changes

urso reviewed Aug 17, 2018

View reviewed changes

kvch mentioned this pull request Aug 21, 2018

Add tag "truncated" to "log.flags" if incoming line is longer than configured limit #7991

Merged

kvch changed the title ~~Add log.multiline if event consists of multiple lines~~ Add event.multiline if event consists of multiple lines Aug 21, 2018

kvch changed the title ~~Add event.multiline if event consists of multiple lines~~ Add event.lines if event consists of multiple lines Aug 21, 2018

kvch force-pushed the feature/filebeat/indicate-multiline branch from f75ccad to f806161 Compare August 21, 2018 12:57

kvch changed the title ~~Add event.lines if event consists of multiple lines~~ Add log.lines if event consists of multiple lines Aug 21, 2018

kvch force-pushed the feature/filebeat/indicate-multiline branch from f806161 to 35b8e44 Compare August 27, 2018 18:48

kvch changed the title ~~Add log.lines if event consists of multiple lines~~ Add tag "multiline" to "log.status" if event consists of multiple lines. Aug 27, 2018

kvch force-pushed the feature/filebeat/indicate-multiline branch from 35b8e44 to d59613d Compare August 27, 2018 18:51

ruflin reviewed Aug 29, 2018

View reviewed changes

kvch force-pushed the feature/filebeat/indicate-multiline branch 2 times, most recently from d2189b2 to 1c48f06 Compare August 30, 2018 10:32

kvch changed the title ~~Add tag "multiline" to "log.status" if event consists of multiple lines.~~ Add tag "multiline" to "log.flags" if event consists of multiple lines. Aug 30, 2018

kvch added 13 commits August 30, 2018 16:14

add function to add tag to a message

9e85a22

add changelog entry

d882b24

fix variable

4516764

follow up in filebeat modules test

9df6ac6

add log.multiline if message consists of multiple lines

6e822b3

Closes elastic#957

add changelog entry

d0998bb

remove outdated test

deb139e

rm unnecessary test

f97e03f

follow up changelog title

629e78d

follow up renaming

6391c20

add test to check both flags

ef90468

follow up renaming in tests and CHANGELOG

841e72b

fix after rebase

1df5455

kvch force-pushed the feature/filebeat/indicate-multiline branch from 1c48f06 to 1df5455 Compare August 30, 2018 14:23

kvch mentioned this pull request Aug 30, 2018

Cherry-pick #7991 to 6.x: Add tag "truncated" to "log.flags" if incoming line is longer than configured limit #8165

Merged

urso approved these changes Aug 30, 2018

View reviewed changes

kvch merged commit 6da83e8 into elastic:master Aug 31, 2018

ruflin reviewed Aug 31, 2018

View reviewed changes

kvch mentioned this pull request Sep 3, 2018

Cherry-pick #7997 to 6.x: Add tag "multiline" to "log.flags" if event consists of multiple lines. #8207

Merged

kvch added v6.5.0 and removed needs_backport PR is waiting to be backported to other branches. labels Sep 3, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add tag "multiline" to "log.flags" if event consists of multiple lines. #7997

Add tag "multiline" to "log.flags" if event consists of multiple lines. #7997

kvch commented Aug 17, 2018 •

edited

Loading

andrewvc left a comment

andrewvc left a comment

urso Aug 17, 2018

ruflin Aug 20, 2018

kvch Aug 21, 2018

urso commented Aug 17, 2018

ruflin commented Aug 20, 2018

webmat commented Aug 20, 2018

andrewvc commented Aug 20, 2018

urso commented Aug 20, 2018

andrewvc commented Aug 20, 2018

kvch commented Aug 21, 2018

ruflin commented Aug 21, 2018

kvch commented Aug 21, 2018

kvch commented Aug 21, 2018

ruflin commented Aug 21, 2018

kvch commented Aug 21, 2018

ruflin commented Aug 22, 2018

exekias commented Aug 22, 2018

ruflin left a comment

ruflin Aug 29, 2018

ruflin Aug 29, 2018

kvch Aug 30, 2018

kvch commented Aug 30, 2018

ruflin Aug 31, 2018

kvch Aug 31, 2018

ruflin Sep 3, 2018

Add tag "multiline" to "log.flags" if event consists of multiple lines. #7997

Add tag "multiline" to "log.flags" if event consists of multiple lines. #7997

Conversation

kvch commented Aug 17, 2018 • edited Loading

andrewvc left a comment

Choose a reason for hiding this comment

andrewvc left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

urso commented Aug 17, 2018

ruflin commented Aug 20, 2018

webmat commented Aug 20, 2018

andrewvc commented Aug 20, 2018

urso commented Aug 20, 2018

andrewvc commented Aug 20, 2018

kvch commented Aug 21, 2018

ruflin commented Aug 21, 2018

kvch commented Aug 21, 2018

kvch commented Aug 21, 2018

ruflin commented Aug 21, 2018

kvch commented Aug 21, 2018

ruflin commented Aug 22, 2018

exekias commented Aug 22, 2018

ruflin left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kvch commented Aug 30, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kvch commented Aug 17, 2018 •

edited

Loading