Fluent-bit: Nanoseconds missing when using forward input

[gmsecrieru]

Hello,

I have been struggling with a curious situation where Docker container logs miss the nanosecond piece of timestamp when using in_forward.

Failling scenario

fluent-bit.conf:

[SERVICE]
    Flush 1
    Daemon Off
    Log_Level info

[INPUT]
    Name forward
    Host 0.0.0.0
    Port 24224

[OUTPUT]
    Name stdout
    Match *

When running a Docker image with this setup, the nanosecond precision is converted to 0s:

[0] e667dc543a03: [1524598344.000000000, {"container_id"=>"e667dc543a034403e743a4b715aa345c3ab36bc5211696ad423c2be09643b230", "container_name"=>"/determined_poincare", "source"=>"stdout", "log"=>"frame=51"}]
[1] e667dc543a03: [1524598344.000000000, {"container_id"=>"e667dc543a034403e743a4b715aa345c3ab36bc5211696ad423c2be09643b230", "container_name"=>"/determined_poincare", "source"=>"stdout", "log"=>"fps=0.0"}]
[2] e667dc543a03: [1524598344.000000000, {"log"=>"stream_0_0_q=0.0", "container_id"=>"e667dc543a034403e743a4b715aa345c3ab36bc5211696ad423c2be09643b230", "container_name"=>"/determined_poincare", "source"=>"stdout"}]
[3] e667dc543a03: [1524598344.000000000, {"container_id"=>"e667dc543a034403e743a4b715aa345c3ab36bc5211696ad423c2be09643b230", "container_name"=>"/determined_poincare", "source"=>"stdout", "log"=>"bitrate=   0.2kbits/s"}]
[4] e667dc543a03: [1524598344.000000000, {"container_id"=>"e667dc543a034403e743a4b715aa345c3ab36bc5211696ad423c2be09643b230", "container_name"=>"/determined_poincare", "source"=>"stdout", "log"=>"total_size=48"}]
[5] e667dc543a03: [1524598344.000000000, {"log"=>"out_time_ms=1920000", "container_id"=>"e667dc543a034403e743a4b715aa345c3ab36bc5211696ad423c2be09643b230", "container_name"=>"/determined_poincare", "source"=>"stdout"}]
[6] e667dc543a03: [1524598344.000000000, {"container_name"=>"/determined_poincare", "source"=>"stdout", "log"=>"out_time=00:00:01.920000", "container_id"=>"e667dc543a034403e743a4b715aa345c3ab36bc5211696ad423c2be09643b230"}]

During several tests, I've noticed that if I change in_forward to in_tail and point the path to the actual container log (i.e. without using --log-driver fluentd option) the precision is there:

Working scenario

fluent-bit.conf:

[SERVICE]
    Flush 1
    Daemon Off
    Log_Level info

