Grokparsefailure with NXlog and Logstash

Elastic Stack Logstash
1

I seem to have a strange(or not) issue with logstash where I am seeing random grokparsefailure.

I am using NXLog to ship IIS logs from 5 of my webservers to Logstash. The NXlog config is as below

Module xm_json
Module xm_fileop
Module im_file File "D:\IISLogs\W3SVC2\u_ex*.log" PollInterval 120 DirCheckInterval 120 ReadFromLast True SavePos True Exec if $raw_event =~ /^#/ drop();
Module om_tcp Host <> Port 5544 OutputType LineBased
Path iis_core => out_logstash

The webservers have a very high number of requests being served per second and hence a large number of request is being send to logstash from the 5 webservers. I can see that I am having some log entries marked as 'grokparsefailure' and seem to be very random.

Logstash conf

input {
tcp {
port => 5544
}
}

filter {

#ignore log comments
if [message] =~ "^#" {
drop {}
}

grok {
# check that fields match your IIS log settings
match => ["message", "%{TIMESTAMP_ISO8601:log_timestamp} %{WORD:iisSite} %{HOSTNAME:sourcehost} %{IPORHOST:hostip} %{WORD:method} %{URIPATH:page} %{NOTSPACE:querystring} %{WORD:port} %{NOTSPACE:username} %{IPORHOST:clientip} %{NOTSPACE:version} %{NOTSPACE:useragent} %{NOTSPACE:cscookie} %{NOTSPACE:referer} %{NOTSPACE:cshost} %{NUMBER:scstatus:int} %{NUMBER:subresponse} %{NUMBER:win32substatus:int} %{NUMBER:scbytes:int} %{NUMBER:csbytes:int} %{NUMBER:timetaken:int}"]
}

date {
match => [ "log_timestamp", "YYYY-MM-dd HH:mm:ss" ]
timezone => "Etc/UCT"
}

useragent {
source=> "useragent"
prefix=> "browser"
}

mutate {
remove_field => [ "host"]
remove_field => [ "message"]
remove_field => [ "cscookie"]
}
}

output {
stdout { codec => rubydebug }
if "_grokparsefailure" in [tags] {
file { path => "C:\logstash\log\failed_grok_events-%{+YYYY-MM-dd}" }
}
elasticsearch {
hosts => "127.0.0.1:9200"
index => "logstash-%{+YYYY.MM.dd}"
}
}

From the failed grok events, I am able to see this

{"message":"\r","@version":"1","@timestamp":"2015-11-29T21:31:26.518Z","tags":["_grokparsefailure"]}

The message part just has '\r' in it and I cant find a line in IIS log that would correspond to it. (I have tested the implementation with a bad grok pattern and the message is showing the corresponding iis log).

Does anyone know if this is NXLog issue or Logstash issue or something that happens when a large number of requests hits logstash.?

2

\r is the carriage return character, i.e. one of the two characters in the Windows line break. Are there any blank lines in the input log? The codec strips trailing newline characters (\n) but perhaps not carriage returns so I suspect that blank lines in Windows files show up as \r in Logstash.

3

Thank you for the reply magnus. I did a search using a script and cant see any blank lines. As these are just plain IISLogs, I dont think there would be any blanks lines in the logs. its so strange that it still shows up though. I have a similar setup for our QA environment and cant see any grokparsefailure in there.

I wonder if it could be a race condition where IIS puts in a new line and nxlog sends the log before it is updated or could be that logstash in some way fails when it receives a large number of log entries.?

PS: I have read many topics that you have replied to and I feel you are doing a great job. Thanks a lot.

4

plz can you tell me how you solve the problem?

thx