Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Parser ignoring timezone #2941

Closed
julianklose opened this issue Jan 13, 2021 · 25 comments · Fixed by #6319
Closed

Parser ignoring timezone #2941

julianklose opened this issue Jan 13, 2021 · 25 comments · Fixed by #6319
Assignees

Comments

@julianklose
Copy link

julianklose commented Jan 13, 2021

I'm using windows release td-agent-bit-1.6.10-win32. The parser is ignoring the timezone set in the logs.

Here a simple example using the default apache parser:

[PARSER]
    Name   apache
    Format regex
    Regex  ^(?<host>[^ ]*) [^ ]* (?<user>[^ ]*) \[(?<time>[^\]]*)\] "(?<method>\S+)(?: +(?<path>[^\"]*?)(?: +\S*)?)?" (?<code>[^ ]*) (?<size>[^ ]*)(?: "(?<referer>[^\"]*)" "(?<agent>[^\"]*)")?$
    Time_Key time
    Time_Format %d/%b/%Y:%H:%M:%S %z

[INPUT]
    name tail
    path /path/to/test.log
    parser apache
    tag  accesslog

[OUTPUT]
    name stdout
    match *

My logs:

192.168.178.23 test - [13/Jan/2021:10:30:31 -0100] "GET /rest HTTP/1.1" 200 59 "http://localhost/" "Mozilla/5.0"
192.168.178.23 test - [13/Jan/2021:10:30:31 +0000] "GET /rest HTTP/1.1" 200 59 "http://localhost/" "Mozilla/5.0"
192.168.178.23 test - [13/Jan/2021:10:30:31 +0100] "GET /rest HTTP/1.1" 200 59 "http://localhost/" "Mozilla/5.0"
192.168.178.23 test - [13/Jan/2021:10:30:31 +0200] "GET /rest HTTP/1.1" 200 59 "http://localhost/" "Mozilla/5.0"

The result:

[0] accesslog: [1610533831.000000000, {"host"=>"192.168.178.23", "user"=>"-", "method"=>"GET", "path"=>"/rest", "code"=>"200", "size"=>"59", "referer"=>"http://localhost/", "agent"=>"Mozilla/5.0"}]
[1] accesslog: [1610533831.000000000, {"host"=>"192.168.178.23", "user"=>"-", "method"=>"GET", "path"=>"/rest", "code"=>"200", "size"=>"59", "referer"=>"http://localhost/", "agent"=>"Mozilla/5.0"}]
[2] accesslog: [1610533831.000000000, {"host"=>"192.168.178.23", "user"=>"-", "method"=>"GET", "path"=>"/rest", "code"=>"200", "size"=>"59", "referer"=>"http://localhost/", "agent"=>"Mozilla/5.0"}]
[3] accesslog: [1610533831.000000000, {"host"=>"192.168.178.23", "user"=>"-", "method"=>"GET", "path"=>"/rest", "code"=>"200", "size"=>"59", "referer"=>"http://localhost/", "agent"=>"Mozilla/5.0"}]

As you can see, every entry was treated as if it was in "+0000".

@fujimotos
Copy link
Member

This is due to Windows' struct tm does not support GMTOFF.

While flb_strptime() does support the parsing of timezones, but
it cannot report back the parsed bit due to this restriction.

We'll need to add a special logic to retain timezone info on Windows.

@fujimotos fujimotos self-assigned this Jan 28, 2021
@github-actions
Copy link
Contributor

github-actions bot commented Mar 6, 2021

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 5 days.

@github-actions github-actions bot added the Stale label Mar 6, 2021
@julianklose
Copy link
Author

Will there be a fix? It is more or less unusable on Windows. I found a workaround using a lua filter but that is not a very good solution.

@github-actions github-actions bot removed the Stale label Mar 7, 2021
@github-actions
Copy link
Contributor

github-actions bot commented Apr 6, 2021

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 5 days.

@github-actions github-actions bot added the Stale label Apr 6, 2021
@github-actions
Copy link
Contributor

This issue was closed because it has been stalled for 5 days with no activity.

