EOFError when using tcp output plugin

[jordansissel]

(This issue was originally filed by @Akshaykapoor at elastic/logstash#2999)

---

I have a custom plugin which is inheriting the tcp output plugin. The error that i receive is,

tcp output exception {:host=>"localhost", :port=>3030, :exception=>#<EOFError: End of file reached>, :backtrace=>["org/jruby/RubyIO.java:3003:in `sysread'", "/opt/logstash/lib/logstash/outputs/tcp.rb:105:in `register'", "org/jruby/RubyProc.java:271:in `call'", "/opt/logstash/lib/logstash/codecs/json.rb:45:in `encode'", "/opt/logstash/lib/logstash/outputs/tcp_custom.rb:42:in `receive'", "/opt/logstash/lib/logstash/outputs/base.rb:86:in `handle'", "(eval):924:in `initialize'", "org/jruby/RubyProc.java:271:in `call'", "/opt/logstash/lib/logstash/pipeline.rb:266:in `output'", "/opt/logstash/lib/logstash/pipeline.rb:225:in `outputworker'", "/opt/logstash/lib/logstash/pipeline.rb:152:in `start_outputs'"], :level=>:warn}

This happens for every alternate event when received by sensu. I tried running with tcp output plugin but the results are still the same EOFError.

[Akshaykapoor]

Looking at the code, for output tcp plugin, i see the comment in there for the exception that is expected and i receive the same.

my tcp plugin config is on the default that is set to be the client, one thing i don't quite understand is the reason for this open read_socket. Maybe someone can help me in understanding this.

      @codec.on_event do |payload|
        begin
          client_socket = connect unless client_socket
          r,w,e = IO.select([client_socket], [client_socket], [client_socket], nil)
          # don't expect any reads, but a readable socket might
          # mean the remote end closed, so read it and throw it away.
          # we'll get an EOFError if it happens.
          client_socket.sysread(16384) if r.any?

          # Now send the payload
          client_socket.syswrite(payload) if w.any?
        rescue => e
          @logger.warn("tcp output exception", :host => @host, :port => @port,
                       :exception => e, :backtrace => e.backtrace)
          client_socket.close rescue nil
          client_socket = nil
          sleep @reconnect_interval
          retry

[Vehyla]

I am experiencing the same thing. It usually makes logstash fall over after a bit of time.

[stuart-warren]

/watch

[Akshaykapoor]

@stuart-warren what do you mean by your comment ?

[stuart-warren]

@Akshaykapoor I also have the same problem, so watching the ticket :)
Specifically logstash-output-tcp from one instance to another instance running logstash-input-tcp

[docwhat]

Is there a work-around until this is fixed?

[RMAdeveloper]

any news?

[cssccarvalho]

Hello,

I'm having the same problem of trying to use the logstash 2.3 with default tcp output plugin. My goal is to send json formated messages to sensu.

Can anybody help?

[signus]

I am seeing this issue on 2.3.4 and 5.0.0-alpha4 with logstash-output-tcp 3.2.0.

According to the register function:

# don't expect any reads, but a readable socket might
# mean the remote end closed, so read it and throw it away.
# we'll get an EOFError if it happens.

Where a readable socket without data means that the socket is ready to be closed. This should not be problematic, but if it is causing performance issues for people (probably means that the socket descriptor could be holding onto inodes for Linux/OSX), it needs to be looked into.

[beeleebow]

So no progress on this?

[ldormoy]

I encounter the same issue. tcp output plugin sending data to tcp input plugin.

[xtruthx]

i experienced the same issue. i am using a tcp output at logstash node1 and tcp input at logstash node2.
logstash version is 5.5.1 on node1 and on node2 it is logstash version 5.4.3. On the input node i am not able to use also 5.5.1. Reason is that i use plugin which depends acutally on this version.
Question is there a valid workaround. Sure using udp is may in my case a option but not the best. Both Systems are RHEL7 systems.

[jsmucr]

This goes deeper. I recently discovered a weird behavior with the GELF output plugin. Later I figured out it discards the first message it's supposed to send to a connection that has been closed by the server side. The situation is simple to simulate on Linux:

1. Create a numbered message generator of some kind.
2. Download NetCat.
3. Create a simple bridge-like Logstash configuration (i.e. raw UDP to raw TCP).
4. Run NetCat on localhost (i.e. nc -kl 12201)
5. Open another terminal window and generate some messages. All should be delivered to the first terminal window.
6. Close NetCat (Ctrl+C) and start it again.
7. Generate at least two numbered messages. All but the first one will be delivered.
8. In case of the tcp output plugin, an exception will appear in the log (which is how I finally learned what is wrong and found this thread).

This is IMHO a critical bug that needs to be fixed ASAP.

[jsmucr]

One more thing I've just discovered: There's indeed a retry attempt (as stated in the source code in posts above) but it successfully retries to send the second message. The first one is gone forever without anyone noticing.

[jsmucr]

I'm getting closer now. :-) The reason why the first message is lost is that sysread does not necessarily have to fail upon server disconnection: It succeeds if the server sends something to the client right before it terminates. The reason in my NetCat example was that I always sent back a few newlines from the client prior to pressing Ctrl+C so that I'd see the terminal output separated well enough.

[imacube]

Still seeing this error on 6.6.1. Logstash to logstash transfer of logs and using TLS (crosses the internet to a public end point).

[jyj1993126]

same problem here in 6.4.2

[samrui]

When the output server recovered, logstash still can't recover. And logstash file description still increase. following is exception logs:
[2019-08-01T00:08:49,284][WARN ][logstash.outputs.tcp ] tcp output exception {:host=>"192.168.3.158", :port=>8180, :exception=>#<EOFError: End of file reached>, :backtrace=>["org/jruby/RubyIO.java:2965:in sysread'", "/opt/o365/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-output-tcp-5.0.2/lib/logstash/outputs/tcp.rb:156:in block in register'", "/opt/o365/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-codec-json-3.0.5/lib/logstash/codecs/json.rb:42:in encode'", "/opt/o365/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-output-tcp-5.0.2/lib/logstash/outputs/tcp.rb:201:in receive'", "/opt/o365/logstash/logstash-core/lib/logstash/outputs/base.rb:92:in block in multi_receive'", "org/jruby/RubyArray.java:1734:in each'", "/opt/o365/logstash/logstash-core/lib/logstash/outputs/base.rb:92:in multi_receive'", "/opt/o365/logstash/logstash-core/lib/logstash/output_delegator_strategies/single.rb:15:in block in multi_receive'", "org/jruby/ext/thread/Mutex.java:148:in synchronize'", "/opt/o365/logstash/logstash-core/lib/logstash/output_delegator_strategies/single.rb:14:in multi_receive'", "/opt/o365/logstash/logstash-core/lib/logstash/output_delegator.rb:49:in multi_receive'", "/opt/o365/logstash/logstash-core/lib/logstash/pipeline.rb:479:in block in output_batch'", "org/jruby/RubyHash.java:1343:in each'", "/opt/o365/logstash/logstash-core/lib/logstash/pipeline.rb:478:in output_batch'", "/opt/o365/logstash/logstash-core/lib/logstash/pipeline.rb:430:in worker_loop'", "/opt/o365/logstash/logstash-core/lib/logstash/pipeline.rb:385:in block in start_workers'"]}

[imacube]

Same, that's what I see. Any time this occurs logstash has to be restarted.

[deepanshumarwah]

Any resolution for this ?
I am getting similar kind of error

tcp output exception {:host=>"localhost", :port=>6514, :exception=>#<EOFError: End of file reached>, :backtrace=>["org/jruby/ext/openssl/SSLSocket.java:857:in sysread'", "/opt/armor/logstash-7.4.2/vendor/bundle/jruby/2.5.0/gems/logstash-output-tcp-6.0.0/lib/logstash/outputs/tcp.rb:158:in block in register'", "/opt/armor/logstash-7.4.2/vendor/bundle/jruby/2.5.0/gems/logstash-codec-json-3.0.5/lib/logstash/codecs/json.rb:42:in encode'", "/opt/armor/logstash-7.4.2/logstash-core/lib/logstash/codecs/delegator.rb:31:in block in encode'", "org/logstash/instrument/metrics/AbstractSimpleMetricExt.java:45:in time'", "org/logstash/instrument/metrics/AbstractNamespacedMetricExt.java:44:in time'", "/opt/armor/logstash-7.4.2/logstash-core/lib/logstash/codecs/delegator.rb:30:in encode'", "/opt/armor/logstash-7.4.2/vendor/bundle/jruby/2.5.0/gems/logstash-output-tcp-6.0.0/lib/logstash/outputs/tcp.rb:203:in receive'", "/opt/armor/logstash-7.4.2/logstash-core/lib/logstash/outputs/base.rb:89:in block in multi_receive'", "org/jruby/RubyArray.java:1800:in each'", "/opt/armor/logstash-7.4.2/logstash-core/lib/logstash/outputs/base.rb:89:in multi_receive'", "org/logstash/config/ir/compiler/OutputStrategyExt.java:118:in multi_receive'", "org/logstash/config/ir/compiler/AbstractOutputDelegatorExt.java:101:in multi_receive'", "/opt/armor/logstash-7.4.2/logstash-core/lib/logstash/java_pipeline.rb:243:in block in start_workers'"]}

[jsmucr]

@deepanshumarwah There's no official resolution. I've fixed this a couple of years ago but nobody seems to be interested: #34
I've updated the PR with the 6.0.0 version we've been using in production for a long time now.