"OpenSSL::SSL::SSLError: Received fatal alert: handshake_failure" in http output

[nfelger]

Hi!

I just upgraded from 1.4.1 to 1.5.3 – almost everything works perfectly, except my http output now fails with OpenSSL::SSL::SSLError: Received fatal alert: handshake_failure for all events. I tried Google and the IRC channel, but haven't been able to get to the bottom of this. (No idea if this is connected to #3657.)

I'm using:

Logstash: 1.5.3
Logstash-forwarder: 0.4.0
Java: java version "1.7.0_79" / OpenJDK Runtime Environment (IcedTea 2.5.6) (7u79-2.5.6-0ubuntu1.14.04.1) / OpenJDK 64-Bit Server VM (build 24.79-b02, mixed mode)

The output config:

output {
  if [type] == "python" and [message] =~ "^slack-it:" {
    if [grab_url] !~ "XXX" {
      http {
        http_method => "post"
        format => 'json'
        mapping => {
          "text" => "%{img_url} url: %{grab_url}, mobile: %{mobile}"
          "icon_emoji" => ":camera:"
          "username" => "slack-it"
        }
        url => 'https://hooks.slack.com/services/XXX/XXX/XXX'
      }
    }
  }
}

The output is trying to connect to hooks.slack.com, but fails. I can connect ok from the host running logstash:

$ openssl s_client -connect hooks.slack.com:443
...
SSL handshake has read 3030 bytes and written 421 bytes

---
New, TLSv1/SSLv3, Cipher is ECDHE-RSA-AES128-GCM-SHA256
Server public key is 2048 bit
Secure Renegotiation IS supported
Compression: NONE
Expansion: NONE
SSL-Session:
    Protocol  : TLSv1.2
    Cipher    : ECDHE-RSA-AES128-GCM-SHA256
...

Here's a --debug log output:

