Multiline codec discrepancies between file and stdin inputs

Elastic Stack Logstash
1

I'm trying to track down a bug in the file input that is combining multiline events separated by a blank line. Here's the alerts.log file which has events:

** Alert 1460993714.111282277: mail  - syslog,linuxkernel,service_availability,
2016 Apr 18 15:35:14 (example) 10.0.84.42->/var/log/syslog
Rule: 5108 (level 12) -> 'System running out of memory. Availability of the system is in risk.'
Apr 18 15:35:13 example kernel: [10514276.882967] Memory cgroup out of memory: Kill process 27060 (php5-fpm) score 594 or sacrifice child

** Alert 1460993722.111282701: mail  - syslog,errors,
2016 Apr 18 15:35:22 (example) 10.0.7.182->/var/log/syslog
Rule: 1002 (level 2) -> 'Unknown problem somewhere in the system.'
Apr 18 15:35:21 example kernel: [34163081.760072] xen:balloon: reserve_additional_memory: add_memory() failed: -17

** Alert 1460993724.111283019: - syslog,access_control,
2016 Apr 18 15:35:24 (example) 10.0.7.182->/var/log/syslog
Rule: 2508 (level 3) -> 'OpenLDAP connection open.'
Apr 18 15:35:24 example slapd[13202]: conn=9520 fd=72 ACCEPT from IP=10.0.0.66:39066 (IP=0.0.0.0:636)

** Alert 1460993728.111283315: - syslog,access_control,
2016 Apr 18 15:35:28 (example) 10.0.7.182->/var/log/syslog
Rule: 2508 (level 3) -> 'OpenLDAP connection open.'
Apr 18 15:35:27 example slapd[13202]: conn=9521 fd=72 ACCEPT from IP=10.0.0.66:39077 (IP=0.0.0.0:636)

** Alert 1460993728.111283611: - syslog,access_control,
2016 Apr 18 15:35:28 (example) 10.0.7.182->/var/log/syslog
Rule: 2508 (level 3) -> 'OpenLDAP connection open.'
Apr 18 15:35:27 example slapd[13202]: conn=9522 fd=72 ACCEPT from IP=10.0.0.66:39078 (IP=0.0.0.0:636)

Here's what I get when running with the stdin input and multiline codec (this is the behavior I want):

cat /tmp/alerts.log | bin/logstash -e 'input { stdin { codec => multiline { pattern => "^$" negate => true what => "previous" } } } output { stdout { codec => rubydebug } }'
Settings: Default pipeline workers: 4
Logstash startup completed
{
    "@timestamp" => "2016-04-18T16:02:21.686Z",
       "message" => "** Alert 1460993714.111282277: mail  - syslog,linuxkernel,service_availability,\n2016 Apr 18 15:35:14 (example) 10.0.84.42->/var/log/syslog\nRule: 5108 (level 12) -> 'System running out of memory. Availability of the system is in risk.'\nApr 18 15:35:13 example kernel: [10514276.882967] Memory cgroup out of memory: Kill process 27060 (php5-fpm) score 594 or sacrifice child",
      "@version" => "1",
          "tags" => [
        [0] "multiline"
    ],
          "host" => "logs.example.com"
}
{
    "@timestamp" => "2016-04-18T16:02:21.766Z",
       "message" => "\n** Alert 1460993722.111282701: mail  - syslog,errors,\n2016 Apr 18 15:35:22 (example) 10.0.7.182->/var/log/syslog\nRule: 1002 (level 2) -> 'Unknown problem somewhere in the system.'\nApr 18 15:35:21 example kernel: [34163081.760072] xen:balloon: reserve_additional_memory: add_memory() failed: -17",
      "@version" => "1",
          "tags" => [
        [0] "multiline"
    ],
          "host" => "logs.example.com"
}
{
    "@timestamp" => "2016-04-18T16:02:21.775Z",
       "message" => "\n** Alert 1460993724.111283019: - syslog,access_control,\n2016 Apr 18 15:35:24 (example) 10.0.7.182->/var/log/syslog\nRule: 2508 (level 3) -> 'OpenLDAP connection open.'\nApr 18 15:35:24 example slapd[13202]: conn=9520 fd=72 ACCEPT from IP=10.0.0.66:39066 (IP=0.0.0.0:636)",
      "@version" => "1",
          "tags" => [
        [0] "multiline"
    ],
          "host" => "logs.example.com"
}
{
    "@timestamp" => "2016-04-18T16:02:21.776Z",
       "message" => "\n** Alert 1460993728.111283315: - syslog,access_control,\n2016 Apr 18 15:35:28 (example) 10.0.7.182->/var/log/syslog\nRule: 2508 (level 3) -> 'OpenLDAP connection open.'\nApr 18 15:35:27 example slapd[13202]: conn=9521 fd=72 ACCEPT from IP=10.0.0.66:39077 (IP=0.0.0.0:636)",
      "@version" => "1",
          "tags" => [
        [0] "multiline"
    ],
          "host" => "logs.example.com"
}
Logstash shutdown completed
2

