An issue on jdbc input seems to hang logstash


(Nicolas Labrot) #1

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


(system) #2

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