Syslog Input Multiline Fail

Elastic Stack Logstash
1

Hi there,

The microtik sends syslog messages of one RADIUS event in several rows

|26|0.099429|10.147.99.3|10.147.99.9|Syslog|137|DAEMON.DEBUG: Feb  8 18:35:18 X5_tihvinskaya3 sending Accounting-Request with id 34 to 185.12.28.167:1813|
|27|0.099581|10.147.99.3|10.147.99.9|Syslog|128|DAEMON.DEBUG: Feb  8 18:35:18 X5_tihvinskaya3     Signature = 0xff4233fa4532473b33ce5c459047da4b|
|28|0.099694|10.147.99.3|10.147.99.9|Syslog|102|DAEMON.DEBUG: Feb  8 18:35:18 X5_tihvinskaya3     Acct-Status-Type = 1|
|29|0.099808|10.147.99.3|10.147.99.9|Syslog|100|DAEMON.DEBUG: Feb  8 18:35:18 X5_tihvinskaya3     NAS-Port-Type = 19|
|30|0.099933|10.147.99.3|10.147.99.9|Syslog|122|DAEMON.DEBUG: Feb  8 18:35:18 X5_tihvinskaya3     Calling-Station-Id = "A8:5C:2C:3B:81:19"|
|31|0.100057|10.147.99.3|10.147.99.9|Syslog|119|DAEMON.DEBUG: Feb  8 18:35:18 X5_tihvinskaya3     Called-Station-Id = "X5_tihvinskaya3"|
|32|0.100186|10.147.99.3|10.147.99.9|Syslog|114|DAEMON.DEBUG: Feb  8 18:35:18 X5_tihvinskaya3     NAS-Port-Id = "Perekrestok_Free"|
|33|0.100311|10.147.99.3|10.147.99.9|Syslog|117|DAEMON.DEBUG: Feb  8 18:35:18 X5_tihvinskaya3     User-Name = "790350925182@4917.com"|
|34|0.100424|10.147.99.3|10.147.99.9|Syslog|103|DAEMON.DEBUG: Feb  8 18:35:18 X5_tihvinskaya3     NAS-Port = 2153775114|
|35|0.100549|10.147.99.3|10.147.99.9|Syslog|110|DAEMON.DEBUG: Feb  8 18:35:18 X5_tihvinskaya3     Acct-Session-Id = "8060000a"|
|36|0.100681|10.147.99.3|10.147.99.9|Syslog|114|DAEMON.DEBUG: Feb  8 18:35:18 X5_tihvinskaya3     Framed-IP-Address = 172.16.0.248|
|37|0.100802|10.147.99.3|10.147.99.9|Syslog|107|DAEMON.DEBUG: Feb  8 18:35:18 X5_tihvinskaya3     MT-Host-IP = 172.16.0.248|
|38|0.100939|10.147.99.3|10.147.99.9|Syslog|110|DAEMON.DEBUG: Feb  8 18:35:18 X5_tihvinskaya3     Event-Timestamp = 1518104118|
|39|0.101056|10.147.99.3|10.147.99.9|Syslog|116|DAEMON.DEBUG: Feb  8 18:35:18 X5_tihvinskaya3     NAS-Identifier = "X5_tihvinskaya3"|
|40|0.101189|10.147.99.3|10.147.99.9|Syslog|101|DAEMON.DEBUG: Feb  8 18:35:18 X5_tihvinskaya3     Acct-Delay-Time = 0|
|41|0.101302|10.147.99.3|10.147.99.9|Syslog|97|DAEMON.DEBUG: Feb  8 18:35:18 X5_tihvinskaya3     MT-Realm = 0x31|
|42|0.101443|10.147.99.3|10.147.99.9|Syslog|111|DAEMON.DEBUG: Feb  8 18:35:18 X5_tihvinskaya3     NAS-IP-Address = 10.191.101.2|

I need to combine them in one line at the input for parsing
I use next Pipeline

input {
	udp {
		port => 8514
		codec => multiline {
			pattern => "DAEMON.DEBUG: %{SYSLOGTIMESTAMP} %{WORD}\s{5}%{WORD}"
			what => "previous"
		}
	}
}

filter {

}
	
output {
	stdout{
		codec => rubydebug
	}
}

If in line 5 there are spaces, then connect to the previous one
But on the output I see all the same separate lines as on the input, only with additional information

