Forwarder error - temporarily failed to flush the buffer - Bad file descriptor

4,078 views
Skip to first unread message

Ian Sherman

unread,
Oct 6, 2015, 5:42:29 AM10/6/15
to Fluentd Google Group
Hi,

I'm having a problem with a forwarder on a single server.  I'm using the secure-forward plugin with td-agent-2.2.1-0.el6.x86_64 on CentOS 6.5

scrubbed configuration file is as follows

<source>
  type tail
  path /var/log/asterisk/queue_log
  pos_file /var/log/td-agent/queue_log.pos
  tag xxx_yyy.queue_log
  format /(?<epoch>\d*)\|(?<uniqueid>[^|]*)\|(?<queue>[^|]*)\|(?<agent>[^|]*)\|(?<event>[^|]*)\|?(?<data1>[^|]*)?\|?(?<data2>[^|]*)?\|?(?<data3>[^|]*)?\|?(?<data4>[^|]*)?\|?(?<data5>[^|]*)?/
  time_format %s
</source>

<match xxx_yyy.queue_log>
  type secure_forward
  send_timeout 60s
  self_hostname host.example.com
  shared_key    secret
  secure yes
  ca_cert_path /etc/td-agent/cert.pem
  keepalive 30
  flush_interval 1s
  buffer_type file
  buffer_path /var/log/td-agent/
  disable_retry_limit true
  <server>
    host fluentd.example.com
  </server>
</match>


It was working perfectly and then suddenly stopped transmitting.  Restarting the service produces the following errors in the td-agent log file.


2015-10-05 10:53:19 +0200 [warn]: temporarily failed to flush the buffer. next_retry=2015-10-05 11:26:34 +0200 error_class="Errno::EBADF" error="Bad file descriptor" plugin_id="object:3fe1c799be50"
  2015-10-05 10:53:19 +0200 [warn]: suppressed same stacktrace
2015-10-05 11:26:56 +0200 [warn]: temporarily failed to flush the buffer. next_retry=2015-10-05 12:41:50 +0200 error_class="Errno::EBADF" error="Bad file descriptor" plugin_id="object:3fe1c799be50"
  2015-10-05 11:26:56 +0200 [warn]: suppressed same stacktrace
2015-10-05 12:42:26 +0200 [warn]: temporarily failed to flush the buffer. next_retry=2015-10-05 14:53:54 +0200 error_class="Errno::EBADF" error="Bad file descriptor" plugin_id="object:3fe1c799be50"
  2015-10-05 12:42:26 +0200 [warn]: suppressed same stacktrace
2015-10-05 14:54:19 +0200 [warn]: temporarily failed to flush the buffer. next_retry=2015-10-05 19:52:54 +0200 error_class="Errno::EBADF" error="Bad file descriptor" plugin_id="object:3fe1c799be50"
  2015-10-05 14:54:19 +0200 [warn]: suppressed same stacktrace
2015-10-05 19:52:59 +0200 [warn]: temporarily failed to flush the buffer. next_retry=2015-10-06 04:48:08 +0200 error_class="Errno::EBADF" error="Bad file descriptor" plugin_id="object:3fe1c799be50"
  2015-10-05 19:52:59 +0200 [warn]: suppressed same stacktrace
2015-10-06 03:06:01 +0200 [info]: force flushing buffered events


Any idea what is causing this?   I'm happy to provide more debugging information but I just need some idea on what to send through.  

Regards,
Ian Sherman

Mr. Fiber

unread,
Oct 6, 2015, 5:49:19 AM10/6/15
to Fluentd Google Group
Could you show me stacktrace logs?

> suppressed same stacktrace

Before this log, you got entire logs including stacktrace.


Masahiro

--
You received this message because you are subscribed to the Google Groups "Fluentd Google Group" group.
To unsubscribe from this group and stop receiving emails from it, send an email to fluentd+u...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Ian Sherman

unread,
Oct 6, 2015, 6:21:10 AM10/6/15
to Fluentd Google Group
Thanks for the quick response.  Full log file below

[root@localhost ~]# cat /var/log/td-agent/td-agent.log
2015-10-06 03:06:35 +0200 [warn]: temporarily failed to flush the buffer. next_retry=2015-10-06 20:33:12 +0200 error_class="Errno::EBADF" error="Bad file descriptor" plugin_id="object:3fe1c799be50"
  2015-10-06 03:06:35 +0200 [warn]: suppressed same stacktrace
