logstash-plugins/logstash-output-tcp

Claims to be threadsafe, is not

andrewvc opened this issue · 4 comments

This plugin claims to be safe for multiple output workers, but in fact is not due to IO#select on jruby not being threadsafe. We should set declare_workers_not_supported! to fix this.

The concurrency error Jruby will raise is below.

tcp output exception {:host=>"localhost", :port=>3333, :exception=>#<ConcurrencyError: can not set IO blocking after select; concurrent select detected?>, :backtrace=>["org/jruby/RubyIO.java:3682:in `select'", "/Users/andrewcholakian/projects/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-tcp-2.0.2/lib/logstash/outputs/tcp.rb:101:in `register'", "org/jruby/RubyProc.java:281:in `call'", "/Users/andrewcholakian/projects/logstash/vendor/bundle/jruby/1.9/gems/logstash-codec-plain-2.0.2/lib/logstash/codecs/plain.rb:41:in `encode'", "/Users/andrewcholakian/projects/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-tcp-2.0.2/lib/logstash/outputs/tcp.rb:143:in `receive'", "/Users/andrewcholakian/projects/logstash/logstash-core/lib/logstash/outputs/base.rb:83:in `multi_receive'", "org/jruby/RubyArray.java:1613:in `each'", "/Users/andrewcholakian/projects/logstash/logstash-core/lib/logstash/outputs/base.rb:83:in `multi_receive'", "/Users/andrewcholakian/projects/logstash/logstash-core/lib/logstash/output_delegator.rb:119:in `worker_multi_receive'", "/Users/andrewcholakian/projects/logstash/logstash-core/lib/logstash/output_delegator.rb:118:in `worker_multi_receive'", "/Users/andrewcholakian/projects/logstash/logstash-core/lib/logstash/output_delegator.rb:65:in `multi_receive'", "/Users/andrewcholakian/projects/logstash/logstash-core/lib/logstash/pipeline.rb:275:in `output_batch'", "org/jruby/RubyHash.java:1342:in `each'", "/Users/andrewcholakian/projects/logstash/logstash-core/lib/logstash/pipeline.rb:275:in `output_batch'", "/Users/andrewcholakian/projects/logstash/logstash-core/lib/logstash/pipeline.rb:206:in `worker_loop'", "/Users/andrewcholakian/projects/logstash/logstash-core/lib/logstash/pipeline.rb:175:in `start_workers'"], :level=>:warn}
jsvd commented

@jsvd HAH!

jsvd commented

apparently all output workers for the tcp output will share the same codec, which means they all run the same instance of the on_event method, so all output workers are actually sending through one of the plugins tcp socket, while all the others are idle o.O

Responsible code https://github.com/logstash-plugins/logstash-output-tcp/blob/master/lib/logstash/outputs/tcp.rb#L97-L101:

   else
      client_socket = nil
      puts "#{self.class} plugin id #{self.object_id} has codec #{@codec.object_id}"
      @codec.on_event do |event, 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
% bin/logstash -e "input { generator { count => 100000 } } output { tcp { workers => 4 port => 3333 host => localhost codec => plain { format => '%{sequence}' } } }" -w 4
LogStash::Outputs::Tcp plugin id 12832 has codec 12834
LogStash::Outputs::Tcp plugin id 12836 has codec 12834
LogStash::Outputs::Tcp plugin id 12838 has codec 12834
LogStash::Outputs::Tcp plugin id 12840 has codec 12834
Settings: User set pipeline workers: 4, Default pipeline workers: 4
LogStash::Outputs::Tcp plugin id 12832 has codec 12834
LogStash::Outputs::Tcp plugin id 12836 has codec 12834
LogStash::Outputs::Tcp plugin id 12838 has codec 12834
LogStash::Outputs::Tcp plugin id 12840 has codec 12834
Logstash startup completed
tcp output exception {:host=>"localhost", :port=>3333, :exception=>#<ConcurrencyError: can not set IO blocking after select; concurrent select detected?>, :backtrace=>["org/jruby/RubyIO.java:3682:in `select'", "/tmp/logstash-2.2.0.snapshot2/vendor/bundle/jruby/1.9/gems/logstash-output-tcp-2.0.2/lib/logstash/outputs/tcp.rb:102:in `register'", "org/jruby/RubyProc.java:281:in `call'", "/tmp/logstash-2.2.0.snapshot2/vendor/bundle/jruby/1.9/gems/logstash-codec-plain-2.0.2/lib/logstash/codecs/plain.rb:41:in `encode'", "/tmp/logstash-2.2.0.snapshot2/vendor/bundle/jruby/1.9/gems/logstash-output-tcp-2.0.2/lib

Also, each output worker should be getting a codec instance for itself. I'm still investigating why that happens.

@jsvd excellent find WRT codecs! I never even considered that. The instances should definitely be separate, I can't believe we never saw a bug there before.