search

seancorfield / next-jdbc

A modern low-level Clojure wrapper for JDBC-based access to databases.
https://cljdoc.org/d/com.github.seancorfield/next.jdbc/
Eclipse Public License 1.0
768 stars 90 forks source link

Intermittent connection failure with repeated execution against reified datasource #118

Closed seancorfield closed 4 years ago

seancorfield commented 4 years ago

See https://clojureverse.org/t/connection-issue-with-next-jdbc/6058

Repro:

(def DS (jdbc/get-datasource CX))
(doseq [x (range 100000)]
  (jdbc/execute! DS ["SELECT 1"]))

where DS is a datasource made from a hash map (db-spec).

l3nz commented 4 years ago

I tried running:

(doseq [x (range 100000)]
  (prn x)
  (jdbc/execute! DS ["SELECT 1"]))

So I can see it trying and can know after how long it fails.

The exact stack trace I get is:

#error{:cause "Operation timed out (Connection timed out)",
       :via [{:type java.sql.SQLNonTransientConnectionException,
              :message "Could not connect to address=(host=127.0.0.1)(port=3306)(type=master) : Socket fail to connect to host:127.0.0.1, port:3306. Operation timed out (Connection timed out)",
              :at [org.mariadb.jdbc.internal.util.exceptions.ExceptionFactory
                   createException
                   "ExceptionFactory.java"
                   73]}
             {:type java.sql.SQLNonTransientConnectionException,
              :message "Socket fail to connect to host:127.0.0.1, port:3306. Operation timed out (Connection timed out)",
              :at [org.mariadb.jdbc.internal.util.exceptions.ExceptionFactory
                   createException
                   "ExceptionFactory.java"
                   73]}
             {:type java.net.ConnectException,
              :message "Operation timed out (Connection timed out)",
              :at [java.net.PlainSocketImpl socketConnect "PlainSocketImpl.java" -2]}],
       :trace [[java.net.PlainSocketImpl socketConnect "PlainSocketImpl.java" -2]
               [java.net.AbstractPlainSocketImpl doConnect "AbstractPlainSocketImpl.java" 350]
               [java.net.AbstractPlainSocketImpl connectToAddress "AbstractPlainSocketImpl.java" 206]
               [java.net.AbstractPlainSocketImpl connect "AbstractPlainSocketImpl.java" 188]
               [java.net.SocksSocketImpl connect "SocksSocketImpl.java" 392]
               [java.net.Socket connect "Socket.java" 589]
               [org.mariadb.jdbc.internal.protocol.AbstractConnectProtocol
                createSocket
                "AbstractConnectProtocol.java"
                250]
               [org.mariadb.jdbc.internal.protocol.AbstractConnectProtocol
                createConnection
                "AbstractConnectProtocol.java"
                512]
               [org.mariadb.jdbc.internal.protocol.AbstractConnectProtocol
                connectWithoutProxy
                "AbstractConnectProtocol.java"
                1341]
               [org.mariadb.jdbc.internal.util.Utils retrieveProxy "Utils.java" 634]
               [org.mariadb.jdbc.MariaDbConnection newConnection "MariaDbConnection.java" 150]
               [org.mariadb.jdbc.Driver connect "Driver.java" 89]
               [java.sql.DriverManager getConnection "DriverManager.java" 664]
               [java.sql.DriverManager getConnection "DriverManager.java" 208]
               [next.jdbc.connection$get_driver_connection invokeStatic "connection.clj" 137]
               [next.jdbc.connection$get_driver_connection invoke "connection.clj" 132]
               [next.jdbc.connection$url_PLUS_etc$reify__2499 getConnection "connection.clj" 321]
               [next.jdbc.connection$make_connection invokeStatic "connection.clj" 343]
               [next.jdbc.connection$make_connection invoke "connection.clj" 331]
               [next.jdbc.connection$eval2517$fn__2518 invoke "connection.clj" 366]
               [next.jdbc.protocols$eval2281$fn__2282$G__2272__2289 invoke "protocols.clj" 24]
               [next.jdbc.result_set$eval3084$fn__3092 invoke "result_set.clj" 685]
               [next.jdbc.protocols$eval2313$fn__2344$G__2304__2353 invoke "protocols.clj" 33]
               [next.jdbc$execute_BANG_ invokeStatic "jdbc.clj" 220]
               [next.jdbc$execute_BANG_ invoke "jdbc.clj" 210]
               [jimmy.core$eval7628 invokeStatic "form-init12065806360273634993.clj" 3]
               [jimmy.core$eval7628 invoke "form-init12065806360273634993.clj" 1]
               [clojure.lang.Compiler eval "Compiler.java" 7177]
               [clojure.lang.Compiler eval "Compiler.java" 7132]
               [clojure.core$eval invokeStatic "core.clj" 3214]
               [clojure.core$eval invoke "core.clj" 3210]
               [clojure.main$repl$read_eval_print__9086$fn__9089 invoke "main.clj" 437]
               [clojure.main$repl$read_eval_print__9086 invoke "main.clj" 437]
               [clojure.main$repl$fn__9095 invoke "main.clj" 458]
               [clojure.main$repl invokeStatic "main.clj" 458]
               [clojure.main$repl doInvoke "main.clj" 368]
               [clojure.lang.RestFn invoke "RestFn.java" 1523]
               [nrepl.middleware.interruptible_eval$evaluate invokeStatic "interruptible_eval.clj" 79]
               [nrepl.middleware.interruptible_eval$evaluate invoke "interruptible_eval.clj" 55]
               [nrepl.middleware.interruptible_eval$interruptible_eval$fn__921$fn__925
                invoke
                "interruptible_eval.clj"
                142]
               [clojure.lang.AFn run "AFn.java" 22]
               [nrepl.middleware.session$session_exec$main_loop__1022$fn__1026 invoke "session.clj" 171]
               [nrepl.middleware.session$session_exec$main_loop__1022 invoke "session.clj" 170]
               [clojure.lang.AFn run "AFn.java" 22]
               [java.lang.Thread run "Thread.java" 748]]}