[INPUT]
    Name tail
    Path /var/lib/docker/containers/<DOCKER_CONTAINER_ID>/*.log

[OUTPUT]
    Name stdout
    Match *

With this config, nanosecond precision is printed as expected:

[0] tail.0: [1524598700.422911026, {"log"=>"{"log":"[mp4 @ 0x7f102d2730a0] Using AVStream.codec to pass codec parameters to muxers is deprecated, use AVStream.codecpar instead.\n","stream":"stderr","time":"2018-04-24T19:37:47.267283855Z"}"}]
[1] tail.0: [1524598700.422927803, {"log"=>"{"log":"frame=51\n","stream":"stdout","time":"2018-04-24T19:37:47.795611724Z"}"}]
[2] tail.0: [1524598700.422929512, {"log"=>"{"log":"fps=0.0\n","stream":"stdout","time":"2018-04-24T19:37:47.795682825Z"}"}]
[3] tail.0: [1524598700.422930957, {"log"=>"{"log":"stream_0_0_q=0.0\n","stream":"stdout","time":"2018-04-24T19:37:47.795689101Z"}"}]
[4] tail.0: [1524598700.422932435, {"log"=>"{"log":"bitrate=   0.2kbits/s\n","stream":"stdout","time":"2018-04-24T19:37:47.795694113Z"}"}]
[5] tail.0: [1524598700.422933923, {"log"=>"{"log":"total_size=48\n","stream":"stdout","time":"2018-04-24T19:37:47.795698881Z"}"}]
[6] tail.0: [1524598700.422935424, {"log"=>"{"log":"out_time_ms=1920000\n","stream":"stdout","time":"2018-04-24T19:37:47.795703697Z"}"}]
[7] tail.0: [1524598700.422936884, {"log"=>"{"log":"out_time=00:00:01.920000\n","stream":"stdout","time":"2018-04-24T19:37:47.795708405Z"}"}]

Is there anything I'm missing? I am currently running fluent-bit v0.12.18 in a Docker container.

Thanks in advance!

[edsiper]

Hi @gmsecrieru

Note that this missing subsecond resolution happens because the Fluentd driver in Docker engine is not including it by default, I've found that it needs to be enabled manually:

$ docker run -ti --log-driver=fluentd --log-opt fluentd-sub-second-precision=true busybox echo "go subsecond!"

note that enabling this mode will be only compatible with Fluent Bit >= 0.12 and Fluentd >= 0.14.

[gmsecrieru]

Hi @edsiper

Thanks a lot for your help! I've tried using --log-opt fluentd-sub-second-precision=true but I'm getting the following:

$ docker run -d --log-driver=fluentd --log-opt fluentd-sub-second-precision=true [...]
docker: Error response from daemon: unknown log opt 'fluentd-sub-second-precision' for fluentd log driver.

Docker version:

$ docker --version
Docker version 17.09.1-ce, build 19e2cf6

Thanks again!

[edsiper]

I am using this version:

$ docker --version
Docker version 18.02.0-ce, build fc4de44

[edsiper]

Fixed.

[gmsecrieru]

Thanks @edsiper -- it took me a little extra time to set up my environment but I can confirm that it works with fluentd-sub-second-precision flag:

[0] 9ca4e8318660: [1524605606.067591287, {"container_id"=>"9ca4e8318660cbc23e2e44ac1769923abeeecf1281a6297c0850820fa3632184", "container_name"=>"/thirsty_raman", "source"=>"stderr", "log"=>"[mp4 @ 0x5641e8bc7560] Using AVStream.codec to pass codec parameters to muxers is deprecated, use AVStream.codecpar instead."}]
[1] 9ca4e8318660: [1524605606.580875228, {"container_id"=>"9ca4e8318660cbc23e2e44ac1769923abeeecf1281a6297c0850820fa3632184", "container_name"=>"/thirsty_raman", "source"=>"stdout", "log"=>"frame=49"}]
[2] 9ca4e8318660: [1524605606.581055754, {"container_id"=>"9ca4e8318660cbc23e2e44ac1769923abeeecf1281a6297c0850820fa3632184", "container_name"=>"/thirsty_raman", "source"=>"stdout", "log"=>"fps=0.0"}]
[3] 9ca4e8318660: [1524605606.581137428, {"container_id"=>"9ca4e8318660cbc23e2e44ac1769923abeeecf1281a6297c0850820fa3632184", "container_name"=>"/thirsty_raman", "source"=>"stdout", "log"=>"stream_0_0_q=29.0"}]
[4] 9ca4e8318660: [1524605606.581189472, {"container_id"=>"9ca4e8318660cbc23e2e44ac1769923abeeecf1281a6297c0850820fa3632184", "container_name"=>"/thirsty_raman", "source"=>"stdout", "log"=>"bitrate= 205.1kbits/s"}]

Thanks again!

[edsiper]

you are welcome!

[JulieLily]

How to use it in kubernetes? The accuracy of the output timestamp is microseconds.