retry_type periodic not working for http

[raulgupto]

Describe the bug

https://docs.fluentd.org/output#retry_type As mentioned here we can control the retry_type as periodic too. I'm using output plugin with similar config here :

<match pattern>
   @type copy
   <store>
      @type http
      endpoint http://logserver.com:9000/api
      content_type application/json
# here in this section #
      <format>
        @type json
      </format>
      <buffer tag>
        @type file
        path /some/path
        retry_type periodic # tried adding this in store http config too in above section, but it was still exponential
        retry_wait 60s
        retry_forever true
        total_limit_size 10GB
        flush_interval 12s
        flush_thread_count 2 
      </buffer>
   </store>
  <store>
    @type prometheus
    <metric>
      name fluentd_output_status_num_records_total
      type counter
      desc The total number of outgoing records
      <labels>
        tag ${tag}
        hostname ${hostname}
      </labels>
    </metric>
  </store>
  
</match>

To Reproduce

You can try with basic bare-minimum output config. Please note I'm also using prometheus to count events

Expected behavior

It should be periodic or exponential as set by user.

Your Environment

- Fluentd version: 1.16.0
- TD Agent version:
- Operating system: RHEL6 / RHEL7
- Kernel version: 3.10.0-1160.90.1.el7.x86_64

Your Configuration

<match pattern>
   @type copy
   <store>
      @type http
      endpoint http://logserver.com:9000/api
      content_type application/json
# here in this section #
      <format>
        @type json
      </format>
      <buffer tag>
        @type file
        path /some/path
        retry_type periodic # tried adding this in store http config too in above section, but it was still exponential
        retry_wait 60s
        retry_forever true
        total_limit_size 10GB
        flush_interval 12s
        flush_thread_count 2 
      </buffer>
   </store>
  <store>
    @type prometheus
    <metric>
      name fluentd_output_status_num_records_total
      type counter
      desc The total number of outgoing records
      <labels>
        tag ${tag}
        hostname ${hostname}
      </labels>
    </metric>
  </store>
  
</match>

Your Error Log

I checked in fluentd prometheus metrics when my http target was down. output_status_retry_wait was growing exponentially.

Additional context

No response

[daipom]

I can not reproduce it.
The retry of Fluentd works as expected.
Maybe it's a matter of how output_status_retry_wait is counted.

• Windows 10 Home
• Fluentd v1.16.1
• ruby 3.2.0 (2022-12-25 revision a528908271) [x64-mingw-ucrt]
• Config:

<source>
  @type sample
  tag test
  sample {"log":{"msg":"foo"},"stream":"bar"}
</source>

<match test.**>
  @type null
  never_flush true # make flush fail forcely
  <buffer tag>
    @type file
    path /test/fluentd/buffer
    flush_interval 3
    retry_type periodic
    retry_wait 3
    retry_forever true
  </buffer>
</match>

• Result:

