Hello,
Logstash: 6.2.4
Oracle driver: 12.1.0.2.0
JDK 8 101-b13
A JDBC plugin pulls rows from an Oracle table. Once a day, the DB is restarted and during the restart, Logstash throws this error:
30574 rufus-scheduler intercepted an error:
30574 job:
30574 Rufus::Scheduler::CronJob "*/5 * * * *" {}
30574 error:
30574 30574
30574 Sequel::DatabaseConnectionError
30574 Java::JavaSql::SQLRecoverableException: ORA-01033: ORACLE initialization or shutdown in progress
30574 oracle.jdbc.driver.T4CTTIoer.processError(oracle/jdbc/driver/T4CTTIoer.java:450)
30574 oracle.jdbc.driver.T4CTTIoer.processError(oracle/jdbc/driver/T4CTTIoer.java:392)
30574 oracle.jdbc.driver.T4CTTIoer.processError(oracle/jdbc/driver/T4CTTIoer.java:385)
30574 oracle.jdbc.driver.T4CTTIoauthenticate.processError(oracle/jdbc/driver/T4CTTIoauthenticate.java:493)
30574 oracle.jdbc.driver.T4CTTIfun.receive(oracle/jdbc/driver/T4CTTIfun.java:522)
30574 oracle.jdbc.driver.T4CTTIfun.doRPC(oracle/jdbc/driver/T4CTTIfun.java:257)
30574 oracle.jdbc.driver.T4CTTIoauthenticate.doOSESSKEY(oracle/jdbc/driver/T4CTTIoauthenticate.java:456)
30574 oracle.jdbc.driver.T4CConnection.logon(oracle/jdbc/driver/T4CConnection.java:594)
30574 oracle.jdbc.driver.PhysicalConnection.connect(oracle/jdbc/driver/PhysicalConnection.java:662)
30574 oracle.jdbc.driver.T4CDriverExtension.getConnection(oracle/jdbc/driver/T4CDriverExtension.java:32)
30574 oracle.jdbc.driver.OracleDriver.connect(oracle/jdbc/driver/OracleDriver.java:560)
30574 java.lang.reflect.Method.invoke(java/lang/reflect/Method.java:498)
30574 org.jruby.javasupport.JavaMethod.invokeDirectWithExceptionHandling(org/jruby/javasupport/JavaMethod.java:468)
30574 org.jruby.javasupport.JavaMethod.invokeDirect(org/jruby/javasupport/JavaMethod.java:326)
30574
30574 [...]
30574 usr.share.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.rufus_minus_scheduler_minus_3_dot_0_dot_9.lib.rufus.scheduler.jobs.block in start_work_thread(/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/rufus-scheduler-3.0.9/lib/rufus/scheduler/jobs.rb:299)
30574 org.jruby.RubyKernel.loop(org/jruby/RubyKernel.java:1292)
30574 org.jruby.RubyKernel$INVOKER$s$0$0$loop.call(org/jruby/RubyKernel$INVOKER$s$0$0$loop.gen)
30574 RUBY.block in start_work_thread(/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/rufus-scheduler-3.0.9/lib/rufus/scheduler/jobs.rb:289)
30574 org.jruby.RubyProc.call(org/jruby/RubyProc.java:289)
30574 org.jruby.RubyProc.call(org/jruby/RubyProc.java:246)
30574 java.lang.Thread.run(java/lang/Thread.java:745)
30574 tz:
30574 ENV['TZ']:
30574 Time.now: 2018-05-14 22:35:00 +0200
30574 scheduler:
30574 object_id: 2022
30574 opts:
30574 {:max_work_threads=>1}
30574 frequency: 0.3
30574 scheduler_lock: #<Rufus::Scheduler::NullLock:0x44ba3b44>
30574 trigger_lock: #<Rufus::Scheduler::NullLock:0x68575a97>
30574 uptime: 450367.324343 (5d5h6m7s324)
30574 down?: false
30574 threads: 2
30574 thread: #<Thread:0x1dae9486>
30574 thread_key: rufus_scheduler_2022
30574 work_threads: 1
30574 active: 1
30574 vacant: 0
30574 max_work_threads: 1
30574 mutexes: {}
30574 jobs: 1
30574 at_jobs: 0
30574 in_jobs: 0
30574 every_jobs: 0
30574 interval_jobs: 0
30574 cron_jobs: 1
30574 running_jobs: 1
30574 work_queue: 0
} 30574 .
After the issue occurs 5 times, lostash stops to process anything.
Hot threads return the following result:
curl -XGET 'localhost:9600/_node/hot_threads?pretty&ignore_idle_threads=false'
{
"host" : "foo",
"version" : "6.2.4",
"http_address" : "127.0.0.1:9600",
"id" : "c37326f5-0d15-44ac-b580-90db73a87d47",
"name" : "foo",
"hot_threads" : {
"time" : "2018-05-15T16:02:23+02:00",
"busiest_threads" : 3,
"threads" : [ {
"name" : "Ruby-0-Thread-25@[oracle_audit1]>worker0",
"thread_id" : 40,
"percent_of_cpu_time" : 0.05,
"state" : "timed_waiting",
"path" : "/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:385",
"traces" : [ "sun.misc.Unsafe.park(Native Method)", "java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)", "java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)" ]
}, {
"name" : "Ruby-0-Thread-26@[oracle_audit2]>worker1",
"thread_id" : 41,
"percent_of_cpu_time" : 0.05,
"state" : "timed_waiting",
"path" : "/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:385",
"traces" : [ "sun.misc.Unsafe.park(Native Method)", "java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)", "java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)" ]
}, {
"name" : "Ruby-0-Thread-34@[oracle_audit3]>worker0",
"thread_id" : 49,
"percent_of_cpu_time" : 0.04,
"state" : "timed_waiting",
"path" : "/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:385",
"traces" : [ "sun.misc.Unsafe.park(Native Method)", "java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)", "java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)" ]
} ]
}
}
The threads seems blocked waiting for something.
The jdbc configuration is the following:
jdbc {
jdbc_driver_library => "/usr/share/logstash/vendor/ojdbc6-12.1.0.2.0.jar"
jdbc_driver_class => "Java::oracle.jdbc.driver.OracleDriver"
jdbc_connection_string => ""
jdbc_user => ""
jdbc_password => ""
schedule => "*/5 * * * *"
statement => ""
use_column_value => true
tracking_column_type => "timestamp"
tracking_column => "timestamp"
jdbc_fetch_size => 1000
jdbc_validate_connection => true
sql_log_level => "debug"
last_run_metadata_path => "/data/logstash/state/.logstash_jdbc_last_run"
}
Is there something wrong ?
Thank you for your help
Nicolas