logstash-plugins/logstash-integration-jdbc

Intermittent error in loading multiple drivers when SyBase driver is used

andsel opened this issue · 1 comments

andsel commented

Logstash information:

Please include the following information:

  1. Logstash version (e.g. bin/logstash --version) 7.14.1 but it happens also in master
  2. Logstash installation source (e.g. built from source, with a package manager: DEB/RPM, expanded from tar or zip archive, docker) tar.gz / sources
  3. How is Logstash being run (e.g. as a service/service manager: systemd, upstart, etc. Via command line, docker/kubernetes) command line
  4. How was the Logstash Plugin installed, already shipped

JVM (e.g. java -version):

If the affected version of Logstash is 7.9 (or earlier), or if it is NOT using the bundled JDK or using the 'no-jdk' version in 7.10 (or higher), please provide the following information:

  1. JVM version (java -version)
openjdk version "11.0.11" 2021-04-20
OpenJDK Runtime Environment AdoptOpenJDK-11.0.11+9 (build 11.0.11+9)
OpenJDK 64-Bit Server VM AdoptOpenJDK-11.0.11+9 (build 11.0.11+9, mixed mode)
  1. JVM installation source (e.g. from the Operating System's package manager, from source, etc). from source
  2. Value of the JAVA_HOME environment variable if set. /home/andrea/.sdkman/candidates/java/current

OS version (uname -a if on a Unix-like system):
Linux kalispera 5.4.0-86-generic #97-Ubuntu SMP Fri Sep 17 19:19:40 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

Description of the problem including expected versus actual behavior:
When multiple pipelines with JDBC input configured to pull data from different DBs are present and one of them is SyBase, jConn4.jar then during startup it happens then randomly some pipelines have problems in loading the driver, and iterate in loading again and again but without success:

[2021-09-28T10:05:31,030][INFO ][logstash.javapipeline    ][oracle_1] Pipeline Java execution initialization time {"seconds"=>0.38}
[2021-09-28T10:05:31,030][INFO ][logstash.javapipeline    ][sybase_1] Pipeline Java execution initialization time {"seconds"=>0.38}
[2021-09-28T10:05:31,030][INFO ][logstash.javapipeline    ][mysql_1] Pipeline Java execution initialization time {"seconds"=>0.29}
[2021-09-28T10:05:31,058][INFO ][logstash.javapipeline    ][oracle_1] Pipeline started {"pipeline.id"=>"oracle_1"}
[2021-09-28T10:05:31,059][INFO ][logstash.javapipeline    ][mysql_1] Pipeline started {"pipeline.id"=>"mysql_1"}
[2021-09-28T10:05:31,060][INFO ][logstash.javapipeline    ][sybase_1] Pipeline started {"pipeline.id"=>"sybase_1"}
[2021-09-28T10:05:31,096][INFO ][logstash.agent           ] Pipelines running {:count=>3, :running_pipelines=>[:oracle_1, :sybase_1, :mysql_1], :non_running_pipelines=>[]}
[2021-09-28T10:05:31,353][ERROR][logstash.javapipeline    ][oracle_1][7238c87971f3621372fc81e4bec547f15795f414b8cdd6af8d3683771d912529] A plugin had an unrecoverable error. Will restart this plugin.
  Pipeline_id:oracle_1
  Plugin: <LogStash::Inputs::Jdbc jdbc_user=>"user", tracking_column_type=>"numeric", use_prepared_statements=>true, use_column_value=>true, tracking_column=>"data_log.log_id", prepared_statement_bind_values=>[":sql_last_value"], schedule=>"* 5 * 1-3 *", prepared_statement_name=>"Fetch_mysql_1", jdbc_password=><password>, statement=>"SELECT * FROM data_log WHERE log_id > ?", jdbc_driver_library=>"/tmp/reproducer/drivers/ojdbc11.jar", jdbc_default_timezone=>"UTC", jdbc_connection_string=>"jdbc:oracle:thin://localhost:1521/test_logstash", id=>"7238c87971f3621372fc81e4bec547f15795f414b8cdd6af8d3683771d912529", jdbc_driver_class=>"Java::oracle.jdbc.driver.OracleDriver", enable_metric=>true, codec=><LogStash::Codecs::Plain id=>"plain_1c4d5568-77b9-4508-bb3d-d45c0e6c4175", enable_metric=>true, charset=>"UTF-8">, jdbc_paging_enabled=>false, jdbc_page_size=>100000, jdbc_validate_connection=>false, jdbc_validation_timeout=>3600, jdbc_pool_timeout=>5, sql_log_level=>"info", connection_retry_attempts=>1, connection_retry_attempts_wait_time=>0.5, plugin_timezone=>"utc", last_run_metadata_path=>"/home/andrea/.logstash_jdbc_last_run", clean_run=>false, record_last_run=>true, lowercase_column_names=>true>
  Error: Java::oracle.jdbc.driver.OracleDriver not loaded. Are you sure you've included the correct jdbc driver in :jdbc_driver_library? ["/home/andrea/workspace/logstash_andsel/vendor/bundle/jruby/2.5.0/gems/sequel-5.48.0/lib/sequel/adapters/jdbc.rb:68:in `load_driver'", "/home/andrea/workspace/logstash_plugins/logstash-integration-jdbc/lib/logstash/plugin_mixins/jdbc/common.rb:27:in `load_driver'", "/home/andrea/workspace/logstash_plugins/logstash-integration-jdbc/lib/logstash/inputs/jdbc.rb:294:in `run'", "/home/andrea/workspace/logstash_andsel/logstash-core/lib/logstash/java_pipeline.rb:405:in `inputworker'", "/home/andrea/workspace/logstash_andsel/logstash-core/lib/logstash/java_pipeline.rb:396:in `block in start_input'"]
  Exception: LogStash::PluginLoadingError
  Stack: /home/andrea/workspace/logstash_plugins/logstash-integration-jdbc/lib/logstash/plugin_mixins/jdbc/common.rb:36:in `load_driver'
/home/andrea/workspace/logstash_plugins/logstash-integration-jdbc/lib/logstash/inputs/jdbc.rb:294:in `run'
/home/andrea/workspace/logstash_andsel/logstash-core/lib/logstash/java_pipeline.rb:405:in `inputworker'
/home/andrea/workspace/logstash_andsel/logstash-core/lib/logstash/java_pipeline.rb:396:in `block in start_input'
[2021-09-28T10:05:31,353][ERROR][logstash.javapipeline    ][sybase_1][e591e44a0e4702e3dae5924b838a9f91e6b853f17a8db18e37f9e450e78e344b] A plugin had an unrecoverable error. Will restart this plugin.
  Pipeline_id:sybase_1
  Plugin: <LogStash::Inputs::Jdbc jdbc_user=>"user", tracking_column_type=>"numeric", use_prepared_statements=>true, use_column_value=>true, tracking_column=>"data_log.log_id", prepared_statement_bind_values=>[":sql_last_value"], schedule=>"* 5 * 1-3 *", prepared_statement_name=>"Fetch_mysql_1", jdbc_password=><password>, statement=>"SELECT * FROM data_log WHERE log_id > ?", jdbc_driver_library=>"/tmp/reproducer/drivers/jconn4.jar", jdbc_default_timezone=>"UTC", jdbc_connection_string=>"jdbc:sybase:Tds:localhost:9000", id=>"e591e44a0e4702e3dae5924b838a9f91e6b853f17a8db18e37f9e450e78e344b", jdbc_driver_class=>"Java::com.sybase.jdbc4.jdbc.SybDriver", enable_metric=>true, codec=><LogStash::Codecs::Plain id=>"plain_1bdc63a6-944e-497c-a3bc-ef6af93f91a9", enable_metric=>true, charset=>"UTF-8">, jdbc_paging_enabled=>false, jdbc_page_size=>100000, jdbc_validate_connection=>false, jdbc_validation_timeout=>3600, jdbc_pool_timeout=>5, sql_log_level=>"info", connection_retry_attempts=>1, connection_retry_attempts_wait_time=>0.5, plugin_timezone=>"utc", last_run_metadata_path=>"/home/andrea/.logstash_jdbc_last_run", clean_run=>false, record_last_run=>true, lowercase_column_names=>true>
  Error: Java::com.sybase.jdbc4.jdbc.SybDriver not loaded. Are you sure you've included the correct jdbc driver in :jdbc_driver_library? ["/home/andrea/workspace/logstash_andsel/vendor/bundle/jruby/2.5.0/gems/sequel-5.48.0/lib/sequel/adapters/jdbc.rb:68:in `load_driver'", "/home/andrea/workspace/logstash_plugins/logstash-integration-jdbc/lib/logstash/plugin_mixins/jdbc/common.rb:27:in `load_driver'", "/home/andrea/workspace/logstash_plugins/logstash-integration-jdbc/lib/logstash/inputs/jdbc.rb:294:in `run'", "/home/andrea/workspace/logstash_andsel/logstash-core/lib/logstash/java_pipeline.rb:405:in `inputworker'", "/home/andrea/workspace/logstash_andsel/logstash-core/lib/logstash/java_pipeline.rb:396:in `block in start_input'"]
  Exception: LogStash::PluginLoadingError
  Stack: /home/andrea/workspace/logstash_plugins/logstash-integration-jdbc/lib/logstash/plugin_mixins/jdbc/common.rb:36:in `load_driver'
/home/andrea/workspace/logstash_plugins/logstash-integration-jdbc/lib/logstash/inputs/jdbc.rb:294:in `run'
/home/andrea/workspace/logstash_andsel/logstash-core/lib/logstash/java_pipeline.rb:405:in `inputworker'
/home/andrea/workspace/logstash_andsel/logstash-core/lib/logstash/java_pipeline.rb:396:in `block in start_input'
/home/andrea/workspace/logstash_andsel/vendor/bundle/jruby/2.5.0/gems/rufus-scheduler-3.0.9/lib/rufus/scheduler/cronline.rb:77: warning: constant ::Fixnum is deprecated
[2021-09-28T10:05:32,375][ERROR][logstash.javapipeline    ][sybase_1][e591e44a0e4702e3dae5924b838a9f91e6b853f17a8db18e37f9e450e78e344b] A plugin had an unrecoverable error. Will restart this plugin.
  Pipeline_id:sybase_1
  Plugin: <LogStash::Inputs::Jdbc jdbc_user=>"user", tracking_column_type=>"numeric", use_prepared_statements=>true, use_column_value=>true, tracking_column=>"data_log.log_id", prepared_statement_bind_values=>[":sql_last_value"], schedule=>"* 5 * 1-3 *", prepared_statement_name=>"Fetch_mysql_1", jdbc_password=><password>, statement=>"SELECT * FROM data_log WHERE log_id > ?", jdbc_driver_library=>"/tmp/reproducer/drivers/jconn4.jar", jdbc_default_timezone=>"UTC", jdbc_connection_string=>"jdbc:sybase:Tds:localhost:9000", id=>"e591e44a0e4702e3dae5924b838a9f91e6b853f17a8db18e37f9e450e78e344b", jdbc_driver_class=>"Java::com.sybase.jdbc4.jdbc.SybDriver", enable_metric=>true, codec=><LogStash::Codecs::Plain id=>"plain_1bdc63a6-944e-497c-a3bc-ef6af93f91a9", enable_metric=>true, charset=>"UTF-8">, jdbc_paging_enabled=>false, jdbc_page_size=>100000, jdbc_validate_connection=>false, jdbc_validation_timeout=>3600, jdbc_pool_timeout=>5, sql_log_level=>"info", connection_retry_attempts=>1, connection_retry_attempts_wait_time=>0.5, plugin_timezone=>"utc", last_run_metadata_path=>"/home/andrea/.logstash_jdbc_last_run", clean_run=>false, record_last_run=>true, lowercase_column_names=>true>
  Error: Java::com.sybase.jdbc4.jdbc.SybDriver not loaded. Are you sure you've included the correct jdbc driver in :jdbc_driver_library? ["/home/andrea/workspace/logstash_andsel/vendor/bundle/jruby/2.5.0/gems/sequel-5.48.0/lib/sequel/adapters/jdbc.rb:68:in `load_driver'", "/home/andrea/workspace/logstash_plugins/logstash-integration-jdbc/lib/logstash/plugin_mixins/jdbc/common.rb:27:in `load_driver'", "/home/andrea/workspace/logstash_plugins/logstash-integration-jdbc/lib/logstash/inputs/jdbc.rb:294:in `run'", "/home/andrea/workspace/logstash_andsel/logstash-core/lib/logstash/java_pipeline.rb:405:in `inputworker'", "/home/andrea/workspace/logstash_andsel/logstash-core/lib/logstash/java_pipeline.rb:396:in `block in start_input'"]
  Exception: LogStash::PluginLoadingError
  Stack: /home/andrea/workspace/logstash_plugins/logstash-integration-jdbc/lib/logstash/plugin_mixins/jdbc/common.rb:36:in `load_driver'
/home/andrea/workspace/logstash_plugins/logstash-integration-jdbc/lib/logstash/inputs/jdbc.rb:294:in `run'
/home/andrea/workspace/logstash_andsel/logstash-core/lib/logstash/java_pipeline.rb:405:in `inputworker'
/home/andrea/workspace/logstash_andsel/logstash-core/lib/logstash/java_pipeline.rb:396:in `block in start_input'

Steps to reproduce:

  1. unpack the following reproducer into /tmp/
    reproducer.tar.gz

  2. cd /tmp/reproducer

  3. download Oracle and SyBase driver from their websites (https://dbschema.com/databases.html may help for Oracle https://dbschema.com/jdbc-driver/Oracle.html, but SyBase has to be retrieved in some other way)

  4. run <path_to_logstash>/bin/logstash --path.settings `pwd`

  5. in the reproducer.tar.gz pack there is also the jruby_multi_threader_load.rb that's used to proove that problem originated from the Sequel library, without Logstash

Provide logs (if relevant):
With some tinkering of the JDBC plugin I was able to print the backtrace of the originating exception:

Error: Java::com.sybase.jdbc4.jdbc.SybDriver not loaded. 
Are you sure you've included the correct jdbc driver in :jdbc_driver_library? 
["/home/andrea/workspace/logstash_andsel/vendor/bundle/jruby/2.5.0/gems/sequel-5.48.0/lib/sequel/adapters/jdbc.rb:68:in `load_driver'", 
 "/home/andrea/workspace/logstash_plugins/logstash-integration-jdbc/lib/logstash/plugin_mixins/jdbc/common.rb:27:in `load_driver'", 
 "/home/andrea/workspace/logstash_plugins/logstash-integration-jdbc/lib/logstash/inputs/jdbc.rb:294:in `run'", 
 "/home/andrea/workspace/logstash_andsel/logstash-core/lib/logstash/java_pipeline.rb:405:in `inputworker'", 
 "/home/andrea/workspace/logstash_andsel/logstash-core/lib/logstash/java_pipeline.rb:396:in `block in start_input'"]
andsel commented

As expirement to solve this, in the jruby_multithreader_load.rb reproducer script I tried to put a lock around the driver loading:

def load_driver_test(db_type, jar_path, driver_class_name, lock)
  sleep(rand(0.1..0.2))
  require jar_path
  begin
    lock.lock()
    driver_impl = Sequel::JDBC.load_driver(driver_class_name)
  rescue Sequel::AdapterNotFound => e
    puts "Problem loading driver #{db_type} #{e}, #{e.backtrace}"
  ensure
    lock.unlock()  
  end  
end

but still crate the problem.
But if we lock also the require jar_path then the problem disappear.