@fujimotos fujimotos reopened this Apr 13, 2021
@github-actions
Copy link
Contributor

This issue was closed because it has been stalled for 5 days with no activity.

@Sabari-Arunkumar-ML
Copy link

@fujimotos Any update on this?

@dkwdjq
Copy link

dkwdjq commented Dec 24, 2021

Any update on this

@dkwdjq
Copy link

dkwdjq commented Dec 24, 2021

help

@qingling128
Copy link
Collaborator

Looks like this remains an issue. Based on some investigation done by @franciscovalentecastro, it affects Windows users that uses a parser with time_format expecting a timezone different from UTC. We are using UTC as a workaround in our tests for now. Haven't heard about customer reports on our side. But it's probably just a matter of time.

@qingling128 qingling128 reopened this Mar 1, 2022
@github-actions github-actions bot removed the Stale label Mar 2, 2022
@github-actions
Copy link
Contributor

This issue is stale because it has been open 90 days with no activity. Remove stale label or comment or this will be closed in 5 days. Maintainers can add the exempt-stale label.

@github-actions github-actions bot added the Stale label May 31, 2022
@github-actions
Copy link
Contributor

github-actions bot commented Jun 6, 2022

This issue was closed because it has been stalled for 5 days with no activity.

@github-actions github-actions bot closed this as completed Jun 6, 2022
@braydonk
Copy link
Contributor

This is still a problem. Perhaps a maintainer could add exempt-stale to this issue?

@ThomasBeavers
Copy link

Will there be a fix? It is more or less unusable on Windows. I found a workaround using a lua filter but that is not a very good solution.

@julianklose Can you give an example of the workaround?

@julianklose
Copy link
Author

@ThomasBeavers My workaround:

[FILTER]
    Name lua
    Match *
    script filter.lua
    call correct_timezone

filter.lua:

function correct_timezone(tag, timestamp, record)
    local utcdate = os.date("!*t", timestamp)
    local localdate = os.date("*t", timestamp)
    localdate.isdst = false
    local offset = os.difftime(os.time(localdate), os.time(utcdate))
    return 1, timestamp - offset, record
end

@artheus
Copy link

artheus commented Aug 13, 2022

I am having this issue as well. I am running some test scenarios before starting to deploy to our environments.
Here is a CRI-O log that I'm using for testing

2022-01-01T12:00:00.29870211Z stdout F 2022-01-02 01:02:03.004 One log
2022-01-01T12:00:00.29870211Z stdout F 2022-03-04T01:02:03.004 Two log
2022-01-01T12:00:00.29870211Z stdout F 2022-05-06 01:02:03.004 +01:00 Three log
2022-01-01T12:00:00.29870211Z stdout F 2022-07-08 01:02:03.004Z+01:00 Four log
2022-01-01T12:00:00.29870211Z stdout F 2022-09-10T01:02:03.004 +01:00 Five log
2022-01-01T12:00:00.29870211Z stdout F 2022-11-12T01:02:03.004Z+01:00 Six log

The two first lines should be parsed, as if in my local time zone Europe/Stockholm, but they are parsed as GMT/UTC
Rest of the log lines actually have the tiime zone in them, which should be parsed correctly, but the time zone is ignored.

Here is my config files:

### fluent-bit.conf
[SERVICE]
    Daemon Off
    Flush 1
    Log_Level debug
    Parsers_File parsers.conf
    Parsers_File custom_parsers.conf
    HTTP_Server Off
    
[INPUT]
    Name tail
    Tag kube.*
    Path test/data/current_input.log
    multiline.parser cri
    Read_From_Head On
    Exit_On_EOF On
    Mem_Buf_Limit 5MB
    
[FILTER]
    Name record_modifier
    Match kube.*
    Remove_key _p
    
[FILTER]
    Name modify
    Match kube.*
    Rename time cri_time
    
[FILTER]
    Name multiline
    Alias multiline-go-python-java
    Match kube.*
    multiline.parser go, python, java
    
