Thread existed by unexpected error: "Connection timeout - SSL"

[rolandjitsu]

Check CONTRIBUTING guideline first and here is the list to help us investigate the problem.

Describe the bug

After it encountered an exception it seems like it restarted itself. And it keeps doing this every now and then.

To Reproduce

Expected behavior

Is this normal behavior? Is there any way to prevent this for happening?

Your Environment

• Fluentd or td-agent version: td-agent 1.4.2
• Operating system:

NAME="Ubuntu"
VERSION="18.04.2 LTS (Bionic Beaver)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 18.04.2 LTS"
VERSION_ID="18.04"
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
VERSION_CODENAME=bionic
UBUNTU_CODENAME=bionic

• Kernel version: 4.15.0-1030-gcp

Note that the logs are coming from some IoT devices on a very slow connection, so some requests might take a long time or timeout quite often.

If you hit the problem with older fluentd version, try latest version first.

Your Configuration

# NOTE: Use for debug
#<system>
#  log_level debug
#</system>

# Receive messages from Fluent Bit
# https://docs.fluentd.org/v1.0/articles/in_forward
<source>
  @type forward
  #@log_level debug
  host 0.0.0.0
  port 5000
  <transport tls>
    cert_path /etc/td-agent/certs/fluentd.cert.pem
    private_key_path /etc/td-agent/certs/fluentd.key.pem
    private_key_passphrase someprivatepass
    client_cert_auth true
    ca_path /etc/td-agent/certs/ca.cert.pem
  </transport>
  <security>
    self_hostname my.host.org
    shared_key somesharedkey
  </security>
</source>

# NOTE: Use for debug
#<match *>
#  @type stdout
#</match>

# Save data in ES
# https://docs.fluentd.org/v1.0/articles/out_elasticsearch
<match {metrics,events}>
  @type elasticsearch
  #@log_level debug
  hosts 10.x.x.3:9200,10.x.x.4:9200
  user fluentd
  password "#{ENV['FLD_ES_PASS']}"
  index_name ${tag}
  include_timestamp true
  # If record does not have @timestamp key
  # See https://bit.ly/2VdhtFO
  time_key datetime
  #time_key_format %Y-%m-%dT%H:%M:%S.%N
  # https://github.com/uken/fluent-plugin-elasticsearch#reload_connections
  reload_connections false
  reload_on_failure true
  reconnect_on_error true
  # https://github.com/uken/fluent-plugin-elasticsearch/issues/620#issuecomment-519788865
  request_timeout 120s
  <buffer>
    # https://docs.fluentd.org/buffer/file
    @type file
    path /var/log/td-agent/es.buffer
    # Flush every 5s
    # https://docs.fluentd.org/v1.0/articles/output-plugin-overview#control-flushing
    flush_mode interval
    flush_interval 1
    flush_thread_count 2
  </buffer>
</match>

Your Error Log

2019-08-29 06:40:40 +0000 [info]: Worker 0 finished unexpectedly with status 1
2019-08-29 06:40:40 +0000 [info]: gem 'fluent-plugin-elasticsearch' version '3.4.3'
2019-08-29 06:40:40 +0000 [info]: gem 'fluent-plugin-kafka' version '0.9.2'
2019-08-29 06:40:40 +0000 [info]: gem 'fluent-plugin-prometheus' version '1.3.0'
2019-08-29 06:40:40 +0000 [info]: gem 'fluent-plugin-record-modifier' version '2.0.1'
2019-08-29 06:40:40 +0000 [info]: gem 'fluent-plugin-rewrite-tag-filter' version '2.1.1'
2019-08-29 06:40:40 +0000 [info]: gem 'fluent-plugin-s3' version '1.1.9'
2019-08-29 06:40:40 +0000 [info]: gem 'fluent-plugin-td' version '1.0.0'
2019-08-29 06:40:40 +0000 [info]: gem 'fluent-plugin-td-monitoring' version '0.2.4'
2019-08-29 06:40:40 +0000 [info]: gem 'fluent-plugin-webhdfs' version '1.2.3'
2019-08-29 06:40:40 +0000 [info]: gem 'fluentd' version '1.4.2'
2019-08-29 06:40:40 +0000 [info]: adding match pattern="{metrics,events}" type="elasticsearch"
2019-08-29 06:40:40 +0000 [warn]: #0 Detected ES 7.x or above: `_doc` will be used as the document `_type`.
2019-08-29 06:40:40 +0000 [info]: adding source type="forward"
2019-08-29 06:40:40 +0000 [warn]: parameter 'host' in <source>
  @type forward
  host 0.0.0.0
  port 5000
  <transport tls>
    cert_path "/etc/td-agent/certs/fluentd.cert.pem"
    private_key_path "/etc/td-agent/certs/fluentd.key.pem"
    private_key_passphrase xxxxxx
    client_cert_auth true
    ca_path "/etc/td-agent/certs/ca.cert.pem"
  </transport>
  <security>
    self_hostname "my.host.org"
    shared_key xxxxxx
  </security>