Adding a reply since I hit the character limit in the first post:

Here's what happens with the same input passed through the file input:

bin/logstash -e 'input { file { path => ["/tmp/alerts.log"] codec => multiline { pattern => "^&" negate => true what => "previous" } } } output { stdout { codec => rubydebug } }'
Settings: Default pipeline workers: 4
Logstash startup completed

^CSIGINT received. Shutting down the pipeline. {:level=>:warn}
{
    "@timestamp" => "2016-04-18T17:01:11.748Z",
       "message" => "** Alert 1460993714.111282277: mail  - syslog,linuxkernel,service_availability,\n2016 Apr 18 15:35:14 (example) 10.0.84.42->/var/log/syslog\nRule: 5108 (level 12) -> 'System running out of memory. Availability of the system is in risk.'\nApr 18 15:35:13 example kernel: [10514276.882967] Memory cgroup out of memory: Kill process 27060 (php5-fpm) score 594 or sacrifice child\n** Alert 1460993722.111282701: mail  - syslog,errors,\n2016 Apr 18 15:35:22 (example) 10.0.7.182->/var/log/syslog\nRule: 1002 (level 2) -> 'Unknown problem somewhere in the system.'\nApr 18 15:35:21 example kernel: [34163081.760072] xen:balloon: reserve_additional_memory: add_memory() failed: -17\n** Alert 1460993724.111283019: - syslog,access_control,\n2016 Apr 18 15:35:24 (example) 10.0.7.182->/var/log/syslog\nRule: 2508 (level 3) -> 'OpenLDAP connection open.'\nApr 18 15:35:24 example slapd[13202]: conn=9520 fd=72 ACCEPT from IP=10.0.0.66:39066 (IP=0.0.0.0:636)\n** Alert 1460993728.111283315: - syslog,access_control,\n2016 Apr 18 15:35:28 (example) 10.0.7.182->/var/log/syslog\nRule: 2508 (level 3) -> 'OpenLDAP connection open.'\nApr 18 15:35:27 example slapd[13202]: conn=9521 fd=72 ACCEPT from IP=10.0.0.66:39077 (IP=0.0.0.0:636)\n** Alert 1460993728.111283611: - syslog,access_control,\n2016 Apr 18 15:35:28 (example) 10.0.7.182->/var/log/syslog\nRule: 2508 (level 3) -> 'OpenLDAP connection open.'\nApr 18 15:35:27 example slapd[13202]: conn=9522 fd=72 ACCEPT from IP=10.0.0.66:39078 (IP=0.0.0.0:636)\n",
      "@version" => "1",
          "tags" => [
        [0] "multiline"
    ],
          "path" => "/tmp/alerts.log",
          "host" => "logs.example.com"
}
Logstash shutdown completed

As you can see, each block of blank line separated events is processed correctly using the stdin input, but they're globbed together with the file input. I found this out while trying to debug this behavior after upgrading to Logstash 2.2.3 from Logstash 1.5.4.

3

Would this be more appropriate as a Github issue?

4

Still looking for some guidance on this issue.

5

AlexClineBB, the only bug we have is that, for LS versions < 5.X - stdin and multiline are not 100% compatible with each other.

Your multiline config for the file input is wrong.

This works.

input {
  file {
    path => "tmp/multilinetest/alexcline.log"
    sincedb_path => "tmp/multilinetest/alexcline.1"
    start_position => "beginning"
    close_older => 5
    codec => multiline {
      pattern => "^\*\* Alert"
      negate => true
      what => "previous"
    }
  }
}
output {
  stdout {
    codec => rubydebug
  }
}

giving...

