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: fix time zone offsets being dropped on Windows #6368

Merged
merged 10 commits into from
Nov 22, 2022

Conversation

jefferbrecht
Copy link
Contributor

Backport of #6319 to 1.9.


Fix time zone offsets being lost on Windows when parsing time stamps.

Fixes #2941.


Testing
Before we can approve your change; please submit the following in a comment:

  • Example configuration file for the change
  • Debug log output from testing the change
  • Attached Valgrind output that shows no leaks or memory corruption was found

If this is a change to packaging of containers or native binaries then please confirm it works for all targets.

Documentation

  • Documentation required for this feature

Backporting

  • Backport to latest stable release.

Fluent Bit is licensed under Apache 2.0, by submitting this pull request I understand that this code will be released under the terms of that license.

This adds a unit test for parsing logs that contain time stamps with
a time zone offset.

This test deliberately fails on Windows; a subsequent commit fixes
the underlying issue and makes the test pass.

Signed-off-by: Jeff Erbrecht <jefferbrecht@google.com>
This wrapper struct adds an explicit time zone offset field on
platforms that do not include such a field within `struct tm`,
such as on Windows. This gives us a place to store parsed
time zone information so that we don't have to drop it.

Signed-off-by: Jeff Erbrecht <jefferbrecht@google.com>
This updates the parser APIs to use flb_tm..

Signed-off-by: Jeff Erbrecht <jefferbrecht@google.com>
This changes the strptime APIs to use flb_tm. Any implementation
conditional on FLB_HAVE_GMTOFF has been reverted since flb_tm
now has a field to store the time zone offset on all platforms.

Signed-off-by: Jeff Erbrecht <jefferbrecht@google.com>
Signed-off-by: Jeff Erbrecht <jefferbrecht@google.com>
Signed-off-by: Jeff Erbrecht <jefferbrecht@google.com>
Signed-off-by: Jeff Erbrecht <jefferbrecht@google.com>
Signed-off-by: Jeff Erbrecht <jefferbrecht@google.com>
Signed-off-by: Jeff Erbrecht <jefferbrecht@google.com>
@jefferbrecht jefferbrecht temporarily deployed to pr November 9, 2022 20:54 Inactive
@jefferbrecht jefferbrecht temporarily deployed to pr November 9, 2022 20:54 Inactive
@jefferbrecht
Copy link
Contributor Author

Example configuration

parsers.conf:

[PARSER]
        Name test
        Format json
        Time_Key time
        Time_Format %Y-%m-%dT%H:%M:%S %z

fluent-bit command line:

./bin/fluent-bit \
    -R parsers.conf \
    -i tail \
        -p path=test.txt \
        -p parser=test \
    -o stdout

Debug log output (Debian 10)

$ ./bin/fluent-bit \
    -R parsers.conf \
    -i tail \
        -p path=test.txt \
        -p parser=test \
    -o stdout \
    -v

Fluent Bit v1.9.9
* Copyright (C) 2015-2022 The Fluent Bit Authors
* Fluent Bit is a CNCF sub-project under the umbrella of Fluentd
* https://fluentbit.io

