Logstash config test hangs when Logstash is running w/ DLQ enabled

Elastic Stack Logstash
1

Hi,

Logstash: 5.6.1

Additional plugins:

  • x-pack (5.6.1)
  • logstash-filter-prune (3.0.3)

I'm observing some strange behaviour when running Logstash config test when an instance of Logstash is already running with the DLQ enabled.

I am running /usr/local/logstash/bin/logstash -f /etc/logstash/conf.d/ -t after Logstash has been configured & started, so there is already a running Logstash instance when I run the test:

/usr/bin/java -Djava.net.preferIPv4Stack=true -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -XX:+DisableExplicitGC -Djava.awt.headless=true -Dfile.encoding=UTF-8 -XX:+HeapDumpOnOutOfMemoryError -Xmx512m -Xms512m -Xss2048k -Djffi.boot.library.path=/usr/local/logstash-5.6.1/vendor/jruby/lib/jni -Xbootclasspath/a:/usr/local/logstash-5.6.1/vendor/jruby/lib/jruby.jar -classpath : -Djruby.home=/usr/local/logstash-5.6.1/vendor/jruby -Djruby.lib=/usr/local/logstash-5.6.1/vendor/jruby/lib -Djruby.script=jruby -Djruby.shell=/bin/sh org.jruby.Main /usr/local/logstash/lib/bootstrap/environment.rb logstash/runner.rb --path.settings /usr/local/logstash/config

Running the config test with debug I can see it hangs at the below:

[2018-02-22T11:57:05,017][DEBUG][logstash.runner          ] --------------- Logstash Settings -------------------
[2018-02-22T11:57:05,023][DEBUG][logstash.runner          ] Reading config file {:config_file=>"/etc/logstash/conf.d/logstash_test.conf"}
[2018-02-22T11:57:05,024][DEBUG][logstash.runner          ] Reading config file {:config_file=>"/etc/logstash/conf.d/shipping_application_logs.conf"}
[2018-02-22T11:57:05,024][DEBUG][logstash.runner          ] Reading config file {:config_file=>"/etc/logstash/conf.d/shipping_asm.conf"}
[2018-02-22T11:57:05,025][DEBUG][logstash.runner          ] Reading config file {:config_file=>"/etc/logstash/conf.d/shipping_beats.conf"}
[2018-02-22T11:57:05,025][DEBUG][logstash.runner          ] Reading config file {:config_file=>"/etc/logstash/conf.d/shipping_infrastructure_logs.conf"}
[2018-02-22T11:57:05,026][DEBUG][logstash.runner          ] Reading config file {:config_file=>"/etc/logstash/conf.d/shipping_metrics20.conf"}
[2018-02-22T11:57:05,026][DEBUG][logstash.runner          ] Reading config file {:config_file=>"/etc/logstash/conf.d/shipping_sensu.conf"}
[2018-02-22T11:57:05,026][DEBUG][logstash.runner          ] Reading config file {:config_file=>"/etc/logstash/conf.d/shipping_system_logs.conf"}

If I stop Logstash and run the config test it works fine, and the output that follows the above is initialisation of the input plugins:

2018-02-22T12:00:40,360][DEBUG][logstash.plugins.registry] On demand adding plugin to the registry {:name=>"syslog", :type=>"input", :class=>LogStash::Inputs::Syslog}
[2018-02-22T12:00:40,374][DEBUG][logstash.plugins.registry] On demand adding plugin to the registry {:name=>"plain", :type=>"codec", :class=>LogStash::Codecs::Plain}
[2018-02-22T12:00:40,376][DEBUG][logstash.codecs.plain    ] config LogStash::Codecs::Plain/@id = "plain_7d54ba1e-1ad6-42fe-b3d7-88a64fc4065d"
[2018-02-22T12:00:40,376][DEBUG][logstash.codecs.plain    ] config LogStash::Codecs::Plain/@enable_metric = true
[2018-02-22T12:00:40,377][DEBUG][logstash.codecs.plain    ] config LogStash::Codecs::Plain/@charset = "UTF-8"
[2018-02-22T12:00:40,378][DEBUG][logstash.inputs.syslog   ] config LogStash::Inputs::Syslog/@port = 5000
[2018-02-22T12:00:40,378][DEBUG][logstash.inputs.syslog   ] config LogStash::Inputs::Syslog/@type = "test"
[2018-02-22T12:00:40,378][DEBUG][logstash.inputs.syslog   ] config LogStash::Inputs::Syslog/@id = "77197fd5f8e37039a8c6b680833438b68075726e-1"
[2018-02-22T12:00:40,378][DEBUG][logstash.inputs.syslog   ] config LogStash::Inputs::Syslog/@enable_metric = true
[2018-02-22T12:00:40,379][DEBUG][logstash.inputs.syslog   ] config LogStash::Inputs::Syslog/@codec = <LogStash::Codecs::Plain id=>"plain_7d54ba1e-1ad6-42fe-b3d7-88a64fc4065d", enable_metric=>true, charset=>"UTF-8">
[2018-02-22T12:00:40,379][DEBUG][logstash.inputs.syslog   ] config LogStash::Inputs::Syslog/@add_field = {}
[2018-02-22T12:00:40,379][DEBUG][logstash.inputs.syslog   ] config LogStash::Inputs::Syslog/@host = "0.0.0.0"

