Logstash fails to load indian log records due to daylight savings change on host machine

[Matt_Simcox]

I'm not sure if there's a way around this one.

I have a concatenated year long log file provided by an indian client who do not yet use logstash. I have set up a test box in Sydney Australia to parse their logs to analyse their transaction volume.

It loads mostly successfully except for any logs between 0200-0300 2/10/2016, all these fail. I have identified this is almost certainly due to NSW Australian daylight saving being found at that time, we skip forward an hour. The logs were on a server in india.

I've tried setting the timezone as follows:

    date {
	match => ["time","yyyy-MM-dd_HH:mm:ss.SSS","yyyy-MM-dd HH:mm:ss.SSS"]
	timezone => "Asia/Kolkata"
}

but I'm still seeing the issue. I'm missing 1450 records, not earth shattering but annoying.

[jakommo (Jakob Reiter)]

Can you post an example that is failing?
I just tried and it seems to work for me:

{
    "@timestamp" => 2016-10-01T21:29:40.997Z,
          "port" => 46418,
      "@version" => "1",
          "host" => "127.0.0.1",
          "time" => "2016-10-02_02:59:40.997",
       "message" => "2016-10-02_02:59:40.997",
          "tags" => []
}

What LS and Java version are you using?

[Matt_Simcox]

Thanks for your reply jakommo, my set up is as follows:

logstash-5.0.1
Java 1.8.0_111
Current system server timezone is AEDT, daylight saving flipped 0200 02/10/2016

#logstash pipeline configuration

filter {
	grok {
	   patterns_dir => ["./patterns"]
	   match => { "message" => "%{TRANTRACK_DATE:time} %{NOTSPACE} %{NOTSPACE}  %{NOTSPACE} - %{NOTSPACE} Completed :\s\w*=(%{WORD:socketval})?,\w*=(%{WORD:txnref})?,\w*=(%{WORD:clientid})?,\w*=(%{NUMBER:respcode})?,\w*=(%{MULTI_WORD:resptext})?,\w*=(%{WORD:duration})?,\w*=(%{TRAN_WITH_SUBTYPE:txntype})?,\w*=(%{WORD:interface})?" }
	   overwrite => ["message"]	
	}
	if ([message] =~ "Transaction Start") {
      drop {}
    }
    date {
    	match => ["time","yyyy-MM-dd_HH:mm:ss.SSS","yyyy-MM-dd HH:mm:ss.SSS"]
		timezone => "Asia/Kolkata"
    }
}

#./patterns directory

TRANTRACK_DATE %{YEAR}[/-]%{MONTHNUM}[/-]%{MONTHDAY}[\s_]%{HOUR}:%{MINUTE}:%{SECOND}[.]\d\d\d
MULTI_WORD [\b\w+|\W\b\s]+
TRAN_WITH_SUBTYPE [\b\w+\[\w+\]\b]+
NUMBER_OR_WORD (%{NUMBER}|%{WORD})


#Record that fails in logstash but parse correctly in grokdebugger

2016-10-02_02:00:01.632 [transaction-1] INFO  companyA.engine.TransactionHandler - <TransactionTracker>Transaction Completed : SOCKETID=61915,TXNREFERENCE=1000000001974928,CLIENTID=10000046,RESPONSECODE=05,RESPONSETEXT=DO NOT HONOUR,DURATION=15,TRANSACTIONTYPE=PURCHASE[STATUS],INTERFACE=CREDITCARD



#example of the failure output
16:19:42.909 [[main]>worker7] WARN  logstash.filters.date - Failed parsing date from field {:field=>"time", :value=>"2016-10-02_02:59:59.999", :exception=>"Invalid format: \"2016-10-02_02:59:59.999\"
is malformed at \"_02:59:59.999\"", :config_parsers=>"yyyy-MM-dd_HH:mm:ss.SSS,yyyy-MM-dd HH:mm:ss.SSS", :config_locale=>"default=en_AU"}

[jakommo (Jakob Reiter)]

Hmm, I tried with AEDT on a Centos7 machine using LS 5.0.1 and Java 8 u 111, but it still works for me.

# timedatectl 
      Local time: Thu 2016-12-22 03:08:14 AEDT
  Universal time: Wed 2016-12-21 16:08:14 UTC
        RTC time: n/a
       Time zone: Australia/Sydney (AEDT, +1100)
     NTP enabled: n/a
NTP synchronized: yes
 RTC in local TZ: no
      DST active: yes
 Last DST change: DST began at
                  Sun 2016-10-02 01:59:59 AEST
                  Sun 2016-10-02 03:00:00 AEDT
 Next DST change: DST ends (the clock jumps one hour backwards) at
                  Sun 2017-04-02 02:59:59 AEDT
                  Sun 2017-04-02 02:00:00 AEST

# rpm -qa | grep openjdk
java-1.8.0-openjdk-headless-1.8.0.111-2.b15.el7_3.x86_64

# logstash-5.0.1/bin/logstash -r -w1 -f ls.conf 
Sending Logstash's logs to /root/logstash-5.0.1/logs which is now configured via log4j2.properties
[2016-12-22T03:09:01,800][INFO ][logstash.inputs.tcp      ] Starting tcp input listener {:address=>"0.0.0.0:5014"}
[2016-12-22T03:09:02,309][INFO ][logstash.pipeline        ] Starting pipeline {"id"=>"main", "pipeline.workers"=>1, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>5, "pipeline.max_inflight"=>125}
[2016-12-22T03:09:02,310][INFO ][logstash.pipeline        ] Pipeline main started
[2016-12-22T03:09:02,495][INFO ][logstash.agent           ] Successfully started Logstash API endpoint {:port=>9600}
{
    "@timestamp" => 2016-10-01T21:29:40.997Z,
          "port" => 57972,
      "@version" => "1",
          "host" => "10.52.101.1",
          "time" => "2016-10-02_02:59:40.997",
       "message" => "2016-10-02_02:59:40.997",
          "tags" => []
}

I just changed the grok to
match => { "message" => "%{TRANTRACK_DATE:time}"}
to accept just the timestamp.

Just to make sure, you are having this problem when sending/reading the value "2016-10-02_02:59:40.997"?
This is the input, not the one it is converted to in UTC, right?

[Matt_Simcox]

Yes this date is being fed in from the log file.