elastic / elastic/logstash

Stalling log messages print Snapshot object making them unreadable

Open
#5,304 0 comments 0 reactions 1 assignee Claimed by @andrewvc View on GitHub
bug v5.5.0
Dominant language
Java
Stars
14.9k
Forks
3.5k
Avg merge
19h 14m
Merged PRs (30d)
63

Description

Stalling log messages in logstash 2.3.1 are formatted correctly if sent to stdout in terminal:

```
{"inflight_count"=>4, "stalling_thread_info"=>{["LogStash::Filters::Ruby", {"code"=>"sleep 0.1"}]=>[{"thread_id"=>16, "name"=>"[main]>worker0", "current_call"=>"[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:128:in `pop'"}, {"thread_id"=>17, "name"=>"[main]>worker1", "current_call"=>"[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:128:in `pop'"}, {"thread_id"=>18, "name"=>"[main]>worker2", "current_call"=>"[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:128:in `pop'"}, {"thread_id"=>19, "name"=>"[main]>worker3", "current_call"=>"[...]/vendor/bundle/jruby/1.9/gems/logstash-output-tcp-2.0.4/lib/logstash/outputs/tcp.rb:114:in `sleep'"}]}} {:level=>:warn}
```

but they're garbled in the log file, printing the Snapshot object directly:

```
{:timestamp=>"2016-05-16T14:51:43.722000+0100", :message=>#140, :events_consumed=>140, :worker_count=>4, :inflight_count=>4, :worker_states=>[{:status=>"sleep", :alive=>true, :index=>0, :inflight_count=>1}, {:status=>"sleep", :alive=>true, :index=>1, :inflight_count=>1}, {:status=>"sleep", :alive=>true, :index=>2, :inflight_count=>1}, {:status=>"sleep", :alive=>true, :index=>3, :inflight_count=>1}], :output_info=>[{:type=>"tcp", :config=>{"host"=>"localhost", "port"=>3333, "__ALLOW_ENV__"=>false}, :is_multi_worker=>false, :events_received=>140, :workers=>"localhost", port=>3333, codec=>"UTF-8">, workers=>1, reconnect_interval=>10, mode=>"client">]>, :busy_workers=>1}], :thread_info=>[{"thread_id"=>15, "name"=>"[main]nil, "backtrace"=>["[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/util/wrapped_synchronous_queue.rb:17:in `push'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-input-generator-2.0.4/lib/logstash/inputs/generator.rb:71:in `run'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-codec-plain-2.0.4/lib/logstash/codecs/plain.rb:35:in `decode'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-input-generator-2.0.4/lib/logstash/inputs/generator.rb:67:in `run'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-input-generator-2.0.4/lib/logstash/inputs/generator.rb:66:in `each'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-input-generator-2.0.4/lib/logstash/inputs/generator.rb:66:in `run'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:342:in `inputworker'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:336:in `start_input'"], "blocked_on"=>"blocked_on_push", "status"=>"run", "current_call"=>"[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/util/wrapped_synchronous_queue.rb:17:in `push'"}, {"thread_id"=>16, "name"=>"[main]>worker0", "plugin"=>["LogStash::Filters::Ruby", {"code"=>"sleep 0.1"}], "backtrace"=>["[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:128:in `pop'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:128:in `worker_multi_receive'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:114:in `multi_receive'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:301:in `output_batch'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:301:in `each'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:301:in `output_batch'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:232:in `worker_loop'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:201:in `start_workers'"], "blocked_on"=>nil, "status"=>"sleep", "current_call"=>"[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:128:in `pop'"}, {"thread_id"=>17, "name"=>"[main]>worker1", "plugin"=>["LogStash::Filters::Ruby", {"code"=>"sleep 0.1"}], "backtrace"=>["[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:128:in `pop'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:128:in `worker_multi_receive'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:114:in `multi_receive'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:301:in `output_batch'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:301:in `each'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:301:in `output_batch'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:232:in `worker_loop'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:201:in `start_workers'"], "blocked_on"=>nil, "status"=>"sleep", "current_call"=>"[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:128:in `pop'"}, {"thread_id"=>18, "name"=>"[main]>worker2", "plugin"=>["LogStash::Filters::Ruby", {"code"=>"sleep 0.1"}], "backtrace"=>["[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:128:in `pop'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:128:in `worker_multi_receive'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:114:in `multi_receive'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:301:in `output_batch'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:301:in `each'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:301:in `output_batch'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:232:in `worker_loop'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:201:in `start_workers'"], "blocked_on"=>nil, "status"=>"sleep", "current_call"=>"[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:128:in `pop'"}, {"thread_id"=>19, "name"=>"[main]>worker3", "plugin"=>["LogStash::Filters::Ruby", {"code"=>"sleep 0.1"}], "backtrace"=>["[...]/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/try.rb:47:in `sleep'", "[...]/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/try.rb:47:in `failure'", "[...]/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/try.rb:106:in `try'", "[...]/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/try.rb:20:in `each'", "[...]/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/try.rb:91:in `try'", "[...]/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/try.rb:123:in `try'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-output-tcp-2.0.4/lib/logstash/outputs/tcp.rb:123:in `connect'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-output-tcp-2.0.4/lib/logstash/outputs/tcp.rb:100:in `register'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-codec-json-2.1.3/lib/logstash/codecs/json.rb:42:in `call'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-codec-json-2.1.3/lib/logstash/codecs/json.rb:42:in `encode'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-output-tcp-2.0.4/lib/logstash/outputs/tcp.rb:143:in `receive'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/outputs/base.rb:83:in `multi_receive'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/outputs/base.rb:83:in `each'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/outputs/base.rb:83:in `multi_receive'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:130:in `worker_multi_receive'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:129:in `worker_multi_receive'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:114:in `multi_receive'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:301:in `output_batch'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:301:in `each'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:301:in `output_batch'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:232:in `worker_loop'", "[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/pipeline.rb:201:in `start_workers'"], "blocked_on"=>nil, "status"=>"sleep", "current_call"=>"[...]/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/try.rb:47:in `sleep'"}], :stalling_threads_info=>[{"thread_id"=>16, "name"=>"[main]>worker0", "plugin"=>["LogStash::Filters::Ruby", {"code"=>"sleep 0.1"}], "current_call"=>"[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:128:in `pop'"}, {"thread_id"=>17, "name"=>"[main]>worker1", "plugin"=>["LogStash::Filters::Ruby", {"code"=>"sleep 0.1"}], "current_call"=>"[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:128:in `pop'"}, {"thread_id"=>18, "name"=>"[main]>worker2", "plugin"=>["LogStash::Filters::Ruby", {"code"=>"sleep 0.1"}], "current_call"=>"[...]/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.1-java/lib/logstash/output_delegator.rb:128:in `pop'"}, {"thread_id"=>19, "name"=>"[main]>worker3", "plugin"=>["LogStash::Filters::Ruby", {"code"=>"sleep 0.1"}], "current_call"=>"[...]/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/try.rb:47:in `sleep'"}]}>, :level=>:warn}
```

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.