better year handling when format does not contain year by jsvd · Pull Request #4 · logstash-plugins/logstash-filter-date

jsvd · 2015-01-06T18:49:00Z

if the time format does not have year then:

use local year if month is the same as current one
use previous year if current month is January but event is December
use next year if current month is December but event is January
use local year otherwise

fixes #3

has very little impact on formats that have year.
For year-less formats there's extra allocation overhead per event (Time.now, time parsing is no longer direct to long, has to go through 2 DateTime objects)

Performance impact for this change was not analyzed.

jordansissel · 2015-01-06T19:50:02Z

Eyeballed the code and tests. Looks ok!

I have not tested and I have also not done perf analysis.

suyograo · 2015-07-24T23:58:25Z

@purbon how can we use the new perf test suite to analyze the implications of this PR? this is a good candidate to validate our perf platform

purbon · 2015-07-27T09:56:22Z

@suyograo makes complete sense, will setup an example test case for this.

purbon · 2015-07-27T13:36:35Z

@jsvd I think you might need to rebase this PR 😸

jsvd · 2015-07-28T16:04:45Z

@purbon done 👍

purbon · 2015-07-28T16:05:40Z

cool, will run this throw the performance gem, kinda want to see how it looks there 😺

purbon · 2015-08-07T12:53:09Z

@jsvd running test with this PR make this output in my machine:


Failures:

  1) LogStash::Filters::Date parsing with java SimpleDateFormat syntax "{"mydate":"Nov 24 01:29:01 -0800"}" when processed
     Failure/Error: insist { subject["@timestamp"].time } == Time.iso8601(output).utc
     Insist::Failure:
       Expected 2015-11-24 09:29:01 UTC, but got 2015-08-07 12:51:30 UTC
     # ./spec/filters/date_spec.rb:96:in `(root)'

  2) LogStash::Filters::Date fill last year if december events arrive in january "Dec 31 23:59:00" when processed
     Failure/Error: insist { subject["@timestamp"].year } == 2013
       (<Time (class)>).now(no args)
           expected: 2 times with any arguments
           received: 3 times
     # ./lib/logstash/filters/date.rb:262:in `filter'
     # ./lib/logstash/filters/date.rb:232:in `filter'
     # ./lib/logstash/filters/date.rb:225:in `filter'
     # (eval):33:in `filter_func'
     # ./spec/filters/date_spec.rb:388:in `(root)'
     # ./spec/filters/date_spec.rb:388:in `(root)'

  3) LogStash::Filters::Date fill next year if january events arrive in december "Jan 01 01:00:00" when processed
     Failure/Error: insist { subject["@timestamp"].year } == 2014
       (<Time (class)>).now(no args)
           expected: 2 times with any arguments
           received: 3 times
     # ./lib/logstash/filters/date.rb:262:in `filter'
     # ./lib/logstash/filters/date.rb:232:in `filter'
     # ./lib/logstash/filters/date.rb:225:in `filter'
     # (eval):33:in `filter_func'
     # ./spec/filters/date_spec.rb:405:in `(root)'
     # ./spec/filters/date_spec.rb:405:in `(root)'

Finished in 1.35 seconds (files took 2.18 seconds to load)
50 examples, 3 failures

Failed examples:

I guess there might be something fishy going on here.

purbon

jsvd · 2015-08-07T13:15:56Z

Strange:

% bundle exec rspec
Using Accessor#strict_set for specs
Run options: exclude {:redis=>true, :socket=>true, :performance=>true, :couchdb=>true, :elasticsearch=>true, :elasticsearch_secure=>true, :export_cypher=>true, :integration=>true, :windows=>true}
..................................................

Finished in 1.23 seconds (files took 2.99 seconds to load)
50 examples, 0 failures

Randomized with seed 42455

Can you provide me with a seed for a failing spec run?

purbon · 2015-08-07T13:32:26Z

Hi,
checked again, this is the seed used.

Randomized with seed 28114

purbon

On Fri, Aug 7, 2015 at 3:16 PM João Duarte notifications@github.com wrote:

Strange:

% bundle exec rspec
Using Accessor#strict_set for specs
Run options: exclude {:redis=>true, :socket=>true, :performance=>true, :couchdb=>true, :elasticsearch=>true, :elasticsearch_secure=>true, :export_cypher=>true, :integration=>true, :windows=>true}
..................................................

