I guess this is an issue but I can't find anything about it. Unfortunately I don't have steps to reproduce it, happens eventually across different prod servers in different log files a few times a day.
I can see that it is aways a partial read of a line, somewhere from the middle to the end. It is never from the beginning to somewhere in the middle. The line sometimes is the first line of a rotated log, sometimes in the middle of the log. Mostly common the line is read empty or with a few characters.
Did anyone had a problem like this? Can you point me any source of a know bug or fix?
Bellow are all the details that I could collect from logstash. All sensitive data was removed.
- Version: Logstash 2.4
- Operating System: Red Hat 4.4.6-3
- Config File:
input {
file {
type => "myservice"
path => “/root/MyService.*”
start_position => "beginning"
codec => multiline {
pattern => "^%{LOGLEVEL}"
negate => true
what => "previous"
}
sincedb_path => “/root/application.db"
}
….
}
filter{
if [type] == "myservice" {
grok {
patterns_dir => “/root/logstash_patterns"
match => ["message", "%{LOGLEVEL:severity}%{SPACE}%{LOG4JTIMESTAMP:logDate}%{SPACE}%{GREEDYDATA:category}%{SPACE}|%{GREEDYDATA:message}"]
overwrite => ["message"]
}
…
}
output {
server_es {
hosts => ["{{ host }}"]
region => "{{ region }}"
index => "{{ index }}"
}
}
-
Log line
...
DEBUG 09 Nov 2016 09:20:44,276 com.service.ui.aop.MetricsInterceptor |Intercepting bean: action:com.service.metrics.RateMetricsFactory pjp:execution(RateMetrics com.service.metrics.RateMetricsFactory.newRateMetrics(String))
... -
Logstash log in debug mode:
{:timestamp=>"2016-11-09T09:20:53.109000+0000", :message=>"_discover_file: /root/MyService.*: new: /root/MyService.2016-11-09-09 (exclude is [])", :level=>:debug, :file=>"filewatch/watch.rb", :line=>"141", :method=>"_discover_file"}
{:timestamp=>"2016-11-09T09:20:54.110000+0000", :message=>"_open_file: /root/MyService.2016-11-09-09: opening", :level=>:debug, :file=>"filewatch/tail.rb", :line=>"118", :method=>"_open_file"}
{:timestamp=>"2016-11-09T09:20:54.110000+0000", :message=>"/root/MyService.2016-11-09-09: sincedb last value 3628, cur size 4068", :level=>:debug, :file=>"filewatch/tail.rb", :line=>"145", :method=>"_open_file"}
{:timestamp=>"2016-11-09T09:20:54.110000+0000", :message=>"/root/MyService.2016-11-09-09: sincedb: seeking to 3628", :level=>:debug, :file=>"filewatch/tail.rb", :line=>"147", :method=>"_open_file"}
{:timestamp=>"2016-11-09T09:20:54.111000+0000", :message=>"Received line", :path=>"/root/MyService.2016-11-09-09", :text=>"r |Intercepting bean: action:com.service.metrics.RateMetricsFactory pjp:execution(RateMetrics com.service.metrics.RateMetricsFactory.newRateMetrics(String))", :level=>:debug, :file=>"logstash/inputs/file.rb", :line=>"207", :method=>"log_line_received"}
{:timestamp=>"2016-11-09T09:20:54.111000+0000", :message=>"Multiline", :pattern=>"^%{LOGLEVEL}", :text=>"r |Intercepting bean: action:com.service.metrics.RateMetricsFactory pjp:execution(RateMetrics com.service.metrics.RateMetricsFactory.newRateMetrics(String))", :match=>true, :negate=>true, :level=>:debug, :file=>"logstash/codecs/multiline.rb", :line=>"168", :method=>"decode"}
{:timestamp=>"2016-11-09T09:20:54.113000+0000", :message=>"filter received", :event=>{"@timestamp"=>"2016-11-09T09:20:54.112Z", "message"=>"r |Intercepting bean: action:com.service.metrics.RateMetricsFactory pjp:execution(RateMetrics com.service.metrics.RateMetricsFactory.newRateMetrics(String))", "@version"=>"1", "host"=>"myhost.com", "path"=>"/root/MyService.2016-11-09-09", "type"=>"myservice"}, :level=>:debug, :file=>"(eval)", :line=>"129", :method=>"filter_func"}
{:timestamp=>"2016-11-09T09:20:54.113000+0000", :message=>"Running grok filter", :event=>
... (big line here) ... }
{:timestamp=>"2016-11-09T09:20:54.115000+0000", :message=>"output received", :event=>{"@timestamp"=>"2016-11-09T09:20:54.112Z", "message"=>"r |Intercepting bean: action:com.service.metrics.RateMetricsFactory pjp:execution(RateMetrics com.service.metrics.RateMetricsFactory.newRateMetrics(String))", "@version"=>"1", "host"=>"myhost.com", "path"=>"/root/MyService.2016-11-09-09", "type"=>"myservice", "tags"=>["_grokparsefailure"]}, :level=>:debug, :file=>"(eval)", :line=>"137", :method=>"output_func"}root/