Logstash timestamp issue - the parsed value is one hour behind the log value


#1

I am using the following code to read McAfee Logs ( I chose to use CSV filters because grok filters turned out to be messy)

input {

stdin{}
}

filter {

csv {
columns => ["timestamp", "McAf_ThreatSeverity", "McAf_Event", "McAf_EventDescription", "McAf_EventCategory", "McAf_ThreatT"]

      separator => "|"
}

date {
locale => "en"
match => ["timestamp", "dd/MM/YYYY:HH:mm:ss"]
timezone => "Europe/London"
add_tag => "McAfee_ThreatEventLog"
}

}

output {
elasticsearch {
#action => "index"
host => "localhost"
}
stdout {
codec => rubydebug
}
}
The input is something like this ...

31/03/2015:12:59:07| SEVERITY_CRITICAL | 1093| Buffer Overflow detected and blocked| Host intrusion buffer overflow| 10.3.1.252| Blocked| buffer overflow
The output is ok EXCEPT for the timestamp which is one hour behind that in the logs. That is,

Using milestone 2 filter plugin 'csv'. This plugin should be stable, but if you see strange behavior, please let us know! For more information on plugin milestones, see http://logstash.net/docs/1.4.2/plugin-milestones {:level=>:warn}
31/03/2015:12:59:07| SEVERITY_CRITICAL | 1093| Buffer Overflow detected and blocked| Host intrusion buffer overflow| 10.3.1.252| Blocked| buffer overflow
{
"message" => [
[0] "31/03/2015:12:59:07| SEVERITY_CRITICAL | 1093| Buffer Overflow detected and blocked| Host intrusion buffer overflow| 10.3.1.252| Blocked| buffer overflow"
],
"@version" => "1",
"@timestamp" => "2015-03-31T11:59:07.000Z",
"host" => "UOD-220076",
"timestamp" => "31/03/2015:12:59:07",
"McAf_ThreatSeverity" => " SEVERITY_CRITICAL ",
"McAf_Event" => " 1093",
"McAf_EventDescription" => " Buffer Overflow detected and blocked",
"McAf_EventCategory" => " Host intrusion buffer overflow",
"McAf_ThreatTargetIPv4Address" => " 10.3.1.252",
"McAf_ActionTaken" => " Blocked",
"McAf_ThreatType" => " buffer overflow",
"tags" => [
[0] "McAfee_ThreatEventLog"
]
}
In the output above, the time in the log is 12:59:07 but the parsed value is 11:59:07.

The interesting thing is that I parsed different logs yesterday (firewall logs) using the following code:

input {

stdin{}
}

filter {

csv {
columns => ["timestamp", "Interface", "Origin", "Type", "Action", "Service", "SourcePort", "SourceIP", "DestinationIP", "P$
separator => "|"
}

date {
locale => "en"
match => ["timestamp", "dd/MMM/YYYY:HH:mm:ss"]
timezone => "Europe/London"
add_tag => "checkpoint_fw"

}

}

output {
elasticsearch {
host => "localhost"
}
stdout {
And the following input....

18/MAR/2015:15:00:00| eth3-04| grog1| Log| Accept| http| 46718| 193.60.148.101| 23.194.230.180| tcp| 0| | | inzone: Local; outzone: External; service_id: http; message_info: Implied rule| Security Gateway/Management

Which gives the correct output of the timestamp as shown below:

[0] "18/MAR/2015:15:00:00| eth3-04| grog1| Log| Accept| http| 46718| 193.60.148.101| 23.194.230.180| tcp| 0| | | inzone: Local; outzone: External; service_id: http; message_info: Implied rule| Security Gateway/Management"

],
"@version" => "1",
"@timestamp" => "2015-03-18T15:00:00.000Z",
"host" => "UOD-220076",
"timestamp" => "18/MAR/2015:15:00:00",
"Interface" => " eth3-04",
"Origin" => " grog1",
"Type" => " Log",
"Action" => " Accept",
"Service" => " http",
"SourcePort" => " 46718",
"SourceIP" => " 193.60.148.101",
"DestinationIP" => " 23.194.230.180",
"Protocol" => " tcp",
"Rule" => " 0",
"RuleName" => " ",
"CurrentRule" => " ",
"Information" => " inzone: Local; outzone: External; service_id: http; message_info: Implied rule",
"Product" => " Security Gateway/Management",
"tags" => [
[0] "checkpoint_fw"
The only difference between the McAfee script and the firewall script (apart from the fields obviously) is that the firewall script uses dd/MMM/YYYY whilst the McAfee script uses dd/MM/YYYY - I highly doubt that would be a significant difference.

Any ideas anyone on how I can get the McAfee timestamp to be exactly what's on the logs ? ( I have even tried changing timezones but all that has done is increase the time difference) - is there a way of saying " + 1 hour" in logstash (not kibana) ?

Thanks.


(Magnus Bäck) #2

You've set Europe/London as the timezone and the UK entered daylight savings time on March 29. The "correct" log entry is from March 18 so London time and UTC coincide, but the "wrong" log entry is from March 31 so the one-hour difference is actually expected.


#3

Magnusbaeck,
Thanks a tonne - I had thought of that initially but didn't pay too much attention to my thoughts.
Well, the question then is, what can be done ? I obviously can't have logs being one hour behind and more so if I want to do some cross analysis with other logs which were obtained prior to UK DST.


(Magnus Bäck) #4

There is nothing to be done. The @timestamp field is supposed to be in UTC so everything is perfectly normal.


(system) #5