[FILTER]
    Name parser
    Alias msg-format-parser
    Match kube.*
    Key_Name log
    Preserve_Key On
    Reserve_Data On
    Parser json_logs
    Parser timed_logs_wt_wsz
    Parser timed_logs_nt_wsz
    Parser timed_logs_wt_wz
    Parser timed_logs_nt_wz
    Parser timed_logs_wt_nz
    Parser timed_logs_nt_nz
    
[FILTER]
    Name modify
    Match kube.*
    Condition Key_Does_Not_Exist time
    Condition Key_Exists cri_time
    Rename cri_time time
    
[FILTER]
    Name modify
    Match kube.*
    Remove cri_time
    
[OUTPUT]
    Name file
    Match *
    File test/output.log
 
### custom-parsers.log

[PARSER]
    Name        json_logs
    Format      json
    Time_Key    time
    Time_Format %Y-%m-%dT%H:%M:%S.%L%z
    
[PARSER]
    Name        timed_logs_nt_nz
    Format      regex
    Regex       ^(?<time>[0-9\-]+ [0-9\:]+\.[0-9]+).*$
    Time_Key    time
    Time_Format %Y-%m-%d %H:%M:%S.%L
    #Time_Offset +01:00
    Time_Keep   On
    
[PARSER]
    Name        timed_logs_wt_nz
    Format      regex
    Regex       ^(?<time>[0-9\-]+T[0-9\:]+\.[0-9]+).*$
    Time_Key    time
    Time_Format %Y-%m-%dT%H:%M:%S.%L
    #Time_Offset +01:00
    Time_Keep   On
    
[PARSER]
    Name        timed_logs_wt_wz
    Format      regex
    Regex       ^(?<time>[0-9\-]+T[0-9\:]+\.[0-9]+Z[\+\-][0-9:]+).*$
    Time_Key    time
    Time_Format %Y-%m-%dT%H:%M:%S.%L%z
    #Time_Offset +01:00
    Time_Keep   On
    
[PARSER]
    Name        timed_logs_nt_wz
    Format      regex
    Regex       ^(?<time>[0-9\-]+ [0-9\:]+\.[0-9]+Z[\+\-][0-9:]+).*$
    Time_Key    time
    Time_Format %Y-%m-%d %H:%M:%S.%L%z
    #Time_Offset +01:00
    Time_Keep   On
    
[PARSER]
    Name        timed_logs_nt_wsz
    Format      regex
    Regex       ^(?<time>[0-9\-]+ [0-9\:]+\.[0-9]+ [\+\-][0-9:]+).*$
    Time_Key    time
    Time_Format %Y-%m-%d %H:%M:%S.%L %z
    #Time_Offset +01:00
    Time_Keep   On
    
[PARSER]
    Name        timed_logs_wt_wsz
    Format      regex
    Regex       ^(?<time>[0-9\-]+T[0-9\:]+\.[0-9]+ [\+\-][0-9:]+).*$
    Time_Key    time
    Time_Format %Y-%m-%dT%H:%M:%S.%L %z
    #Time_Offset +01:00
    Time_Keep   On

I am running tests using bats-core. My test:

### time_prefixed_entries.bats

#!/usr/bin/env bats

load test_helper.bash

@test "time prefixed log entries should be parsed correctly" {
    setup_input "time-prefixed-entries.log"

    run fluent-bit -c charts/fluent-bit/build/conf/fluent-bit.conf
    [ "$status" -eq 0 ]

    assert_output_lines 6

    IFS=$'\n' # iterate lines instead of words
    output_lines="$(cat "$output_file")"

    for line in $output_lines
    do
      json_line="$(echo "$line" | cut -d ' ' -f 2-)"
      #NOTE: gdate is gnu-date app for mac
      TZ="Europe/Stockholm" gdate -d @"$(echo "$json_line" | jq '.[0]')" +%Y-%m-%dT%H:%M:%S.%N
      echo "$json_line" | jq '.[0]'
      echo "$json_line" | jq '.[1].time'
      echo "$json_line" | jq '.[1].log'
    done

    exit 1
}

### test_helper.bash

