Default year gets stale in running instance during calendar year change

[dshelepov]

In logstash-filter-date/lib/logstash/filters/date.rb, this line (163 at the moment):

joda_parser = org.joda.time.format.DateTimeFormat.forPattern(format).withDefaultYear(Time.new.year)

will cause a problem when current year rolls over, because the filter will continue using the default year based on when the daemon was originally started, and not the current year.

[wiibaa]

Also discussed in elastic/logstash#2306

[jsvd]

This is a problem when parsing time formats that don't contain the year.
I don't think there's an elegant solution for now, since .withDefaultYear only takes an unboxed integer.
The fix is calculating the current year for each parse, changing line 172 to:
parsers << lambda { |date| joda_parser.withDefaultYear(Time.new.year).parseMillis(date) }

This might be too slow however...generating an extra time object and DateTimeParser for each parse action (each event). An alternative is somehow caching the year value, but still means an extra DateTimeParser for each event..

A last alternative might be appending the current year to the field before reaching the date filter,but might be slow as well, and not friendly at all....

[kiranos]

had this today, I use regular

    syslog_pri { }
    date {
      match => [ "syslog_timestamp", "MMM  d HH:mm:ss", "MMM dd HH:mm:ss" ]
    }

this seems to be the standard way of using date with syslog (from reading book, etc) A restart solved it and now logs are coming in as expected again.

[dshelepov]

Here is a possible solution. Set up a thread-local cache consisting of two [month, year] key-value pairs. When an event arrives whose month is already cached, just use the cached year. Otherwise, look up current year, evict the oldest row and replace it with newest tuple instead.

This approach will work well unless we receive events more than one month old (in which case they can be dated incorrectly if they are from the previous year), or if we can have several months of idle time between events, such that the month-value tuple from last year still persists in the cache on the event anniversary.

[jordansissel]

Logstash historical behavior noted here:

In the past, before I found withDefaultYear Logstash would look at the pattern and see no year and would know to inject the current year at parse-time:

• https://github.com/elasticsearch/logstash/blob/v1.1.13/lib/logstash/filters/date.rb#L156-L162
• https://github.com/elasticsearch/logstash/blob/v1.1.13/lib/logstash/filters/date.rb#L215-L233

The logic was, if the pattern had no 'y' then we force the year to be "now" at filtering time.

[jordansissel]

Here goes a little wild ride -"Hold on to your butts!" - https://www.youtube.com/watch?v=-W6as8oVcuM

The current behavior is not correct as many have noted. I also do not believe "use the current year" to be correct, either. I think the logic should be something like:

• Use the current year by default
• If the parsed timestamp is many months in the future from current real time, and there was no year in the pattern, then assume "last year"

This would allow for clock skew in this situation:

• Some server sends logstash a log with time 'Jan 1 00:00:01'
• Logstash receives, but is out of time sync by 2 minutes, so "now" is 'Dec 31 23:58:01'
• What year is it? I believe Logstash should parse this with the year a human would assume "Jan 1" occurs on, not the previous year "Dec 31" occurs.

The same skew could happen inverted where Logstash is "ahead" (Jan 1) in time and a remote server is behind (Dec 31)

The simplistic clock skew "year correction" doesn't work so well on backfill scenarios, though. If the Logstash server time is "Jan 1" and you are backfilling last-month's logs, surely "last year" is correct and "this year" is incorrect.

---

Bug Fix Proposal

I think we may need tunable behavior here - some kind of setting (on by default) that intelligently corrects for timestamps that are missing years.

Definitions:

• L-Time "Logstash server time".
• S-Time "Application server (log) time"

Preconditions:

• S-Time has no known year due to missing data (syslog timestamp, etc)
• L-Time has a known year.

Some proposal:

• The "Current Year" should always be S-Time's year
• If L-Time month is December, and S-Time is January, then set the event year to "L-Time year" + 1
• If L-Time month is January, and S-Time is December, then set the event year to "L-TIme year" - 1
• L-Time should be looked up each time we need to know what the current year is.
• New boolean setting compute_year_if_missing (default: enabled) which would do the year correction.
• If this setting is disabled, then always use "current year" according to L-Time

This allows for L and S nodes to have significant (small number of days) drift or lag and should still choose the correct year.

[wiibaa]

Adding my two cents for log backfilling use case, what if L-Time month is neither January or December and you need to backfill log of S-Time for last year (or even year-2)...
IMHO I would name the new setting on_missing_year with a string value that could take either a fixed year like 2013 or special values COMPUTE or CURRENT.
Thoughts?

[dshelepov]

•L-Time should be computed every time the filter is invoked (via Time.now)

Does Time.now() carry only a trivial perf cost? I don't know about Ruby, but in other languages that is often not the case. I'd be wary of making expensive system calls for every incoming event when a change in returned value is expected only once per month.

In my reasonably complex production configuration (branching logic, multiple grok filters, field rewrites, etc.), date filter is already by far the biggest CPU hog, taking up as much as 40% of CPU/wallclock in that particular logstash instance. I'd say date could already benefit from a little performance optimization; introducing even more non-trivial work on the critical path could be painful.

[jordansissel]

Does Time.now() carry only a trivial perf cost?

I will remove this implementation detail. It is not important for the discussion.

[jordansissel]

@dshelepov if you have performance concerns with the date filter, I would love to address them. Can you file a separate ticket with your observations, config, and maybe a sample log?

[dshelepov]

@jordansissel Sure, I'll be happy to file a perf-related ticket. I'll do it later this week. I can't provide my exact config due to NDAs, so I'll have to manually construct one and generate some example data that would illustrate an area for potential improvement.