Subsecond timestamps written as fractions

[pstray]

Describe the bug

I get weird timestamp lines in the log, seems like the sub-seconds part of the timestamps gets printed as a fraction, like in the following:
2021-07-19 12:56:20 +0200 [warn]: #0 failed to flush the buffer. retry_time=9 next_retry_seconds=2021-07-19 13:00:22 24648004639507749129/34359738368000000000 +0200 chunk="5c777a670a11ecf6fe7fe48328099911

this line is produced from fluentd-1.12.3/lib/fluent/plugin/output.rb:1238

To Reproduce

happens all the time when failing to flush buffers

Expected behavior

A sane timestamp, like next_retry_seconds=2021-07-19 12:52:09.802562942 +0200

Your Environment

- Fluentd version: 1.12.3 (b6e76c09d60ee866de6470f2bdd2551e7c8591d3
- TD Agent version: 4.1.1
- Operating system: Ubuntu 20.04.2 LTS
- Kernel version: 5.4.0-73-generic #82-Ubuntu

Your Configuration

<match **>
  @type forward
  <server>
    host some-host.example.com
  </server>
  <buffer>
    @type file
    path /srv/fluentd/sensor-queue-1.buffer
    chunk_limit_size 128k
    total_limit_size 1M
  </buffer>
</match>

Your Error Log

2021-07-19 12:56:20 +0200 [warn]: #0 failed to flush the buffer. retry_time=9 next_retry_seconds=2021-07-19 13:00:22 24648004639507749129/34359738368000000000 +0200 chunk="5c777a670a11ecf6fe7fe48328099911

Additional context

Nothing more

[kenhys]

I'm not sure, but #calc_next_time, #recalc_next_time may cause similar situation, too.

require_relative "lib/fluent/plugin_helper/retry_state"
include Fluent::PluginHelper::RetryState
> @retry = retry_state_create("hoge", :exponential_backoff, 30, 100)
> a=@retry.calc_next_time
 => 2021-08-16 13:52:15 46768506850790742099/137438953472000000000 +0900 
> a.class
 => Time 

[ashie]

Hmm, it's Time class's behaviour:

irb(main):012:0> a = Time.now
=> 2021-09-06 14:40:51.187185555 +0900
irb(main):013:0> a + 1
=> 2021-09-06 14:40:52.187185555 +0900
irb(main):014:0> a + 1.1
=> 2021-09-06 14:40:52 252611085641443258669/879609302220800000000 +0900

round or floor or ceil is needed:

irb(main):016:0> (a + 1.1).round(3)
=> 2021-09-06 14:40:52.287 +0900
irb(main):018:0> (a + 1.1).floor(3)
=> 2021-09-06 14:40:52.287 +0900
irb(main):019:0> (a + 1.1).ceil(3)
=> 2021-09-06 14:40:52.288 +0900

[ashie]

Hmm, it seems Ruby 2.7 or later's behavior.
Ruby 2.6 or prior doesn't show nano seconds field.

irb(main):015:0> now = Time.now
=> 2021-09-28 14:43:29 +0900
irb(main):016:0> now + 0.111
=> 2021-09-28 14:43:29 +0900