log-courier finishes before sent data get acknowledged

[martinhynar]

Hi, I am using log-courier (1.8.3) with logstash (2.3.4), both are running on Oracle Linux 6.8, and quite often I see following error in logstash's logs.

{:timestamp=>"2016-11-03T05:35:30.858000-0700",
 :hint=>"Unknown error, connection aborted",
 :peer=>"10.10.17.114:41474",
 :level=>:warn,
 :message=>"Broken pipe - Broken pipe",
 :exception=>Errno::EPIPE,
 :backtrace=>[
   "org/jruby/RubyIO.java:1347:in `write_nonblock'",
   "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.9.0/lib/log-courier/server_tcp.rb:312:in `send'",
   "org/jruby/RubyKernel.java:1479:in `loop'",
   "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.9.0/lib/log-courier/server_tcp.rb:310:in `send'",
   "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.9.0/lib/log-courier/server.rb:219:in `process_jdat'",
   "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.9.0/lib/log-courier/server.rb:214:in `process_jdat'",
   "org/jruby/RubyKernel.java:1479:in `loop'",
   "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.9.0/lib/log-courier/server.rb:168:in `process_jdat'",
   "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.9.0/lib/log-courier/server.rb:91:in `run'",
   "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.9.0/lib/log-courier/server_tcp.rb:274:in `process_messages'",
   "org/jruby/RubyKernel.java:1479:in `loop'",
   "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.9.0/lib/log-courier/server_tcp.rb:250:in `process_messages'",
   "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.9.0/lib/log-courier/server_tcp.rb:238:in `run'",
   "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.9.0/lib/log-courier/server_tcp.rb:204:in `run_thread'",
   "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.9.0/lib/log-courier/server_tcp.rb:167:in `run'"]}

My setup is that Logstash is constantly running and log-courier is started on disposable virtual machines. These machines exist only for some limited time (few hours) to do some job. I use log-courier to collect logs there. Before the machine is disposed, service log-courier stop is called there to finish it nicely.

At this point, I am trying to understand what is happening, why it is happening and how to eliminate it.

First of all, at the time of stopping log-courier, there might be some data that are still to be sent or are just in transfer. Here I assume, that log-courier persists positions of files it reads and exits. Looking at the error from logstash, it says that there is problem with log-courier/server_tcp.rb:send and I understand it that it tries to acknowledge received data but log-courier is already gone.

Is there some way to instruct log-courier to finish all pending data? Perhaps via lc-admin.

[driskell]

@martinhynar The problem is if the files are still being modified, this could result in an exit time that is indeterminable. And eventually the service wrapper will kill Log Courier and you still won't have finished sending events.

I'm open to ideas on how that might be solved.

Have you looked at version 2? The lc-admin reports a completion, which reports at 100% when the file is fully sent. Maybe that's useful to you? You could implement your own stop script that waits until lc-admin reports 100% completion. I was also looking to add a "global" completion percent or flag at some point. My time has been massively absorbed in other things lately though so not sure when I'll get to that.

[martinhynar]

Hi, I finally returned to this problem to try the stopping strategy you proposed. Unfortunately, at the same time I am also upgrading to LogStash 5.1.1 and have this problem:

bin/logstash-plugin install logstash-input-courier
Validating logstash-input-courier
Installing logstash-input-courier
Plugin version conflict, aborting
ERROR: Installation Aborted, message: Bundler could not find compatible versions for gem "logstash-core":
  In snapshot (Gemfile.lock):
    logstash-core (= 5.1.1)

  In Gemfile:
    logstash-core-plugin-api (>= 0) java depends on
      logstash-core (= 5.1.1) java

    logstash-input-courier (>= 0) java depends on
      logstash-core (~> 1.4) java

    logstash-core (>= 0) java

Running `bundle update` will rebuild your snapshot from scratch, using only
the gems in your Gemfile, which may resolve the conflict.

Is LS 5.1.1 supported?

[driskell]

It is now. The plugin should install fine. I pushed 1.9.1 today.

[driskell]

I'll close this issue for now. Let me know if you need any more help. Looking back at it - it could've been a slow pipeline - in that Logstash was too slow to acknowledge and so Log Courier aborted so as not to prevent shutdown too long. It waits about 30 seconds or so.