[2022/11/09 14:32:48] [ info] Configuration:
[2022/11/09 14:32:48] [ info]  flush time     | 1.000000 seconds
[2022/11/09 14:32:48] [ info]  grace          | 5 seconds
[2022/11/09 14:32:48] [ info]  daemon         | 0
[2022/11/09 14:32:48] [ info] ___________
[2022/11/09 14:32:48] [ info]  inputs:
[2022/11/09 14:32:48] [ info]      tail
[2022/11/09 14:32:48] [ info] ___________
[2022/11/09 14:32:48] [ info]  filters:
[2022/11/09 14:32:48] [ info] ___________
[2022/11/09 14:32:48] [ info]  outputs:
[2022/11/09 14:32:48] [ info]      stdout.0
[2022/11/09 14:32:48] [ info] ___________
[2022/11/09 14:32:48] [ info]  collectors:
[2022/11/09 14:32:48] [ info] [fluent bit] version=1.9.9, commit=c2af158058, pid=3763643
[2022/11/09 14:32:48] [debug] [engine] coroutine stack size: 24576 bytes (24.0K)
[2022/11/09 14:32:48] [ info] [storage] version=1.3.0, type=memory-only, sync=normal, checksum=disabled, max_chunks_up=128
[2022/11/09 14:32:48] [ info] [cmetrics] version=0.3.7
[2022/11/09 14:32:48] [debug] [tail:tail.0] created event channels: read=22 write=23
[2022/11/09 14:32:48] [debug] [input:tail:tail.0] flb_tail_fs_inotify_init() initializing inotify tail input
[2022/11/09 14:32:48] [debug] [input:tail:tail.0] inotify watch fd=28
[2022/11/09 14:32:48] [debug] [input:tail:tail.0] scanning path test.txt
[2022/11/09 14:32:48] [debug] [input:tail:tail.0] inode=9967726 with offset=174 appended as test.txt
[2022/11/09 14:32:48] [debug] [input:tail:tail.0] scan_glob add(): test.txt, inode 9967726
[2022/11/09 14:32:48] [debug] [input:tail:tail.0] 1 new files found on path 'test.txt'
[2022/11/09 14:32:48] [debug] [stdout:stdout.0] created event channels: read=30 write=31
[2022/11/09 14:32:48] [debug] [router] default match rule tail.0:stdout.0
[2022/11/09 14:32:48] [ info] [output:stdout:stdout.0] worker #0 started
[2022/11/09 14:32:48] [ info] [sp] stream processor started
[2022/11/09 14:32:48] [debug] [input:tail:tail.0] inode=9967726 file=test.txt promote to TAIL_EVENT
[2022/11/09 14:32:48] [ info] [input:tail:tail.0] inotify_fs_add(): inode=9967726 watch_fd=1 name=test.txt
[2022/11/09 14:32:48] [debug] [input:tail:tail.0] [static files] processed 0b, done
[2022/11/09 14:32:52] [debug] [input:tail:tail.0] inode=9967726 events: IN_MODIFY
[2022/11/09 14:32:52] [debug] [input chunk] update output instances with new chunk size diff=25
[2022/11/09 14:32:52] [debug] [task] created task=0x7f750c023880 id=0 OK
[2022/11/09 14:32:52] [debug] [output:stdout:stdout.0] task_id=0 assigned to thread #0
[0] tail.0: [1509589521.000000000, {"message"=>"test"}]
[2022/11/09 14:32:52] [debug] [out flush] cb_destroy coro_id=0
[2022/11/09 14:32:52] [debug] [task] destroy task=0x7f750c023880 (task_id=0)
^C[2022/11/09 14:32:53] [engine] caught signal (SIGINT)
[2022/11/09 14:32:53] [ info] [input] pausing tail.0
[2022/11/09 14:32:53] [ warn] [engine] service will shutdown in max 5 seconds
[2022/11/09 14:32:54] [ info] [engine] service has stopped (0 pending tasks)
[2022/11/09 14:32:54] [debug] [input:tail:tail.0] inode=9967726 removing file name test.txt
[2022/11/09 14:32:54] [ info] [input:tail:tail.0] inotify_fs_remove(): inode=9967726 watch_fd=1
[2022/11/09 14:32:54] [ info] [output:stdout:stdout.0] thread worker #0 stopping...
[2022/11/09 14:32:54] [ info] [output:stdout:stdout.0] thread worker #0 stopped

Debug log output (Windows Server 2019)

$ ./bin/Release/fluent-bit.exe \
    -R parsers.conf \
    -i tail \
        -p path=test.txt \
        -p parser=test \
    -o stdout \
    -v

Fluent Bit v1.9.9
* Copyright (C) 2015-2022 The Fluent Bit Authors
* Fluent Bit is a CNCF sub-project under the umbrella of Fluentd
* https://fluentbit.io