</source> is not used.
2019-08-29 06:40:40 +0000 [info]: #0 starting fluentd worker pid=6147 ppid=10639 worker=0
2019-08-29 06:40:40 +0000 [info]: #0 listening port port=5000 bind="0.0.0.0"
2019-08-29 06:40:40 +0000 [info]: #0 fluentd worker is now running worker=0
2019-08-29 06:41:02 +0000 [warn]: #0 no patterns matched tag="fluent-bit"
2019-08-29 06:41:18 +0000 [warn]: #0 no patterns matched tag="fluent-bit"
2019-08-29 06:42:35 +0000 [warn]: #0 no patterns matched tag="fluent-bit"
2019-08-29 06:44:33 +0000 [warn]: #0 no patterns matched tag="fluent-bit"
2019-08-29 06:48:54 +0000 [warn]: #0 no patterns matched tag="fluent-bit"
2019-08-29 06:56:33 +0000 [warn]: #0 no patterns matched tag="fluent-bit"
2019-08-29 07:12:27 +0000 [warn]: #0 no patterns matched tag="fluent-bit"
2019-08-29 07:44:23 +0000 [warn]: #0 no patterns matched tag="fluent-bit"
2019-08-29 08:48:00 +0000 [warn]: #0 thread exited by unexpected error plugin=Fluent::Plugin::ForwardInput title=:event_loop error_class=Errno::ETIMEDOUT error="Connection timed out - SSL_accept"
2019-08-29 08:48:00 +0000 [error]: #0 unexpected error error_class=Errno::ETIMEDOUT error="Connection timed out - SSL_accept"
  2019-08-29 08:48:00 +0000 [error]: #0 /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.4.2/lib/fluent/plugin_helper/server.rb:695:in `accept_nonblock'
  2019-08-29 08:48:00 +0000 [error]: #0 /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.4.2/lib/fluent/plugin_helper/server.rb:695:in `try_handshake'
  2019-08-29 08:48:00 +0000 [error]: #0 /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.4.2/lib/fluent/plugin_helper/server.rb:711:in `try_tls_accept'
  2019-08-29 08:48:00 +0000 [error]: #0 /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.4.2/lib/fluent/plugin_helper/server.rb:738:in `on_readable'
  2019-08-29 08:48:00 +0000 [error]: #0 /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/cool.io-1.5.4/lib/cool.io/io.rb:186:in `on_readable'
  2019-08-29 08:48:00 +0000 [error]: #0 /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/cool.io-1.5.4/lib/cool.io/loop.rb:88:in `run_once'
  2019-08-29 08:48:00 +0000 [error]: #0 /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/cool.io-1.5.4/lib/cool.io/loop.rb:88:in `run'
  2019-08-29 08:48:00 +0000 [error]: #0 /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.4.2/lib/fluent/plugin_helper/event_loop.rb:93:in `block in start'
  2019-08-29 08:48:00 +0000 [error]: #0 /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.4.2/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2019-08-29 08:48:00 +0000 [error]: #0 unexpected error error_class=Errno::ETIMEDOUT error="Connection timed out - SSL_accept"
  2019-08-29 08:48:00 +0000 [error]: #0 suppressed same stacktrace
2019-08-29 08:48:01 +0000 [info]: Worker 0 finished unexpectedly with status 1

Additional context

[repeatedly]

Duplicated #2592