Stalled pipeline help

Elastic Stack Logstash
1

Hi,
I have a logstash 6.1.1 running in a docker container, and am trying to understand why one our pipeline is not sending data. I stopped the instance and noticed that in the log it mentionned the pipeline was stalled:

[2018-06-29T09:33:04,371][WARN ][logstash.runner ] SIGTERM received. Shutting down the agent.
[2018-06-29T09:33:04,475][INFO ][logstash.pipeline ] Pipeline terminated {"pipeline.id"=>"rtsp"}
[2018-06-29T09:33:09,486][WARN ][logstash.shutdownwatcher ] {"inflight_count"=>0, "stalling_thread_info"=>{"other"=>[{"thread_id"=>38, "name"=>"[rtsp]<file", "current_call"=>"[...]/logstash-core/lib/logstash/util/wrapped_acked_queue.rb:54:in write'"}, {"thread_id"=>39, "name"=>"[rtsp]<file", "current_call"=>"[...]/logstash-core/lib/logstash/util/wrapped_acked_queue.rb:54:in write'"}]}}
[2018-06-29T09:33:09,490][ERROR][logstash.shutdownwatcher ] The shutdown process appears to be stalled due to busy or blocked plugins. Check the logs for more information.

My questions:

  • what logs is the message referring to, because I checked logstash-plain.log (and found that message) but nothing more ?
  • Is the wrapped_acked_queue responsible for writing the checkpointing/persistence files/queues ? If so is it an indication that the worker is busy writing many events to the persistence queues ?

Thanks for your help and time

Olivier

2

Ok so I finally realized the logs I did not checked were the docker logs, that's one question less.
For lack of a smarter thing to do, I stopped (as gracefuly as possible) and restarted logstash with only that pipeline enabled. I pasted the log below, snipped for clarity.

To me, it looks like the pipeline is initalizing and reading the persistent queue but somehow it fails to do so because of bad XML... Still the pipeline is apparently running, but nothing comes out of it (it also otuputs to STDOUT) despite input files being added regularly... It looks like the input plugin is blocked writing pending events to the queue...

That's as much as I can understand for now, any idea how to proceed from there?

Thanks for your help!

2018-06-29T13:19:49,330][INFO ][logstash.modules.scaffold] Initializing module {:module_name=>"fb_apache", :directory=>"/usr/share/logstash/modules/fb_apache/configuration"}
[2018-06-29T13:19:49,333][INFO ][logstash.modules.scaffold] Initializing module {:module_name=>"netflow", :directory=>"/usr/share/logstash/modules/netflow/configuration"}
[2018-06-29T13:19:49,851][INFO ][logstash.modules.scaffold] Initializing module {:module_name=>"arcsight", :directory=>"/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/x-pack-6.1.1-java/modules/arcsight/configuration"}
[2018-06-29T13:19:50,303][INFO ][logstash.runner ] Starting Logstash {"logstash.version"=>"6.1.1"}
[2018-06-29T13:19:50,371][INFO ][logstash.agent ] Successfully started Logstash API endpoint {:port=>9600}
[2018-06-29T13:21:05,128][WARN ][org.logstash.ackedqueue.Queue] recovered head data page 15 is different than checkpoint, using recovered page information
[2018-06-29T13:21:18,152][INFO ][logstash.outputs.elasticsearch] Elasticsearch pool URLs updated {:changes=>{:removed=>, :added=>[http://elastic:xxxxxx@spade:9306/]}}
[2018-06-29T13:21:18,155][INFO ][logstash.outputs.elasticsearch] Running health check to see if an Elasticsearch connection is working {:healthcheck_url=>http://elastic:xxxxxx@spade:9306/, :path=>"/"}
[2018-06-29T13:21:18,329][WARN ][logstash.outputs.elasticsearch] Restored connection to ES instance {:url=>"http://elastic:xxxxxx@spade:9306/"}
[2018-06-29T13:21:18,394][INFO ][logstash.outputs.elasticsearch] ES Output version determined {:es_version=>nil}
[2018-06-29T13:21:18,395][WARN ][logstash.outputs.elasticsearch] Detected a 6.x and above cluster: the type event field won't be used to determine the document _type {:es_version=>6}
[2018-06-29T13:21:18,405][INFO ][logstash.outputs.elasticsearch] Using mapping template from {:path=>"/data_bkp/logstash/01_CPDLC/templates/rtsp_template.json"}
[2018-06-29T13:21:18,431][INFO ][logstash.outputs.elasticsearch] Attempting to install template
...snip...
[2018-06-29T13:21:18,458][INFO ][logstash.outputs.elasticsearch] Installing elasticsearch template to _template/rtsp_template
[2018-06-29T13:21:18,698][INFO ][logstash.outputs.elasticsearch] New Elasticsearch output {:class=>"LogStash::Outputs::Elasticsearch", :hosts=>["//spade:9306"]}
[2018-06-29T13:21:19,119][INFO ][logstash.pipeline ] Starting pipeline {:pipeline_id=>"rtsp", "pipeline.workers"=>1, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>5, "pipeline.max_inflight"=>125, :thread=>"#<Thread:0x4bbee808@/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:245 run>"}
Exception in thread "Ruby-0-Thread-9@[rtsp]>worker0: /usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:392" org.logstash.ackedqueue.QueueRuntimeException: deserialize invocation error
at org.logstash.ackedqueue.Queue.deserialize(Queue.java:701)
at org.logstash.ackedqueue.Batch.deserializeElements(Batch.java:62)
at org.logstash.ackedqueue.Batch.(Batch.java:26)
at org.logstash.ackedqueue.Queue._readPageBatch(Queue.java:574)
at org.logstash.ackedqueue.Queue.readBatch(Queue.java:558)
...snip...
at org.logstash.ackedqueue.Queue.deserialize(Queue.java:699)
... 50 more
Caused by: com.fasterxml.jackson.databind.exc.MismatchedInputException: Unexpected token (START_OBJECT), expected START_ARRAY: need JSON Array to contain As.WRAPPER_ARRAY type information for class java.util.HashMap
at [Source: (byte)"�dMETA�dpathxR/data_nfs/rtsp/LOGS/OPS_GVA/2018/06/28/Cockpit_unzipped/res_LSAG_20180628_013.csvdhosthgsrecs01�dDATA�h@versiona1dhosthgsrecs01dpathxR/data_nfs/rtsp/LOGS/OPS_GVA/2018/06/28/Cockpit_unzipped/res_LSAG_20180628_013.csvcACCdLSAGj@timestampx2018-06-28T09:57:29.848Zgmessagex�28.06.2018;09:36:50;EZS78EL;0x4B1A34;28.06.2018;09:36:48;ATN_AIR;CPDLC message;99;;0;;1;DM99 CURRENT DATA AUTHORITY;EGKK;LSGG;46.6846275;5.0775558333333;23875;103.23303;1;1;1;0;1;0;-914.0625;0.3515625;INN;��"; line: -1, column: 0]
... 55 more
[2018-06-29T13:21:19,680][INFO ][logstash.pipeline ] Pipeline started {"pipeline.id"=>"rtsp"}
[2018-06-29T13:21:19,693][INFO ][logstash.agent ] Pipelines running {:count=>1, :pipelines=>["rtsp"]}

3

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.