2018-02-09T13:48:34.557Z 10.147.99.3 <31>Feb  9 16:48:34 X5_tihvinskaya3 sending Accounting-Request with id 35 to 185.12.28.167:1813
2018-02-09T13:48:34.558Z 10.147.99.3 <31>Feb  9 16:48:34 X5_tihvinskaya3     Acct-Status-Type = 1
2018-02-09T13:48:34.558Z 10.147.99.3 <31>Feb  9 16:48:34 X5_tihvinskaya3     NAS-Port-Type = 19
2018-02-09T13:48:34.558Z 10.147.99.3 <31>Feb  9 16:48:34 X5_tihvinskaya3     Calling-Station-Id = "9C:35:EB:E4:F0:F5"
2018-02-09T13:48:34.558Z 10.147.99.3 <31>Feb  9 16:48:34 X5_tihvinskaya3     Called-Station-Id = "X5_tihvinskaya3"
2018-02-09T13:48:34.558Z 10.147.99.3 <31>Feb  9 16:48:34 X5_tihvinskaya3     NAS-Port-Id = "Perekrestok_Free"
2018-02-09T13:48:34.558Z 10.147.99.3 <31>Feb  9 16:48:34 X5_tihvinskaya3     User-Name = "790350925182@4917.com"
2018-02-09T13:48:34.559Z 10.147.99.3 <31>Feb  9 16:48:34 X5_tihvinskaya3     Event-Timestamp = 1518184114
2018-02-09T13:48:34.559Z 10.147.99.3 <31>Feb  9 16:48:34 X5_tihvinskaya3     NAS-Identifier = "X5_tihvinskaya3"
2018-02-09T13:48:34.559Z 10.147.99.3 <31>Feb  9 16:48:34 X5_tihvinskaya3     Acct-Delay-Time = 0
2018-02-09T13:48:34.559Z 10.147.99.3 <31>Feb  9 16:48:34 X5_tihvinskaya3     MT-Realm = 0x31
2018-02-09T13:48:34.559Z 10.147.99.3 <31>Feb  9 16:48:34 X5_tihvinskaya3     NAS-IP-Address = 10.191.101.2

What am I doing wrong?

2

Hi there,

I try to figure it out by including debug logs.
Here's what I see:
The multiline codec is loaded.

