fluent-bit
fluent-bit copied to clipboard
fluent
Parser ignoring timezone
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".
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.
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[bot] avatar](https://avatars.githubusercontent.com/in/15368?v=4 "Published by a pub.dev verified publisher"){kind=small}
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.
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.
This issue was closed because it has been stalled for 5 days with no activity.
This issue was closed because it has been stalled for 5 days with no activity.
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.
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.
This issue was closed because it has been stalled for 5 days with no activity.
This is still a problem. Perhaps a maintainer could add exempt-stale to this issue?
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?
@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
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.
This is due to Windows'
struct tmdoes 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
@cosmo0920 do you know if there was a workaround for this on Windows when implementing winevtlog?
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
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?
- https://docs.fluentbit.io/manual/pipeline/inputs/windows-event-log
- https://docs.fluentbit.io/manual/pipeline/inputs/windows-event-log-winevtlog
Is
in_winevtlogexpected to deprecatein_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.
Hello,
I did a ton of test, and the result is not great.
We are using the LUA from https://github.com/fluent/fluent-bit/issues/2941#issuecomment-1210907504
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.
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.
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.
I applied @igorpeshansky's idea and came up with a fix here. I'll clean up my commits and then open some PRs.