or:

#error{:cause "Can't assign requested address (connect failed)",
       :via [{:type java.sql.SQLNonTransientConnectionException,
              :message "Could not connect to address=(host=127.0.0.1)(port=3306)(type=master) : Socket fail to connect to host:127.0.0.1, port:3306. Can't assign requested address (connect failed)",
              :at [org.mariadb.jdbc.internal.util.exceptions.ExceptionFactory
                   createException
                   "ExceptionFactory.java"
                   73]}
             {:type java.sql.SQLNonTransientConnectionException,
              :message "Socket fail to connect to host:127.0.0.1, port:3306. Can't assign requested address (connect failed)",
              :at [org.mariadb.jdbc.internal.util.exceptions.ExceptionFactory
                   createException
                   "ExceptionFactory.java"
                   73]}
             {:type java.net.ConnectException,
              :message "Can't assign requested address (connect failed)",
              :at [java.net.PlainSocketImpl socketConnect "PlainSocketImpl.java" -2]}],
       :trace [[java.net.PlainSocketImpl socketConnect "PlainSocketImpl.java" -2]
               [java.net.AbstractPlainSocketImpl doConnect "AbstractPlainSocketImpl.java" 350]
               [java.net.AbstractPlainSocketImpl connectToAddress "AbstractPlainSocketImpl.java" 206]
               [java.net.AbstractPlainSocketImpl connect "AbstractPlainSocketImpl.java" 188]
               [java.net.SocksSocketImpl connect "SocksSocketImpl.java" 392]
               [java.net.Socket connect "Socket.java" 589]
               [org.mariadb.jdbc.internal.protocol.AbstractConnectProtocol
                createSocket
                "AbstractConnectProtocol.java"
                250]
               [org.mariadb.jdbc.internal.protocol.AbstractConnectProtocol
                createConnection
                "AbstractConnectProtocol.java"
                512]
               [org.mariadb.jdbc.internal.protocol.AbstractConnectProtocol
                connectWithoutProxy
                "AbstractConnectProtocol.java"
                1341]
               [org.mariadb.jdbc.internal.util.Utils retrieveProxy "Utils.java" 634]
               [org.mariadb.jdbc.MariaDbConnection newConnection "MariaDbConnection.java" 150]
               [org.mariadb.jdbc.Driver connect "Driver.java" 89]
               [java.sql.DriverManager getConnection "DriverManager.java" 664]
               [java.sql.DriverManager getConnection "DriverManager.java" 208]
               [next.jdbc.connection$get_driver_connection invokeStatic "connection.clj" 137]
               [next.jdbc.connection$get_driver_connection invoke "connection.clj" 132]
               [next.jdbc.connection$url_PLUS_etc$reify__2499 getConnection "connection.clj" 321]
               [next.jdbc.connection$make_connection invokeStatic "connection.clj" 343]
               [next.jdbc.connection$make_connection invoke "connection.clj" 331]
               [next.jdbc.connection$eval2517$fn__2518 invoke "connection.clj" 366]
               [next.jdbc.protocols$eval2281$fn__2282$G__2272__2289 invoke "protocols.clj" 24]
               [next.jdbc.result_set$eval3084$fn__3092 invoke "result_set.clj" 685]
               [next.jdbc.protocols$eval2313$fn__2344$G__2304__2353 invoke "protocols.clj" 33]
               [next.jdbc$execute_BANG_ invokeStatic "jdbc.clj" 220]
               [next.jdbc$execute_BANG_ invoke "jdbc.clj" 210]
               [jimmy.core$eval7474 invokeStatic "form-init12065806360273634993.clj" 3]
               [jimmy.core$eval7474 invoke "form-init12065806360273634993.clj" 1]
               [clojure.lang.Compiler eval "Compiler.java" 7177]
               [clojure.lang.Compiler eval "Compiler.java" 7132]
               [clojure.core$eval invokeStatic "core.clj" 3214]
               [clojure.core$eval invoke "core.clj" 3210]
               [clojure.main$repl$read_eval_print__9086$fn__9089 invoke "main.clj" 437]
               [clojure.main$repl$read_eval_print__9086 invoke "main.clj" 437]
               [clojure.main$repl$fn__9095 invoke "main.clj" 458]
               [clojure.main$repl invokeStatic "main.clj" 458]
               [clojure.main$repl doInvoke "main.clj" 368]
               [clojure.lang.RestFn invoke "RestFn.java" 1523]
               [nrepl.middleware.interruptible_eval$evaluate invokeStatic "interruptible_eval.clj" 79]
               [nrepl.middleware.interruptible_eval$evaluate invoke "interruptible_eval.clj" 55]
               [nrepl.middleware.interruptible_eval$interruptible_eval$fn__921$fn__925
                invoke
                "interruptible_eval.clj"
                142]
               [clojure.lang.AFn run "AFn.java" 22]
               [nrepl.middleware.session$session_exec$main_loop__1022$fn__1026 invoke "session.clj" 171]
               [nrepl.middleware.session$session_exec$main_loop__1022 invoke "session.clj" 170]
               [clojure.lang.AFn run "AFn.java" 22]
               [java.lang.Thread run "Thread.java" 748]]}