Logstash startup completed
{
    "@timestamp" => "2016-04-22T07:51:13.145Z",
       "message" => "** Alert 1460993714.111282277: mail  - syslog,linuxkernel,service_availability,\n2016 Apr 18 15:35:14 (example) 10.0.84.42->/var/log/syslog\nRule: 5108 (level 12) -> 'System running out of memory. Availability of the system is in risk.'\nApr 18 15:35:13 example kernel: [10514276.882967] Memory cgroup out of memory: Kill process 27060 (php5-fpm) score 594 or sacrifice child",
      "@version" => "1",
          "tags" => [
        [0] "multiline"
    ],
          "path" => "tmp/multilinetest/alexcline.log",
          "host" => "EMBP.local"
}
{
    "@timestamp" => "2016-04-22T07:51:13.147Z",
       "message" => "** Alert 1460993722.111282701: mail  - syslog,errors,\n2016 Apr 18 15:35:22 (example) 10.0.7.182->/var/log/syslog\nRule: 1002 (level 2) -> 'Unknown problem somewhere in the system.'\nApr 18 15:35:21 example kernel: [34163081.760072] xen:balloon: reserve_additional_memory: add_memory() failed: -17",
      "@version" => "1",
          "tags" => [
        [0] "multiline"
    ],
          "path" => "tmp/multilinetest/alexcline.log",
          "host" => "EMBP.local"
}
{
    "@timestamp" => "2016-04-22T07:51:13.148Z",
       "message" => "** Alert 1460993724.111283019: - syslog,access_control,\n2016 Apr 18 15:35:24 (example) 10.0.7.182->/var/log/syslog\nRule: 2508 (level 3) -> 'OpenLDAP connection open.'\nApr 18 15:35:24 example slapd[13202]: conn=9520 fd=72 ACCEPT from IP=10.0.0.66:39066 (IP=0.0.0.0:636)",
      "@version" => "1",
          "tags" => [
        [0] "multiline"
    ],
          "path" => "tmp/multilinetest/alexcline.log",
          "host" => "EMBP.local"
}
{
    "@timestamp" => "2016-04-22T07:51:13.149Z",
       "message" => "** Alert 1460993728.111283315: - syslog,access_control,\n2016 Apr 18 15:35:28 (example) 10.0.7.182->/var/log/syslog\nRule: 2508 (level 3) -> 'OpenLDAP connection open.'\nApr 18 15:35:27 example slapd[13202]: conn=9521 fd=72 ACCEPT from IP=10.0.0.66:39077 (IP=0.0.0.0:636)",
      "@version" => "1",
          "tags" => [
        [0] "multiline"
    ],
          "path" => "tmp/multilinetest/alexcline.log",
          "host" => "EMBP.local"
}
{
    "@timestamp" => "2016-04-22T07:51:18.164Z",
       "message" => "** Alert 1460993728.111283611: - syslog,access_control,\n2016 Apr 18 15:35:28 (example) 10.0.7.182->/var/log/syslog\nRule: 2508 (level 3) -> 'OpenLDAP connection open.'\nApr 18 15:35:27 example slapd[13202]: conn=9522 fd=72 ACCEPT from IP=10.0.0.66:39078 (IP=0.0.0.0:636)",
      "@version" => "1",
          "tags" => [
        [0] "multiline"
    ],
          "path" => "tmp/multilinetest/alexcline.log",
          "host" => "EMBP.local"
}
^CSIGINT received. Shutting down the pipeline. {:level=>:warn}
Logstash shutdown completed

However the pattern "^\*\* Alert" almost works for stdin. 4 events are emitted but the last one is trapped in the multiline buffer because another line starting with ** Alert never arrives. If it did it would end the accumulation of lines for Event 5 and begin accumulating for Event 6.

For the file input config, the close_older => 5 will 'close' the file internally and cause a flush of lines accumulated in the multiline codec resulting in Event 5 being emitted - effectively saying "After 5 seconds, I have not seen anymore input in this file so flush what you have accumulated, there are no more lines for this multiline section". You can see this because Event 5 timestamp is 5 seconds later than Event 4.

It must also be noted that, for the file input + multiline, blank lines are ignored.

1 Like
6

Hi Guy,

Thank you for the clarification. I guess the bug I'm running into is the change in behavior of the file input + multiline codec between 1.5.4 and 2.2.3. Since newlines weren't ignored previously, the configuration I was using worked and didn't require flushing. Events are multiple lines followed by a blank line.

I'll test out your file input configuration and hopefully can get the events processed again. I'll keep my eyes open for LS 5.x and the renewed compatibility between the file input and multiline codec.

Thanks again.

7

The multiline codec ignoring blank lines side-effect was introduced in 0.1.4 on January 27 2015, to cope with inputs that supplied text with embedded newline characters - the upside, the text was split on newlines and the resulting array of lines was fed to multiline - the downside, text containing only one newline, when split gives an empty array, effectively ignoring the empty line.

It is a bit harder to say exactly which version of Logstash has this codec version.

I think it is reasonable to expect behavioural changes when making such a big step (from 1.5.X to 2.2.X)