[2022/11/09 14:11:37] [ info] Configuration:
[2022/11/09 14:11:37] [ info]  flush time     | 1.000000 seconds
[2022/11/09 14:11:37] [ info]  grace          | 5 seconds
[2022/11/09 14:11:37] [ info]  daemon         | 0
[2022/11/09 14:11:37] [ info] ___________
[2022/11/09 14:11:37] [ info]  inputs:
[2022/11/09 14:11:37] [ info]      tail
[2022/11/09 14:11:37] [ info] ___________
[2022/11/09 14:11:37] [ info]  filters:
[2022/11/09 14:11:37] [ info] ___________
[2022/11/09 14:11:37] [ info]  outputs:
[2022/11/09 14:11:37] [ info]      stdout.0
[2022/11/09 14:11:37] [ info] ___________
[2022/11/09 14:11:37] [ info]  collectors:
[2022/11/09 14:11:37] [ info] [fluent bit] version=1.9.9, commit=c2af158058, pid=5560
[2022/11/09 14:11:37] [debug] [engine] coroutine stack size: 98302 bytes (96.0K)
[2022/11/09 14:11:37] [ info] [storage] version=1.3.0, type=memory-only, sync=normal, checksum=disabled, max_chunks_up=128
[2022/11/09 14:11:37] [ info] [cmetrics] version=0.3.7
[2022/11/09 14:11:37] [debug] [tail:tail.0] created event channels: read=704 write=708
[2022/11/09 14:11:37] [debug] [input:tail:tail.0] flb_tail_fs_stat_init() initializing stat tail input
[2022/11/09 14:11:37] [debug] [input:tail:tail.0] inode=5910974511020940 with offset=189 appended as C:\Users\jefferbrecht\go\src\github.com\jefferbrecht\fluent-bit\build\test.txt
[2022/11/09 14:11:37] [debug] [input:tail:tail.0] 1 new files found on path 'test.txt'
[2022/11/09 14:11:37] [debug] [stdout:stdout.0] created event channels: read=732 write=736
[2022/11/09 14:11:37] [debug] [router] default match rule tail.0:stdout.0
[2022/11/09 14:11:37] [ info] [sp] stream processor started
[2022/11/09 14:11:37] [debug] [input:tail:tail.0] inode=5910974511020940 file=C:\Users\jefferbrecht\go\src\github.com\jefferbrecht\fluent-bit\build\test.txt promote to TAIL_EVENT
[2022/11/09 14:11:37] [debug] [input:tail:tail.0] [static files] processed 0b, done
[2022/11/09 14:11:37] [ info] [output:stdout:stdout.0] worker #0 started
[2022/11/09 14:12:37] [debug] [input:tail:tail.0] 0 new files found on path 'test.txt'
[2022/11/09 14:12:40] [debug] [input chunk] update output instances with new chunk size diff=25
[2022/11/09 14:12:41] [debug] [task] created task=000001FE74B4F6E0 id=0 OK
[2022/11/09 14:12:41] [debug] [output:stdout:stdout.0] task_id=0 assigned to thread #0
[0] tail.0: [1509589521.000000000, {"message"=>"test"}]
[2022/11/09 14:12:41] [debug] [out flush] cb_destroy coro_id=0
[2022/11/09 14:12:41] [debug] [task] destroy task=000001FE74B4F6E0 (task_id=0)
[2022/11/09 14:13:09] [engine] caught signal (SIGINT)
[2022/11/09 14:13:09] [ info] [input] pausing tail.0
[2022/11/09 14:13:09] [ warn] [engine] service will shutdown in max 5 seconds
[2022/11/09 14:13:10] [ info] [engine] service has stopped (0 pending tasks)
[2022/11/09 14:13:10] [debug] [input:tail:tail.0] inode=5910974511020940 removing file name C:\Users\jefferbrecht\go\src\github.com\jefferbrecht\fluent-bit\build\test.txt
[2022/11/09 14:13:10] [ info] [output:stdout:stdout.0] thread worker #0 stopping...
[2022/11/09 14:13:10] [ info] [output:stdout:stdout.0] thread worker #0 stopped

valgrind output

$ valgrind ./bin/fluent-bit \
    -R parsers.conf \
    -i tail \
        -p path=test.txt \
        -p parser=test \
    -o stdout \
    -v

==3772014== Memcheck, a memory error detector
==3772014== Copyright (C) 2002-2022, and GNU GPL'd, by Julian Seward et al.
==3772014== Using Valgrind-3.19.0 and LibVEX; rerun with -h for copyright info
==3772014== Command: ./bin/fluent-bit -R parsers.conf -i tail -p path=test.txt -p parser=test -o stdout -v
==3772014==
Fluent Bit v1.9.9
* Copyright (C) 2015-2022 The Fluent Bit Authors
* Fluent Bit is a CNCF sub-project under the umbrella of Fluentd
* https://fluentbit.io