2023-07-09 20:34:16 +0900 [warn]: #0 failed to flush the buffer. retry_times=0 next_retry_time=2023-07-09 20:34:19 +0900 chunk="6000c24aaa6eca9d4804dc4a11dc0e52" error_class=RuntimeError error="failed to flush"
2023-07-09 20:34:19 +0900 [warn]: #0 failed to flush the buffer. retry_times=1 next_retry_time=2023-07-09 20:34:22 +0900 chunk="6000c24aaa6eca9d4804dc4a11dc0e52" error_class=RuntimeError error="failed to flush"
2023-07-09 20:34:21 +0900 [warn]: #0 failed to flush the buffer. retry_times=2 next_retry_time=2023-07-09 20:34:25 +0900 chunk="6000c24aaa6eca9d4804dc4a11dc0e52" error_class=RuntimeError error="failed to flush"
2023-07-09 20:34:24 +0900 [warn]: #0 failed to flush the buffer. retry_times=3 next_retry_time=2023-07-09 20:34:27 +0900 chunk="6000c24aaa6eca9d4804dc4a11dc0e52" error_class=RuntimeError error="failed to flush"
2023-07-09 20:34:27 +0900 [warn]: #0 failed to flush the buffer. retry_times=4 next_retry_time=2023-07-09 20:34:30 +0900 chunk="6000c24aaa6eca9d4804dc4a11dc0e52" error_class=RuntimeError error="failed to flush"
2023-07-09 20:34:30 +0900 [warn]: #0 failed to flush the buffer. retry_times=5 next_retry_time=2023-07-09 20:34:34 +0900 chunk="6000c24aaa6eca9d4804dc4a11dc0e52" error_class=RuntimeError error="failed to flush"
2023-07-09 20:34:33 +0900 [warn]: #0 failed to flush the buffer. retry_times=6 next_retry_time=2023-07-09 20:34:37 +0900 chunk="6000c24aaa6eca9d4804dc4a11dc0e52" error_class=RuntimeError error="failed to flush"
2023-07-09 20:34:37 +0900 [warn]: #0 failed to flush the buffer. retry_times=7 next_retry_time=2023-07-09 20:34:40 +0900 chunk="6000c24aaa6eca9d4804dc4a11dc0e52" error_class=RuntimeError error="failed to flush"
2023-07-09 20:34:39 +0900 [warn]: #0 failed to flush the buffer. retry_times=8 next_retry_time=2023-07-09 20:34:43 +0900 chunk="6000c24aaa6eca9d4804dc4a11dc0e52" error_class=RuntimeError error="failed to flush"
2023-07-09 20:34:42 +0900 [warn]: #0 failed to flush the buffer. retry_times=9 next_retry_time=2023-07-09 20:34:46 +0900 chunk="6000c24aaa6eca9d4804dc4a11dc0e52" error_class=RuntimeError error="failed to flush"
2023-07-09 20:34:45 +0900 [warn]: #0 failed to flush the buffer. retry_times=10 next_retry_time=2023-07-09 20:34:49 +0900 chunk="6000c24aaa6eca9d4804dc4a11dc0e52" error_class=RuntimeError error="failed to flush"
2023-07-09 20:34:48 +0900 [warn]: #0 failed to flush the buffer. retry_times=11 next_retry_time=2023-07-09 20:34:52 +0900 chunk="6000c24aaa6eca9d4804dc4a11dc0e52" error_class=RuntimeError error="failed to flush"
2023-07-09 20:34:51 +0900 [warn]: #0 failed to flush the buffer. retry_times=12 next_retry_time=2023-07-09 20:34:55 +0900 chunk="6000c24aaa6eca9d4804dc4a11dc0e52" error_class=RuntimeError error="failed to flush"
2023-07-09 20:34:55 +0900 [warn]: #0 failed to flush the buffer. retry_times=13 next_retry_time=2023-07-09 20:34:58 +0900 chunk="6000c24aaa6eca9d4804dc4a11dc0e52" error_class=RuntimeError error="failed to flush"
2023-07-09 20:34:58 +0900 [warn]: #0 failed to flush the buffer. retry_times=14 next_retry_time=2023-07-09 20:35:01 +0900 chunk="6000c24aaa6eca9d4804dc4a11dc0e52" error_class=RuntimeError error="failed to flush"
2023-07-09 20:35:01 +0900 [warn]: #0 failed to flush the buffer. retry_times=15 next_retry_time=2023-07-09 20:35:04 +0900 chunk="6000c24aaa6eca9d4804dc4a11dc0e52" error_class=RuntimeError error="failed to flush"

[raulgupto]

Do you mean the prometheus metrics is showing it like that and its not the retry behaviour ? Because I do not agree with this, as the metrics exposed by prometheus has accurate count of retry times as well. Can you please retry this behaviour with copy plugin and with prometheus included in the copy.

[daipom]

https://github.com/fluent/fluent-plugin-prometheus/blob/41fa2df366ceef7b46de154859c852926cba48a9/lib/fluent/plugin/in_prometheus_output_monitor.rb#L194-L207

Looks like that fluent-plugin-prometheus calculates as follows.

• next_time - start

start is not the last time, but the first retry time.
This would be the cause.

We need to check if this is a bug of Fluentd or fluent-plugin-prometheus.

[daipom]

It seems that Fluentd defines start as the start of the retry (retry_times=0), and it is not wrong.

I think this is a bug of fluent-plugin-prometheus.
The value output_status_retry_wait means the elapsed time for the start of the retry (retry_times=0).

If using exponential_backoff, the value would be wrong and hard to notice.
If using periodic, the value would be completely wrong and easy to notice.

fluentd/lib/fluent/plugin/in_monitor_agent.rb

Lines 368 to 384 in aaa40f7

	RETRY_INFO = {
	'start' => '@start',
	'steps' => '@steps',
	'next_time' => '@next_time',
	}
	def get_retry_info(pe_retry)
	retry_variables = {}
	if pe_retry
	RETRY_INFO.each_pair { |key, param|
	retry_variables[key] = pe_retry.instance_variable_get(param)
	}
	end
	retry_variables
	end

• retry_state: https://github.com/fluent/fluentd/blob/aaa40f71758eb5fa7b3a89084e69a00c0910fb3b/lib/fluent/plugin_helper/retry_state.rb

[daipom]

I have made the issue for fluent-plugin-prometheus: fluent/fluent-plugin-prometheus#217

I close this issue now.
Thanks for your report @raulgupto!