They usually happen after ~16400 attempts. You wait a few seconds, and you're good to go again.

Using:

Server



JVM is:

* "java.vm.version" "25.181-b13",
* "java.vm.vendor" "Oracle Corporation",
* "java.vm.name" "Java HotSpot(TM) 64-Bit Server VM",
* "java.runtime.version" "1.8.0_181-b13",
l3nz commented 4 years ago

Interestingly ( and contrarily to my previous post) I seem to get the same result with:

(with-open [ds (jdbc/get-datasource JDBC)]
  (doseq [x (range 100000)]
    (prn x)
    (jdbc/execute! ds ["SELECT 1"])))

But different error:

#error{:cause "No matching field found: close for class next.jdbc.connection$url_PLUS_etc$reify__2509",
       :via [{:type java.lang.IllegalArgumentException,
              :message "No matching field found: close for class next.jdbc.connection$url_PLUS_etc$reify__2509",
              :at [clojure.lang.Reflector getInstanceField "Reflector.java" 397]}],
       :trace [[clojure.lang.Reflector getInstanceField "Reflector.java" 397]
               [clojure.lang.Reflector invokeNoArgInstanceMember "Reflector.java" 440]
               [jimmy.core$eval7476 invokeStatic "form-init8948134786209118560.clj" 1]
               [jimmy.core$eval7476 invoke "form-init8948134786209118560.clj" 1]
               [clojure.lang.Compiler eval "Compiler.java" 7177]
               [clojure.lang.Compiler eval "Compiler.java" 7132]
               [clojure.core$eval invokeStatic "core.clj" 3214]
               [clojure.core$eval invoke "core.clj" 3210]
               [clojure.main$repl$read_eval_print__9086$fn__9089 invoke "main.clj" 437]
               [clojure.main$repl$read_eval_print__9086 invoke "main.clj" 437]
               [clojure.main$repl$fn__9095 invoke "main.clj" 458]
               [clojure.main$repl invokeStatic "main.clj" 458]
               [clojure.main$repl doInvoke "main.clj" 368]
               [clojure.lang.RestFn invoke "RestFn.java" 1523]
               [nrepl.middleware.interruptible_eval$evaluate invokeStatic "interruptible_eval.clj" 79]
               [nrepl.middleware.interruptible_eval$evaluate invoke "interruptible_eval.clj" 55]
               [nrepl.middleware.interruptible_eval$interruptible_eval$fn__921$fn__925
                invoke
                "interruptible_eval.clj"
                142]
               [clojure.lang.AFn run "AFn.java" 22]
               [nrepl.middleware.session$session_exec$main_loop__1022$fn__1026 invoke "session.clj" 171]
               [nrepl.middleware.session$session_exec$main_loop__1022 invoke "session.clj" 170]
               [clojure.lang.AFn run "AFn.java" 22]
               [java.lang.Thread run "Thread.java" 748]]}

