LS 2.1.0 Multiline codec does not make use of auto_flush_interval

[nellicus]

using Logstash 2.1.0, the multiline codec does not seem to apply auto_flush_interval setting.

logstash-codec-multiline is updated to version 2.0.11 as per elastic/logstash#6306

Logstash shutdown completed
Antonios-MacBook-Air:107646 abonuccelli$ cat logstash.config 
input { 
	file{ 
		path => "/opt/elk/test/107646/my_events.log" 
		sincedb_path => "/dev/null"
		start_position => "beginning"
		type => "mytype"
		codec => multiline {
			pattern => "^%{TIMESTAMP_ISO8601} "
                	negate => true
                	what => "previous"
			auto_flush_interval => "2"
		}
	} 
} 

filter { 

	grok { 
		match => {"message" => "\A%{GREEDYDATA}"} 
	} 
}

output { 
stdout {codec=>rubydebug} 
}
Antonios-MacBook-Air:107646 abonuccelli$ cat my_events.log 
2016-11-27T08:10:46.963Z - FIRST EVENT message_body
2016-11-27T08:10:46.963Z - message_body
2016-11-27T08:10:46.949Z - message_body
2016-11-27T08:10:46.949Z - message_body
2016-11-27T08:10:46.935Z - message_body
2016-11-27T08:10:46.934Z - message_body
2016-11-27T08:10:46.920Z - message_body
2016-11-27T08:10:46.920Z - message_body
2016-11-27T08:10:46.920Z - message_body
2016-11-27T08:10:46.920Z - LAST EVENT message_body

