Fluent-bit: "time string length is too long" when using fractional seconds

[theasp]

I'm getting the error time string length is too long when using fractional seconds and the format %s.%L:

[2018/06/29 02:17:12] [debug] [out_fw] 2 entries tag='tag_hostname.tag_username.bash' tag_len=30
[2018/06/29 02:17:12] [debug] [task] destroy task=0x7f159a903000 (task_id=0)
[2018/06/29 02:17:12] [debug] [dyntag tail.0] 0x7f159f670060 destroy (tag=tag_hostname.tag_username.bash, bytes=318)
[2018/06/29 02:17:19] [debug] [in_tail] file=/home/asp/.bash_log/industrial.gt0.ca/70d26b1e-fb75-4187-adca-1591ac9bfc04.json event
[2018/06/29 02:17:19] [error] [parser] time string length is too long
[2018/06/29 02:17:19] [debug] [input tail.0] [mem buf] size = 155
[2018/06/29 02:17:19] [debug] [in_tail] file=/home/asp/.bash_log/industrial.gt0.ca/70d26b1e-fb75-4187-adca-1591ac9bfc04.json read=174 lines=1
[2018/06/29 02:17:20] [debug] [in_tail] file=/home/asp/.bash_log/industrial.gt0.ca/70d26b1e-fb75-4187-adca-1591ac9bfc04.json event
[2018/06/29 02:17:20] [error] [parser] time string length is too long
[2018/06/29 02:17:20] [debug] [input tail.0] [mem buf] size = 322
[2018/06/29 02:17:20] [debug] [in_tail] file=/home/asp/.bash_log/industrial.gt0.ca/70d26b1e-fb75-4187-adca-1591ac9bfc04.json read=193 lines=1
[2018/06/29 02:17:22] [debug] [task] created task=0x7f159a903000 id=0 OK
[2018/06/29 02:17:22] [debug] [out_forward] request 322 bytes to flush
[2018/06/29 02:17:22] [debug] [out_fw] 2 entries tag='tag_hostname.tag_username.bash' tag_len=30

sample:

{"type":"end","timestamp":1530239065.807368,"session":"70d26b1e-fb75-4187-adca-1591ac9bfc04","username":"","hostname":"industrial.gt0.ca","id":285,"cmd":"less /srv/asp-fluentd-bash/etc/fluent-bit.conf","rc":0}
{"type":"start","timestamp":1530239069.60937,"session":"70d26b1e-fb75-4187-adca-1591ac9bfc04","hostname":"industrial.gt0.ca","id":286,"cmd":"less /srv/asp-fluentd-bash/etc/parsers.conf"}

fluent-bit.conf:

[SERVICE]
  Flush 5
  Daemon off
  Parsers_File parsers.conf
  Log_Level debug

[INPUT]
  Name tail
  Path /home/asp/.bash_log/*/*.json
  DB /home/asp/.bash_log/.fluent-bit.db
  Parser bash-log-json
  Tag tag_hostname.tag_username.bash

[OUTPUT]
  Name forward
  Match *
  Host fluentd
  Port 24224

parsers.conf:

[PARSER]
  Name bash-log-json
  Format json
  Time_Key timestamp
  Time_Format %s.%L

[nokute78]

Hmm, can you convert data type of timestamp to string.
e.g. "timestamp":1530239065.807368 -> "timestamp":"1530239065.807368"

In this case, the data type of timestamp is float.
Time_Key and Time_Format is an option for string, so it causes [parser] time string length is too long.

"Types" option is to convert data types, but json parser doesn't support it...

[theasp]

That makes perfect sense! Yeah, I suppose I could convert it to a string, or deal with the timestamp when it gets to fluentd. Reading time as epoch seconds (float or int) seems like it should be supported though. Maybe attempt to use the value if Time_Format isn't set?

[nokute78]

If you remove Time_Key, fluent-bit can send data to fluentd.
record_transformer Filter Plugin of fluentd can overwrite timestamp.

new parsers.conf:

[PARSER]
  Name bash-log-json
  Format json
#  Time_Key timestamp
  Time_Format %s.%L

forward.conf (for fluentd):

<source>
  @type forward
  port 24224
</source>
<filter **>
   @type record_transformer
   renew_time_key timestamp
</filter>
<match **>
   @type   stdout
</match>

Then fluentd can receive data and timestamp will be received time.

[taka@localhost fluentd]$ bundle exec bin/fluentd -c ../fluent/forward.conf
.
.
2018-07-03 21:59:07.458121430 +0900 fluent.info: {"worker":0,"message":"fluentd worker is now running worker=0"}
2018-06-29 11:24:25.807369947 +0900 tag_hostname.tag_username.bash: {"type":"end","timestamp":1530239065.80737,"session":"70d26b1e-fb75-4187-adca-1591ac9bfc04","username":"","hostname":"industrial.gt0.ca","id":285,"cmd":"less /srv/asp-fluentd-bash/etc/fluent-bit.conf","rc":0}
2018-06-29 11:24:29.609369993 +0900 tag_hostname.tag_username.bash: {"type":"start","timestamp":1530239069.60937,"session":"70d26b1e-fb75-4187-adca-1591ac9bfc04","hostname":"industrial.gt0.ca","id":286,"cmd":"less /srv/asp-fluentd-bash/etc/parsers.conf"}

Reading time as epoch seconds (float or int) seems like it should be supported though.

Yes, I think so.

[ayenter]

@edsiper Is there any possibility that floats will be supported in the future?

[nokute78]

I found a workaround for this issue.
filter_lua helps us!

sample input data

{"Timestamp"=>1530239065.807368, "data"=>"missing"}

expected output is

[1530239065.807368040, {"Timestamp"=>1530239065.807368, "data"=>"missing"}]

time.lua

function float_time(tag, timestamp, record)
         return 1, record["Timestamp"], record
end

1 means lua script changed timestamp/record.
You should modify key name (Timestamp) properly.
In this case, record["Timestamp"] is 1530239065.807368.

a.conf

[INPUT]
    Name dummy
    Tag  dummy.data
    Dummy {"Timestamp":1530239065.807368, "data":"missing"}

[FILTER]
    Name lua
    Match dummy.*
    script time.lua
    call   float_time

[OUTPUT]
    Name stdout
    Match *

result is

$ ../bin/fluent-bit -c a.conf 
Fluent Bit v1.4.0
Copyright (C) Treasure Data

[2019/10/13 06:50:57] [ info] [storage] initializing...
[2019/10/13 06:50:57] [ info] [storage] in-memory
[2019/10/13 06:50:57] [ info] [storage] normal synchronization mode, checksum disabled, max_chunks_up=128
[2019/10/13 06:50:57] [ info] [engine] started (pid=35217)
[2019/10/13 06:50:57] [ info] [sp] stream processor started
[0] dummy.data: [1530239065.807368040, {"Timestamp"=>1530239065.807368, "data"=>"missing"}]
[1] dummy.data: [1530239065.807368040, {"Timestamp"=>1530239065.807368, "data"=>"missing"}]
[2] dummy.data: [1530239065.807368040, {"Timestamp"=>1530239065.807368, "data"=>"missing"}]
[3] dummy.data: [1530239065.807368040, {"Timestamp"=>1530239065.807368, "data"=>"missing"}]
^C[engine] caught signal (SIGINT)

[macropin]

Can we please have support for integer or float epoch timestamps?

Using lua to workaround this issue is a hack.