Log-courier upgrade affects logstash boot time

[deviantony]

After upgrading from 0.11 to 0.12, my logstash indexer takes like 5sec to boot and the logstash log file is spammed with the following lines:

...
{:timestamp=>"2014-08-06T15:43:21.703000+0200", :message=>"[LogCourierServer] Invalid message: not enough data", :level=>:warn}
{:timestamp=>"2014-08-06T15:43:21.704000+0200", :message=>"[LogCourierServer] ZMQ recv_string failed: recv_string error: -1", :level=>:warn}
{:timestamp=>"2014-08-06T15:43:21.704000+0200", :message=>"[LogCourierServer] Invalid message: not enough data", :level=>:warn}
{:timestamp=>"2014-08-06T15:43:21.704000+0200", :message=>"[LogCourierServer] ZMQ recv_string failed: recv_string error: -1", :level=>:warn}
...

[driskell]

Hi

Sorry you are having issues.

I caught this once before during testing but thought I had fixed it. Can you share your config for logstash?
I will also see if I can reproduce this again.

Thanks

Jason

[deviantony]

Hey Jason,

I've setup log-courier on my logstash instance with the following setup.

I've installed logstash from the debian repository.

I've copied the libzmq & libsodium libraries into /usr/local/lib:

lrwxrwxrwx  1 root root       19 juil. 21 16:53 libsodium.so -> libsodium.so.10.2.0*
lrwxrwxrwx  1 root root       19 juil. 21 16:53 libsodium.so.10 -> libsodium.so.10.2.0*
-rwxr-xr-x  1 root root  1228781 juil. 21 16:53 libsodium.so.10.2.0*
lrwxrwxrwx  1 root root       15 juil. 21 16:51 libzmq.so -> libzmq.so.3.1.0*
lrwxrwxrwx  1 root root       15 juil. 21 16:51 libzmq.so.3 -> libzmq.so.3.1.0*
-rwxr-xr-x  1 root root  3337152 juil. 21 16:51 libzmq.so.3.1.0*

Then, applied the ldconfig

sudo ldconfig

I've then installed/upgraded the log-courier via:

sudo su
export GEM_HOME=/opt/logstash/vendor/bundle/jruby/
java -jar vendor/jar/jruby-complete-1.7.11.jar -S gem install /tmp/logstash-lc/log-courier-0.12.gem
cp -rp /path/to/lib/logstash /opt/logstash/lib
chown -R logstash:logstash lib/
chown -R logstash:logstash vendor

Here are my configuration files for logstash:

00_input.conf

input {
 courier {
    port => 5001
    transport => "zmq"
    curve_secret_key => "MY_CURVE_SECRET_KEY"
  }
}

10_output.conf

output {
  elasticsearch {
  }
}

And when I try to stop the logstash service, it seems that the logstash process is still running:

$ sudo service logstash stop
logstash stop/waiting
$ ps aux | grep java 
logstash  2335 59.2  7.5 2093108 155044 ?      SNsl 11:51   0:22 /usr/bin/java -Djava.io.tmpdir=/var/lib/logstash -Xmx500m -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -Djava.awt.headless=true -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -jar /opt/logstash/vendor/jar/jruby-complete-1.7.11.jar -I/opt/logstash/lib /opt/logstash/lib/logstash/runner.rb web -l /var/log/logstash/logstash.log

[deviantony]

Btw, by applying the same setup/configuration on another fresh logstash node I can't seem to start the logstash service and I've got the following error if I try to start it manually:

$ sudo -u logstash /opt/logstash/bin/logstash -f /etc/logstash/conf.d -l /var/log/logstash/logstash.log
Sending logstash logs to /var/log/logstash/logstash.log.
Using milestone 1 input plugin 'courier'. This plugin should work, but would benefit from use by folks like you. Please let us know if you find bugs or have suggestions on how to improve this plugin.  For more information on plugin milestones, see http://logstash.net/docs/1.4.2-modified/plugin-milestones {:level=>:warn}
LoadError: no such file to load -- log-courier/server
       require at org/jruby/RubyKernel.java:1085
       require at file:/opt/logstash/vendor/jar/jruby-complete-1.7.11.jar!/META-INF/jruby.home/lib/ruby/shared/rubygems/core_ext/kernel_require.rb:55
       require at file:/opt/logstash/vendor/jar/jruby-complete-1.7.11.jar!/META-INF/jruby.home/lib/ruby/shared/rubygems/core_ext/kernel_require.rb:53
       require at /opt/logstash/vendor/bundle/jruby/1.9/gems/polyglot-0.3.4/lib/polyglot.rb:65
      register at /opt/logstash/lib/logstash/inputs/courier.rb:68
  start_inputs at /opt/logstash/lib/logstash/pipeline.rb:135
          each at org/jruby/RubyArray.java:1613
  start_inputs at /opt/logstash/lib/logstash/pipeline.rb:134
           run at /opt/logstash/lib/logstash/pipeline.rb:72
       execute at /opt/logstash/lib/logstash/agent.rb:139
           run at /opt/logstash/lib/logstash/runner.rb:168
          call at org/jruby/RubyProc.java:271
    initialize at /opt/logstash/vendor/bundle/jruby/1.9/gems/stud-0.0.17/lib/stud/task.rb:12

[driskell]

Hi @deviantony

Looks like you are using ZMQ 3.x according to those library version numbers. That will not allow use of CURVE_SECRET_KEY - it requires ZMQ 4.x libraries. I will check docs to make sure this is clear. Basically the "plainzmq" transport is ZMQ 3.x, and "zmq" is ZMQ 4.x as its only since 4.x that an encrypted and authenticated connection is possible using ZMQ (without rolling owns crypto library).

That could explain the first issue with the looping etc. if the library kept erroring I will try to reproduce and maybe I need to put a version check into the library so it complains nicely.

Regarding the last issue, that could be related to current path. A lot of plugins in Logstash use relative path for library access and you need to run logstash from the "/opt/logstash" folder or it will fail to load those libraries. Can you give that a try? I'll put it on my list to use a more solid path if I can.

Jason

[driskell]

Just to confirm - that first issue with the spam - that's a bug and I suggest to kill logstash if that occurs! It essentially means the ZMQ stuff hit a loop.

[deviantony]

Hey,

I just seen I made an error in my setup:

export GEM_HOME=/opt/logstash/vendor/bundle/jruby/

Is not a good value.

I've updated my procedure using the following GEM_HOME:

export GEM_HOME=/opt/logstash/vendor/bundle/jruby/1.9

So I've reinstalled both nodes, the fresh node is now working fine but I still have those log messages in my updated instance when I stop (not at startup) the logstash service.

About the ZMQ libraries, the name seems to be misleading. I've built the libraries this way:

apt-get install build-essential uuid-dev
wget http://download.zeromq.org/zeromq-4.0.4.tar.gz
tar xvpfz zeromq-4.0.4.tar.gz
cd zeromq-4.0.4.tar.gz
./configure
make
sudo make install
sudo ldconfig

And I can see the following in my folder:

-rw-r--r-- 1 root root  8350056 août   7 13:39 libzmq.a
-rwxr-xr-x 1 root root      956 août   7 13:39 libzmq.la
lrwxrwxrwx 1 root root       15 août   7 13:39 libzmq.so -> libzmq.so.3.1.0
lrwxrwxrwx 1 root root       15 août   7 13:39 libzmq.so.3 -> libzmq.so.3.1.0
-rwxr-xr-x 1 root root  3337152 août   7 13:39 libzmq.so.3.1.0

Plus, it's working on my fresh node setup.

[driskell]

Ah OK. So the ZMQ spam you get when you try to stop the service?

I'm aware that logstash will not shut down gracefully when using log-courier as the shutdown signal is lost - which I'm aiming to fix for next version (I've been doing lots of work on the log-courier binary itself lately.) This will then allow it to gracefully shutdown. I'll take a look and see if I can reproduce this.

Previously it would be caused during timeouts sometimes, so I stripped that. It seemed raising an exception during the zmq_receive would possibly corrupt the ZMQ library status. I'll look further - maybe the shutdown exception is causing the same thing.

Jason