TCP output throws NPE with ssl

[jswid]

I am using TCP output with ssl certs and the logstash-6.3.1. All components are 6.3.1, as this is a relatively new install. The flow is using two logstash nodes that use input to tcp output on the sending side, then tcp input to elasticsearch on the receiving side.

The behavior I am seeing is that the sending logstash shows repeated errors in the logs, but I do not see errors on the receiving side. When I initially boot logstash to send the logs, nothing appears in elasticsearch. However when I quit the sending logstash, a couple log messages will appear in ES, with a timestamp of when the sending logstash was started!

I don't think there is an issue with the certs or networking, because the beats input with ssl is working just fine on a different port. Also, a very small amount of data does get sent.

It is possible this issue is caused by a bug in jruby which has been fixed in a more recent version.

Here is the output plugin config

output {
  tcp {
    port => 8750
    host => "xxx.xxx.com"
    ssl_enable => true
    ssl_cacert => "/etc/logstash/ssl/ca.crt"
    ssl_key => "/etc/logstash/ssl/client.key"
    ssl_cert => "/etc/logstash/ssl/client.crt"
    ssl_verify => false
  }
}

I see this warning in the logs of the sending logstash

[2018-07-20T15:46:22,823][WARN ][logstash.outputs.tcp     ] tcp output exception {:host=>"xxx.xxx.com", :port=>8750, :exception=>java.lang.NullPointerException, :backtrace=>["org.jruby.ext.openssl.SSLSocket.callSite(SSLSocket.java:149)", ... 

The backtrace array in that message breaks into:

org.jruby.ext.openssl.SSLSocket.callSite(SSLSocket.java:149)
org.jruby.ext.openssl.SSLSocket.syswriteImpl(SSLSocket.java:899)
org.jruby.ext.openssl.SSLSocket.syswrite(SSLSocket.java:910)
org.jruby.ext.openssl.SSLSocket$INVOKER$i$1$0$syswrite.call(SSLSocket$INVOKER$i$1$0$syswrite.gen)
org.jruby.internal.runtime.methods.JavaMethod$JavaMethodOneOrN.call(JavaMethod.java:850)
org.jruby.ir.targets.InvokeSite.fail(InvokeSite.java:198)
usr.share.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_output_minus_tcp_minus_5_dot_0_dot_3.lib.logstash.outputs.tcp.RUBY$block$register$9(/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-output-tcp-5.0.3/lib/logstash/outputs/tcp.rb:159)
org.jruby.runtime.CompiledIRBlockBody.callDirect(CompiledIRBlockBody.java:145)
org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:71)
org.jruby.runtime.Block.call(Block.java:124)
org.jruby.RubyProc.call(RubyProc.java:289)
org.jruby.RubyProc.call19(RubyProc.java:273)
org.jruby.RubyProc$INVOKER$i$0$0$call19.call(RubyProc$INVOKER$i$0$0$call19.gen)
org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:145)
usr.share.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_codec_minus_json_minus_3_dot_0_dot_5.lib.logstash.codecs.json.RUBY$method$encode$0(/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-codec-json-3.0.5/lib/logstash/codecs/json.rb:42)
usr.share.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_codec_minus_json_minus_3_dot_0_dot_5.lib.logstash.codecs.json.RUBY$method$encode$0$__VARARGS__(/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-codec-json-3.0.5/lib/logstash/codecs/json.rb)
org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:77)
org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:93)
org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:145)
usr.share.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_output_minus_tcp_minus_5_dot_0_dot_3.lib.logstash.outputs.tcp.RUBY$method$receive$0(/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-output-tcp-5.0.3/lib/logstash/outputs/tcp.rb:201)
usr.share.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_output_minus_tcp_minus_5_dot_0_dot_3.lib.logstash.outputs.tcp.RUBY$method$receive$0$__VARARGS__(/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-output-tcp-5.0.3/lib/logstash/outputs/tcp.rb)
org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:77)
org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:93)
org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:145)
usr.share.logstash.logstash_minus_core.lib.logstash.outputs.base.RUBY$block$multi_receive$1(/usr/share/logstash/logstash-core/lib/logstash/outputs/base.rb:91)
...

I think this might be related to this bug, but I am not sure: https://github.com/jruby/jruby-openssl/issues/165

The NPE originates from the same line of code, although in my case, the initial handshake succeeds, but the NPEs begin to happen essentially immediately afterwards. If this bug is to blame, it would be in version jruby-openssl 0.10.0, and is fixed in version 0.10.1.

I do not know how to to test my theory any further or what to do to resolve the issue at this point.

[jswid]

I tried out some older versions of logstash. The only version which displays the error in the logs is 6.3.1. 6.3.0, 6.2.4, 6.2.0, and 6.1.0 do not show any warnings in their logs, but I only see them deliver 1 entry to elasticsearch, and again the entry does not show up until after the agent is shut down. Generally i wait a random interval under 3 minutes, and shut down and within 6 seconds, I see something new in elasticsearch.

The difference with 6.3.1 is that there is a warning in the logs, and while in all cases, nothing shows up until after logstash is shutdown, with 6.3.1, it delivers about 1 message per error message in the logs, which is on a retry loop about 8-10 seconds or so.