Stalled Logstash shutdown with http output

[joshuar]

Logstash 6.1.1
logstash-output-http (5.1.1)

It looks like in certain situations, this plugin can lead to Logstash stalling during shutdown, and only able to be forced shutdown (with either the forced-shutdown option or a kill command).

Consider the following configuration (FYI the creds here is just elastic:changeme):

input {
	stdin {}
}

output {
	http {
		http_method => "post"
		url => "https://localhost:9200/test/doc"
		cacert => "/path/to/ca.crt"
		headers => {"Authorization"=> "Basic ZWxhc3RpYzpjaGFuZ2VtZQ=="}
		format=> "message"
		message => '{"message": "%{message}"}'
		content_type=>"application/json"
		retry_failed => false
	}
}

Understood this is not a recommended method for indexing to Elasticsearch but is totally doable with the plugin as is.

In this scenario, when I send some text to Logstash from stdin, it gets indexed as a new document in the test index, but then on attempting to shut down Logstash I get the following messages:

^C[2018-01-08T11:44:54,675][WARN ][logstash.runner          ] SIGINT received. Shutting down the agent.
[2018-01-08T11:44:54,785][DEBUG][logstash.instrument.periodicpoller.os] PeriodicPoller: Stopping
[2018-01-08T11:44:54,867][DEBUG][logstash.instrument.periodicpoller.jvm] PeriodicPoller: Stopping
[2018-01-08T11:44:54,870][DEBUG][logstash.instrument.periodicpoller.persistentqueue] PeriodicPoller: Stopping
[2018-01-08T11:44:54,872][DEBUG][logstash.instrument.periodicpoller.deadletterqueue] PeriodicPoller: Stopping
[2018-01-08T11:44:55,077][DEBUG][logstash.agent           ] Shutting down all pipelines {:pipelines_count=>1}
[2018-01-08T11:44:55,112][DEBUG][logstash.agent           ] Converging pipelines
[2018-01-08T11:44:55,114][DEBUG][logstash.agent           ] Needed actions to converge {:actions_count=>1}
[2018-01-08T11:44:55,115][DEBUG][logstash.agent           ] Executing action {:action=>LogStash::PipelineAction::Stop/pipeline_id:main}
[2018-01-08T11:44:55,231][DEBUG][logstash.pipeline        ] Closing inputs {:pipeline_id=>"main", :thread=>"#<Thread:0x3376af5a sleep>"}
[2018-01-08T11:44:55,249][DEBUG][logstash.inputs.stdin    ] stopping {:plugin=>"LogStash::Inputs::Stdin"}
[2018-01-08T11:44:55,321][DEBUG][logstash.inputs.stdin    ] stopping {:plugin=>"LogStash::Inputs::Stdin"}
[2018-01-08T11:44:55,334][DEBUG][logstash.pipeline        ] Closed inputs {:pipeline_id=>"main", :thread=>"#<Thread:0x3376af5a sleep>"}
[2018-01-08T11:44:55,359][DEBUG][logstash.inputs.stdin    ] closing {:plugin=>"LogStash::Inputs::Stdin"}
[2018-01-08T11:44:55,390][DEBUG][logstash.pipeline        ] Closing inputs {:pipeline_id=>"main", :thread=>"#<Thread:0x3376af5a sleep>"}
[2018-01-08T11:44:55,395][DEBUG][logstash.pipeline        ] Input plugins stopped! Will shutdown filter/output workers. {:pipeline_id=>"main", :thread=>"#<Thread:0x3376af5a run>"}
[2018-01-08T11:44:55,492][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline {:pipeline_id=>"main", :thread=>"#<Thread:0x3376af5a sleep>"}
[2018-01-08T11:44:55,521][DEBUG][logstash.pipeline        ] Pushing shutdown {:pipeline_id=>"main", :thread=>"#<Thread:0x60119466@[main]>worker0 run>"}
[2018-01-08T11:44:55,550][DEBUG][logstash.pipeline        ] Pushing shutdown {:pipeline_id=>"main", :thread=>"#<Thread:0x2e5d719e@[main]>worker1 run>"}
[2018-01-08T11:44:55,551][DEBUG][logstash.pipeline        ] Pushing shutdown {:pipeline_id=>"main", :thread=>"#<Thread:0x1f78c86e@[main]>worker2 run>"}
[2018-01-08T11:44:55,551][DEBUG][logstash.pipeline        ] Pushing shutdown {:pipeline_id=>"main", :thread=>"#<Thread:0x703651de@[main]>worker3 run>"}
[2018-01-08T11:44:55,596][DEBUG][logstash.pipeline        ] Shutdown waiting for worker thread {:pipeline_id=>"main", :thread=>"#<Thread:0x60119466@[main]>worker0 run>"}
[2018-01-08T11:44:59,689][WARN ][logstash.runner          ] Received shutdown signal, but pipeline is still waiting for in-flight events
to be processed. Sending another ^C will force quit Logstash, but this may cause
data loss.
[2018-01-08T11:45:00,265][WARN ][logstash.shutdownwatcher ] {"inflight_count"=>0, "stalling_thread_info"=>{"other"=>[{"thread_id"=>31, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-output-http-5.1.1/lib/logstash/outputs/http.rb:140:in `pop'"}]}}
[2018-01-08T11:45:00,277][ERROR][logstash.shutdownwatcher ] The shutdown process appears to be stalled due to busy or blocked plugins. Check the logs for more information.
[2018-01-08T11:45:05,251][WARN ][logstash.shutdownwatcher ] {"inflight_count"=>0, "stalling_thread_info"=>{"other"=>[{"thread_id"=>31, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-output-http-5.1.1/lib/logstash/outputs/http.rb:140:in `pop'"}]}}
[2018-01-08T11:45:10,251][WARN ][logstash.shutdownwatcher ] {"inflight_count"=>0, "stalling_thread_info"=>{"other"=>[{"thread_id"=>31, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-output-http-5.1.1/lib/logstash/outputs/http.rb:140:in `pop'"}]}}

And the last message indicating a stalled shutdown due to 0 inflight messages repeats ad nauseum.

Attached is a thread dump from Logstash in this state:
logstash-threads.txt

Here is a heap dump: logstash.hprof.zip

So this plugin seems to work in terms of indexing and talking to Elasticsearch this way, but stalls Logstash shutdown. Adding keepalive => false doesn't seem to help here.