Antonios-MacBook-Air:107646 abonuccelli./logstash-5.0.0/bin/logstash -f logstash.config 
Sending Logstash logs to /opt/elk/test/107646/logstash-5.0.0/logs which is now configured via log4j2.properties.
[2016-11-28T15:57:35,671][INFO ][logstash.pipeline        ] Starting pipeline {"id"=>"main", "pipeline.workers"=>4, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>5, "pipeline.max_inflight"=>500}
[2016-11-28T15:57:35,682][INFO ][logstash.pipeline        ] Pipeline main started
[2016-11-28T15:57:35,750][INFO ][logstash.agent           ] Successfully started Logstash API endpoint {:port=>9600}
{
          "path" => "/opt/elk/test/107646/my_events.log",
    "@timestamp" => 2016-11-28T14:57:35.654Z,
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
       "message" => "2016-11-27T08:10:46.963Z - FIRST EVENT message_body",
          "type" => "mytype"
}
{
          "path" => "/opt/elk/test/107646/my_events.log",
    "@timestamp" => 2016-11-28T14:57:35.681Z,
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
       "message" => "2016-11-27T08:10:46.963Z - message_body",
          "type" => "mytype"
}
{
          "path" => "/opt/elk/test/107646/my_events.log",
    "@timestamp" => 2016-11-28T14:57:35.683Z,
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
       "message" => "2016-11-27T08:10:46.949Z - message_body",
          "type" => "mytype"
}
{
          "path" => "/opt/elk/test/107646/my_events.log",
    "@timestamp" => 2016-11-28T14:57:35.684Z,
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
       "message" => "2016-11-27T08:10:46.949Z - message_body",
          "type" => "mytype"
}
{
          "path" => "/opt/elk/test/107646/my_events.log",
    "@timestamp" => 2016-11-28T14:57:35.685Z,
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
       "message" => "2016-11-27T08:10:46.935Z - message_body",
          "type" => "mytype"
}
{
          "path" => "/opt/elk/test/107646/my_events.log",
    "@timestamp" => 2016-11-28T14:57:35.686Z,
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
       "message" => "2016-11-27T08:10:46.934Z - message_body",
          "type" => "mytype"
}
{
          "path" => "/opt/elk/test/107646/my_events.log",
    "@timestamp" => 2016-11-28T14:57:35.687Z,
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
       "message" => "2016-11-27T08:10:46.920Z - message_body",
          "type" => "mytype"
}
{
          "path" => "/opt/elk/test/107646/my_events.log",
    "@timestamp" => 2016-11-28T14:57:35.687Z,
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
       "message" => "2016-11-27T08:10:46.920Z - message_body",
          "type" => "mytype"
}
{
          "path" => "/opt/elk/test/107646/my_events.log",
    "@timestamp" => 2016-11-28T14:57:35.688Z,
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
       "message" => "2016-11-27T08:10:46.920Z - message_body",
          "type" => "mytype"
}
{
          "path" => "/opt/elk/test/107646/my_events.log",
    "@timestamp" => 2016-11-28T14:57:38.151Z,
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
       "message" => "2016-11-27T08:10:46.920Z - LAST EVENT message_body",
          "type" => "mytype"
}
^C[2016-11-28T15:57:40,322][WARN ][logstash.runner          ] SIGINT received. Shutting down the agent.
[2016-11-28T15:57:40,332][WARN ][logstash.agent           ] stopping pipeline {:id=>"main"}
^[[AAntonios-MacBook-Air:107646 abonuccelli$ ./logstash-2.1.0/bin/logstash -f logstash.config 
Settings: Default filter workers: 2
Logstash startup completed
{
    "@timestamp" => "2016-11-28T14:57:52.812Z",
       "message" => "2016-11-27T08:10:46.963Z - FIRST EVENT message_body",
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
          "path" => "/opt/elk/test/107646/my_events.log",
          "type" => "mytype"
}
{
    "@timestamp" => "2016-11-28T14:57:52.814Z",
       "message" => "2016-11-27T08:10:46.963Z - message_body",
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
          "path" => "/opt/elk/test/107646/my_events.log",
          "type" => "mytype"
}
{
    "@timestamp" => "2016-11-28T14:57:52.815Z",
       "message" => "2016-11-27T08:10:46.949Z - message_body",
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
          "path" => "/opt/elk/test/107646/my_events.log",
          "type" => "mytype"
}
{
    "@timestamp" => "2016-11-28T14:57:52.815Z",
       "message" => "2016-11-27T08:10:46.949Z - message_body",
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
          "path" => "/opt/elk/test/107646/my_events.log",
          "type" => "mytype"
}
{
    "@timestamp" => "2016-11-28T14:57:52.816Z",
       "message" => "2016-11-27T08:10:46.935Z - message_body",
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
          "path" => "/opt/elk/test/107646/my_events.log",
          "type" => "mytype"
}
{
    "@timestamp" => "2016-11-28T14:57:52.816Z",
       "message" => "2016-11-27T08:10:46.934Z - message_body",
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
          "path" => "/opt/elk/test/107646/my_events.log",
          "type" => "mytype"
}
{
    "@timestamp" => "2016-11-28T14:57:52.816Z",
       "message" => "2016-11-27T08:10:46.920Z - message_body",
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
          "path" => "/opt/elk/test/107646/my_events.log",
          "type" => "mytype"
}
{
    "@timestamp" => "2016-11-28T14:57:52.817Z",
       "message" => "2016-11-27T08:10:46.920Z - message_body",
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
          "path" => "/opt/elk/test/107646/my_events.log",
          "type" => "mytype"
}
{
    "@timestamp" => "2016-11-28T14:57:52.817Z",
       "message" => "2016-11-27T08:10:46.920Z - message_body",
      "@version" => "1",
          "host" => "Antonios-MacBook-Air.local",
          "path" => "/opt/elk/test/107646/my_events.log",
          "type" => "mytype"
}

WAITED A MINUTE HERE


^CSIGINT received. Shutting down the pipeline. {:level=>:warn}
Logstash shutdown completed
Antonios-MacBook-Air:107646 abonuccelli$ 

[jordansissel]

Does this problem occur with newer Logstash versions (2.4? 5.0?)

[nellicus]

as per the test above, no,it doesn't happen with 5.0

[jordansissel]

If it doesn't happen on newer releases, I'm not sure if there is any action to take here. Can you advise?

[nellicus]

@jordansissel since 2.1.0 is a supported version && it appears there is something wrong in this scenario I have filed this.

said the above I'll see if I can convince this user to upgrade rather than staying on 2.1.0.