Unable to use the zmq transport option

[driskell]

Unable to use the zmq transport option

[driskell]

Ah yes the plugin is the old version. I will throw up some quick commits to get this working for you.

[driskell]

I've just updated the plugin - can you let me know if it works OK?
It was just a missing declaration for the curve_secret_key entry - seems I didn't upload the correct version originally sorry.

[deviantony]

Thanks @driskell, I'll try this today and give you feedback.

[deviantony]

Logstash is now able to start with the following configuration:

  courier {
    port => 5077
    transport => "zmq"
    curve_secret_key => "xxx"
  }

Now, I can't start log-courier:

$ sudo /opt/log-courier/log-courier -config="/opt/log-courier/lc.conf"
Configuration error: Unrecognised transport 'zmq'

Here is my log-courier configuration:

{
        "network": {
                "transport": "zmq",
                "servers": [ "10.10.1.2:5077" ],
                "curve server key": "xxx",
                "curve public key": "xxx",
                "curve secret key": "xxx"
        },
        "files": [
                {
                        "paths": [ "/path/to/file.log" ],
                        "fields": { "tags": "TAG" }
                }
        ]
}

[deviantony]

My bad, I was using the bad log-courier binary. Log-courier is starting with these logs:

2014/07/21 08:55:46.811678 Starting pipeline
2014/07/21 08:55:46.811889 Loading registrar data from ./.log-courier
2014/07/21 08:55:46.812716 Pipeline ready
2014/07/21 08:55:46.812824 Launching harvester on rotated file: /path/to/file.log
2014/07/21 08:55:46.813169 Registrar received a new file event for /path/to/file.log
2014/07/21 08:55:46.813679 Registrar received a deletion event for /path/to/file.log
2014/07/21 08:55:46.813478 Started harvester at position 0 (requested 0): /path/to/file.log
2014/07/21 08:55:46.814856 Connected with 10.10.1.2:5077 (10.10.1.2) 
2014/07/21 08:56:06.832415 Transport error, will reconnect: Server did not respond within network timeout
2014/07/21 08:56:07.833235 Connected with 10.10.1.2:5077 (10.10.1.2) 
2014/07/21 08:56:22.833884 Transport error, will reconnect: Server did not respond within network timeout
2014/07/21 08:56:23.834636 Connected with 10.10.1.2:5077 (10.10.1.2) 
...

Seems like log-courier is unable to join my logstash server though.

[deviantony]

Also, I can't stop the log-courier application. After hitting Ctrl^C:

^C2014/07/21 08:59:22.186064 Initiating shutdown
2014/07/21 08:59:22.198642 Spooler exiting
2014/07/21 08:59:22.198727 Harvester for /path/to/file.log exiting
2014/07/21 08:59:22.198793 Prospector exiting
...
2014/07/21 09:06:31.769322 Transport error, will reconnect: Server did not respond within network timeout
2014/07/21 09:06:32.769699 Connected with 10.10.1.2:5077 (10.10.1.2) 
...

Seems that log-courier is stuck in a loop. I had to use kill -9 to end the process.

[deviantony]

After more investigation on the logstash host, I can see that, when using log-courier input, the logstash instance is respawning frequently (no errors in the logs) :

Jul 21 09:11:27 ls-indexer-01 kernel: [414465.778592] init: logstash main process (11334) terminated with status 1
Jul 21 09:11:27 ls-indexer-01 kernel: [414465.778633] init: logstash main process ended, respawning
Jul 21 09:11:34 ls-indexer-01 kernel: [414473.085125] init: logstash main process (11362) terminated with status 1
Jul 21 09:11:34 ls-indexer-01 kernel: [414473.085146] init: logstash main process ended, respawning
Jul 21 09:11:42 ls-indexer-01 kernel: [414481.280972] init: logstash main process (11390) terminated with status 1
Jul 21 09:11:42 ls-indexer-01 kernel: [414481.280990] init: logstash main process ended, respawning
Jul 21 09:11:49 ls-indexer-01 kernel: [414488.746162] init: logstash main process (11419) terminated with status 1
Jul 21 09:11:49 ls-indexer-01 kernel: [414488.746180] init: logstash main process ended, respawning
Jul 21 09:11:57 ls-indexer-01 kernel: [414496.095297] init: logstash main process (11454) terminated with status 1
Jul 21 09:11:57 ls-indexer-01 kernel: [414496.095316] init: logstash main process ended, respawning

[driskell]

That's not good. How are you running logstash and storing its logs?
Normally when it hits an error it will go to STDOUT or STDERR, so just need to make sure both are going to logs. It could be the log-courier plugin is breaking. Another option is to run logstash manually from cmd line and see if when it exits it outputs anything.

Also a good check to narrow things down, if you stop log-courier, does logstash stop respawning? This will tell us if the logstash plugin problem is occurring all the time - or if it is only occurring when log-courier connects to it.

I guess one thing to do is make sure that ZMQ 4.x is also installed on the logstash server. The log-courier plugin will try to load it. Though if the logstash problem only occurs when log-courier is trying to connect, it's probably not this.

[driskell]

Regarding the shutdown when ZMQ is reconnecting - I'll look into that. Possibly it's not checking for shutdown between reconnects when it should be. But that should be a simple one to resolve.

[deviantony]

Ok, I was missing the libzmq.so & libsodium.so libraries.

I've added the missing libs, now I got the following error when I try to start logstash:

Sending logstash logs to /var/log/logstash/logstash-debug.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: The libzmq version 4.0.4 is incompatible with ffi-rzmq.
           ZMQ at /opt/logstash/vendor/bundle/jruby/1.9/gems/ffi-rzmq-1.0.0/lib/ffi-rzmq/libzmq.rb:283
        (root) at /opt/logstash/vendor/bundle/jruby/1.9/gems/ffi-rzmq-1.0.0/lib/ffi-rzmq/libzmq.rb:1
       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
        (root) at /opt/logstash/vendor/bundle/jruby/1.9/gems/ffi-rzmq-1.0.0/lib/ffi-rzmq.rb:1
          each at org/jruby/RubyArray.java:1613
        (root) at /opt/logstash/vendor/bundle/jruby/1.9/gems/ffi-rzmq-1.0.0/lib/ffi-rzmq.rb:71
       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
        (root) at /opt/logstash/vendor/bundle/jruby/1.9/gems/ffi-rzmq-1.0.0/lib/ffi-rzmq.rb:70
       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
        (root) at /opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-0.10/lib/log-courier/server_zmq.rb:1
        (root) at /opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-0.10/lib/log-courier/server_zmq.rb:15
        (root) at /opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-0.10/lib/log-courier/server.rb:1
          each at org/jruby/RubyArray.java:1613
    initialize at /opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-0.10/lib/log-courier/server.rb:44
      register at /opt/logstash/lib/logstash/inputs/courier.rb:69
  start_inputs at /opt/logstash/lib/logstash/pipeline.rb:135
           run at /opt/logstash/lib/logstash/runner.rb:168
          call at org/jruby/RubyProc.java:271
  start_inputs at /opt/logstash/lib/logstash/pipeline.rb:134

Have you tried to use log-courier with zeromq 4.0.4 ?

[deviantony]

Seems that ffi-rzmq 2.x adds support to zmq 4.x:
chuckremes/ffi-rzmq#107

[driskell]

Hi @deviantony

Yes the ffi-rzmq gems bundled with Logstash are too old and require updated. I must have forgot this by the time I documented the integration, sorry, and the log-courier gem didn't depend on the newer version thus it didn't auto-update during installation.

I've modified the gem spec so log-courier gem now depends on the new versions. When it is installed it will automatically trigger the ffi-rzmq gems to be updated.

I tested this from scratch with a downloaded Logstash so there's definitely nothing else missing now to stop this working!

Thanks,

Jason

[deviantony]

Hey @driskell, I've built and installed the gem and now the logstash process is starting fine :)

But I'm still unable to connect to it with log-courier:

user@machine:/opt/log-courier$ ./log-courier -config=lc.conf
2014/07/22 09:13:06.256545 Starting pipeline
2014/07/22 09:13:06.256660 Pipeline ready
2014/07/22 09:13:06.256995 Launching harvester on new file: /path/to/file.log
2014/07/22 09:13:06.257970 Registrar received a new file event for /path/to/file.log
2014/07/22 09:13:06.258235 Started harvester at position 1977548 (requested 1977548): /path/to/file.log
2014/07/22 09:13:06.258334 Connected with 10.10.1.2:5077 (10.10.1.2) 
2014/07/22 09:14:56.262194 Transport error, will reconnect: Server did not respond within network timeout
2014/07/22 09:14:57.263008 Connected with 10.10.1.2:5077 (10.10.1.2) 
2014/07/22 09:15:12.263526 Transport error, will reconnect: Server did not respond within network timeout
2014/07/22 09:15:13.264089 Connected with 10.10.1.2:5077 (10.10.1.2) 

Is it possible to add some debug to it? I've tried using the following configuration file:

{
        "general": {
                "log level": "debug",
                "log file": "/opt/log-courier/lc.log"
        },
        "network": {
                "transport": "zmq",
                "servers": [ "10.10.1.2:5077" ],
                "curve server key": "xxx",
                "curve public key": "xxx",
                "curve secret key": "xxx"
        },
        "files": [
                {
                        "paths": [ "/path/to/file.log" ],
                        "fields": { "tags": "TAG" }
                }
        ]
}

But the log file is empty. I've also tried with "log syslog": true, but I don't have more info.

Thanks for your work & reactivity, keep up the good job man !

[driskell]

Thanks!

Is this when idle, when no logs are transmitting to the server?
Or are there logs to send which aren't been sending.

I ask because it looks like it started at the end of the log file - thus nothing will be getting sent. It could be a bug in the idle code where it is assuming it should be getting a response when it isn't. I can understand why I've not seen this then as all my servers are continuously streaming logs.

Jason

[deviantony]

It was idle, but I just tried with a bash script filling lines in a log file, the behavior is the same. Maybe if we could have more information on that transport error? Is there a way to add debug?

[driskell]

I've got some notes on implementing ZMQ monitoring so Log Courier can get notifications from what's happening on the ZMQ layer (it's all abstracted away by default) such as connects, disconnects, errors etc. At the moment Log Courier just lets ZMQ do the work.

"log level": "debug" currently only adds a few more lines of logging - specifically around acknowledgements. It adds the "Registrar received X" events and it also logs a little more about log rotations. "log file" I have fixed locally and will push when tested.

Is Logstash receiving any events? Can you check that the curve keys are correct. I remember during early testing if the keys weren't right things would just timeout as ZMQ would silently discard the messages - the main reason I want to get ZMQ monitoring in there eventually.

[deviantony]

Guess what, I've generated new curve keys (with the lc-curvekey from the develop branch) and restart the services, now it works ! I think we can close this issue.

It would be great to have more info from ZMQ indeed :)

Thanks mate!