New pipeline might break plugins by calling the register method twice

[imriz]

Sample config:

input {

  udp {
    type => "syslog"
    buffer_size => 65536
    host => "0.0.0.0"
    port => 5140
    codec =>   plain {
      charset => "UTF-8"
    }
  }

}

output {
tcp {
    host => '127.0.0.1'
    port => '2048'
    mode => 'server'
}
}

Debug log:

{:timestamp=>"2016-03-20T16:24:48.723000+0200", :message=>"Starting tcp output listener", :address=>"127.0.0.1:2048", :level=>:info, :file=>"logstash/outputs/tcp.rb", :line=>"75", :method=>"register"}
{:timestamp=>"2016-03-20T16:24:48.742000+0200", :message=>"Will start workers for output", :worker_count=>1, :class=>LogStash::Outputs::Tcp, :level=>:debug, :file=>"logstash/output_delegator.rb", :line=>"34", :method=>"initialize"}
{:timestamp=>"2016-03-20T16:24:48.758000+0200", :message=>"Starting tcp output listener", :address=>"127.0.0.1:2048", :level=>:info, :file=>"logstash/outputs/tcp.rb", :line=>"75", :method=>"register"}
{:timestamp=>"2016-03-20T16:24:48.762000+0200", :message=>"Starting UDP listener", :address=>"0.0.0.0:5140", :level=>:info, :file=>"logstash/inputs/udp.rb", :line=>"60", :method=>"udp_listener"}
{:timestamp=>"2016-03-20T16:24:48.766000+0200", :message=>"The error reported is: \n  Address already in use - bind - Address already in use", :file=>"logstash/agent.rb", :line=>"222", :method=>"execute"}
{:timestamp=>"2016-03-20T16:24:48.775000+0200", :message=>["org/jruby/ext/socket/RubyTCPServer.java:118:in `initialize'", "org/jruby/RubyIO.java:853:in `new'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-tcp-2.0.2/lib/logstash/outputs/tcp.rb:76:in `register'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.2.2-java/lib/logstash/output_delegator.rb:105:in `register'", "org/jruby/RubyArray.java:1613:in `each'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.2.2-java/lib/logstash/output_delegator.rb:105:in `register'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.2.2-java/lib/logstash/pipeline.rb:170:in `start_workers'", "org/jruby/RubyArray.java:1613:in `each'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.2.2-java/lib/logstash/pipeline.rb:170:in `start_workers'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.2.2-java/lib/logstash/pipeline.rb:123:in `run'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.2.2-java/lib/logstash/agent.rb:211:in `execute'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.2.2-java/lib/logstash/runner.rb:90:in `run'", "org/jruby/RubyProc.java:281:in `call'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.2.2-java/lib/logstash/runner.rb:95:in `run'", "org/jruby/RubyProc.java:281:in `call'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/task.rb:24:in `initialize'"], :file=>"logstash/agent.rb", :line=>"223", :method=>"execute"}

The reason is that the register method is being called twice -
Once in the https://github.com/elastic/logstash/blob/master/logstash-core/lib/logstash/pipeline.rb#L58
and another in

logstash/logstash-core/lib/logstash/pipeline.rb

Line 207 in 592835c

def start_workers

This behaviour was introduced in 028576b (Issue #4340)

This might happen in several other plugins that do logic in the register method.

[ebuildy]

Strange I see only 1 call to input register:

https://github.com/elastic/logstash/blob/master/logstash-core/lib/logstash/pipeline.rb#L373

And didn't have any error with new pipeline (released 2 months ago now).

[imriz]

@ebuildy I didn't look into input plugins, but there is a call in the eval here:
https://github.com/elastic/logstash/blob/master/logstash-core/lib/logstash/pipeline.rb#L99

The stack of the first call:

{:timestamp=>"2016-03-20T07:43:46.892000-0500", :message=>"[\"/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.2.2-java/lib/logstash/output_delegator.rb:29:in `initialize'\", \"/opt/logstash/vendor/bundle/jr
uby/1.9/gems/logstash-core-2.2.2-java/lib/logstash/pipeline.rb:403:in `plugin'\", \"(eval):7:in `initialize'\", \"/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.2.2-java/lib/logstash/pipeline.rb:57:in `eval'\", \"/opt/logstash
/vendor/bundle/jruby/1.9/gems/logstash-core-2.2.2-java/lib/logstash/pipeline.rb:57:in `initialize'\", \"/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.2.2-java/lib/logstash/agent.rb:172:in `execute'\", \"/opt/logstash/vendor/b
undle/jruby/1.9/gems/logstash-core-2.2.2-java/lib/logstash/runner.rb:90:in `run'\", \"/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.2.2-java/lib/logstash/runner.rb:95:in `call'\", \"/opt/logstash/vendor/bundle/jruby/1.9/gems/
logstash-core-2.2.2-java/lib/logstash/runner.rb:95:in `run'\", \"/opt/logstash/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/task.rb:24:in `call'\", \"/opt/logstash/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/task.rb:24:in `init
ialize'\"]", :level=>:info, :file=>"logstash/outputs/example_output.rb", :line=>"302", :method=>"register"}

Can you reproduce the error with the above sample (simple) config?

[imriz]

To be more precise, the eval creates a new Logstash::OutputDelegator, which then calls the register in the initialize method.

It delegates only output and filter plugins. Input plugin just gets initiated directly (

logstash/logstash-core/lib/logstash/pipeline.rb

Line 451 in 592835c

def plugin(plugin_type, name, *args)

).

[suyograo]

Looks like this will be solved in #4763

[imriz]

Yep, seems like it. Will it be released as part of 2.2.3?The way I see it, it is a major bug, as it makes at least some core plugins unusable, and in some can even result data loss (for the s3 plugin for example).

[suyograo]

@imriz absolutely. its going to be part of 2.2.3 and 2.3.0 releasing soon.

[imriz]

Thanks :)

[suyograo]

Fixed in #4763