# global constants
git_root="$(git rev-parse --show-toplevel)"
output_file="$git_root/test/output.log"
input_file="$git_root/test/data/current_input.log"

readonly git_root
readonly output_file
readonly input_file

# setup & teardown
setup_input() { # - must be run manually
  cp "$git_root/test/data/$1" "$input_file"
}

# setup() {} - runs before each test

teardown() { # - runs after each test
  rm -f "$input_file"
  rm -f "$output_file"
}

# setup_file() {} - runs before each bats file
# teardown_file() {} - runs after each bats file

# setup_suite() {} - runs once before starting testing
# teardown_suite() {} - runs once after ending testing

# helper functions
error() {
  echo "$1"
  exit 1
}

assert_output_lines() {
  local expected_lines
  expected_lines="$1"

  local num_lines
  num_lines="$(wc -l < "$output_file" | xargs )"

  [ "$num_lines" -eq "$expected_lines" ] || error "expected 1 output lines, but got $num_lines"
}

assert_equal() {
  local expected
  local actual

  expected="$1"
  actual="$2"

  [ "$1" == "$2" ] || error "expected value $expected, but got $actual"
}

Here is the output, which shows the unexpected results:

.... omitted fluent-bit logs ....

   2022-01-02T02:02:03.004000000  # GNU date
   1641085323.004  # Epoch secs
   "2022-01-02 01:02:03.004"  # Record time key
   "2022-01-02 01:02:03.004 One log"  # Record log key

   2022-03-04T02:02:03.004000000  # GNU date
   1646355723.004  # Epoch secs
   "2022-03-04T01:02:03.004"  # Record time key
   "2022-03-04T01:02:03.004 Two log"  # Record log key

   2022-05-06T02:02:03.004000000  # GNU date
   1651795323.004  # Epoch secs
   "2022-05-06 01:02:03.004 +01:00"  # Record time key
   "2022-05-06 01:02:03.004 +01:00 Three log"  # Record log key

   2022-07-08T03:02:03.004000000  # GNU date
   1657242123.004  # Epoch secs
   "2022-07-08 01:02:03.004Z+01:00"  # Record time key
   "2022-07-08 01:02:03.004Z+01:00 Four log"  # Record log key

   2022-09-10T02:02:03.004000000  # GNU date
   1662768123.004  # Epoch secs
   "2022-09-10T01:02:03.004 +01:00"  # Record time key
   "2022-09-10T01:02:03.004 +01:00 Five log"  # Record log key

   2022-11-12T02:02:03.004000000  # GNU date
   1668214923.004  # Epoch secs
   "2022-11-12T01:02:03.004Z+01:00"  # Record time key
   "2022-11-12T01:02:03.004Z+01:00 Six log"  # Record log key

.... omitted test failure statement ....

With this setup, using fluent-bit version 1.9.7

$ fluent-bit -V
Fluent Bit v1.9.7
Git commit: 

This should be fully reproducible with the data I've provided here.

@artheus
Copy link

artheus commented Aug 13, 2022

This is due to Windows' struct tm does not support GMTOFF.

While flb_strptime() does support the parsing of timezones, but it cannot report back the parsed bit due to this restriction.

We'll need to add a special logic to retain timezone info on Windows.

My answer above is from macos which also seems to be affected by this.

EDIT: macos does support GMTOFF

@agup006
Copy link
Member

agup006 commented Aug 19, 2022

@cosmo0920 do you know if there was a workaround for this on Windows when implementing winevtlog?

@cosmo0920
Copy link
Contributor

On Windows, we can use TIME_ZONE_INFORMATION Related functions to adjust from UTC to local time:
Ref: https://learn.microsoft.com/ja-jp/windows/win32/api/timezoneapi/nf-timezoneapi-gettimezoneinformation

our usage: https://github.com/fluent/fluent-bit/blob/master/plugins/in_winevtlog/pack.c#L197

@qingling128
Copy link
Collaborator

Thanks for taking a look @cosmo0920 . Do I understand it correctly that if we use the winevtlog input plugin instead of in_winlog, the problem is solved?

