Logstash not getting "message" from log file input

Elastic Stack Logstash
1

If I start Logstash with -f /etc/logstash/conf.d then one of my conf files (windowslogs.conf; whose job it is to read and parse Windows log files forwarded by NXlog on Windows hosts) does not work. Logstash recognizes that lines are being added to the log files because I get _grokParseFail tags, but this is because there is no "message" portion of the entry. But if I start with -f /etc/logstash/conf.d/windowslogs.conf then it reads those Windows log files fine and parses them without problem.

Any ideas? I'm pretty much a Logstash NOOB.

Thanks in advance!!!

Here's an example:

Line in log:
Sep 15 10:25:25 144.17.53.5 {"EventTime": "2015-09-15 10:25:25","Hostname":"BBTSSNOW","Keywords":-9214364837600034816,"EventType":"AUDIT_SUCCESS","SeverityValue":2,"Severity":"INFO","EventID":5156,"SourceName":"Microsoft-Windows-Security-Auditing","ProviderGuid":"{54849625-5478-4994-A5BA-3E3B0328C30D}","Version":1,"Task":12810,"OpcodeValue":0,"RecordNumber":75370997,"ProcessID":4,"ThreadID":88,"Channel":"Security","Message":"The Windows Filtering Platform has permitted a connection.\r\n\r\nApplication Information:\r\n\tProcess ID:\t\t976\r\n\tApplication Name:\t\device\harddiskvolume2\windows\system32\svchost.exe\r\n\r\nNetwork Information:\r\n\tDirection:\t\tOutbound\r\n\tSource Address:\t\t144.17.53.5\r\n\tSource Port:\t\t55170\r\n\tDestination Address:\t144.17.3.82\r\n\tDestination Port:\t\t53\r\n\tProtocol:\t\t17\r\n\r\nFilter Information:\r\n\tFilter Run-Time ID:\t0\r\n\tLayer Name:\t\tConnect\r\n\tLayer Run-Time ID:\t48","Category":"Filtering Platform Connection","Opcode":"Info","Application":"\device\harddiskvolume2\windows\system32\svchost.exe","Direction":"%%14593","SourceAddress":"144.17.53.5","SourcePort":"55170","DestAddress":"144.17.3.82","DestPort":"53","Protocol":"17","FilterRTID":"0","LayerName":"%%14611","LayerRTID":"48","RemoteUserID":"S-1-0-0","RemoteMachineID":"S-1-0-0","EventReceivedTime":1442334325,"SourceModuleName":"in","SourceModuleType":"im_msvistalog"}#015

What I get from Logstash (using file output, rubydebug) I realize this does not correspond to the log entry as above, just an example:
{"@version":"1","@timestamp":"2015-09-14T22:18:17.316Z","host":"elk.snow.edu","path":"/var/log/hosts/windows/144.17.53.5/user-2015-09-14.log","type":"windows","tags":["windows","_grokParseFailWin1"]}

Here's my grok:
grok {
tag_on_failure => [ "_grokParseFailWin1" ]
match => [ "message", "%{SYSLOGTIMESTAMP:@timestamp} %{SYSLOGHOST:syslog_host} %{JSON:raw_message}%{GREEDYDATA}" ]
}

After the grok I do:
json {
source => "raw_message"
}

Here's JSON in custom patterns (since it's greedy, it will read to the last closing brace)
JSON {.*} (The curly braces are escaped, but this post is stripping them off)

2

Do you have any other files in /etc/logstash/conf.d besides windowslogs.conf?

3

Yes, there are conf files for parsing other types of log files. Specifically, I have an authpriv.conf, firewall-outside.conf, linuxsyslogs.conf and of course windowslogs.conf. The others seem to work fine.

Within each of those, when I read an input file I mark it with a type and tags so that I can, for example, in the filter and output sections use: if "windows" in [tags] { ........

4

It seems something's off with those conditions in the other files. Your example output record is completely lacking a message field. How is that possible?

Other comments:

  • Don't grok directly to @timestamp, at least not when the input string isn't ISO8601. Use the date filter to populate that field.
  • To avoid surprises when posting configuration snippets etc here, format it as preformatted text (Ctrl/Cmd+K).
  • The %{GREEDYDATA} at the end of the grok expression serves no purpose.
5

Hi, your mention of something being off with the other config files led me to go through them and I indeed did find a problem. I had a closing brace in a wrong place which put a snippet of code (a mutate that deletes the "message" if grok'ed properly) outside of the if statement thereby always deleting the "message" portion. I imagine it only caused a problem with the windowslogs.conf because the problem was in the weblogs.conf which is alphabetically before windowslogs since I believe they are processed lexigraphically in order.

Thanks for the tip off!!

And by the way, I'lve implemented the date filter and removed unecessary %{GREEDYDATA}.

6

It sounds like the place where the brace was wrong looked something like

grok {
  ...
}
if "_grokparsefailure" not in [tags] {
  mutate {
    remove_field => ["message"]
  }
}

but that can be simplified like this:

grok {
  ...
  remove_field => ["message"]
}
7

Oh cool. Yep, that's exactly what I had going on. You have been most helpful, thank you!