[2022/11/09 15:45:37] [ info] Configuration:
[2022/11/09 15:45:37] [ info]  flush time     | 1.000000 seconds
[2022/11/09 15:45:37] [ info]  grace          | 5 seconds
[2022/11/09 15:45:37] [ info]  daemon         | 0
[2022/11/09 15:45:37] [ info] ___________
[2022/11/09 15:45:37] [ info]  inputs:
[2022/11/09 15:45:37] [ info]      tail
[2022/11/09 15:45:37] [ info] ___________
[2022/11/09 15:45:37] [ info]  filters:
[2022/11/09 15:45:37] [ info] ___________
[2022/11/09 15:45:37] [ info]  outputs:
[2022/11/09 15:45:37] [ info]      stdout.0
[2022/11/09 15:45:37] [ info] ___________
[2022/11/09 15:45:37] [ info]  collectors:
[2022/11/09 15:45:37] [ info] [fluent bit] version=1.9.9, commit=c2af158058, pid=3772014
[2022/11/09 15:45:37] [debug] [engine] coroutine stack size: 24576 bytes (24.0K)
[2022/11/09 15:45:37] [ info] [storage] version=1.3.0, type=memory-only, sync=normal, checksum=disabled, max_chunks_up=128
[2022/11/09 15:45:37] [ info] [cmetrics] version=0.3.7
[2022/11/09 15:45:37] [debug] [tail:tail.0] created event channels: read=22 write=23
[2022/11/09 15:45:37] [debug] [input:tail:tail.0] flb_tail_fs_inotify_init() initializing inotify tail input
[2022/11/09 15:45:37] [debug] [input:tail:tail.0] inotify watch fd=28
[2022/11/09 15:45:37] [debug] [input:tail:tail.0] scanning path test.txt
[2022/11/09 15:45:37] [debug] [input:tail:tail.0] inode=9967726 with offset=290 appended as test.txt
[2022/11/09 15:45:37] [debug] [input:tail:tail.0] scan_glob add(): test.txt, inode 9967726
[2022/11/09 15:45:38] [ info] [output:stdout:stdout.0] worker #0 started
[2022/11/09 15:45:37] [debug] [input:tail:tail.0] 1 new files found on path 'test.txt'
[2022/11/09 15:45:37] [debug] [stdout:stdout.0] created event channels: read=30 write=31
[2022/11/09 15:45:37] [debug] [router] default match rule tail.0:stdout.0
[2022/11/09 15:45:37] [ info] [sp] stream processor started
[2022/11/09 15:45:38] [debug] [input:tail:tail.0] inode=9967726 file=test.txt promote to TAIL_EVENT
[2022/11/09 15:45:38] [ info] [input:tail:tail.0] inotify_fs_add(): inode=9967726 watch_fd=1 name=test.txt
[2022/11/09 15:45:38] [debug] [input:tail:tail.0] [static files] processed 0b, done
[2022/11/09 15:45:41] [debug] [input:tail:tail.0] inode=9967726 events: IN_MODIFY
[2022/11/09 15:45:41] [debug] [input chunk] update output instances with new chunk size diff=25
[2022/11/09 15:45:42] [debug] [task] created task=0x51cecf0 id=0 OK
[2022/11/09 15:45:42] [debug] [output:stdout:stdout.0] task_id=0 assigned to thread #0
[0] tail.0: [1509589521.000000000, {"message"=>"test"}]
[2022/11/09 15:45:42] [debug] [out flush] cb_destroy coro_id=0
[2022/11/09 15:45:42] [debug] [task] destroy task=0x51cecf0 (task_id=0)
^C[2022/11/09 15:45:44] [engine] caught signal (SIGINT)
[2022/11/09 15:45:44] [ info] [input] pausing tail.0
[2022/11/09 15:45:44] [ warn] [engine] service will shutdown in max 5 seconds
[2022/11/09 15:45:45] [ info] [engine] service has stopped (0 pending tasks)
[2022/11/09 15:45:45] [debug] [input:tail:tail.0] inode=9967726 removing file name test.txt
[2022/11/09 15:45:45] [ info] [input:tail:tail.0] inotify_fs_remove(): inode=9967726 watch_fd=1
[2022/11/09 15:45:45] [ info] [output:stdout:stdout.0] thread worker #0 stopping...
[2022/11/09 15:45:45] [ info] [output:stdout:stdout.0] thread worker #0 stopped
==3772014==
==3772014== HEAP SUMMARY:
==3772014==     in use at exit: 66,765 bytes in 2,284 blocks
==3772014==   total heap usage: 4,411 allocs, 2,127 frees, 908,792 bytes allocated
==3772014==
==3772014== LEAK SUMMARY:
==3772014==    definitely lost: 0 bytes in 0 blocks
==3772014==    indirectly lost: 0 bytes in 0 blocks
==3772014==      possibly lost: 0 bytes in 0 blocks
==3772014==    still reachable: 66,765 bytes in 2,284 blocks
==3772014==         suppressed: 0 bytes in 0 blocks
==3772014== Rerun with --leak-check=full to see details of leaked memory
==3772014==
==3772014== For lists of detected and suppressed errors, rerun with: -s
==3772014== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)

Note: The same leak is reported by valgrind on 1.9.

@jefferbrecht jefferbrecht temporarily deployed to pr November 9, 2022 21:11 Inactive
Signed-off-by: Jeff Erbrecht <jefferbrecht@google.com>
@jefferbrecht jefferbrecht temporarily deployed to pr November 9, 2022 21:18 Inactive
@jefferbrecht jefferbrecht temporarily deployed to pr November 9, 2022 21:18 Inactive
@jefferbrecht jefferbrecht temporarily deployed to pr November 9, 2022 21:34 Inactive
@lubingfeng
Copy link

Good to see your fix on this issue, @jefferbrecht. Look forward to seeing this one gets merged into 1.9.x.

@lubingfeng
Copy link

@edsiper @leonardo-albertovich @fujimotos @koleini I am wondering when you can help review the fix.

@lubingfeng
Copy link

Any update on this one?

@edsiper edsiper merged commit cae9a8f into fluent:1.9 Nov 22, 2022
@BenoitPoulet
Copy link

Hello,

In which build can we have this patch ?

Is it available in the 2.0.6 released some days ago ?

Thanks

@PettitWesley
Copy link
Contributor

@edsiper How come I don't see this in the release notes for 1.9.10?

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

Successfully merging this pull request may close these issues.

5 participants