search

fluent / fluent-bit

Fast and Lightweight Logs and Metrics processor for Linux, BSD, OSX and Windows
https://fluentbit.io
Apache License 2.0
5.86k stars 1.59k forks source link

Buffer/Flushing issue #563

Closed barrachri closed 6 years ago

barrachri commented 6 years ago

I've built a docker image of fluentbit using the master version (I was interested in testing this feature https://github.com/fluent/fluent-bit/issues/388).

This is my conf

[SERVICE]
    Flush           5
    Log_Level       debug

[INPUT]
    Name  forward
    unix_path /bind-fluent-bit/fluent-bit.sock

[OUTPUT]
    Name  stdout
    Match *

The docker service is running with this command

/fluent-bit/bin/fluent-bit -c /fluent-bit/etc/fluent-bit.conf

Now the system seems to work but I have a strange behaviour that it might be related to buffer/flushing configuration.

This the command

sudo docker run --log-driver=fluentd --log-opt "fluentd-address=unix:///bind-fluent-bit/fluent-bit.sock" -ti busybox echo message

and this is the output

[2018/04/15 11:44:27] [ info] [engine] started
[2018/04/15 11:44:27] [ info] [in_fw] listening on unix:///bind-fluent-bit/fluent-bit.sock
[2018/04/15 11:44:27] [debug] [router] input=forward.0 'DYNAMIC TAG'
[2018/04/15 11:45:08] [debug] [input forward.0] [mem buf] size = 146
[2018/04/15 11:45:11] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 11:45:11] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 11:45:11] [debug] [dyntag forward.0] 0x7f318666e060 destroy (tag=1d856a594c30, bytes=146)
[2018/04/15 12:33:49] [debug] [input forward.0] [mem buf] size = 150
[2018/04/15 12:33:51] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:33:51] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:33:51] [debug] [dyntag forward.0] 0x7f318666e060 destroy (tag=b3ddab7767d8, bytes=150)
[2018/04/15 12:34:16] [debug] [input forward.0] [mem buf] size = 149
[2018/04/15 12:34:16] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:34:16] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:34:16] [debug] [dyntag forward.0] 0x7f318666e060 destroy (tag=14e34990a9f9, bytes=149)
[2018/04/15 12:34:41] [debug] [input forward.0] [mem buf] size = 144
[2018/04/15 12:34:41] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:34:42] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:34:42] [debug] [dyntag forward.0] 0x7f318666e060 destroy (tag=de18b37ea0bf, bytes=144)
[2018/04/15 12:42:39] [debug] [input forward.0] [mem buf] size = 149

as you can see the echo is not there, but if I keep sending messages the logs will finally appear:

[2018/04/15 11:44:27] [ info] [engine] started
[2018/04/15 11:44:27] [ info] [in_fw] listening on unix:///bind-fluent-bit/fluent-bit.sock
[2018/04/15 11:44:27] [debug] [router] input=forward.0 'DYNAMIC TAG'
[2018/04/15 11:45:08] [debug] [input forward.0] [mem buf] size = 146
[2018/04/15 11:45:11] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 11:45:11] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 11:45:11] [debug] [dyntag forward.0] 0x7f318666e060 destroy (tag=1d856a594c30, bytes=146)
[2018/04/15 12:33:49] [debug] [input forward.0] [mem buf] size = 150
[2018/04/15 12:33:51] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:33:51] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:33:51] [debug] [dyntag forward.0] 0x7f318666e060 destroy (tag=b3ddab7767d8, bytes=150)
[2018/04/15 12:34:16] [debug] [input forward.0] [mem buf] size = 149
[2018/04/15 12:34:16] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:34:16] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:34:16] [debug] [dyntag forward.0] 0x7f318666e060 destroy (tag=14e34990a9f9, bytes=149)
[2018/04/15 12:34:41] [debug] [input forward.0] [mem buf] size = 144
[2018/04/15 12:34:41] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:34:42] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:34:42] [debug] [dyntag forward.0] 0x7f318666e060 destroy (tag=de18b37ea0bf, bytes=144)
[2018/04/15 12:42:39] [debug] [input forward.0] [mem buf] size = 149
[2018/04/15 12:42:41] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:42:41] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:42:41] [debug] [dyntag forward.0] 0x7f318666e060 destroy (tag=a5db6782e5ad, bytes=149)
[2018/04/15 12:44:30] [debug] [input forward.0] [mem buf] size = 141
[2018/04/15 12:44:31] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:44:31] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:44:31] [debug] [dyntag forward.0] 0x7f318666e060 destroy (tag=39d70f0d4294, bytes=141)
[2018/04/15 12:44:36] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:44:34] [debug] [input forward.0] [mem buf] size = 142
[2018/04/15 12:44:36] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:44:36] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:44:36] [debug] [dyntag forward.0] 0x7f318666e060 destroy (tag=840849bca885, bytes=142)
[2018/04/15 12:44:38] [debug] [input forward.0] [mem buf] size = 154
[2018/04/15 12:44:41] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:44:41] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:44:41] [debug] [dyntag forward.0] 0x7f318666e060 destroy (tag=e60eacfaedd0, bytes=154)
[2018/04/15 12:44:42] [debug] [input forward.0] [mem buf] size = 145
[2018/04/15 12:44:46] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:44:46] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:44:46] [debug] [dyntag forward.0] 0x7f318666e060 destroy (tag=3fce7573b75d, bytes=145)
[2018/04/15 12:44:48] [debug] [input forward.0] [mem buf] size = 144
[2018/04/15 12:44:51] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:44:51] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:44:51] [debug] [dyntag forward.0] 0x7f318666e060 destroy (tag=f148ab7335ed, bytes=144)
[2018/04/15 12:44:52] [debug] [input forward.0] [mem buf] size = 147
[2018/04/15 12:44:55] [debug] [input forward.0] [mem buf] size = 293
[2018/04/15 12:44:56] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:44:56] [debug] [task] created task=0x7f31866d60e0 id=1 OK
[2018/04/15 12:44:56] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:44:56] [debug] [dyntag forward.0] 0x7f318666e060 destroy (tag=f3a188b9fd6e, bytes=147)
[2018/04/15 12:44:56] [debug] [task] destroy task=0x7f31866d60e0 (task_id=1)
[2018/04/15 12:44:56] [debug] [dyntag forward.0] 0x7f318666e0c0 destroy (tag=57c52a50b6ab, bytes=146)
[2018/04/15 12:44:58] [debug] [input forward.0] [mem buf] size = 142
[2018/04/15 12:45:01] [debug] [task] created task=0x7f31866d60e0 id=0 OK
[2018/04/15 12:45:01] [debug] [task] destroy task=0x7f31866d60e0 (task_id=0)
[2018/04/15 12:45:01] [debug] [dyntag forward.0] 0x7f318666e0c0 destroy (tag=d62fbf2b128a, bytes=142)
[2018/04/15 12:45:11] [debug] [input forward.0] [mem buf] size = 144
[2018/04/15 12:45:11] [debug] [task] created task=0x7f31866d60e0 id=0 OK
[2018/04/15 12:45:11] [debug] [task] destroy task=0x7f31866d60e0 (task_id=0)
[2018/04/15 12:45:11] [debug] [dyntag forward.0] 0x7f318666e0c0 destroy (tag=6291695e6070, bytes=144)
[2018/04/15 12:45:17] [debug] [input forward.0] [mem buf] size = 148
[2018/04/15 12:45:20] [debug] [input forward.0] [mem buf] size = 294
[2018/04/15 12:45:21] [debug] [task] created task=0x7f31866d60e0 id=0 OK
[2018/04/15 12:45:21] [debug] [task] created task=0x7f31866d6000 id=1 OK
[2018/04/15 12:45:21] [debug] [task] destroy task=0x7f31866d60e0 (task_id=0)
[2018/04/15 12:45:21] [debug] [dyntag forward.0] 0x7f318666e0c0 destroy (tag=021423a28327, bytes=148)
[2018/04/15 12:45:21] [debug] [task] destroy task=0x7f31866d6000 (task_id=1)
[2018/04/15 12:45:21] [debug] [dyntag forward.0] 0x7f318666e180 destroy (tag=cbd6d9b84c52, bytes=146)
[2018/04/15 12:45:44] [debug] [input forward.0] [mem buf] size = 149
[2018/04/15 12:45:46] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:45:46] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:45:46] [debug] [dyntag forward.0] 0x7f318666e180 destroy (tag=1a2f44439084, bytes=149)
[2018/04/15 12:45:55] [debug] [input forward.0] [mem buf] size = 149
[2018/04/15 12:45:56] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:45:56] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:45:56] [debug] [dyntag forward.0] 0x7f318666e180 destroy (tag=744e631037f5, bytes=149)
[2018/04/15 12:45:58] [debug] [input forward.0] [mem buf] size = 148
[2018/04/15 12:46:01] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:46:01] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:46:01] [debug] [dyntag forward.0] 0x7f318666e180 destroy (tag=83f18ee8f0fb, bytes=148)
[2018/04/15 12:46:04] [debug] [input forward.0] [mem buf] size = 146
[2018/04/15 12:46:06] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:46:06] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:46:06] [debug] [dyntag forward.0] 0x7f318666e180 destroy (tag=19ecb2eab575, bytes=146)
Fluent-Bit v0.13.0
Copyright (C) Treasure Data