My gut feeling is that this seems to be a problem with how quickly one opens connections; if I run a query that just takes a while, it will go on forever.

l3nz commented 4 years ago

Interestingly,, I tried this on a "stock" centos 7:

My deps.edn

{:paths ["src"]
 :deps {org.clojure/clojure {:mvn/version "1.10.1"}
        seancorfield/next.jdbc {:mvn/version "1.0.462"}
        org.mariadb.jdbc/mariadb-java-client {:mvn/version "2.6.0"}
}}

I iniut the namespace as:


(ns xxx.core
  (:require [next.jdbc :as jdbc]
            [next.jdbc.sql :as sql]
            [next.jdbc.result-set :as rs]
            [clojure.string :as str]
            ))

 (def JDBC
  {:dbtype "mariadb"
   :dbname "mysql"
   :user "root"
   :password ""})

This works great:

(def ds (jdbc/get-datasource JDBC))

(doseq [x (range 100000)]
  (prn x)
  (jdbc/execute! ds ["SELECT 1"]))

But this crashes on closing, no matter how many iterations you give:

(with-open [ds (jdbc/get-datasource JDBC)]
  (doseq [x (range 3)]
    (prn x)
    (jdbc/execute! ds ["SELECT 1"])))

because

#error {
 :cause "No matching field found: close for class next.jdbc.connection$url_PLUS_etc$reify__1117"
 :via
 [{:type java.lang.IllegalArgumentException
   :message "No matching field found: close for class next.jdbc.connection$url_PLUS_etc$reify__1117"
   :at [clojure.lang.Reflector getInstanceField "Reflector.java" 397]}]
 :trace
 [[clojure.lang.Reflector getInstanceField "Reflector.java" 397]
  [clojure.lang.Reflector invokeNoArgInstanceMember "Reflector.java" 440]
  [jimmy.core$eval1931 invokeStatic "NO_SOURCE_FILE" 1]
  [jimmy.core$eval1931 invoke "NO_SOURCE_FILE" 1]
  [clojure.lang.Compiler eval "Compiler.java" 7177]
  [clojure.lang.Compiler eval "Compiler.java" 7132]
  [clojure.core$eval invokeStatic "core.clj" 3214]
  [clojure.core$eval invoke "core.clj" 3210]
  [clojure.main$repl$read_eval_print__9086$fn__9089 invoke "main.clj" 437]
  [clojure.main$repl$read_eval_print__9086 invoke "main.clj" 437]
  [clojure.main$repl$fn__9095 invoke "main.clj" 458]
  [clojure.main$repl invokeStatic "main.clj" 458]
  [clojure.main$repl_opt invokeStatic "main.clj" 522]
  [clojure.main$main invokeStatic "main.clj" 667]
  [clojure.main$main doInvoke "main.clj" 616]
  [clojure.lang.RestFn invoke "RestFn.java" 397]
  [clojure.lang.AFn applyToHelper "AFn.java" 152]
  [clojure.lang.RestFn applyTo "RestFn.java" 132]
  [clojure.lang.Var applyTo "Var.java" 705]
  [clojure.main main "main.java" 40]]}
seancorfield commented 4 years ago

You can't use .close (or with-open) on a regular javax.sql.DataSource: https://docs.oracle.com/en/java/javase/11/docs/api/java.sql/javax/sql/DataSource.html

Connection pool datasources usually have a .close method to shutdown the pool, but it's not part of JDBC proper.

That explains the No matching field found: close for class next.jdbc.connection$url_PLUS_etc$reify__... errors you're seeing -- not related to the original problem.

Given that you couldn't repro on the stock CentOS setup and I can't repro with any combination of MariaDB driver versions against Percona 5.7 on macOS -- but you can repro fairly reliably on macOS, JDK 8, and the 10.4.10 MariaDB server, I'm going to point the finger at the server implementation, not next.jdbc and not the JDBC driver. Especially since you get different errors that are related to timeouts and socket connections. So I'm going to close this out.