{:timestamp=>"2015-08-10T17:58:22.031000+0000", :message=>"Flushing", :plugin=><LogStash::Filters::Multiline pattern=>"^\\S*?([Ee]rror|Exception):\\s", what=>"previous", periodic_flush=>true, source=>"message", allow_duplicates=>true, negate=>false, stream_identity=>"%{host}.%{path}.%{type}", max_age=>5>, :level=>:debug, :file=>"(eval)", :line=>"612", :method=>"initialize"}
{:timestamp=>"2015-08-10T17:58:25.834000+0000", :message=>"config LogStash::Codecs::Plain/@charset = \"UTF-8\"", :level=>:debug, :file=>"logstash/config/mixin.rb", :line=>"112", :method=>"config_init"}
{:timestamp=>"2015-08-10T17:58:25.879000+0000", :message=>"filter received", :event=>{"message"=>"{\"tags\": [], \"mobile\": true, \"@version\": 1, \"@timestamp\": \"2015-08-10T17:52:10.269135Z\", \"grab_url\": \"http://example.com\", \"host\": \"somehost\", \"path\": \"/some/path\", \"logger\": \"serve\", \"type\": \"python\", \"message\": \"slack-it: grab finished\", \"levelname\": \"INFO\", \"img_url\": \"https://someurl\"}", "@version"=>"1", "@timestamp"=>"2015-08-10T17:58:25.875Z", "file"=>"/mnt/log/testing.logstash", "host"=>"ip-10-0-4-128", "offset"=>"290", "type"=>"python"}, :level=>:debug, :file=>"(eval)", :line=>"907", :method=>"filter_func"}
{:timestamp=>"2015-08-10T17:58:25.880000+0000", :message=>"Running json filter", :event=>#<LogStash::Event:0x74a4ebd7 @metadata={}, @accessors=#<LogStash::Util::Accessors:0x7777ac14 @store={"message"=>"{\"tags\": [], \"mobile\": true, \"@version\": 1, \"@timestamp\": \"2015-08-10T17:52:10.269135Z\", \"grab_url\": \"http://example.com\", \"host\": \"somehost\", \"path\": \"/some/path\", \"logger\": \"serve\", \"type\": \"python\", \"message\": \"slack-it: grab finished\", \"levelname\": \"INFO\", \"img_url\": \"https://someurl\"}", "@version"=>"1", "@timestamp"=>"2015-08-10T17:58:25.875Z", "file"=>"/mnt/log/testing.logstash", "host"=>"ip-10-0-4-128", "offset"=>"290", "type"=>"python"}, @lut={"file"=>[{"message"=>"{\"tags\": [], \"mobile\": true, \"@version\": 1, \"@timestamp\": \"2015-08-10T17:52:10.269135Z\", \"grab_url\": \"http://example.com\", \"host\": \"somehost\", \"path\": \"/some/path\", \"logger\": \"serve\", \"type\": \"python\", \"message\": \"slack-it: grab finished\", \"levelname\": \"INFO\", \"img_url\": \"https://someurl\"}", "@version"=>"1", "@timestamp"=>"2015-08-10T17:58:25.875Z", "file"=>"/mnt/log/testing.logstash", "host"=>"ip-10-0-4-128", "offset"=>"290", "type"=>"python"}, "file"], "host"=>[{"message"=>"{\"tags\": [], \"mobile\": true, \"@version\": 1, \"@timestamp\": \"2015-08-10T17:52:10.269135Z\", \"grab_url\": \"http://example.com\", \"host\": \"somehost\", \"path\": \"/some/path\", \"logger\": \"serve\", \"type\": \"python\", \"message\": \"slack-it: grab finished\", \"levelname\": \"INFO\", \"img_url\": \"https://someurl\"}", "@version"=>"1", "@timestamp"=>"2015-08-10T17:58:25.875Z", "file"=>"/mnt/log/testing.logstash", "host"=>"ip-10-0-4-128", "offset"=>"290", "type"=>"python"}, "host"], "offset"=>[{"message"=>"{\"tags\": [], \"mobile\": true, \"@version\": 1, \"@timestamp\": \"2015-08-10T17:52:10.269135Z\", \"grab_url\": \"http://example.com\", \"host\": \"somehost\", \"path\": \"/some/path\", \"logger\": \"serve\", \"type\": \"python\", \"message\": \"slack-it: grab finished\", \"levelname\": \"INFO\", \"img_url\": \"https://someurl\"}", "@version"=>"1", "@timestamp"=>"2015-08-10T17:58:25.875Z", "file"=>"/mnt/log/testing.logstash", "host"=>"ip-10-0-4-128", "offset"=>"290", "type"=>"python"}, "offset"], "type"=>[{"message"=>"{\"tags\": [], \"mobile\": true, \"@version\": 1, \"@timestamp\": \"2015-08-10T17:52:10.269135Z\", \"grab_url\": \"http://example.com\", \"host\": \"somehost\", \"path\": \"/some/path\", \"logger\": \"serve\", \"type\": \"python\", \"message\": \"slack-it: grab finished\", \"levelname\": \"INFO\", \"img_url\": \"https://someurl\"}", "@version"=>"1", "@timestamp"=>"2015-08-10T17:58:25.875Z", "file"=>"/mnt/log/testing.logstash", "host"=>"ip-10-0-4-128", "offset"=>"290", "type"=>"python"}, "type"], "[type]"=>[{"message"=>"{\"tags\": [], \"mobile\": true, \"@version\": 1, \"@timestamp\": \"2015-08-10T17:52:10.269135Z\", \"grab_url\": \"http://example.com\", \"host\": \"somehost\", \"path\": \"/some/path\", \"logger\": \"serve\", \"type\": \"python\", \"message\": \"slack-it: grab finished\", \"levelname\": \"INFO\", \"img_url\": \"https://someurl\"}", "@version"=>"1", "@timestamp"=>"2015-08-10T17:58:25.875Z", "file"=>"/mnt/log/testing.logstash", "host"=>"ip-10-0-4-128", "offset"=>"290", "type"=>"python"}, "type"]}>, @data={"message"=>"{\"tags\": [], \"mobile\": true, \"@version\": 1, \"@timestamp\": \"2015-08-10T17:52:10.269135Z\", \"grab_url\": \"http://example.com\", \"host\": \"somehost\", \"path\": \"/some/path\", \"logger\": \"serve\", \"type\": \"python\", \"message\": \"slack-it: grab finished\", \"levelname\": \"INFO\", \"img_url\": \"https://someurl\"}", "@version"=>"1", "@timestamp"=>"2015-08-10T17:58:25.875Z", "file"=>"/mnt/log/testing.logstash", "host"=>"ip-10-0-4-128", "offset"=>"290", "type"=>"python"}, @metadata_accessors=#<LogStash::Util::Accessors:0x86f14f0 @store={}, @lut={}>, @cancelled=false>, :level=>:debug, :file=>"logstash/filters/json.rb", :line=>"58", :method=>"filter"}
{:timestamp=>"2015-08-10T17:58:25.896000+0000", :message=>"Event after json filter", :event=>#<LogStash::Event:0x74a4ebd7 @metadata={}, @accessors=#<LogStash::Util::Accessors:0x7777ac14 @store={"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, @lut={"file"=>[{"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, "file"], "host"=>[{"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, "host"], "offset"=>[{"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, "offset"], "type"=>[{"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, "type"], "[type]"=>[{"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, "type"], "message"=>[{"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, "message"]}>, @data={"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, @metadata_accessors=#<LogStash::Util::Accessors:0x86f14f0 @store={}, @lut={}>, @cancelled=false>, :level=>:debug, :file=>"logstash/filters/json.rb", :line=>"101", :method=>"filter"}
{:timestamp=>"2015-08-10T17:58:25.908000+0000", :message=>"output received", :event=>{"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, :level=>:debug, :file=>"(eval)", :line=>"923", :method=>"output_func"}
{:timestamp=>"2015-08-10T17:58:25.937000+0000", :message=>"Flushing output", :outgoing_count=>1, :time_since_last_flush=>52.933, :outgoing_events=>{nil=>[["index", {:_id=>nil, :_index=>"logstash-2015.08.10", :_type=>"python", :_routing=>nil}, #<LogStash::Event:0x74a4ebd7 @metadata={"retry_count"=>0}, @accessors=#<LogStash::Util::Accessors:0x7777ac14 @store={"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, @lut={"file"=>[{"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, "file"], "host"=>[{"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, "host"], "offset"=>[{"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, "offset"], "type"=>[{"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, "type"], "[type]"=>[{"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, "type"], "message"=>[{"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, "message"], "[levelname]"=>[{"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, "levelname"]}>, @data={"message"=>"slack-it: grab finished", "@version"=>1, "@timestamp"=>"2015-08-10T17:52:10.269Z", "file"=>"/mnt/log/testing.logstash", "host"=>"somehost", "offset"=>"290", "type"=>"python", "tags"=><Java::JavaUtil::ArrayList:1 []>, "mobile"=>true, "grab_url"=>"http://example.com", "path"=>"/some/path", "logger"=>"serve", "levelname"=>"INFO", "img_url"=>"https://someurl"}, @metadata_accessors=#<LogStash::Util::Accessors:0x86f14f0 @store={"retry_count"=>0}, @lut={}>, @cancelled=false>]]}, :batch_timeout=>1, :force=>nil, :final=>nil, :level=>:debug, :file=>"stud/buffer.rb", :line=>"207", :method=>"buffer_flush"}
{:timestamp=>"2015-08-10T17:58:26.954000+0000", :message=>"Unhandled exception", :request=><FTW::Request(@13488) @protocol="https" @body="{\"text\":\"https://someurl\\nurl: http://example.com, mobile: true\",\"icon_emoji\":\":camera:\",\"username\":\"slack-it\"}" @method="POST" @headers=FTW::HTTP::Headers <{"host"=>"hooks.slack.com", "connection"=>"keep-alive", "content-type"=>"application/json", "content-length"=>111}> @version=1.1 @request_uri="/services/T0272DW4H/B02SC2UBB/0Dt5UDWtnbGFWELzennN9tkz" @logger=#<Cabin::Channel:0x538ef60 @subscriber_lock=#<Mutex:0x5ceb8a4d>, @data={}, @metrics=#<Cabin::Metrics:0x6bc4f4e3 @channel=#<Cabin::Channel:0x538ef60 ...>, @metrics={}, @metrics_lock=#<Mutex:0x4fa99a5b>>, @subscribers={}, @level=:info> @port=443 >, :response=>nil, :exception=>#<OpenSSL::SSL::SSLError: Received fatal alert: handshake_failure>, :stacktrace=>["org/jruby/ext/openssl/SSLSocket.java:195:in `connect_nonblock'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/ftw-0.0.44/lib/ftw/connection.rb:413:in `do_secure'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/ftw-0.0.44/lib/ftw/connection.rb:393:in `secure'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/ftw-0.0.44/lib/ftw/agent.rb:449:in `connect'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/ftw-0.0.44/lib/ftw/agent.rb:283:in `execute'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-http-1.0.0/lib/logstash/outputs/http.rb:126:in `receive'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.3-java/lib/logstash/outputs/base.rb:88:in `handle'", "(eval):941:in `output_func'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.3-java/lib/logstash/pipeline.rb:244:in `outputworker'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.3-java/lib/logstash/pipeline.rb:166:in `start_outputs'"], :level=>:warn, :file=>"logstash/outputs/http.rb", :line=>"133", :method=>"receive"}
{:timestamp=>"2015-08-10T17:58:27.030000+0000", :message=>"Flushing", :plugin=><LogStash::Filters::Multiline pattern=>"^\\s", what=>"previous", periodic_flush=>true, source=>"message", allow_duplicates=>true, negate=>false, stream_identity=>"%{host}.%{path}.%{type}", max_age=>5>, :level=>:debug, :file=>"(eval)", :line=>"579", :method=>"initialize"}
{:timestamp=>"2015-08-10T17:58:27.031000+0000", :message=>"Flushing", :plugin=><LogStash::Filters::Multiline pattern=>"^\\S*?([Ee]rror|Exception):\\s", what=>"previous", periodic_flush=>true, source=>"message", allow_duplicates=>true, negate=>false, stream_identity=>"%{host}.%{path}.%{type}", max_age=>5>, :level=>:debug, :file=>"(eval)", :line=>"612", :method=>"initialize"}

Please let me know if I can provide any other useful information!

[suyograo]

Related to #3657, we are working on a fix in 1.5.4. stay tuned!

[nfelger]

Thanks a lot for the quick response!

[suyograo]

1.5.4 and 1.4.5 has been released with this fix.

[nfelger]

@suyograo I just installed 1.5.4 for testing, and unfortunately it doesn't fix this issue for me. Is there anything I can do to help get to the bottom of this?
(Please note this is about outgoing http requests, not LSF->LS connections.)

More details below.

Confirming I've got 1.5.4.

$ /opt/logstash/bin/logstash --version
logstash 1.5.4

Minimal config with which I can replicate the error:

$ cat handshake_error.conf
input {
  stdin {}
}

output {
  http {
    http_method => "post"
    format => "json"
    mapping => {
      "text" => "%{message}"
    }
    url => "https://hooks.slack.com/services/XXX/XXX/XXX"
  }
}

Logstash debug ouput:

$ echo '{"message": "test 123"}' | /opt/logstash/bin/logstash --debug -f handshake_error.conf

Reading config file {:file=>"logstash/agent.rb", :level=>:debug, :line=>"309", :method=>"local_config"}
Compiled pipeline code:
        @inputs = []
        @filters = []
        @outputs = []
        @periodic_flushers = []
        @shutdown_flushers = []

          @input_stdin_1 = plugin("input", "stdin")

          @inputs << @input_stdin_1

          @output_http_2 = plugin("output", "http", LogStash::Util.hash_merge_many({ "http_method" => ("post") }, { "format" => ("json") }, { "mapping" => {("text") => ("%{message}")} }, { "url" => ("https://hooks.slack.com/services/XXX/XXX/XXX") }))

          @outputs << @output_http_2

  def filter_func(event)
    events = [event]
    @logger.debug? && @logger.debug("filter received", :event => event.to_hash)
    events
  end
  def output_func(event)
    @logger.debug? && @logger.debug("output received", :event => event.to_hash)
    @output_http_2.handle(event)

  end {:level=>:debug, :file=>"logstash/pipeline.rb", :line=>"29", :method=>"initialize"}
Plugin not defined in namespace, checking for plugin file {:type=>"input", :name=>"stdin", :path=>"logstash/inputs/stdin", :level=>:debug, :file=>"logstash/plugin.rb", :line=>"133", :method=>"lookup"}
Plugin not defined in namespace, checking for plugin file {:type=>"codec", :name=>"line", :path=>"logstash/codecs/line", :level=>:debug, :file=>"logstash/plugin.rb", :line=>"133", :method=>"lookup"}
config LogStash::Codecs::Line/@charset = "UTF-8" {:level=>:debug, :file=>"logstash/config/mixin.rb", :line=>"111", :method=>"config_init"}
config LogStash::Inputs::Stdin/@debug = false {:level=>:debug, :file=>"logstash/config/mixin.rb", :line=>"111", :method=>"config_init"}
config LogStash::Inputs::Stdin/@codec = <LogStash::Codecs::Line charset=>"UTF-8"> {:level=>:debug, :file=>"logstash/config/mixin.rb", :line=>"111", :method=>"config_init"}
config LogStash::Inputs::Stdin/@add_field = {} {:level=>:debug, :file=>"logstash/config/mixin.rb", :line=>"111", :method=>"config_init"}
Plugin not defined in namespace, checking for plugin file {:type=>"output", :name=>"http", :path=>"logstash/outputs/http", :level=>:debug, :file=>"logstash/plugin.rb", :line=>"133", :method=>"lookup"}
Plugin not defined in namespace, checking for plugin file {:type=>"codec", :name=>"plain", :path=>"logstash/codecs/plain", :level=>:debug, :file=>"logstash/plugin.rb", :line=>"133", :method=>"lookup"}
config LogStash::Codecs::Plain/@charset = "UTF-8" {:level=>:debug, :file=>"logstash/config/mixin.rb", :line=>"111", :method=>"config_init"}
config LogStash::Outputs::Http/@http_method = "post" {:level=>:debug, :file=>"logstash/config/mixin.rb", :line=>"111", :method=>"config_init"}
config LogStash::Outputs::Http/@format = "json" {:level=>:debug, :file=>"logstash/config/mixin.rb", :line=>"111", :method=>"config_init"}
config LogStash::Outputs::Http/@mapping = {"text"=>"%{message}"} {:level=>:debug, :file=>"logstash/config/mixin.rb", :line=>"111", :method=>"config_init"}
config LogStash::Outputs::Http/@url = "https://hooks.slack.com/services/XXX/XXX/XXX" {:level=>:debug, :file=>"logstash/config/mixin.rb", :line=>"111", :method=>"config_init"}
config LogStash::Outputs::Http/@type = "" {:level=>:debug, :file=>"logstash/config/mixin.rb", :line=>"111", :method=>"config_init"}
config LogStash::Outputs::Http/@tags = [] {:level=>:debug, :file=>"logstash/config/mixin.rb", :line=>"111", :method=>"config_init"}
config LogStash::Outputs::Http/@exclude_tags = [] {:level=>:debug, :file=>"logstash/config/mixin.rb", :line=>"111", :method=>"config_init"}
config LogStash::Outputs::Http/@codec = <LogStash::Codecs::Plain charset=>"UTF-8"> {:level=>:debug, :file=>"logstash/config/mixin.rb", :line=>"111", :method=>"config_init"}
config LogStash::Outputs::Http/@workers = 1 {:level=>:debug, :file=>"logstash/config/mixin.rb", :line=>"111", :method=>"config_init"}
config LogStash::Outputs::Http/@verify_ssl = true {:level=>:debug, :file=>"logstash/config/mixin.rb", :line=>"111", :method=>"config_init"}
Plugin is finished {:plugin=><LogStash::Inputs::Stdin debug=>false, codec=><LogStash::Codecs::Line charset=>"UTF-8">>, :level=>:info, :file=>"logstash/plugin.rb", :line=>"61", :method=>"finished"}
stdin shutting down. {:level=>:debug, :file=>"logstash/inputs/stdin.rb", :line=>"52", :method=>"teardown"}
Pipeline started {:level=>:info, :file=>"logstash/pipeline.rb", :line=>"87", :method=>"run"}
Logstash startup completed
output received {:event=>{"message"=>"{\"message\": \"test 123\"}", "@version"=>"1", "@timestamp"=>"2015-08-24T13:08:16.517Z", "host"=>"ip-10-0-4-128"}, :level=>:debug, :file=>"(eval)", :line=>"21", :method=>"output_func"}
Unhandled exception {:request=><FTW::Request(@13458) @protocol="https" @body="{\"text\":\"{\\\"message\\\": \\\"test 123\\\"}\"}" @method="POST" @headers=FTW::HTTP::Headers <{"host"=>"hooks.slack.com", "connection"=>"keep-alive", "content-type"=>"application/json", "content-length"=>38}> @version=1.1 @request_uri="/services/XXX/XXX/XXX" @logger=#<Cabin::Channel:0x3aa1abcd @subscriber_lock=#<Mutex:0x4c163dcd>, @data={}, @metrics=#<Cabin::Metrics:0x483384c1 @channel=#<Cabin::Channel:0x3aa1abcd ...>, @metrics={}, @metrics_lock=#<Mutex:0x2e50bfef>>, @subscribers={}, @level=:info> @port=443 >, :response=>nil, :exception=>#<OpenSSL::SSL::SSLError: Received fatal alert: handshake_failure>, :stacktrace=>["org/jruby/ext/openssl/SSLSocket.java:195:in `connect_nonblock'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/ftw-0.0.44/lib/ftw/connection.rb:413:in `do_secure'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/ftw-0.0.44/lib/ftw/connection.rb:393:in `secure'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/ftw-0.0.44/lib/ftw/agent.rb:449:in `connect'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/ftw-0.0.44/lib/ftw/agent.rb:283:in `execute'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-http-1.0.0/lib/logstash/outputs/http.rb:126:in `receive'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.4-java/lib/logstash/outputs/base.rb:88:in `handle'", "(eval):22:in `output_func'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.4-java/lib/logstash/pipeline.rb:244:in `outputworker'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.4-java/lib/logstash/pipeline.rb:166:in `start_outputs'"], :level=>:warn, :file=>"logstash/outputs/http.rb", :line=>"133", :method=>"receive"}
Plugin is finished {:plugin=><LogStash::Outputs::Http http_method=>"post", format=>"json", mapping=>{"text"=>"%{message}"}, url=>"https://hooks.slack.com/services/XXX/XXX/XXX", codec=><LogStash::Codecs::Plain charset=>"UTF-8">, workers=>1, verify_ssl=>true>, :level=>:info, :file=>"logstash/plugin.rb", :line=>"61", :method=>"finished"}
Pipeline shutdown complete. {:level=>:info, :file=>"logstash/pipeline.rb", :line=>"101", :method=>"run"}
Logstash shutdown completed

The OpenSSL::SSL::SSLError: Received fatal alert: handshake_failure is still in there.

[nfelger]

Not sure if this is at all helpful, but I stumbled on the -Djavax.net.debug=all flag, which gives this extended output:

trigger seeding of SecureRandom
done seeding SecureRandom
Using SSLEngineImpl.
trigger seeding of SecureRandom
done seeding SecureRandom
Using SSLEngineImpl.
Allow unsafe renegotiation: false
Allow legacy hello messages: true
Is initial handshake: true
Is secure renegotiation: false
%% No cached client session
*** ClientHello, TLSv1.1
RandomCookie:  GMT: 1423645977 bytes = { 8, 6, 22, 206, 50, 158, 56, 205, 124, 24, 113, 23, 9, 131, 108, 134, 112, 178, 7, 17, 46, 85, 5, 44, 14, 170, 80, 18 }
Session ID:  {}
Cipher Suites: [TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA]
Compression Methods:  { 0 }
Extension renegotiation_info, renegotiated_connection: <empty>
***
[write] MD5 and SHA1 hashes:  len = 58
0000: 01 00 00 36 03 02 55 DB   1D 19 08 06 16 CE 32 9E  ...6..U.......2.
0010: 38 CD 7C 18 71 17 09 83   6C 86 70 B2 07 11 2E 55  8...q...l.p....U
0020: 05 2C 0E AA 50 12 00 00   08 00 39 00 38 00 33 00  .,..P.....9.8.3.
0030: 32 01 00 00 05 FF 01 00   01 00                    2.........
>output, WRITE: TLSv1.1 Handshake, length = 58
[Raw write]: length = 63
0000: 16 03 02 00 3A 01 00 00   36 03 02 55 DB 1D 19 08  ....:...6..U....
0010: 06 16 CE 32 9E 38 CD 7C   18 71 17 09 83 6C 86 70  ...2.8...q...l.p
0020: B2 07 11 2E 55 05 2C 0E   AA 50 12 00 00 08 00 39  ....U.,..P.....9
0030: 00 38 00 33 00 32 01 00   00 05 FF 01 00 01 00     .8.3.2.........
[Raw read]: length = 5
0000: 15 03 02 00 02                                     .....
[Raw read]: length = 2
0000: 02 28                                              .(
>output, READ: TLSv1.1 Alert, length = 2
>output, RECV TLSv1 ALERT:  fatal, handshake_failure
>output, fatal: engine already closed.  Rethrowing javax.net.ssl.SSLException: Received fatal alert: handshake_failure
>output, fatal: engine already closed.  Rethrowing javax.net.ssl.SSLException: Received fatal alert: handshake_failure
>output, called closeOutbound()
>output, closeOutboundInternal()
>output, SEND TLSv1 ALERT:  warning, description = close_notify
>output, WRITE: TLSv1 Alert, length = 2
[Raw write]: length = 7
0000: 15 03 01 00 02 01 00                               .......

[naneau]

Running into the exact same issue (incidentally, also calling https://hooks.slack.com/). Incoming LSF/LS connections work just fine, but the outgoing HTTP connection fails with handshake_failure

[nfelger]

@naneau I think this is due to a bug in the HTTP library used: jordansissel/ruby-ftw#31. Not sure it's any help, but if you know some Ruby, it's not actually very hard to write your own HTTP output plugin that just uses Net::HTTP until this gets fixed: https://www.elastic.co/guide/en/logstash/current/_how_to_write_a_logstash_output_plugin.html

[ph]

We are switching from ruby-ftw to manticore which should fix that situation, there is a PR in the work waiting for review logstash-plugins/logstash-output-http#19

[naneau]

Thinking about just using the exec output with a curl call in it as a temporary fix

[ph]

@naneau If you can give a shot with the PR and see if it fixes your issue that would be awesome.

[naneau]

@ph is there an easy way to do this in an existing logstash install?

[ph]

@naneau I think the easiest way would be to clone the repository and build the gem.

# need to be run under a jruby environement, you can use rbenv/rvm for that
gem build logstash-output-http.gemspec 

# In the logstash installation
bin/plugin install path/to/logstash-output-http.gem

[ph]

@naneau you can also use this logstash-plugins/logstash-output-slack#1, I haven't tested it and it is not released. But it's a specialized plugin for slack.

I did not know it existed.

[naneau]

@ph was using that but it seems to have broken in more recent LS versions. Server didn't have RVM available so haven't been able to test that gem separately either. Using an exec output to do what I want now. I'll see if I can test that PR you mentioned elsewhere later.

[ph]

@naneau we just released a new version for logstash-output-http that include logstash-plugins/logstash-output-http#19, You can update the plugin by using this command bin/plugin update logstash-output-http

[naneau]

@ph can confirm, with the updated plugin, this problem no longer occurs. Thanks!

[ph]

@naneau thanks for confirming this, I will close this issue.

[ShinJJang]

+1 I also have same problem. Could I know when this change reflect to stable version?

[ph]

@ShinJJang this updated plugin will be part of logstash 2.0

[ShinJJang]

@ph Thanks for reply!