Finished in 1.23 seconds (files took 2.99 seconds to load)
50 examples, 0 failures

Randomized with seed 42455

Can you provide me with a seed for a failing spec run?

—
Reply to this email directly or view it on GitHub
#4 (comment)
.

purbon · 2015-08-07T13:33:16Z

I check with your seed and I get the same error. :-(

purbon

On Fri, Aug 7, 2015 at 3:32 PM Pere Urbon-Bayes pere.urbon@elastic.co
wrote:

Hi,
checked again, this is the seed used.

Randomized with seed 28114

purbon

On Fri, Aug 7, 2015 at 3:16 PM João Duarte notifications@github.com
wrote:

Strange:

% bundle exec rspec
Using Accessor#strict_set for specs
Run options: exclude {:redis=>true, :socket=>true, :performance=>true, :couchdb=>true, :elasticsearch=>true, :elasticsearch_secure=>true, :export_cypher=>true, :integration=>true, :windows=>true}
..................................................

Finished in 1.23 seconds (files took 2.99 seconds to load)
50 examples, 0 failures

Randomized with seed 42455

Can you provide me with a seed for a failing spec run?

—
Reply to this email directly or view it on GitHub
#4 (comment)
.

ph · 2015-08-07T13:52:08Z

on a clean clone, one test is failing on me.


Failures:

  1) LogStash::Filters::Date fill last year if december events arrive in january "Dec 31 23:59:00" when processed
     Failure/Error: insist { subject["@timestamp"].year } == 2013
     Insist::Failure:
       Expected 2013, but got 2014
     # ./spec/filters/date_spec.rb:388:in `(root)'

Finished in 1.56 seconds (files took 2.48 seconds to load)
50 examples, 1 failure

Failed examples:

rspec ./spec/filters/date_spec.rb:385 # LogStash::Filters::Date fill last year if december events arrive in january "Dec 31 23:59:00" when processed

Randomized with seed 54520

ph · 2015-08-07T13:52:58Z

used @purbon's seed I have the same issue

Failures:

  1) LogStash::Filters::Date fill last year if december events arrive in january "Dec 31 23:59:00" when processed
     Failure/Error: insist { subject["@timestamp"].year } == 2013
     Insist::Failure:
       Expected 2013, but got 2014
     # ./spec/filters/date_spec.rb:388:in `(root)'

Finished in 1.69 seconds (files took 2.18 seconds to load)
50 examples, 1 failure

Failed examples:

rspec ./spec/filters/date_spec.rb:385 # LogStash::Filters::Date fill last year if december events arrive in january "Dec 31 23:59:00" when processed

Randomized with seed 28114

/t/logstash-filter-date git:pr/4 ❯❯❯ ruby -v                                                                                                                                                                                                                                                                                                                            ⏎
jruby 1.7.20 (1.9.3p551) 2015-05-04 3086e6a on Java HotSpot(TM) 64-Bit Server VM 1.8.0_20-b26 +jit [darwin-x86_64]

purbon · 2015-08-07T13:54:07Z

@ph interesting you see one issue, I see three. Might be we should set another variables in the config to setup the same environment for everyone. I have the feeling this is working different in three completely different machines (PT/DE/Canada).

purbon

ph · 2015-08-07T13:54:41Z

Yeah, could be related to some locales

jsvd · 2015-08-07T13:56:14Z

Ok so making sure that we set a timezone in the test plugin instance should make this work. awesome failure !

purbon · 2015-08-07T13:57:22Z

😺

jsvd · 2015-08-07T14:21:39Z

@purbon can you check that at least 2 of the 3 errors are gone now?

purbon · 2015-08-07T14:24:36Z

my execution looks like this now:

purbon-elastic% bundle exec rspec
Using Accessor#strict_set for specs
Run options: exclude {:redis=>true, :socket=>true, :performance=>true, :couchdb=>true, :elasticsearch=>true, :elasticsearch_secure=>true, :export_cypher=>true, :integration=>true, :windows=>true}
................................................

Finished in 1.36 seconds (files took 1.84 seconds to load)
48 examples, 0 failures

Randomized with seed 33520

errors are gone for me 😸

jsvd · 2015-08-07T14:37:20Z

@purbon can you teach me to run benchmarks on this pr?

purbon · 2015-08-07T14:37:51Z

yeah!

purbon · 2015-08-07T14:42:18Z