So the config test only fails when Logstash is already running; however I think I've narrowed it down a bit further. If I change my main Logstash config (/usr/local/logstash/config/logstash.yml) to set DLQ to false (previously true), the config test successfully runs and completes, even when Logstash is already running in the background.:

dead_letter_queue.enable: false

I've tried doing an strace on the config test when it hangs, but I just see the below constantly looping, so I'm not too sure what it's trying to do when it gets stuck:

strace -fp 19505

[pid 19505] futex(0x7f45d413ec54, FUTEX_WAIT_BITSET_PRIVATE, 1, {5129, 840252721}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
[pid 19505] futex(0x7f45d413ec28, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 19505] clock_gettime(CLOCK_MONOTONIC, {5129, 840461101}) = 0
[pid 19505] clock_gettime(CLOCK_MONOTONIC, {5129, 840507583}) = 0
[pid 19505] clock_gettime(CLOCK_MONOTONIC, {5129, 840537435}) = 0
[pid 19505] clock_gettime(CLOCK_MONOTONIC, {5129, 840576137}) = 0

This has been tested on a fresh install/server

Any help would be greatly appreciated

Cheers,
Mike

2

Testing on Logstash 6.2.2 I get the below:

[2018-02-22T17:28:45,127][INFO ][logstash.modules.scaffold] Initializing module {:module_name=>"fb_apache", :directory=>"/usr/local/logstash/modules/fb_apache/configuration"}
[2018-02-22T17:28:45,132][INFO ][logstash.modules.scaffold] Initializing module {:module_name=>"netflow", :directory=>"/usr/local/logstash/modules/netflow/configuration"}
[2018-02-22T17:28:45,301][INFO ][logstash.modules.scaffold] Initializing module {:module_name=>"arcsight", :directory=>"/usr/local/logstash/vendor/bundle/jruby/2.3.0/gems/x-pack-6.2.2-java/modules/arcsight/configuration"}
[2018-02-22T17:28:45,721][WARN ][logstash.config.source.multilocal] Ignoring the 'pipelines.yml' file because modules or command line options are specified
[2018-02-22T17:28:45,923][ERROR][org.logstash.common.DeadLetterQueueFactory] unable to create dead letter queue writer
org.logstash.LockException: Lock held by another program on lock path: /usr/local/logstash-6.2.2/data/dead_letter_queue/main/.lock
	at org.logstash.FileLockFactory.obtainLock(FileLockFactory.java:81) ~[logstash-core.jar:?]
	at org.logstash.common.io.DeadLetterQueueWriter.<init>(DeadLetterQueueWriter.java:61) ~[logstash-core.jar:?]
	at org.logstash.common.DeadLetterQueueFactory.newWriter(DeadLetterQueueFactory.java:68) ~[logstash-core.jar:?]
	at org.logstash.common.DeadLetterQueueFactory.lambda$getWriter$0(DeadLetterQueueFactory.java:59) ~[logstash-core.jar:?]
	at java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1660) [?:1.8.0_60]
	at org.logstash.common.DeadLetterQueueFactory.getWriter(DeadLetterQueueFactory.java:59) [logstash-core.jar:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_60]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_60]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~
.......
Configuration OK
[2018-02-22T17:28:46,110][INFO ][logstash.runner          ] Using config.test_and_exit mode. Config Validation Result: OK. Exiting Logstash

This seems to be correct behaviour, possibly fixed with https://github.com/elastic/logstash/commit/64388f34a566722fa49788239b116fe010e01a16 ?

Closing this off since upgrading appears it will fix the issue.

3

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