2015-10-06 11:40:11 +0200 [info]: shutting down fluentd
2015-10-06 11:40:11 +0200 [info]: process finished code=0
2015-10-06 11:40:17 +0200 [info]: reading config file path="/etc/td-agent/td-agent.conf"
2015-10-06 11:40:17 +0200 [info]: starting fluentd-0.12.12
2015-10-06 11:40:17 +0200 [info]: gem 'fluent-mixin-config-placeholders' version '0.3.0'
2015-10-06 11:40:17 +0200 [info]: gem 'fluent-mixin-plaintextformatter' version '0.2.6'
2015-10-06 11:40:17 +0200 [info]: gem 'fluent-plugin-mongo' version '0.7.10'
2015-10-06 11:40:17 +0200 [info]: gem 'fluent-plugin-rewrite-tag-filter' version '1.4.1'
2015-10-06 11:40:17 +0200 [info]: gem 'fluent-plugin-s3' version '0.5.9'
2015-10-06 11:40:17 +0200 [info]: gem 'fluent-plugin-scribe' version '0.10.14'
2015-10-06 11:40:17 +0200 [info]: gem 'fluent-plugin-secure-forward' version '0.3.2'
2015-10-06 11:40:17 +0200 [info]: gem 'fluent-plugin-td' version '0.10.27'
2015-10-06 11:40:17 +0200 [info]: gem 'fluent-plugin-td-monitoring' version '0.2.1'
2015-10-06 11:40:17 +0200 [info]: gem 'fluent-plugin-webhdfs' version '0.4.1'
2015-10-06 11:40:17 +0200 [info]: gem 'fluentd' version '0.12.12'
2015-10-06 11:40:17 +0200 [info]: adding match pattern="xxx_yyy.queue_log" type="secure_forward"
2015-10-06 11:40:17 +0200 [info]: adding match pattern="td.*.*" type="tdlog"
2015-10-06 11:40:17 +0200 [info]: adding match pattern="debug.**" type="stdout"
2015-10-06 11:40:17 +0200 [info]: adding source type="tail"
2015-10-06 11:40:17 +0200 [info]: adding source type="forward"
2015-10-06 11:40:17 +0200 [info]: adding source type="http"
2015-10-06 11:40:17 +0200 [info]: adding source type="debug_agent"
2015-10-06 11:40:17 +0200 [info]: using configuration file: <ROOT>

  <source>
    type tail
    path /var/log/asterisk/queue_log
    pos_file /var/log/td-agent/queue_log.pos
    tag xxx_yyy.queue_log
    format /(?<epoch>\d*)\|(?<uniqueid>[^|]*)\|(?<queue>[^|]*)\|(?<agent>[^|]*)\|(?<event>[^|]*)\|?(?<data1>[^|]*)?\|?(?<data2>[^|]*)?\|?(?<data3>[^|]*)?\|?(?<data4>[^|]*)?\|?(?<data5>[^|]*)?/
    time_format %s
  </source>
  <match xxx_yyy.queue_log>
    type secure_forward
    send_timeout 60s
    self_hostname host.example.com
    shared_key secret
    secure yes
    ca_cert_path /etc/td-agent/cert.pem
    keepalive 30
    flush_interval 1s
    buffer_type file
    buffer_path /var/log/td-agent/
    disable_retry_limit true
    <server>
      host fluentd.example.com
    </server>
  </match>
  <match td.*.*>
    type tdlog
    apikey xxxxxx
    auto_create_table
    buffer_type file
    buffer_path /var/log/td-agent/buffer/td
    <secondary>
      type file
      path /var/log/td-agent/failed_records
      buffer_path /var/log/td-agent/failed_records.*
    </secondary>
  </match>
  <match debug.**>
    type stdout
  </match>
  <source>
    type forward
  </source>
  <source>
    type http
    port 8888
  </source>
  <source>
    type debug_agent
    bind 127.0.0.1
    port 24230
  </source>
</ROOT>
2015-10-06 11:40:17 +0200 [info]: following tail of /var/log/asterisk/queue_log
2015-10-06 11:40:17 +0200 [info]: listening fluent socket on 0.0.0.0:24224
2015-10-06 11:40:17 +0200 [info]: listening dRuby uri="druby://127.0.0.1:24230" object="Engine"
2015-10-06 11:40:18 +0200 [warn]: temporarily failed to flush the buffer. next_retry=2015-10-06 11:40:19 +0200 error_class="RuntimeError" error="no one nodes with valid ssl session" plugin_id="object:3ff88bd9bdcc"
  2015-10-06 11:40:18 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-secure-forward-0.3.2/lib/fluent/plugin/out_secure_forward.rb:233:in `write_objects'
  2015-10-06 11:40:18 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/output.rb:463:in `write'
  2015-10-06 11:40:18 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/buffer.rb:325:in `write_chunk'
  2015-10-06 11:40:18 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/buffer.rb:304:in `pop'
  2015-10-06 11:40:18 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/output.rb:321:in `try_flush'
  2015-10-06 11:40:18 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/output.rb:140:in `run'
