Logstash 5 stops event output after some time

Hi everyone,

I'm struggling with a strange problem with a Logstash 5 that I'm running on a Windows 2012 x64.... Logstash seems to miss the output of some events, or sometimes it stops outputting events entirely.

My Logstash is getting its input from a PostgreSQL database, it filters/builds the events, and them outputs them via HTTP. The Logstash configuration is like this:

input {
  jdbc {
     ...
    statement => "select * from metrics_table where metric_timestamp > :sql_last_value"
	use_column_value => "true"
	tracking_column => "metric_timestamp"
	tracking_column_type => "numeric"
	last_run_metadata_path => "../log/metrics-logstash_jdbc_last_run"
	schedule => "* * * * *"
    ....
  }
}
filter {
    ## Add fields, rename fields, remove fields, convert some fields, and then...
	ruby {
		code => "
		event.to_hash.each do |k,v|
			if v == nil
				event.remove(k)
			end
		end
		event.set( 'event_body', event.to_json.inspect )
		event.to_hash.each do |k|
			if k !~ /m_Timestamp|^m_CustomerRelay$|event_body/
				event.remove(k)
			end
		end
		"
	}
}
output {
	http {
		http_method => "post"
		content_type => "application/json"
		format => "message"
            ...
		message => '{ "time":"%{m_Timestamp}", "host":"%{m_CustomerRelay}", "event":%{event_body} }'
	}
}

The database table is generating around 350 new entries per minute, and the table only has the data for the current day.

Everything starts an seem to be working as expected, but them it seems that after some time Logstatsh stops outputting the events, and I also detected that some events present in the DB table are never sent via teh HTTP output.

When I activate debug in Logstash, the debug output is very heavy, but I've only detected errors similar to the one bellow for now:

[2017-07-17T11:21:14,514][FATAL][logstash.runner ] An unexpected error occurred! {:error=>#<ThreadError: killed thread>, :backtrace=>["org/jruby/RubyThread.java:836:inwakeup'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/interval.rb:44:in stop!'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/task.rb:52:instop!'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/logstash-core/lib/logstash/runner.rb:411:in trap_sigint'", "org/jruby/RubyProc.java:281:incall'", "org/jruby/RubyArray.java:1613:in each'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/trap.rb:46:insimulate_signal'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/trap.rb:26:in trap'", "org/jruby/RubyProc.java:281:incall'"]}`

I have a second Logstash agent with a very similar configuration running on the same Windows machine, receiving its input from a second database table, and this one keeps working and working as expected.
The only thing different is that the event rate in that case is significantly lower, about 50 new lines per minute.

Any pointers for the cause or to aid me in the investigation?

Thanks.

Hi,

On a side situation on this subject, I detected that the input-jdbc-plugin seemed not to be updating the file:
last_run_metadata_path => "../log/metrics-logstash_jdbc_last_run"
in some cases, causes still not clear to me, causing a real mess in the DB lines input to Logstatsh.

I moved the file into a TMP public directory, to check if it is a case of insufficient permissions - the other Logstash Agent don't seem to have this problem.

I'm running both Logstash Agents as Windows Services , by the way.
The default System Account can be in play here.

But it seems that the main difference is the rate of new lines per minute in the DB Table used by each Agent.

Found this errors in the Logstash log:

[2017-07-17T19:23:21,611][DEBUG][logstash.agent           ] Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
[2017-07-17T19:23:21,611][DEBUG][logstash.agent           ] 2017-07-17 19:23:21 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
[2017-07-17T19:23:21,627][DEBUG][logstash.agent           ] org/jruby/RubyIO.java:3705:in `select'
C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
[2017-07-17T19:23:21,627][DEBUG][logstash.agent           ] ["org/jruby/RubyIO.java:3705:in `select'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'"]
[2017-07-17T19:23:21,627][DEBUG][logstash.agent           ] Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
[2017-07-17T19:23:23,189][DEBUG][logstash.agent           ] 2017-07-17 19:23:23 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
[2017-07-17T19:23:23,189][DEBUG][logstash.agent           ] ["org/jruby/RubyIO.java:3705:in `select'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'"]
[2017-07-17T19:23:23,189][DEBUG][logstash.agent           ] org/jruby/RubyIO.java:3705:in `select'
C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'

[2017-07-17T19:31:44,541][DEBUG][logstash.agent           ] 2017-07-17 19:31:44 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
[2017-07-17T19:31:44,541][DEBUG][logstash.agent           ] Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
[2017-07-17T19:31:45,119][DEBUG][logstash.agent           ] ["org/jruby/RubyIO.java:3705:in `select'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'"]
[2017-07-17T19:31:45,119][DEBUG][logstash.agent           ] Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
[2017-07-17T19:31:45,119][DEBUG][logstash.agent           ] ["org/jruby/RubyIO.java:3705:in `select'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'"]
[2017-07-17T19:31:45,119][DEBUG][logstash.agent           ] org/jruby/RubyIO.java:3705:in `select'
C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
[2017-07-17T19:31:45,119][DEBUG][logstash.agent           ] Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
[2017-07-17T19:31:45,119][DEBUG][logstash.agent           ] ["org/jruby/RubyIO.java:3705:in `select'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'"]

They seem to appear immediately before Logstash is re-reading the configuration file...

The Logstash agent stopped again sending events.

Running Logstash from the command line with debug output, to try to get any error...

Detected this one:

    Error: Your application used more memory than the safety cap of 1G
    Specify -J-Xmx####m to increase it (#### = cap size in MB).
    ...
    [2017-07-17T19:31:44,541][DEBUG][logstash.agent           ] 2017-07-17 19:31:44 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
    [2017-07-17T19:31:44,541][DEBUG][logstash.agent           ] Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
    [2017-07-17T19:31:45,119][DEBUG][logstash.agent           ] ["org/jruby/RubyIO.java:3705:in `select'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'"]
    [2017-07-17T19:31:45,119][DEBUG][logstash.agent           ] Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
    [2017-07-17T19:31:45,119][DEBUG][logstash.agent           ] ["org/jruby/RubyIO.java:3705:in `select'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'"]
    [2017-07-17T19:31:45,119][DEBUG][logstash.agent           ] org/jruby/RubyIO.java:3705:in `select'
    C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
    C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
    [2017-07-17T19:31:45,119][DEBUG][logstash.agent           ] Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
    [2017-07-17T19:31:45,119][DEBUG][logstash.agent           ] ["org/jruby/RubyIO.java:3705:in `select'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'", "C:/PROGRA~2/ALTITU~1/LOGSTA~1/ahm-metrics/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'"]

Oh well, changing the Java8 JRE to of teh Logstash Agent x64, and using now:

JRUBY_OPTS=-J-Xmx2g

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