", "container_id"=>"1d856a594c30444388bed729efffecaa375a7f7675dac9efc96e67205ed1a706", "container_name"=>"/inspiring_euler"}]
", "container_id"=>"b3ddab7767d877b9c1caf2692a787a11a4fe981ac780883f8ea0d1c91b52f99b"}]urce"=>"stdout", "log"=>"ciccio02
", "container_id"=>"14e34990a9f9c15aa2737847d82e0a2b26f355a12abdaa55772b693533cf3f68"}]rce"=>"stdout", "log"=>"ciccio03
[0] de18b37ea0bf: [1523795681.000000000, {"container_id"=>"de18b37ea0bfe2fec04dde5e37785513c4bc7fdcb71446e04afc8c23b9d54029", "container_name"=>"/vibrant_yalow", "source"=>"stdo"}], "log"=>"ciccio04
", "container_id"=>"a5db6782e5ad942875c1b73754fafd100c66a3956ffee3d2153eaea4a8ecc158", "container_name"=>"/affectionate_euler"}]
[0] 39d70f0d4294: [1523796270.000000000, {"container_id"=>"39d70f0d429437e81ab9a73eb5a7f25bc4cb706f092f27b6f637792ef844b7f7", "container_name"=>"/stoic_pike", "source"=>"stdout""}]log"=>"ciccio05
[0] 840849bca885: [1523796274.000000000, {"container_id"=>"840849bca885a5c395cdea23ca0dd37945e3eec622ce256e9f7eb5c65232b3ee", "container_name"=>"/hungry_kare", "source"=>"stdout"}]"log"=>"ciccio05
", "container_id"=>"e60eacfaedd07a6b98bab4e1d6996ecdffc833e804d956e9b38b84846271e497", "container_name"=>"/compassionate_goldstine"}]
", "container_id"=>"3fce7573b75df4f1b89d320a019cba9688b14c5499c4740dda00d2d8a16eb37d", "container_name"=>"/vigilant_payne", "source"=>"stdout"}]
[0] f148ab7335ed: [1523796288.000000000, {"container_id"=>"f148ab7335ede3e3b577345f240cfa3c58f8a0b1bed5d04ad3e1a262ef38b3c7", "container_name"=>"/loving_colden", "source"=>"stdo"}], "log"=>"ciccio05
", "container_id"=>"f3a188b9fd6e22f294b3dac2bba40e2e8939216fe3261a1be305b2da728424c4"}]e"=>"stdout", "log"=>"ciccio05
", "container_id"=>"57c52a50b6ab2d091354b3a21e9669930fd52a42de8510fce939b28989175658", "container_name"=>"/gallant_hawking", "source"=>"stdout"}]
", "container_id"=>"d62fbf2b128a4672066d0ad5618fef4b1b7fb561c5be03af3e0d20711def7a96", "container_name"=>"/keen_colden"}]
[0] 6291695e6070: [1523796311.000000000, {"container_id"=>"6291695e6070b9fdd823846dccb5a86b13f568d37dfa90d946f34d2707a0aba7", "container_name"=>"/stoic_perlman", "source"=>"stdo"}], "log"=>"ciccio05
[0] 021423a28327: [1523796317.000000000, {"container_id"=>"021423a28327d3a09df06f91613201f82105ecbd38a77553dec44c7f8bdf4dd7", "container_name"=>"/determined_euclid", "source"=>""}]out", "log"=>"ciccio05
[0] cbd6d9b84c52: [1523796320.000000000, {"container_id"=>"cbd6d9b84c52378cb3ce4e5d09d3aea81980b6e342b7d2cd2bb3f09e705cf330", "container_name"=>"/cocky_blackwell", "source"=>"st"}]t", "log"=>"ciccio05
[0] 1a2f44439084: [1523796344.000000000, {"container_id"=>"1a2f4443908401fead8993682e6d23dd140e4130beadebf93fd7827665825989", "container_name"=>"/xenodochial_spence", "source"=>"}]dout", "log"=>"ciccio05
", "container_id"=>"744e631037f587d8e7b16da102e7c8a532459e0de9d0605278df2c6bc40ee24b", "container_name"=>"/elated_brahmagupta", "source"=>"stdout"}]
", "container_id"=>"83f18ee8f0fb8fbb8093e3a68c77869f0714fd810a9595270a00d9a7b15d8910", "container_name"=>"/peaceful_williams", "source"=>"stdout"}]
[2018/04/15 12:46:07] [debug] [input forward.0] [mem buf] size = 143
[2018/04/15 12:46:11] [debug] [task] created task=0x7f31866d6000 id=0 OK
[2018/04/15 12:46:11] [debug] [task] destroy task=0x7f31866d6000 (task_id=0)
[2018/04/15 12:46:11] [debug] [dyntag forward.0] 0x7f318666e180 destroy (tag=8c1d54549338, bytes=143)
edsiper commented 6 years ago

Looks like related to buffering in docker maybe ?, note that your flush time is 5 seconds, try to set to 1 and see if the message is there.

tip: use "echo -n message" to avoid \r mess up the stdout

barrachri commented 6 years ago

I don't have the same issue if I use the http for example (always with docker), I'll try to check with 1 sec.

dkarthi commented 5 years ago

Hi,

I am facing the same issue with docker image even with 1 sec.

This is my config

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

[INPUT] Name tail Path /tmp/log/access.log Parser java_test

[OUTPUT] Name kafka Match * Brokers kafka-staging:9092 Topics karthik_test

I am getting the below output but new logs are not showing up.

EVENT [2019/06/27 19:29:02] [debug] [task] created task=0x7ff534e3b900 id=0 OK [2019/06/27 19:29:02] [debug] [out_kafka] enqueued message (277 bytes) for topic 'karthik_test' [2019/06/27 19:29:02] [debug] [out_kafka] enqueued message (326 bytes) for topic 'karthik_test' [2019/06/27 19:29:02] [debug] [out_kafka] enqueued message (335 bytes) for topic 'karthik_test' [2019/06/27 19:29:02] [debug] [out_kafka] enqueued message (335 bytes) for topic 'karthik_test' [2019/06/27 19:29:02] [debug] [out_kafka] enqueued message (335 bytes) for topic 'karthik_test' [2019/06/27 19:29:02] [debug] [out_kafka] enqueued message (330 bytes) for topic 'karthik_test' [2019/06/27 19:29:02] [debug] [out_kafka] enqueued message (329 bytes) for topic 'karthik_test' [2019/06/27 19:29:02] [debug] [out_kafka] enqueued message (338 bytes) for topic 'karthik_test' [2019/06/27 19:29:02] [debug] [out_kafka] enqueued message (333 bytes) for topic 'karthik_test' [2019/06/27 19:29:02] [debug] [out_kafka] enqueued message (325 bytes) for topic 'karthik_test' [2019/06/27 19:29:02] [debug] [out_kafka] enqueued message (331 bytes) for topic 'karthik_test' [2019/06/27 19:29:02] [debug] [out_kafka] enqueued message (325 bytes) for topic 'karthik_test' [2019/06/27 19:29:02] [debug] [out_kafka] enqueued message (326 bytes) for topic 'karthik_test' [2019/06/27 19:29:02] [debug] [out_kafka] enqueued message (309 bytes) for topic 'karthik_test' [2019/06/27 19:29:02] [debug] [out_kafka] enqueued message (335 bytes) for topic 'karthik_test' [2019/06/27 19:29:02] [debug] [out_kafka] enqueued message (352 bytes) for topic 'karthik_test' [2019/06/27 19:29:02] [debug] [out_kafka] enqueued message (305 bytes) for topic 'karthik_test' [2019/06/27 19:29:02] [debug] [task] destroy task=0x7ff534e3b900 (task_id=0)

edsiper commented 5 years ago

please open a new ticket with full details.