2015-10-06 11:40:18 +0200 [info]: connection established to fluentd.example.com
2015-10-06 11:40:58 +0200 [warn]: temporarily failed to flush the buffer. next_retry=2015-10-06 11:40:21 +0200 error_class="Errno::EBADF" error="Bad file descriptor" plugin_id="object:3ff88bd9bdcc"
  2015-10-06 11:40:58 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/2.1.0/openssl/buffering.rb:326:in `syswrite'
  2015-10-06 11:40:58 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/2.1.0/openssl/buffering.rb:326:in `do_write'
  2015-10-06 11:40:58 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/2.1.0/openssl/buffering.rb:344:in `write'
  2015-10-06 11:40:58 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/2.1.0/fileutils.rb:494:in `copy_stream'
  2015-10-06 11:40:58 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/2.1.0/fileutils.rb:494:in `copy_stream'
  2015-10-06 11:40:58 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/buffer.rb:109:in `block in write_to'
  2015-10-06 11:40:58 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/plugin/buf_file.rb:64:in `open'
  2015-10-06 11:40:58 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/buffer.rb:108:in `write_to'
  2015-10-06 11:40:58 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-secure-forward-0.3.2/lib/fluent/plugin/out_secure_forward.rb:274:in `send_data'
  2015-10-06 11:40:58 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-secure-forward-0.3.2/lib/fluent/plugin/out_secure_forward.rb:238:in `write_objects'
  2015-10-06 11:40:58 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/output.rb:463:in `write'
  2015-10-06 11:40:58 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/buffer.rb:325:in `write_chunk'
  2015-10-06 11:40:58 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/buffer.rb:304:in `pop'
  2015-10-06 11:40:58 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/output.rb:321:in `try_flush'
  2015-10-06 11:40:58 +0200 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/output.rb:140:in `run'
2015-10-06 11:41:38 +0200 [warn]: temporarily failed to flush the buffer. next_retry=2015-10-06 11:40:24 +0200 error_class="Errno::EBADF" error="Bad file descriptor" plugin_id="object:3ff88bd9bdcc"
  2015-10-06 11:41:38 +0200 [warn]: suppressed same stacktrace
2015-10-06 11:42:13 +0200 [warn]: temporarily failed to flush the buffer. next_retry=2015-10-06 11:40:32 +0200 error_class="Errno::EBADF" error="Bad file descriptor" plugin_id="object:3ff88bd9bdcc"
  2015-10-06 11:42:13 +0200 [warn]: suppressed same stacktrace
2015-10-06 11:42:52 +0200 [warn]: temporarily failed to flush the buffer. next_retry=2015-10-06 11:40:48 +0200 error_class="Errno::EBADF" error="Bad file descriptor" plugin_id="object:3ff88bd9bdcc"
  2015-10-06 11:42:52 +0200 [warn]: suppressed same stacktrace
2015-10-06 11:43:28 +0200 [warn]: temporarily failed to flush the buffer. next_retry=2015-10-06 11:41:17 +0200 error_class="Errno::EBADF" error="Bad file descriptor" plugin_id="object:3ff88bd9bdcc"
  2015-10-06 11:43:28 +0200 [warn]: suppressed same stacktrace
2015-10-06 11:44:08 +0200 [warn]: temporarily failed to flush the buffer. next_retry=2015-10-06 11:42:25 +0200 error_class="Errno::EBADF" error="Bad file descriptor" plugin_id="object:3ff88bd9bdcc"
  2015-10-06 11:44:08 +0200 [warn]: suppressed same stacktrace
2015-10-06 11:44:43 +0200 [warn]: temporarily failed to flush the buffer. next_retry=2015-10-06 11:44:22 +0200 error_class="Errno::EBADF" error="Bad file descriptor" plugin_id="object:3ff88bd9bdcc"
  2015-10-06 11:44:43 +0200 [warn]: suppressed same stacktrace
2015-10-06 11:45:24 +0200 [warn]: temporarily failed to flush the buffer. next_retry=2015-10-06 11:48:09 +0200 error_class="Errno::EBADF" error="Bad file descriptor" plugin_id="object:3ff88bd9bdcc"
  2015-10-06 11:45:24 +0200 [warn]: suppressed same stacktrace
2015-10-06 11:48:28 +0200 [warn]: temporarily failed to flush the buffer. next_retry=2015-10-06 11:56:40 +0200 error_class="Errno::EBADF" error="Bad file descriptor" plugin_id="object:3ff88bd9bdcc"
  2015-10-06 11:48:28 +0200 [warn]: suppressed same stacktrace
2015-10-06 11:57:03 +0200 [warn]: temporarily failed to flush the buffer. next_retry=2015-10-06 12:14:42 +0200 error_class="Errno::EBADF" error="Bad file descriptor" plugin_id="object:3ff88bd9bdcc"
  2015-10-06 11:57:03 +0200 [warn]: suppressed same stacktrace

Mr. Fiber

unread,
Oct 6, 2015, 6:59:39 AM10/6/15
to Fluentd Google Group
I'm not sure why this error happen.
BTW, you should add prefix to secure-forward's buffer_path.

> buffer_path /var/log/td-agent/

From this configuration, secure-forward seems to use entire files under /var/log/td-agent as a buffer files, e.g. /var/log/td-agent/td-agent.log.

If this problem is reproducible, dump chunk file path is very useful.
Could you add "log.info es.path" to out_secure_forward.rb? Maybe after this line.


Ian Sherman

unread,
Oct 6, 2015, 7:44:26 AM10/6/15
to Fluentd Google Group
Thanks Masahiro.  

Changing the buffer_path to buffer_path /var/log/td-agent/queue_log.*.buffer has fixed the error.
Reply all
Reply to author
Forward
0 new messages