I was actually going to do it myself, when I encounter this errors ... but is good if I can teach you too 😄

purbon · 2015-09-07T20:12:54Z

Hi,
super interesting, I was running test here in order to continue doing benchmarking, however I found out that I still see:

Failures:

  1) LogStash::Filters::Date parsing with java SimpleDateFormat syntax "{"mydate":"Nov 24 01:29:01 -0800"}" when processed
     Failure/Error: insist { subject["@timestamp"].time } == Time.iso8601(output).utc
     Insist::Failure:
       Expected 2015-11-24 09:29:01 UTC, but got 2015-09-07 20:11:45 UTC
     # ./spec/filters/date_spec.rb:96:in `(root)'

  2) LogStash::Filters::Date fill next year if january events arrive in december "Jan 01 01:00:00" when processed
     Failure/Error: insist { subject["@timestamp"].year } == 2014
       (<Time (class)>).now(no args)
           expected: 2 times with any arguments
           received: 3 times
     # ./lib/logstash/filters/date.rb:262:in `filter'
     # ./lib/logstash/filters/date.rb:232:in `filter'
     # ./lib/logstash/filters/date.rb:225:in `filter'
     # (eval):33:in `filter_func'
     # ./spec/filters/date_spec.rb:407:in `(root)'
     # ./spec/filters/date_spec.rb:407:in `(root)'

  3) LogStash::Filters::Date fill last year if december events arrive in january "Dec 31 23:59:00" when processed
     Failure/Error: insist { subject["@timestamp"].year } == 2013
       (<Time (class)>).now(no args)
           expected: 2 times with any arguments
           received: 3 times
     # ./lib/logstash/filters/date.rb:262:in `filter'
     # ./lib/logstash/filters/date.rb:232:in `filter'
     # ./lib/logstash/filters/date.rb:225:in `filter'
     # (eval):33:in `filter_func'
     # ./spec/filters/date_spec.rb:389:in `(root)'
     # ./spec/filters/date_spec.rb:389:in `(root)'

Finished in 1.36 seconds (files took 1.92 seconds to load)
50 examples, 3 failures

Failed examples:

rspec ./spec/filters/date_spec.rb:94 # LogStash::Filters::Date parsing with java SimpleDateFormat syntax "{"mydate":"Nov 24 01:29:01 -0800"}" when processed
rspec ./spec/filters/date_spec.rb:404 # LogStash::Filters::Date fill next year if january events arrive in december "Jan 01 01:00:00" when processed
rspec ./spec/filters/date_spec.rb:386 # LogStash::Filters::Date fill last year if december events arrive in january "Dec 31 23:59:00" when processed

Randomized with seed 44127

when running the specs, I am missing something?

/cheers

jsvd · 2015-09-08T08:44:08Z

hum..my first guess was local timezone, but I can't make it fail on others:

logstash-filter-date (git)-[new_year_bug] % TZ=Europe/Berlin bundle exec rspec --seed 44127
Using Accessor#strict_set for specs
Run options: exclude {:redis=>true, :socket=>true, :performance=>true, :couchdb=>true, :elasticsearch=>true, :elasticsearch_secure=>true, :export_cypher=>true, :integration=>true, :windows=>true}
..................................................

Finished in 1.1 seconds (files took 2.65 seconds to load)
50 examples, 0 failures

Randomized with seed 44127

purbon · 2015-11-03T15:21:56Z

@jsvd I tested several times and everything works, also used another machine in a different time zone.

purbon · 2015-11-03T15:23:33Z

LGTM

if the time format does not have year then: * use local year if month is the same as current one * use previous year if current month is January but event is December * use next year if current month is December but event is January * use local year otherwise

jordansissel · 2015-12-21T19:06:28Z

date filter version 2.1.0 published with this fix.

# Before
% bin/logstash -e 'input { generator { message => "Jan 01 01:12:23" count => 1 } } filter { date { match => [ "message", "MMM dd HH:mm:ss" ] } }'
{
  "message"    => "Jan 01 01:12:23",
...
  "@timestamp" => "2015-01-01T09:12:23.000Z",
}

# Upgrade
% bin/plugin update logstash-filter-date
Updating logstash-filter-date
Updated logstash-filter-date 2.0.2 to 2.1.0

