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.

Sign up for GitHub

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

Jump to bottom

in_tail: fix symlink log rotation for fs_stat on linux #2052

Merged
merged 1 commit into from
May 1, 2020
Merged

in_tail: fix symlink log rotation for fs_stat on linux #2052

merged 1 commit into from
May 1, 2020

Conversation

zackwine
Copy link
Contributor

@zackwine zackwine commented Mar 26, 2020 •
edited
Loading

When compiled with FLB_HAVE_INOTIFY=no for linux, records were continuously
resent if the files in PATH are symlinks. This patch ensures the fs_stat file
monitoring correctly handles symlinks when checking for file rotations.

The issue was found when running fluentbit as a daemonset in kubernetes where all
files in /var/log/containers/* are symlinks.

This patch was tested by forwarding 1M records of 1K size when compiled with
both FLB_HAVE_INOTIFY=no/yes and verifying the output metrics reported exactly
1M records. The test was executed by running a container logging to stdout
in a kubernetes cluster where symlinks are the target input. Further docker
was configured to rotate logs at 10M to ensure multiple file rotations
occurred.

Signed-off-by: Zack Wine [email protected]

Enter [N/A] in the box, if an item is not applicable to your change.

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

Documentation

  • [NA] Documentation required for this feature

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.

@zackwine
in_tail: fix symlink log rotation for fs_stat on linux
955fb09 
When compiled with FLB_HAVE_INOTIFY=no for linux records were continuously
resent if the files in PATH are symlinks.  This patch ensures the fs_stat file
monitoring correctly handles symlinks when checking for file rotations.

The issue was found when running fluentbit as a daemonset in kubernetes where all
files in /var/log/containers/* are symlinks.

This patch was tested by forwarding 1M records of 1K size when compiled with
both FLB_HAVE_INOTIFY=no/yes and verifying the output metrics reported exactly
1M records.  The test was executed by running a container logging to stdout
in a kubernetes cluster where symlinks are the target input.  Further docker
was configured to rotate logs at 10M to ensure multiple file rotations
occurred.

Signed-off-by: Zack Wine <[email protected]>
@edsiper edsiper requested a review from fujimotos March 26, 2020 18:26
@zackwine
Copy link
Contributor Author

fluent-bit.conf

[SERVICE]
  Flush 1
  Daemon Off
  Log_Level debug
  Parsers_File parsers.conf

  # HTTP Server
  # ===========
  # Enable/Disable the built-in HTTP Server for metrics
  HTTP_Server  On
  HTTP_Listen  0.0.0.0
  HTTP_PORT    24231

[INPUT]
  Name tail
  Path /var/log/containers/*.log
  Parser docker
  Tag kube.*
  Mem_Buf_Limit 5MB
  Refresh_Interval  5
  Rotate_Wait       5

[OUTPUT]
  Name stdout
  Match *

Debug log simulating 3 log rotations:

root@bd31b68b9de1:/fluent-bit/etc# /fluent-bit/bin/fluent-bit -c fluent-bit.conf 
Fluent Bit v1.5.0
* Copyright (C) 2019-2020 The Fluent Bit Authors
* Copyright (C) 2015-2018 Treasure Data
* Fluent Bit is a CNCF sub-project under the umbrella of Fluentd
* https://fluentbit.io

[2020/03/26 19:26:34] [ info] Configuration:
[2020/03/26 19:26:34] [ info]  flush time     | 1.000000 seconds
[2020/03/26 19:26:34] [ info]  grace          | 5 seconds
[2020/03/26 19:26:34] [ info]  daemon         | 0
[2020/03/26 19:26:34] [ info] ___________
[2020/03/26 19:26:34] [ info]  inputs:
[2020/03/26 19:26:34] [ info]      tail
[2020/03/26 19:26:34] [ info] ___________
[2020/03/26 19:26:34] [ info]  filters:
[2020/03/26 19:26:34] [ info] ___________
[2020/03/26 19:26:34] [ info]  outputs:
[2020/03/26 19:26:34] [ info]      stdout.0
[2020/03/26 19:26:34] [ info] ___________
[2020/03/26 19:26:34] [ info]  collectors:
[2020/03/26 19:26:34] [debug] [storage] [cio stream] new stream registered: tail.0
[2020/03/26 19:26:34] [ info] [storage] version=1.0.3, initializing...
[2020/03/26 19:26:34] [ info] [storage] in-memory
[2020/03/26 19:26:34] [ info] [storage] normal synchronization mode, checksum disabled, max_chunks_up=128
[2020/03/26 19:26:34] [ info] [engine] started (pid=184)
[2020/03/26 19:26:34] [debug] [engine] coroutine stack size: 24576 bytes (24.0K)
[2020/03/26 19:26:34] [debug] [input:tail:tail.0] scanning path /var/log/containers/*.log
[2020/03/26 19:26:34] [debug] [input:tail:tail.0] cannot read info from: /var/log/containers/*.log
[2020/03/26 19:26:34] [debug] [router] match rule tail.0:stdout.0
[2020/03/26 19:26:34] [ info] [http_server] listen iface=0.0.0.0 tcp_port=24231
[2020/03/26 19:26:34] [ info] [sp] stream processor started
[2020/03/26 19:31:53] [debug] [input:tail:tail.0] add to scan queue /var/log/containers/link-fake.log, offset=0
[2020/03/26 19:31:53] [debug] [input:tail:tail.0] append new file: /var/log/containers/link-fake.log
[2020/03/26 19:31:53] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log promote to TAIL_EVENT
[2020/03/26 19:32:52] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log collect event
[2020/03/26 19:32:52] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log read=1460 lines=10
[0] kube.var.log.containers.link-fake.log: [1585251172.500415200, {"log"=>"timestamp=2020-03-26T19:32:52+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=0"}]
[1] kube.var.log.containers.link-fake.log: [1585251172.500431100, {"log"=>"timestamp=2020-03-26T19:32:52+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=1"}]
[2] kube.var.log.containers.link-fake.log: [1585251172.500442400, {"log"=>"timestamp=2020-03-26T19:32:52+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=2"}]
[3] kube.var.log.containers.link-fake.log: [1585251172.500453800, {"log"=>"timestamp=2020-03-26T19:32:52+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=3"}]
[4] kube.var.log.containers.link-fake.log: [1585251172.500464900, {"log"=>"timestamp=2020-03-26T19:32:52+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=4"}]
[5] kube.var.log.containers.link-fake.log: [1585251172.500476000, {"log"=>"timestamp=2020-03-26T19:32:52+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=5"}]
[6] kube.var.log.containers.link-fake.log: [1585251172.500487000, {"log"=>"timestamp=2020-03-26T19:32:52+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=6"}]
[7] kube.var.log.containers.link-fake.log: [1585251172.500498100, {"log"=>"timestamp=2020-03-26T19:32:52+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=7"}]
[8] kube.var.log.containers.link-fake.log: [1585251172.500509200, {"log"=>"timestamp=2020-03-26T19:32:52+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=8"}]
[9] kube.var.log.containers.link-fake.log: [1585251172.500520300, {"log"=>"timestamp=2020-03-26T19:32:52+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=9"}]
[2020/03/26 19:32:52] [debug] [task] created task=0x7f3427230980 id=0 OK
[2020/03/26 19:32:52] [debug] [task] destroy task=0x7f3427230980 (task_id=0)
[2020/03/26 19:33:48] [debug] [input:tail:tail.0] file rotated: /var/log/containers/link-fake.log -> /var/log/fake-logs/fake.log.1
[2020/03/26 19:33:48] [debug] [input:tail:tail.0] scanning path /var/log/containers/*.log
[2020/03/26 19:33:48] [debug] [input:tail:tail.0] add to scan queue /var/log/containers/link-fake.log, offset=0
[2020/03/26 19:33:48] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log promote to TAIL_EVENT
[2020/03/26 19:33:53] [debug] [input:tail:tail.0] purge rotated file /var/log/fake-logs/fake.log.1
[2020/03/26 19:35:41] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log collect event
[2020/03/26 19:35:41] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log read=292 lines=2
[2020/03/26 19:35:41] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log collect event
[2020/03/26 19:35:41] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log read=1168 lines=8
[0] kube.var.log.containers.link-fake.log: [1585251341.500277400, {"log"=>"timestamp=2020-03-26T19:35:41+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=0"}]
[1] kube.var.log.containers.link-fake.log: [1585251341.500286900, {"log"=>"timestamp=2020-03-26T19:35:41+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=1"}]
[2] kube.var.log.containers.link-fake.log: [1585251341.750510300, {"log"=>"timestamp=2020-03-26T19:35:41+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=2"}]
[3] kube.var.log.containers.link-fake.log: [1585251341.750531100, {"log"=>"timestamp=2020-03-26T19:35:41+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=3"}]
[4] kube.var.log.containers.link-fake.log: [1585251341.750548700, {"log"=>"timestamp=2020-03-26T19:35:41+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=4"}]
[5] kube.var.log.containers.link-fake.log: [1585251341.750566300, {"log"=>"timestamp=2020-03-26T19:35:41+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=5"}]
[6] kube.var.log.containers.link-fake.log: [1585251341.750584200, {"log"=>"timestamp=2020-03-26T19:35:41+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=6"}]
[7] kube.var.log.containers.link-fake.log: [1585251341.750617500, {"log"=>"timestamp=2020-03-26T19:35:41+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=7"}]
[8] kube.var.log.containers.link-fake.log: [1585251341.750635400, {"log"=>"timestamp=2020-03-26T19:35:41+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=8"}]
[9] kube.var.log.containers.link-fake.log: [1585251341.750825600, {"log"=>"timestamp=2020-03-26T19:35:41+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=9"}]
[2020/03/26 19:35:42] [debug] [task] created task=0x7f34272308e0 id=0 OK
[2020/03/26 19:35:42] [debug] [task] destroy task=0x7f34272308e0 (task_id=0)
[2020/03/26 19:36:55] [debug] [input:tail:tail.0] file rotated: /var/log/containers/link-fake.log -> /var/log/fake-logs/fake.log.1
[2020/03/26 19:36:55] [debug] [input:tail:tail.0] scanning path /var/log/containers/*.log
[2020/03/26 19:36:55] [debug] [input:tail:tail.0] add to scan queue /var/log/containers/link-fake.log, offset=0
[2020/03/26 19:36:55] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log promote to TAIL_EVENT
[2020/03/26 19:37:01] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log collect event
[2020/03/26 19:37:01] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log read=1460 lines=10
[0] kube.var.log.containers.link-fake.log: [1585251421.500469400, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=0"}]
[1] kube.var.log.containers.link-fake.log: [1585251421.500482800, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=1"}]
[2] kube.var.log.containers.link-fake.log: [1585251421.500494100, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=2"}]
[3] kube.var.log.containers.link-fake.log: [1585251421.500505200, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=3"}]
[4] kube.var.log.containers.link-fake.log: [1585251421.500516600, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=4"}]
[5] kube.var.log.containers.link-fake.log: [1585251421.500527700, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=5"}]
[6] kube.var.log.containers.link-fake.log: [1585251421.500538800, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=6"}]
[7] kube.var.log.containers.link-fake.log: [1585251421.500549800, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=7"}]
[8] kube.var.log.containers.link-fake.log: [1585251421.500558300, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=8"}]
[9] kube.var.log.containers.link-fake.log: [1585251421.500568300, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=9"}]
[2020/03/26 19:37:01] [debug] [task] created task=0x7f3427230b60 id=0 OK
[2020/03/26 19:37:01] [debug] [task] destroy task=0x7f3427230b60 (task_id=0)
[2020/03/26 19:37:03] [debug] [input:tail:tail.0] purge rotated file /var/log/fake-logs/fake.log.1

@zackwine
Copy link
Contributor Author

Valgrind results:

root@bd31b68b9de1:/fluent-bit/etc# valgrind /fluent-bit/bin/fluent-bit -c fluent-bit.conf 
==364== Memcheck, a memory error detector
==364== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==364== Using Valgrind-3.14.0 and LibVEX; rerun with -h for copyright info
==364== Command: /fluent-bit/bin/fluent-bit -c fluent-bit.conf
==364== 
Fluent Bit v1.5.0
* Copyright (C) 2019-2020 The Fluent Bit Authors
* Copyright (C) 2015-2018 Treasure Data
* Fluent Bit is a CNCF sub-project under the umbrella of Fluentd
* https://fluentbit.io

[2020/03/26 19:39:50] [ info] Configuration:
[2020/03/26 19:39:50] [ info]  flush time     | 1.000000 seconds
[2020/03/26 19:39:50] [ info]  grace          | 5 seconds
[2020/03/26 19:39:50] [ info]  daemon         | 0
[2020/03/26 19:39:50] [ info] ___________
[2020/03/26 19:39:50] [ info]  inputs:
[2020/03/26 19:39:50] [ info]      tail
[2020/03/26 19:39:50] [ info] ___________
[2020/03/26 19:39:50] [ info]  filters:
[2020/03/26 19:39:50] [ info] ___________
[2020/03/26 19:39:50] [ info]  outputs:
[2020/03/26 19:39:50] [ info]      stdout.0
[2020/03/26 19:39:50] [ info] ___________
[2020/03/26 19:39:50] [ info]  collectors:
[2020/03/26 19:39:50] [debug] [storage] [cio stream] new stream registered: tail.0
[2020/03/26 19:39:50] [ info] [storage] version=1.0.3, initializing...
[2020/03/26 19:39:50] [ info] [storage] in-memory
[2020/03/26 19:39:50] [ info] [storage] normal synchronization mode, checksum disabled, max_chunks_up=128
[2020/03/26 19:39:50] [ info] [engine] started (pid=364)
[2020/03/26 19:39:50] [debug] [engine] coroutine stack size: 24576 bytes (24.0K)
[2020/03/26 19:39:50] [debug] [input:tail:tail.0] scanning path /var/log/containers/*.log
[2020/03/26 19:39:50] [debug] [input:tail:tail.0] add to scan queue /var/log/containers/link-fake.log, offset=0
[2020/03/26 19:39:50] [debug] [router] match rule tail.0:stdout.0
[2020/03/26 19:39:50] [ info] [http_server] listen iface=0.0.0.0 tcp_port=24231
[2020/03/26 19:39:50] [ info] [sp] stream processor started
[2020/03/26 19:39:50] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log read=1460 lines=10
[2020/03/26 19:39:50] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log promote to TAIL_EVENT
[0] kube.var.log.containers.link-fake.log: [1585251590.943116200, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=0"}]
[1] kube.var.log.containers.link-fake.log: [1585251590.948963000, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=1"}]
[2] kube.var.log.containers.link-fake.log: [1585251590.949033800, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=2"}]
[3] kube.var.log.containers.link-fake.log: [1585251590.949183900, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=3"}]
[4] kube.var.log.containers.link-fake.log: [1585251590.949241300, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=4"}]
[5] kube.var.log.containers.link-fake.log: [1585251590.949299400, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=5"}]
[6] kube.var.log.containers.link-fake.log: [1585251590.949356500, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=6"}]
[7] kube.var.log.containers.link-fake.log: [1585251590.949440200, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=7"}]
[2020/03/26 19:39:51] [debug] [task] created task=0x5eb2930 id=0 OK
[8] kube.var.log.containers.link-fake.log: [1585251590.949506900, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=8"}]
[9] kube.var.log.containers.link-fake.log: [1585251590.949581700, {"log"=>"timestamp=2020-03-26T19:37:01+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=9"}]
[2020/03/26 19:39:51] [debug] [task] destroy task=0x5eb2930 (task_id=0)
[2020/03/26 19:40:04] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log collect event
[2020/03/26 19:40:04] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log read=1460 lines=10
[0] kube.var.log.containers.link-fake.log: [1585251604.252725400, {"log"=>"timestamp=2020-03-26T19:40:04+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=0"}]
[1] kube.var.log.containers.link-fake.log: [1585251604.252817500, {"log"=>"timestamp=2020-03-26T19:40:04+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=1"}]
[2] kube.var.log.containers.link-fake.log: [1585251604.252937600, {"log"=>"timestamp=2020-03-26T19:40:04+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=2"}]
[3] kube.var.log.containers.link-fake.log: [1585251604.253015600, {"log"=>"timestamp=2020-03-26T19:40:04+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=3"}]
[4] kube.var.log.containers.link-fake.log: [1585251604.253096800, {"log"=>"timestamp=2020-03-26T19:40:04+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=4"}]
[5] kube.var.log.containers.link-fake.log: [1585251604.253266700, {"log"=>"timestamp=2020-03-26T19:40:04+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=5"}]
[6] kube.var.log.containers.link-fake.log: [1585251604.253386600, {"log"=>"timestamp=2020-03-26T19:40:04+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=6"}]
[2020/03/26 19:40:04] [debug] [task] created task=0x5fbb560 id=0 OK
[7] kube.var.log.containers.link-fake.log: [1585251604.253464300, {"log"=>"timestamp=2020-03-26T19:40:04+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=7"}]
[8] kube.var.log.containers.link-fake.log: [1585251604.253549300, {"log"=>"timestamp=2020-03-26T19:40:04+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=8"}]
[9] kube.var.log.containers.link-fake.log: [1585251604.253652500, {"log"=>"timestamp=2020-03-26T19:40:04+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=9"}]
[2020/03/26 19:40:05] [debug] [task] destroy task=0x5fbb560 (task_id=0)
[2020/03/26 19:40:14] [debug] [input:tail:tail.0] file rotated: /var/log/containers/link-fake.log -> /var/log/fake-logs/fake.log.1
[2020/03/26 19:40:14] [debug] [input:tail:tail.0] scanning path /var/log/containers/*.log
[2020/03/26 19:40:14] [debug] [input:tail:tail.0] add to scan queue /var/log/containers/link-fake.log, offset=0
[2020/03/26 19:40:14] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log promote to TAIL_EVENT
[2020/03/26 19:40:19] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log collect event
[2020/03/26 19:40:19] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log read=1314 lines=9
[0] kube.var.log.containers.link-fake.log: [1585251619.750745900, {"log"=>"timestamp=2020-03-26T19:40:19+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=0"}]
[1] kube.var.log.containers.link-fake.log: [1585251619.750829200, {"log"=>"timestamp=2020-03-26T19:40:19+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=1"}]
[2020/03/26 19:40:20] [debug] [input:tail:tail.0] purge rotated file /var/log/fake-logs/fake.log.1
[2020/03/26 19:40:20] [debug] [task] created task=0x60e0110 id=0 OK
[2] kube.var.log.containers.link-fake.log: [1585251619.750890400, {"log"=>"timestamp=2020-03-26T19:40:19+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=2"}]
[3] kube.var.log.containers.link-fake.log: [1585251619.750947600, {"log"=>"timestamp=2020-03-26T19:40:19+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=3"}]
[4] kube.var.log.containers.link-fake.log: [1585251619.751557300, {"log"=>"timestamp=2020-03-26T19:40:19+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=4"}]
[5] kube.var.log.containers.link-fake.log: [1585251619.751917800, {"log"=>"timestamp=2020-03-26T19:40:19+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=5"}]
[6] kube.var.log.containers.link-fake.log: [1585251619.752094300, {"log"=>"timestamp=2020-03-26T19:40:19+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=6"}]
[7] kube.var.log.containers.link-fake.log: [1585251619.752245400, {"log"=>"timestamp=2020-03-26T19:40:19+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=7"}]
[8] kube.var.log.containers.link-fake.log: [1585251619.752461600, {"log"=>"timestamp=2020-03-26T19:40:19+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=8"}]
[2020/03/26 19:40:20] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log collect event
[2020/03/26 19:40:20] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log read=146 lines=1
[2020/03/26 19:40:20] [debug] [task] destroy task=0x60e0110 (task_id=0)
[0] kube.var.log.containers.link-fake.log: [1585251620.023741600, {"log"=>"timestamp=2020-03-26T19:40:19+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=9"}]
[2020/03/26 19:40:20] [debug] [task] created task=0x6145d90 id=0 OK
[2020/03/26 19:40:21] [debug] [task] destroy task=0x6145d90 (task_id=0)
[2020/03/26 19:40:24] [debug] [input:tail:tail.0] file rotated: /var/log/containers/link-fake.log -> /var/log/fake-logs/fake.log.1
[2020/03/26 19:40:24] [debug] [input:tail:tail.0] scanning path /var/log/containers/*.log
[2020/03/26 19:40:24] [debug] [input:tail:tail.0] add to scan queue /var/log/containers/link-fake.log, offset=0
[2020/03/26 19:40:24] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log promote to TAIL_EVENT
[2020/03/26 19:40:30] [debug] [input:tail:tail.0] purge rotated file /var/log/fake-logs/fake.log.1
[2020/03/26 19:40:34] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log collect event
[2020/03/26 19:40:34] [debug] [input:tail:tail.0] file=/var/log/containers/link-fake.log read=1460 lines=10
[0] kube.var.log.containers.link-fake.log: [1585251634.002506800, {"log"=>"timestamp=2020-03-26T19:40:33+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=0"}]
[1] kube.var.log.containers.link-fake.log: [1585251634.002675700, {"log"=>"timestamp=2020-03-26T19:40:33+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=1"}]
[2020/03/26 19:40:34] [debug] [task] created task=0x8ab0660 id=0 OK
[2] kube.var.log.containers.link-fake.log: [1585251634.002757300, {"log"=>"timestamp=2020-03-26T19:40:33+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=2"}]
[3] kube.var.log.containers.link-fake.log: [1585251634.002834900, {"log"=>"timestamp=2020-03-26T19:40:33+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=3"}]
[4] kube.var.log.containers.link-fake.log: [1585251634.002913800, {"log"=>"timestamp=2020-03-26T19:40:33+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=4"}]
[5] kube.var.log.containers.link-fake.log: [1585251634.003119000, {"log"=>"timestamp=2020-03-26T19:40:33+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=5"}]
[6] kube.var.log.containers.link-fake.log: [1585251634.003265200, {"log"=>"timestamp=2020-03-26T19:40:33+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=6"}]
[7] kube.var.log.containers.link-fake.log: [1585251634.003382700, {"log"=>"timestamp=2020-03-26T19:40:33+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=7"}]
[8] kube.var.log.containers.link-fake.log: [1585251634.003707000, {"log"=>"timestamp=2020-03-26T19:40:33+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=8"}]
[9] kube.var.log.containers.link-fake.log: [1585251634.003783800, {"log"=>"timestamp=2020-03-26T19:40:33+00:00, component=fake, action=none, level=WARN, FCID=39484200ad049294aasdfasd, sessionId=342413asfsafsdasfd4, cnt=9"}]
[2020/03/26 19:40:35] [debug] [task] destroy task=0x8ab0660 (task_id=0)
^C[engine] caught signal (SIGINT)
[2020/03/26 19:40:43] [ info] [input] pausing tail.0
==364== Invalid free() / delete / delete[] / realloc()
==364==    at 0x48369AB: free (in /usr/lib/x86_64-linux-gnu/valgrind/vgpreload_memcheck-amd64-linux.so)
==364==    by 0x509CAB9: free_key_mem (dlerror.c:223)
==364==    by 0x509CAB9: __dlerror_main_freeres (dlerror.c:239)
==364==    by 0x5224B71: __libc_freeres (in /lib/x86_64-linux-gnu/libc-2.28.so)
==364==    by 0x482B19E: _vgnU_freeres (in /usr/lib/x86_64-linux-gnu/valgrind/vgpreload_core-amd64-linux.so)
==364==    by 0x177248: flb_signal_handler (in /fluent-bit/bin/fluent-bit)
==364==    by 0x50F383F: ??? (in /lib/x86_64-linux-gnu/libc-2.28.so)
==364==    by 0x51B57EE: epoll_wait (epoll_wait.c:30)
==364==    by 0x5F47CD: _mk_event_wait (mk_event_epoll.c:345)
==364==    by 0x5F4ABD: mk_event_wait (mk_event.c:163)
==364==    by 0x20451F: flb_engine_start (in /fluent-bit/bin/fluent-bit)
==364==    by 0x17848A: main (in /fluent-bit/bin/fluent-bit)
==364==  Address 0x5d9b1f0 is in a rw- anonymous segment
==364== 
==364== 
==364== HEAP SUMMARY:
==364==     in use at exit: 89,588 bytes in 663 blocks
==364==   total heap usage: 4,615 allocs, 3,953 frees, 5,038,863 bytes allocated
==364== 
==364== LEAK SUMMARY:
==364==    definitely lost: 472 bytes in 4 blocks
==364==    indirectly lost: 475 bytes in 3 blocks
==364==      possibly lost: 0 bytes in 0 blocks
==364==    still reachable: 88,641 bytes in 656 blocks
==364==         suppressed: 0 bytes in 0 blocks
==364== Rerun with --leak-check=full to see details of leaked memory
==364== 
==364== For counts of detected and suppressed errors, rerun with: -v
==364== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)

@fujimotos
Copy link
Member

@zackwine I think I can take time for this patch somewhere this week.
WFM.

@fujimotos
Copy link
Member

@edsiper @zackwine Sorry for being late. I can confirm this fix is correct.

I set up the testing environment as below:

$ ls -l *.txt
lrwxrwxrwx 1 fujimoto fujimoto 7 Apr 16 11:03 link.txt -> log.txt
-rw-r--r-- 1 fujimoto fujimoto 6 Apr 16 11:06 log.txt

When I moved the log.txt to log.txt.1, Fluent Bit detects the rotation
correctly (when @zackwine's fix is applied).

This patch should be good to be merged into mainline.

@zackwine
Copy link
Contributor Author

Thanks @fujimotos. I can also confirm I have been running load tests with these changes for over a month in a Kubernetes environment. Is there a timeline on when this will be merged?

@edsiper
Copy link
Member

edsiper commented May 1, 2020

thanks @fujimotos for the review and @zackwine for the fix.

This is being merged now.

@edsiper edsiper merged commit 754c40a into fluent:master May 1, 2020
edsiper pushed a commit that referenced this pull request May 1, 2020
@zackwine @edsiper
in_tail: fix symlink log rotation for stat(2) backend on Linux (#2052)
0a05f22 
When compiled with FLB_HAVE_INOTIFY=no for linux records were continuously
resent if the files in PATH are symlinks.  This patch ensures the fs_stat file
monitoring correctly handles symlinks when checking for file rotations.

The issue was found when running fluentbit as a daemonset in kubernetes where all
files in /var/log/containers/* are symlinks.

This patch was tested by forwarding 1M records of 1K size when compiled with
both FLB_HAVE_INOTIFY=no/yes and verifying the output metrics reported exactly
1M records.  The test was executed by running a container logging to stdout
in a kubernetes cluster where symlinks are the target input.  Further docker
was configured to rotate logs at 10M to ensure multiple file rotations
occurred.

Signed-off-by: Zack Wine <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@fujimotos fujimotos fujimotos approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
3 participants
@zackwine @fujimotos @edsiper