Is in_winevtlog expected to deprecate in_winlog?

@cosmo0920
Copy link
Contributor

cosmo0920 commented Sep 20, 2022

Is in_winevtlog expected to deprecate in_winlog?

No, they are still supported like as fluent-plugin-windows-eventlog.
But, winlog uses a bit of old API to retrieve Windows EventLog.

Do I understand it correctly that if we use the winevtlog input plugin instead of in_winlog, the problem is solved?

Presumably, Yes. in_winevtlog uses localtime to emit its gathered EventLogs.

@BenoitPoulet
Copy link

Hello,

I did a ton of test, and the result is not great.

We are using the LUA from #2941 (comment)

And even with this, the sent timestamp is wrong, sometimes :

From the Fluentbit output :
[2] eventlogs: [1664975031.809980100, {"ProviderName"=>"Service Control Manager", "ProviderGuid"=>"{555908D1-A6D7-4695-8E1E-26931D2012F4}", "Qualifiers"=>16384, "EventID"=>7036, "Version"=>0, "Level"=>4, "Task"=>0, "Opcode"=>0, "Keywords"=>"0x8080000000000000", "TimeCreated"=>"2022-10-05 15:03:45 +0100", "EventRecordID"=>1102, "ActivityID"=>"", "RelatedActivityID"=>"", "ProcessID"=>568, "ThreadID"=>3136, "Channel"=>"System", "Computer"=>"piwv-monitoring-02", "UserID"=>"", "Message"=>"Le service Service Configuration du r├®seau est entr├® dans lÔÇÖ├®tat : en cours dÔÇÖex├®cution.", "StringInserts"=>["Service Configuration du r├®seau", "en cours dÔÇÖex├®cution", "4E0065007400530065007400750070005300760063002F0034000000"]}]

Capture from the destination Rsyslog :
{"timestamp_original":"2022-10-05T13:03:51+02:00", "host":"piwv-monitoring-02", "severity":"warning", "facility":"user", "programname":"Service", "procid":"-", "message":" Control Manager[7036]: Le service Service Configuration du réseau est entré dans l’état : en cours d’exécution."}

The timestamp received is not the same as the one seen in the stdout

sometime the right one is sent, sometimes not.

@jefferbrecht
Copy link
Contributor

We use winlog followed by a regex parser with Time_Format in order to overwrite the log record's timestamp.

Because winlog and winevtlog both format TimeGenerated and TimeWritten (or TimeCreated for winevtlog) as strings using local time zone data, we end up needing to do an additional parser step to overwrite the log record's timestamp, which isn't possible due to this bug: all of our users running winlog on machines with time zone offsets are getting logs with the wrong timestamps.

We identified a partial workaround for this, which is to set the environment variable TZ=UTC0 for the fluent-bit process. This forces winlog to format TimeGenerated/TimeWritten using a time zone offset of +0000 which sidesteps the bug. But this is not ideal because it's a process-wide variable that has other side effects as well (for example, the logs from fluent-bit are now timestamped as UTC rather than local time).

We also expose JSON and regex parsers to our users who are free to configure time formats including %z, and those parsers are broken with no workaround currently.

We really need a proper fix for this issue. Fundamentally it is a bug with the parsers. Switching to winevtlog will not help because it still formats TimeCreated as a local time with time zone offset.

@igorpeshansky
Copy link
Contributor

igorpeshansky commented Oct 6, 2022

We should be able to wrap struct tm into a fluent-bit-specific struct that adds timezone info on Windows (and other platforms that don't have tm_gmtoff), e.g.:

struct flb_tm {
  struct tm tm;
#ifndef FLB_HAVE_GMTOFF
  long int tm_gmtoff;
#endif
};

We can then use either tm->tm.tm_gmtoff when FLB_HAVE_GMTOFF is defined, or tm->tm_gmtoff when it's not.

@jefferbrecht
Copy link
Contributor

I applied @igorpeshansky's idea and came up with a fix here. I'll clean up my commits and then open some PRs.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.