# After
% bin/logstash -e 'input { generator { message => "Jan 01 01:12:23" count => 1 } } filter { date { match => [ "message", "MMM dd HH:mm:ss" ] } }'
{
  "message"    => "Jan 01 01:12:23",
...
  "@timestamp" => "2016-01-01T09:12:23.000Z",
}

rtoma · 2016-01-12T13:57:40Z

This bug bit me on Logstash 1.5.x - we now have ES indices dated 2015 with 2016 data.

A backport to 1.5.x is too late of course, but fixing the most popular version would have made a lot of sense.

This is intended to keep parity of behavior between Logstash and Elasticsearch here was the original PR: logstash-plugins/logstash-filter-date#4

tishma · 2019-05-28T08:55:37Z

I know I'm quite late for this discussion, yet - I can't think of a case where we want result to appear in future unless event is in January, and we hit end-of-year clock skew.
I would consider using previous year as an ultimate default, say, whenever result is more than a few days in the future - otherwise, we end up with future timestamps in case we are indexing October or November in January or February for whatever reason.

jsvd added the bug label Jan 6, 2015

jordansissel added the O(2) label Jan 7, 2015

electrical mentioned this pull request Jan 9, 2015

Index was created with a name 2014 elastic/elasticsearch#9210

Closed

jordansissel removed the O(2) label Jun 29, 2015

suyograo assigned jsvd Jul 24, 2015

purbon assigned purbon and unassigned jsvd Jul 27, 2015

jsvd force-pushed the new_year_bug branch from 5bd7f9d to 2ef24d3 Compare July 28, 2015 16:04

jsvd mentioned this pull request Nov 2, 2015

Add option to handle dates without year when going from Dec 31st to Jan 1st #33

Closed

jsvd added 2 commits November 4, 2015 09:54

ensure timezone sensitive tests are run in UTC

cfd8949

jsvd force-pushed the new_year_bug branch from 833a077 to cfd8949 Compare November 4, 2015 09:58

jsvd merged commit cfd8949 into logstash-plugins:master Nov 4, 2015

ppf2 mentioned this pull request Dec 17, 2015

Default year, month and date when not specified #51

Open

jsvd deleted the new_year_bug branch January 20, 2016 16:26

wiibaa mentioned this pull request Feb 5, 2016

date filter year guessing problem elastic/logstash#4637

Closed

wiibaa mentioned this pull request Mar 31, 2016

Leap year bug? elastic/logstash#4929

Closed

talevy mentioned this pull request Jun 15, 2017

[WIP] update DateFormat to use same year heuristic as Logstash elastic/elasticsearch#25266

Closed

tishma unassigned purbon May 28, 2019

goller mentioned this pull request Jan 22, 2020

RFC3164 influxdata/go-syslog#27

Merged

8 tasks

Conversation

jsvd commented Jan 6, 2015

Uh oh!

jordansissel commented Jan 6, 2015

Uh oh!

suyograo commented Jul 24, 2015

Uh oh!

purbon commented Jul 27, 2015

Uh oh!

purbon commented Jul 27, 2015

Uh oh!

jsvd commented Jul 28, 2015

Uh oh!

purbon commented Jul 28, 2015

Uh oh!

purbon commented Aug 7, 2015

Uh oh!

jsvd commented Aug 7, 2015

Uh oh!

purbon commented Aug 7, 2015

Uh oh!

purbon commented Aug 7, 2015

Uh oh!

ph commented Aug 7, 2015

Uh oh!

ph commented Aug 7, 2015

Uh oh!

purbon commented Aug 7, 2015

Uh oh!

ph commented Aug 7, 2015

Uh oh!

jsvd commented Aug 7, 2015

Uh oh!

purbon commented Aug 7, 2015

Uh oh!

jsvd commented Aug 7, 2015

Uh oh!

purbon commented Aug 7, 2015

Uh oh!

jsvd commented Aug 7, 2015

Uh oh!

purbon commented Aug 7, 2015

Uh oh!

purbon commented Aug 7, 2015

Uh oh!

purbon commented Sep 7, 2015

Uh oh!

jsvd commented Sep 8, 2015

Uh oh!

purbon commented Nov 3, 2015

Uh oh!

purbon commented Nov 3, 2015

Uh oh!

jordansissel commented Dec 21, 2015

Uh oh!

rtoma commented Jan 12, 2016

Uh oh!

tishma commented May 28, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants

tishma commented May 28, 2019 •

edited

Loading