[2018-02-12T13:30:15,390][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@pattern = "<31>%{SYSLOGTIMESTAMP} %{WORD}\\s{5}%{WORD}"
[2018-02-12T13:30:15,390][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@what = "previous"
[2018-02-12T13:30:15,390][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@id = "2b3d2bb0-01f0-4d00-a101-d77830cf103d"
[2018-02-12T13:30:15,390][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@enable_metric = true
[2018-02-12T13:30:15,390][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@negate = false
[2018-02-12T13:30:15,390][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@patterns_dir = []
[2018-02-12T13:30:15,390][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@charset = "UTF-8"
[2018-02-12T13:30:15,390][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@multiline_tag = "multiline"
[2018-02-12T13:30:15,390][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@max_lines = 500
[2018-02-12T13:30:15,391][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@max_bytes = 10485760

The codec takes strings and correctly parses them.

[2018-02-12T13:41:59,025][DEBUG][logstash.codecs.multiline] Multiline {:pattern=>"<31>%{SYSLOGTIMESTAMP} %{WORD}\\s{5}%{WORD}", :text=>"<31>Feb 12 13:41:59 X5_tihvinskaya3 sending Accounting-Request with id 48 to 185.12.28.167:1813", :match=>false, :negate=>false}
[2018-02-12T13:41:59,026][DEBUG][logstash.codecs.multiline] Multiline {:pattern=>"<31>%{SYSLOGTIMESTAMP} %{WORD}\\s{5}%{WORD}", :text=>"<31>Feb 12 13:41:59 X5_tihvinskaya3     Signature = 0xfd4b666fe587c339551d5bb83e47749c", :match=>true, :negate=>false}
[2018-02-12T13:41:59,026][DEBUG][logstash.codecs.multiline] Multiline {:pattern=>"<31>%{SYSLOGTIMESTAMP} %{WORD}\\s{5}%{WORD}", :text=>"<31>Feb 12 13:41:59 X5_tihvinskaya3     Acct-Status-Type = 2", :match=>true, :negate=>false}
[2018-02-12T13:41:59,026][DEBUG][logstash.codecs.multiline] Multiline {:pattern=>"<31>%{SYSLOGTIMESTAMP} %{WORD}\\s{5}%{WORD}", :text=>"<31>Feb 12 13:41:59 X5_tihvinskaya3     Acct-Terminate-Cause = 6", :match=>true, :negate=>false}
[2018-02-12T13:41:59,026][DEBUG][logstash.codecs.multiline] Multiline {:pattern=>"<31>%{SYSLOGTIMESTAMP} %{WORD}\\s{5}%{WORD}", :text=>"<31>Feb 12 13:41:59 X5_tihvinskaya3     NAS-Port-Type = 19", :match=>true, :negate=>false}
[2018-02-12T13:41:59,027][DEBUG][logstash.codecs.multiline] Multiline {:pattern=>"<31>%{SYSLOGTIMESTAMP} %{WORD}\\s{5}%{WORD}", :text=>"<31>Feb 12 13:41:59 X5_tihvinskaya3     Calling-Station-Id = \"9C:35:EB:E4:F0:F5\"", :match=>true, :negate=>false}
[2018-02-12T13:41:59,027][DEBUG][logstash.codecs.multiline] Multiline {:pattern=>"<31>%{SYSLOGTIMESTAMP} %{WORD}\\s{5}%{WORD}", :text=>"<31>Feb 12 13:41:59 X5_tihvinskaya3     Called-Station-Id = \"X5_tihvinskaya3\"", :match=>true, :negate=>false}

But the filter receives separate non-merged events.

[2018-02-12T13:41:59,132][DEBUG][logstash.pipeline        ] filter received {"event"=>{"@version"=>"1", "@timestamp"=>2018-02-12T10:41:59.026Z, "host"=>"10.147.99.3", "message"=>"<31>Feb 12 13:41:59 X5_tihvinskaya3 sending Accounting-Request with id 48 to 185.12.28.167:1813"}}
[2018-02-12T13:41:59,132][DEBUG][logstash.pipeline        ] filter received {"event"=>{"@version"=>"1", "@timestamp"=>2018-02-12T10:41:59.026Z, "host"=>"10.147.99.3", "message"=>"<31>Feb 12 13:41:59 X5_tihvinskaya3     Signature = 0xfd4b666fe587c339551d5bb83e47749c"}}
[2018-02-12T13:41:59,132][DEBUG][logstash.pipeline        ] filter received {"event"=>{"@version"=>"1", "@timestamp"=>2018-02-12T10:41:59.026Z, "host"=>"10.147.99.3", "message"=>"<31>Feb 12 13:41:59 X5_tihvinskaya3     Acct-Status-Type = 2"}}
[2018-02-12T13:41:59,132][DEBUG][logstash.pipeline        ] filter received {"event"=>{"@version"=>"1", "@timestamp"=>2018-02-12T10:41:59.027Z, "host"=>"10.147.99.3", "message"=>"<31>Feb 12 13:41:59 X5_tihvinskaya3     Acct-Terminate-Cause = 6"}}
[2018-02-12T13:41:59,132][DEBUG][logstash.pipeline        ] filter received {"event"=>{"@version"=>"1", "@timestamp"=>2018-02-12T10:41:59.027Z, "host"=>"10.147.99.3", "message"=>"<31>Feb 12 13:41:59 X5_tihvinskaya3     NAS-Port-Type = 19"}}
[2018-02-12T13:41:59,132][DEBUG][logstash.pipeline        ] filter received {"event"=>{"@version"=>"1", "@timestamp"=>2018-02-12T10:41:59.027Z, "host"=>"10.147.99.3", "message"=>"<31>Feb 12 13:41:59 X5_tihvinskaya3     Calling-Station-Id = \"9C:35:EB:E4:F0:F5\""}}
[2018-02-12T13:41:59,132][DEBUG][logstash.pipeline        ] filter received {"event"=>{"@version"=>"1", "@timestamp"=>2018-02-12T10:41:59.027Z, "host"=>"10.147.99.3", "message"=>"<31>Feb 12 13:41:59 X5_tihvinskaya3     Called-Station-Id = \"X5_tihvinskaya3\""}}

Has anyone encountered such a codec behavior?

3

The UDP protocol does not guarantee delivery or ordering, so I do not see the point in trying to use a multiline codec here. If you need guarantees delivery and/or ordering, you should use TCP instead.

4

@Christian_Dahlqvist Are you saying that the multiline codec does not work with the udp plugin? Or it is not desirable to use it with udp?
If it is not desirable, then I agree with you, but this does not explain why it does not work.

5

As there is no ordering guaranteed in the UDP protocol, you have no guarantee that events will be grouped together correctly. I copied a couple of your events (with sequence number added) into a file and sent this through nc, and even though the multiline codec did group events, it was not the correct ordering nor grouping.

The multiline codec requires a stream of events in the correct order, and since UDP can not provide this, it will not be able to give correct results.

If you need your events to be assembled correctly, use TCP or get the source system to send complete events per UDP message.

6

@Christian_Dahlqvist
I understand you and I agree that UDP is not what I need, but I still do not understand why the codec does not work. It just does not work with UDP and all or somewhere there is an error in my config.

Pavel

7

What do you mean by does not work? Can you provide a simple recreation?

When I tried it it did assemble lines, but not in the correct order or groups.

Which version of Logstash are you using?

8

I use 6.2.1 version.
I provide debug logs in the post below

I do not see any lines, combined into one event.

9

I can see lines getting combined when I test it, but it does in my opinion not really matter, as I can not have any guarantee that my data will be assembled correctly due to the properties of the underlying protocol. It does in my opinion not make any sense to use a multiline codec together with a UDP input.

10

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.