Maximum consumed results reached when Hikari close a SQL Server connection, leading to excessive logging #15933

MelleD · 2023-12-11T14:53:19Z

Expected behavior

The warning is not happen and there is no endless loop

Actual behavior

Iam using Hikari as JDBC connection pool and running into a query or socket timeout.
Hikari will evict/close the connection. Then it comes to the endless loop

Steps to reproduce the problem

Set SQL Server queryTimeout to 5 seconds.

configuration.settings().setBatchSize( 100 );

      final StringBuilder stringBuilder = new StringBuilder( "SELECT * FROM twin WITH (TABLOCKX, HOLDLOCK)" );
      stringBuilder.append( " WHERE 0 = 1" );
      stringBuilder.append( " WAITFOR DELAY '00:01'" );

      try {
         dslContext.query( stringBuilder.toString() ).execute();
      } catch ( final Exception e ) {
         e.printStackTrace();
      }

Then the endless loop happen in com.zaxxer.hikari.pool.ProxyConnection#checkException when the connection will evicted.

Comes always into jOOQ Tools#consumeExceptions

      case SQLSERVER:
                consumeLoop: for (i = 0; i < maxConsumedExceptions; i++)
                    try {
                        if (!stmt.getMoreResults() && stmt.getUpdateCount() == -1)
                            break consumeLoop;
                    }
                    catch (SQLException e) {
                        previous.setNextException(e);
                        previous = e;
                    }
        }

        if (i == maxConsumedExceptions)
            log.warn("Maximum consumed results reached: " + maxConsumedExceptions + ". This is probably a bug. Please report to https://jooq.org/bug");

jOOQ Version

jOOQ Professional 3.18.7

Database product and version

Azure SQL

Java Version

No response

OS Version

No response

JDBC driver name and version (include name if unofficial driver)

No response

The text was updated successfully, but these errors were encountered:

lukaseder · 2023-12-12T09:39:18Z

Thank you very much for your report.

This doesn't look like something that's easy to reproduce out of the box. Have you considered creating a minimal reproducer based on our MCVE templates here? https://github.com/jOOQ/jOOQ-mcve

At the same time, what's your expectation for jOOQ here? It doesn't look like the endless loop should happen in the first place. Can you rule out any bug in Hikari or mssql-jdbc?

MelleD · 2023-12-13T08:10:16Z

Hey @lukaseder ,

Here is an example that you can start straight away.
https://github.com/MelleD/spring-boot-jooq-exception-example

There are 2 conditions. You need the jooq pro dependency because it is related to the Tools with SQL SERVER dialect.

Secondly, unfortunately you can't use a TestContainer because you have to produce a timeout, which I couldn't manage with the TestContainerConnection. Maybe you know a way, I left the TestContainer in there.
To test, I simply started a SQL Server with Docker.

I haven't been able to figure out where the bug really is yet. I don't believe in Hikari because it only requests further exceptions.
I'm wondering why there is more than one exception in the result of a timeout?

lukaseder · 2023-12-21T09:34:27Z

I'm looking into your reproducer now, thanks for your patience. I can't reproduce any issues. This is what I'm getting:

"C:\Program Files\Java\jdk-21\bin\java.exe" -XX:TieredStopAtLevel=1 -Dspring.output.ansi.enabled=always -Dcom.sun.management.jmxremote -Dspring.jmx.enabled=true -Dspring.liveBeansView.mbeanDomain -Dspring.application.admin.enabled=true "-Dmanagement.endpoints.jmx.exposure.include=*" "-javaagent:C:\Program Files\JetBrains\IntelliJ IDEA 2023.1.4\lib\idea_rt.jar=54767:C:\Program Files\JetBrains\IntelliJ IDEA 2023.1.4\bin" -Dfile.encoding=UTF-8 -Dsun.stdout.encoding=UTF-8 -Dsun.stderr.encoding=UTF-8 -classpath C:\Users\lukas\jOOQ\mcve\15933\spring-boot-jooq-exception-example\target\classes;C:\Users\lukas\.m2\repository\org\springframework\boot\spring-boot-starter-web\3.2.0\spring-boot-starter-web-3.2.0.jar;C:\Users\lukas\.m2\repository\org\springframework\boot\spring-boot-starter\3.2.0\spring-boot-starter-3.2.0.jar;C:\Users\lukas\.m2\repository\org\springframework\boot\spring-boot\3.2.0\spring-boot-3.2.0.jar;C:\Users\lukas\.m2\repository\org\springframework\boot\spring-boot-autoconfigure\3.2.0\spring-boot-autoconfigure-3.2.0.jar;C:\Users\lukas\.m2\repository\org\springframework\boot\spring-boot-starter-logging\3.2.0\spring-boot-starter-logging-3.2.0.jar;C:\Users\lukas\.m2\repository\ch\qos\logback\logback-classic\1.4.11\logback-classic-1.4.11.jar;C:\Users\lukas\.m2\repository\ch\qos\logback\logback-core\1.4.11\logback-core-1.4.11.jar;C:\Users\lukas\.m2\repository\org\apache\logging\log4j\log4j-to-slf4j\2.21.1\log4j-to-slf4j-2.21.1.jar;C:\Users\lukas\.m2\repository\org\apache\logging\log4j\log4j-api\2.21.1\log4j-api-2.21.1.jar;C:\Users\lukas\.m2\repository\org\slf4j\jul-to-slf4j\2.0.9\jul-to-slf4j-2.0.9.jar;C:\Users\lukas\.m2\repository\jakarta\annotation\jakarta.annotation-api\2.1.1\jakarta.annotation-api-2.1.1.jar;C:\Users\lukas\.m2\repository\org\springframework\spring-core\6.1.1\spring-core-6.1.1.jar;C:\Users\lukas\.m2\repository\org\springframework\spring-jcl\6.1.1\spring-jcl-6.1.1.jar;C:\Users\lukas\.m2\repository\org\springframework\boot\spring-boot-starter-json\3.2.0\spring-boot-starter-json-3.2.0.jar;C:\Users\lukas\.m2\repository\com\fasterxml\jackson\core\jackson-databind\2.15.3\jackson-databind-2.15.3.jar;C:\Users\lukas\.m2\repository\com\fasterxml\jackson\core\jackson-core\2.15.3\jackson-core-2.15.3.jar;C:\Users\lukas\.m2\repository\com\fasterxml\jackson\datatype\jackson-datatype-jdk8\2.15.3\jackson-datatype-jdk8-2.15.3.jar;C:\Users\lukas\.m2\repository\com\fasterxml\jackson\datatype\jackson-datatype-jsr310\2.15.3\jackson-datatype-jsr310-2.15.3.jar;C:\Users\lukas\.m2\repository\com\fasterxml\jackson\module\jackson-module-parameter-names\2.15.3\jackson-module-parameter-names-2.15.3.jar;C:\Users\lukas\.m2\repository\org\springframework\boot\spring-boot-starter-tomcat\3.2.0\spring-boot-starter-tomcat-3.2.0.jar;C:\Users\lukas\.m2\repository\org\apache\tomcat\embed\tomcat-embed-core\10.1.16\tomcat-embed-core-10.1.16.jar;C:\Users\lukas\.m2\repository\org\apache\tomcat\embed\tomcat-embed-el\10.1.16\tomcat-embed-el-10.1.16.jar;C:\Users\lukas\.m2\repository\org\apache\tomcat\embed\tomcat-embed-websocket\10.1.16\tomcat-embed-websocket-10.1.16.jar;C:\Users\lukas\.m2\repository\org\springframework\spring-web\6.1.1\spring-web-6.1.1.jar;C:\Users\lukas\.m2\repository\org\springframework\spring-beans\6.1.1\spring-beans-6.1.1.jar;C:\Users\lukas\.m2\repository\io\micrometer\micrometer-observation\1.12.0\micrometer-observation-1.12.0.jar;C:\Users\lukas\.m2\repository\io\micrometer\micrometer-commons\1.12.0\micrometer-commons-1.12.0.jar;C:\Users\lukas\.m2\repository\org\springframework\spring-webmvc\6.1.1\spring-webmvc-6.1.1.jar;C:\Users\lukas\.m2\repository\org\springframework\spring-aop\6.1.1\spring-aop-6.1.1.jar;C:\Users\lukas\.m2\repository\org\springframework\spring-context\6.1.1\spring-context-6.1.1.jar;C:\Users\lukas\.m2\repository\org\springframework\spring-expression\6.1.1\spring-expression-6.1.1.jar;C:\Users\lukas\.m2\repository\org\springframework\boot\spring-boot-starter-jooq\3.2.0\spring-boot-starter-jooq-3.2.0.jar;C:\Users\lukas\.m2\repository\org\springframework\boot\spring-boot-starter-jdbc\3.2.0\spring-boot-starter-jdbc-3.2.0.jar;C:\Users\lukas\.m2\repository\com\zaxxer\HikariCP\5.0.1\HikariCP-5.0.1.jar;C:\Users\lukas\.m2\repository\org\springframework\spring-jdbc\6.1.1\spring-jdbc-6.1.1.jar;C:\Users\lukas\.m2\repository\org\springframework\spring-tx\6.1.1\spring-tx-6.1.1.jar;C:\Users\lukas\.m2\repository\org\jooq\pro\jooq\3.18.7\jooq-3.18.7.jar;C:\Users\lukas\.m2\repository\io\r2dbc\r2dbc-spi\1.0.0.RELEASE\r2dbc-spi-1.0.0.RELEASE.jar;C:\Users\lukas\.m2\repository\org\reactivestreams\reactive-streams\1.0.4\reactive-streams-1.0.4.jar;C:\Users\lukas\.m2\repository\org\springframework\boot\spring-boot-configuration-processor\3.2.0\spring-boot-configuration-processor-3.2.0.jar;C:\Users\lukas\.m2\repository\org\liquibase\liquibase-core\4.24.0\liquibase-core-4.24.0.jar;C:\Users\lukas\.m2\repository\com\opencsv\opencsv\5.8\opencsv-5.8.jar;C:\Users\lukas\.m2\repository\org\apache\commons\commons-lang3\3.13.0\commons-lang3-3.13.0.jar;C:\Users\lukas\.m2\repository\org\apache\commons\commons-text\1.10.0\commons-text-1.10.0.jar;C:\Users\lukas\.m2\repository\org\apache\commons\commons-collections4\4.4\commons-collections4-4.4.jar;C:\Users\lukas\.m2\repository\org\yaml\snakeyaml\2.2\snakeyaml-2.2.jar;C:\Users\lukas\.m2\repository\javax\xml\bind\jaxb-api\2.3.1\jaxb-api-2.3.1.jar;C:\Users\lukas\.m2\repository\com\microsoft\sqlserver\mssql-jdbc\12.4.2.jre11\mssql-jdbc-12.4.2.jre11.jar;C:\Users\lukas\.m2\repository\org\testcontainers\testcontainers\1.19.3\testcontainers-1.19.3.jar;C:\Users\lukas\.m2\repository\junit\junit\4.13.2\junit-4.13.2.jar;C:\Users\lukas\.m2\repository\org\hamcrest\hamcrest-core\2.2\hamcrest-core-2.2.jar;C:\Users\lukas\.m2\repository\org\hamcrest\hamcrest\2.2\hamcrest-2.2.jar;C:\Users\lukas\.m2\repository\org\slf4j\slf4j-api\2.0.9\slf4j-api-2.0.9.jar;C:\Users\lukas\.m2\repository\org\apache\commons\commons-compress\1.24.0\commons-compress-1.24.0.jar;C:\Users\lukas\.m2\repository\org\rnorth\duct-tape\duct-tape\1.0.8\duct-tape-1.0.8.jar;C:\Users\lukas\.m2\repository\org\jetbrains\annotations\17.0.0\annotations-17.0.0.jar;C:\Users\lukas\.m2\repository\com\github\docker-java\docker-java-api\3.3.4\docker-java-api-3.3.4.jar;C:\Users\lukas\.m2\repository\com\fasterxml\jackson\core\jackson-annotations\2.15.3\jackson-annotations-2.15.3.jar;C:\Users\lukas\.m2\repository\com\github\docker-java\docker-java-transport-zerodep\3.3.4\docker-java-transport-zerodep-3.3.4.jar;C:\Users\lukas\.m2\repository\com\github\docker-java\docker-java-transport\3.3.4\docker-java-transport-3.3.4.jar;C:\Users\lukas\.m2\repository\net\java\dev\jna\jna\5.13.0\jna-5.13.0.jar;C:\Users\lukas\.m2\repository\org\testcontainers\mssqlserver\1.19.3\mssqlserver-1.19.3.jar;C:\Users\lukas\.m2\repository\org\testcontainers\jdbc\1.19.3\jdbc-1.19.3.jar;C:\Users\lukas\.m2\repository\org\testcontainers\database-commons\1.19.3\database-commons-1.19.3.jar com.test.TestApplication
Picked up JAVA_TOOL_OPTIONS: -Dfile.encoding=UTF8 -Duser.language=en
10:33:19,140 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.4.11
10:33:19,144 |-INFO in ch.qos.logback.classic.util.ContextInitializer@24d09c1 - Here is a list of configurators discovered as a service, by rank: 
10:33:19,144 |-INFO in ch.qos.logback.classic.util.ContextInitializer@24d09c1 -   org.springframework.boot.logging.logback.RootLogLevelConfigurator
10:33:19,144 |-INFO in ch.qos.logback.classic.util.ContextInitializer@24d09c1 - They will be invoked in order until ExecutionStatus.DO_NOT_INVOKE_NEXT_IF_ANY is returned.
10:33:19,144 |-INFO in ch.qos.logback.classic.util.ContextInitializer@24d09c1 - Constructed configurator of type class org.springframework.boot.logging.logback.RootLogLevelConfigurator
10:33:19,149 |-INFO in ch.qos.logback.classic.util.ContextInitializer@24d09c1 - org.springframework.boot.logging.logback.RootLogLevelConfigurator.configure() call lasted 1 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
10:33:19,149 |-INFO in ch.qos.logback.classic.util.ContextInitializer@24d09c1 - Trying to configure with ch.qos.logback.classic.joran.SerializedModelConfigurator
10:33:19,150 |-INFO in ch.qos.logback.classic.util.ContextInitializer@24d09c1 - Constructed configurator of type class ch.qos.logback.classic.joran.SerializedModelConfigurator
10:33:19,158 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.scmo]
10:33:19,158 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.scmo]
10:33:19,158 |-INFO in ch.qos.logback.classic.util.ContextInitializer@24d09c1 - ch.qos.logback.classic.joran.SerializedModelConfigurator.configure() call lasted 8 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
10:33:19,158 |-INFO in ch.qos.logback.classic.util.ContextInitializer@24d09c1 - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator
10:33:19,161 |-INFO in ch.qos.logback.classic.util.ContextInitializer@24d09c1 - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator
10:33:19,161 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
10:33:19,161 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.xml]
10:33:19,161 |-INFO in ch.qos.logback.classic.util.ContextInitializer@24d09c1 - ch.qos.logback.classic.util.DefaultJoranConfigurator.configure() call lasted 0 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
10:33:19,161 |-INFO in ch.qos.logback.classic.util.ContextInitializer@24d09c1 - Trying to configure with ch.qos.logback.classic.BasicConfigurator
10:33:19,162 |-INFO in ch.qos.logback.classic.util.ContextInitializer@24d09c1 - Constructed configurator of type class ch.qos.logback.classic.BasicConfigurator
10:33:19,162 |-INFO in ch.qos.logback.classic.BasicConfigurator@54c62d71 - Setting up default configuration.
10:33:19,177 |-INFO in ch.qos.logback.classic.util.ContextInitializer@24d09c1 - ch.qos.logback.classic.BasicConfigurator.configure() call lasted 15 milliseconds. ExecutionStatus=NEUTRAL
10:33:19,468 |-WARN in ch.qos.logback.core.joran.action.IncludeAction - Could not find resource corresponding to [logback-spring-default.xml]
10:33:19,489 |-INFO in ch.qos.logback.core.model.processor.DefaultProcessor@65045a87 - End of configuration.
10:33:19,489 |-INFO in org.springframework.boot.logging.logback.SpringBootJoranConfigurator@47f4e407 - Registering current configuration as safe fallback point


  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v3.2.0)


Process finished with exit code 1

I'll try a bit more...

lukaseder · 2023-12-21T09:39:08Z

From the command line:

$ mvn clean install exec:java -Dexec.mainClass="com.test.TestApplication"
Picked up JAVA_TOOL_OPTIONS: -Dfile.encoding=UTF8 -Duser.language=en
[INFO] Scanning for projects...
[INFO]
[INFO] ----< org.springframework.boot:spring-boot-jooq-exception-example >-----
[INFO] Building spring-boot-jooq-exception-example DEV-SNAPSHOT
[INFO]   from pom.xml
[INFO] --------------------------------[ jar ]---------------------------------
[INFO]
[INFO] --- clean:3.3.2:clean (default-clean) @ spring-boot-jooq-exception-example ---
[INFO] Deleting C:\Users\lukas\jOOQ\mcve\15933\spring-boot-jooq-exception-example\target
[INFO]
[INFO] --- resources:3.3.1:resources (default-resources) @ spring-boot-jooq-exception-example ---
[INFO] Copying 1 resource from src\main\resources to target\classes
[INFO] Copying 4 resources from src\main\resources to target\classes
[INFO]
[INFO] --- compiler:3.11.0:compile (default-compile) @ spring-boot-jooq-exception-example ---
[INFO] Changes detected - recompiling the module! :source
[INFO] Compiling 2 source files with javac [debug release 17] to target\classes
[INFO] Annotation processing is enabled because one or more processors were found
  on the class path. A future release of javac may disable annotation processing
  unless at least one processor is specified by name (-processor), or a search
  path is specified (--processor-path, --processor-module-path), or annotation
  processing is enabled explicitly (-proc:only, -proc:full).
  Use -Xlint:-options to suppress this message.
  Use -proc:none to disable annotation processing.
[INFO]
[INFO] --- resources:3.3.1:testResources (default-testResources) @ spring-boot-jooq-exception-example ---
[INFO] skip non existing resourceDirectory C:\Users\lukas\jOOQ\mcve\15933\spring-boot-jooq-exception-example\src\test\resources
[INFO]
[INFO] --- compiler:3.11.0:testCompile (default-testCompile) @ spring-boot-jooq-exception-example ---
[INFO] No sources to compile
[INFO]
[INFO] --- surefire:3.1.2:test (default-test) @ spring-boot-jooq-exception-example ---
[INFO] No tests to run.
[INFO]
[INFO] --- jar:3.3.0:jar (default-jar) @ spring-boot-jooq-exception-example ---
[INFO] Building jar: C:\Users\lukas\jOOQ\mcve\15933\spring-boot-jooq-exception-example\target\spring-boot-jooq-exception-example-DEV-SNAPSHOT.jar
[INFO]
[INFO] --- install:3.1.1:install (default-install) @ spring-boot-jooq-exception-example ---
[INFO] Installing C:\Users\lukas\jOOQ\mcve\15933\spring-boot-jooq-exception-example\pom.xml to C:\Users\lukas\.m2\repository\org\springframework\boot\spring-boot-jooq-exception-example\DEV-SNAPSHOT\spring-boot-jooq-exception-example-DEV-SNAPSHOT.pom
[INFO] Installing C:\Users\lukas\jOOQ\mcve\15933\spring-boot-jooq-exception-example\target\spring-boot-jooq-exception-example-DEV-SNAPSHOT.jar to C:\Users\lukas\.m2\repository\org\springframework\boot\spring-boot-jooq-exception-example\DEV-SNAPSHOT\spring-boot-jooq-exception-example-DEV-SNAPSHOT.jar
[INFO]
[INFO] --- exec:3.1.1:java (default-cli) @ spring-boot-jooq-exception-example ---
10:38:05,898 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.4.11
10:38:05,900 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5cf4006 - Here is a list of configurators discovered as a service, by rank:
10:38:05,900 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5cf4006 -   org.springframework.boot.logging.logback.RootLogLevelConfigurator
10:38:05,900 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5cf4006 - They will be invoked in order until ExecutionStatus.DO_NOT_INVOKE_NEXT_IF_ANY is returned.
10:38:05,900 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5cf4006 - Constructed configurator of type class org.springframework.boot.logging.logback.RootLogLevelConfigurator
10:38:05,906 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5cf4006 - org.springframework.boot.logging.logback.RootLogLevelConfigurator.configure() call lasted 0 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
10:38:05,906 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5cf4006 - Trying to configure with ch.qos.logback.classic.joran.SerializedModelConfigurator
10:38:05,906 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5cf4006 - Constructed configurator of type class ch.qos.logback.classic.joran.SerializedModelConfigurator
10:38:05,919 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.scmo]
10:38:05,919 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.scmo]
10:38:05,919 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5cf4006 - ch.qos.logback.classic.joran.SerializedModelConfigurator.configure() call lasted 13 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
10:38:05,919 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5cf4006 - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator
10:38:05,919 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5cf4006 - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator
10:38:05,920 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
10:38:05,920 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.xml]
10:38:05,920 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5cf4006 - ch.qos.logback.classic.util.DefaultJoranConfigurator.configure() call lasted 1 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
10:38:05,920 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5cf4006 - Trying to configure with ch.qos.logback.classic.BasicConfigurator
10:38:05,920 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5cf4006 - Constructed configurator of type class ch.qos.logback.classic.BasicConfigurator
10:38:05,920 |-INFO in ch.qos.logback.classic.BasicConfigurator@2d3481b3 - Setting up default configuration.
10:38:05,925 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5cf4006 - ch.qos.logback.classic.BasicConfigurator.configure() call lasted 5 milliseconds. ExecutionStatus=NEUTRAL
10:38:06,229 |-WARN in ch.qos.logback.core.joran.action.IncludeAction - Could not find resource corresponding to [logback-spring-default.xml]
10:38:06,251 |-INFO in ch.qos.logback.core.model.processor.DefaultProcessor@6f8bc353 - End of configuration.
10:38:06,251 |-INFO in org.springframework.boot.logging.logback.SpringBootJoranConfigurator@55f675e9 - Registering current configuration as safe fallback point


  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v3.2.0)

Running Changeset: db/changelog/changelogs/changelog-1.0.0-ddl.yaml::1.0.0::melle
Liquibase: Update has been successful. Rows affected: 1
XXXX
org.springframework.dao.DataAccessResourceFailureException: jOOQ; SQL [SELECT * FROM test WITH (TABLOCKX, HOLDLOCK) WHERE 0 = 1 WAITFOR DELAY '00:01']; The connection is closed.
        at org.jooq_3.18.7.SQLSERVER2022.debug(Unknown Source)
        at org.springframework.jdbc.support.SQLStateSQLExceptionTranslator.doTranslate(SQLStateSQLExceptionTranslator.java:121)
        at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:107)
        at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:116)
        at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:116)
        at org.springframework.boot.autoconfigure.jooq.JooqExceptionTranslator.translate(JooqExceptionTranslator.java:94)
        at org.springframework.boot.autoconfigure.jooq.JooqExceptionTranslator.handle(JooqExceptionTranslator.java:81)
        at org.springframework.boot.autoconfigure.jooq.JooqExceptionTranslator.exception(JooqExceptionTranslator.java:55)
        at org.jooq.impl.ExecuteListeners.exception(ExecuteListeners.java:304)
        at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:361)
        at com.test.StartupListener.doSomethingAfterStartup(StartupListener.java:24)
        at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
        at java.base/java.lang.reflect.Method.invoke(Method.java:580)
        at org.springframework.context.event.ApplicationListenerMethodAdapter.doInvoke(ApplicationListenerMethodAdapter.java:365)
        at org.springframework.context.event.ApplicationListenerMethodAdapter.processEvent(ApplicationListenerMethodAdapter.java:237)
        at org.springframework.context.event.ApplicationListenerMethodAdapter.onApplicationEvent(ApplicationListenerMethodAdapter.java:168)
        at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:178)
        at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:171)
        at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:149)
        at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:445)
        at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:378)
        at org.springframework.boot.context.event.EventPublishingRunListener.ready(EventPublishingRunListener.java:109)
        at org.springframework.boot.SpringApplicationRunListeners.lambda$ready$6(SpringApplicationRunListeners.java:80)
        at java.base/java.lang.Iterable.forEach(Iterable.java:75)
        at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:118)
        at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:112)
        at org.springframework.boot.SpringApplicationRunListeners.ready(SpringApplicationRunListeners.java:80)
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:341)
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:1342)
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:1331)
        at com.test.TestApplication.main(TestApplication.java:15)
        at org.codehaus.mojo.exec.ExecJavaMojo.lambda$execute$0(ExecJavaMojo.java:283)
        at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: The connection is closed.
        at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:231)
        at com.microsoft.sqlserver.jdbc.SQLServerConnection.checkClosed(SQLServerConnection.java:1728)
        at com.microsoft.sqlserver.jdbc.SQLServerStatement.checkClosed(SQLServerStatement.java:1115)
        at com.microsoft.sqlserver.jdbc.SQLServerStatement.getMoreResults(SQLServerStatement.java:1401)
        at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.getMoreResults(HikariProxyPreparedStatement.java)
        at org.jooq.tools.jdbc.DefaultStatement.getMoreResults(DefaultStatement.java:236)
        at org.jooq.impl.Tools.consumeExceptions(Tools.java:4633)
        at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:466)
        at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:346)
        ... 23 more
Finish

Still not your reproducing your problem

lukaseder · 2023-12-21T09:44:21Z

I'm sorry, I don't know what I should be looking for...

MelleD · 2023-12-21T11:37:36Z

Sorry I thought you set a breakpoint here:

      if (i == maxConsumedExceptions)
            log.warn("Maximum consumed results reached: " + maxConsumedExceptions + ". This is probably a bug. Please report to https://jooq.org/bug");

i configured the logger now you see the log entry at the beginning

2023-12-21T12:38:49.060+01:00  WARN 53890 --- [           main] org.jooq.impl.Tools                      : Maximum consumed results reached: 256. This is probably a bug. Please report to https://jooq.org/bug

and then a lot of (256?)

2023-12-21T12:39:08.171+01:00 ERROR 53890 --- [           main] o.s.b.a.jooq.JooqExceptionTranslator     : Execution of SQL statement failed.

org.springframework.dao.DataAccessResourceFailureException: jOOQ; SQL [SELECT * FROM test WITH (TABLOCKX, HOLDLOCK) WHERE 0 = 1 WAITFOR DELAY '00:01']; Die Verbindung wurde geschlossen.

Hope this helps

lukaseder · 2023-12-21T15:11:14Z

I see now, thanks for the additional information. I can reproduce the problem. In my opinion, this is a bug in mssql-jdbc. Have you tried reporting it to their team (ideally by removing jOOQ first, and replicating that loop with plain JDBC)?

OutOfMemoryError with SQL Azure, caused by long-running loop of consuming further exceptions #3696

They do not seem to correctly implement the protocol around Statement.getMoreResults() and/or Statement.getUpdateCount() in this particular case. That loop's upper bound has been implemented as a safeguard against similar problems that have been encountered in the past. See e.g.:

OutOfMemoryError with SQL Azure, caused by long-running loop of consuming further exceptions #3696

I'm not sure if jOOQ can really do anything here. The exceptions aren't even the same instance, so mssql-jdbc always throws a new one it seems. If it had been the same instance, we could abort the loop as soon as the previous and the next exceptions are the same.

I mean, we could work around this particular case by hard coding the error message and stopping the loop prematurely. Or, you can also change the log level for this particular logger. Another workaround is to lower the value of Tools.maxConsumedExceptions via reflection

I'll make a decision about this issue later.

MelleD · 2023-12-21T15:20:16Z

I see now, thanks for the additional information. I can reproduce the problem. In my opinion, this is a bug in mssql-jdbc. Have you tried reporting it to their team (ideally by removing jOOQ first, and replicating that loop with plain JDBC)?

Let me try that. And then I try to report a bug on driver level

Tools.maxConsumedExceptions

Thanks, that was my first thought. Maybe you can do it public for better access?
Or another way to hook in that you can cancel the loop yourself, e.g. based on the error message or whatever.

In our case there can actually be no further exception

lukaseder · 2023-12-21T15:24:38Z

Thanks, that was my first thought. Maybe you can do it public for better access?

No. The point is, this isn't a documented thing. There's a bug, and you need a workaround.

Or another way to hook in that you can cancel the loop yourself, e.g. based on the error message or whatever.

Maybe, though, do note there's a bug somewhere (probably mssql-jdbc), and rather than documenting or implementing workarounds, the bug should be fixed.

You could also proxy the JDBC driver and implement the aborting logic there.

MelleD · 2024-01-22T16:01:40Z

Hi @lukaseder

I just wanted to make an example for the JDBC driver. However, I'm still unsure why this is a driver bug. Maybe you can say again why you think it's a JDBC driver bug.

From my point of view, the endless loop occurs in jOOQ, because not checking if the connection is closed.
The stmt.getMoreResults() will be a SqlServerException because the connection is already closed due to the timeout, so no more results can be fetched. This also happens with the Plain Datasource:

   public void doSomethingAfterStartup() throws SQLException {
      final StringBuilder stringBuilder = new StringBuilder( "SELECT * FROM twin WITH (TABLOCKX, HOLDLOCK)" );
      stringBuilder.append( " WHERE 0 = 1" );
      stringBuilder.append( " WAITFOR DELAY '00:01'" );
      Statement stmt = null;
      Connection con = null;
      try {
         con = dataSource.getConnection();
         stmt = con.createStatement();
         final ResultSet rs = stmt.executeQuery( stringBuilder.toString() );

      } catch ( final Exception e ) {
         try {
            if ( !stmt.getMoreResults() && stmt.getUpdateCount() == -1 ) {
               System.out.println( "Never reach here" );
            }
         } catch ( final SQLServerException e1 ) {
            if ( con.isClosed() ) {
               System.out.println( "Connection is closed" );

            }
         } catch ( final SQLException e1 ) {
            e1.printStackTrace();
         }

      }

      System.out.println( "Finish" );

   }
}

So IMHO this should be checked into the Tools class:

      // So far, this issue has been observed only with SQL Server
        switch (configuration.family()) {
            case SQLDATAWAREHOUSE:
            case SQLSERVER:
                consumeLoop: for (i = 0; i < maxConsumedExceptions; i++)
                    try {
                        if (!stmt.getMoreResults() && stmt.getUpdateCount() == -1)
                            break consumeLoop;
                    }
                    catch (SQLException e) {
                        if(stmt.isClosed() or (e is close exception){
                           break consumeLoop;
                        }
                        
                        previous.setNextException(e);
                        previous = e;
                    }
        }

lukaseder · 2024-01-23T07:30:30Z

From my point of view, the endless loop occurs in jOOQ, because not checking if the connection is closed.

Yes, you're right. Both getMoreResults() and getUpdateCount() methods state: "SQLException - if a database access error occurs or this method is called on a closed Statement"

lukaseder · 2024-01-23T07:46:21Z

I also don't know why this didn't reproduce any issues at the time:

Maximum consumed results reached when Hikari close a SQL Server connection, leading to excessive logging #15933 (comment)

It does generate tons of exception logs now on the computer I'm at now.

…ver connection, leading to excessive logging

lukaseder · 2024-01-23T07:51:50Z

Fixed in versions:

3.20.0
3.19.4 (Maximum consumed results reached when Hikari close a SQL Server connection, leading to excessive logging - Merge [#15933] #16129)
3.18.11 (Maximum consumed results reached when Hikari close a SQL Server connection, leading to excessive logging - Merge [#15933] #16130)
3.17.20 (Maximum consumed results reached when Hikari close a SQL Server connection, leading to excessive logging - Merge [#15933] #16131)

MelleD · 2024-01-23T08:24:54Z

I also don't know why this didn't reproduce any issues at the time:

Maximum consumed results reached when Hikari close a SQL Server connection, leading to excessive logging #15933 (comment)

It does generate tons of exception logs now on the computer I'm at now.

Did you tried it before maybe with a TestContainer Image? I figured out with TestContainer image it is not reproducable because of the proxy connection

lukaseder · 2024-01-23T08:31:48Z

Could be, I don't recall...

MelleD added the T: Defect label Dec 11, 2023

lukaseder added this to the Version 3.19.0 milestone Dec 12, 2023

lukaseder added this to To do in 3.19 Other improvements via automation Dec 12, 2023

lukaseder added C: Functionality C: DB: SQL Server P: Medium E: Professional Edition E: Enterprise Edition labels Dec 12, 2023

lukaseder removed this from To do in 3.19 Other improvements Dec 12, 2023

lukaseder modified the milestones: Version 3.19.0, Version 3.20.0 Dec 12, 2023

lukaseder added the R: Feedback Pending label Dec 12, 2023

lukaseder removed the R: Feedback Pending label Dec 21, 2023

lukaseder added this to To do in 3.20 Other improvements via automation Jan 23, 2024

lukaseder changed the title ~~[SQLServer] Maximum consumed results reached when Hikari close a connection~~ Maximum consumed results reached when Hikari close a SQL Server connection, leading to excessive logs Jan 23, 2024

lukaseder changed the title ~~Maximum consumed results reached when Hikari close a SQL Server connection, leading to excessive logs~~ Maximum consumed results reached when Hikari close a SQL Server connection Jan 23, 2024

lukaseder changed the title ~~Maximum consumed results reached when Hikari close a SQL Server connection~~ Maximum consumed results reached when Hikari close a SQL Server connection, leading to excessive logging Jan 23, 2024

lukaseder added a commit that referenced this issue Jan 23, 2024

[#15933] Maximum consumed results reached when Hikari close a SQL Ser…

47339e4

…ver connection, leading to excessive logging

lukaseder added a commit that referenced this issue Jan 23, 2024

[#15933] Maximum consumed results reached when Hikari close a SQL Ser…

697a23e

…ver connection, leading to excessive logging

lukaseder added a commit that referenced this issue Jan 23, 2024

[#15933] Maximum consumed results reached when Hikari close a SQL Ser…

b4a62d0

…ver connection, leading to excessive logging

lukaseder added a commit that referenced this issue Jan 23, 2024

[#15933] Maximum consumed results reached when Hikari close a SQL Ser…

42210f4

…ver connection, leading to excessive logging

lukaseder closed this as completed Jan 23, 2024

3.20 Other improvements automation moved this from To do to Done Jan 23, 2024

lukaseder added the R: Fixed label Jan 23, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Maximum consumed results reached when Hikari close a SQL Server connection, leading to excessive logging #15933

Maximum consumed results reached when Hikari close a SQL Server connection, leading to excessive logging #15933

MelleD commented Dec 11, 2023

lukaseder commented Dec 12, 2023

MelleD commented Dec 13, 2023

lukaseder commented Dec 21, 2023

lukaseder commented Dec 21, 2023

lukaseder commented Dec 21, 2023

MelleD commented Dec 21, 2023 •

edited

lukaseder commented Dec 21, 2023

MelleD commented Dec 21, 2023 •

edited

lukaseder commented Dec 21, 2023

MelleD commented Jan 22, 2024 •

edited

lukaseder commented Jan 23, 2024 •

edited

lukaseder commented Jan 23, 2024

lukaseder commented Jan 23, 2024

MelleD commented Jan 23, 2024

lukaseder commented Jan 23, 2024

Maximum consumed results reached when Hikari close a SQL Server connection, leading to excessive logging #15933

Maximum consumed results reached when Hikari close a SQL Server connection, leading to excessive logging #15933

Comments

MelleD commented Dec 11, 2023

Expected behavior

Actual behavior

Steps to reproduce the problem

jOOQ Version

Database product and version

Java Version

OS Version

JDBC driver name and version (include name if unofficial driver)

lukaseder commented Dec 12, 2023

MelleD commented Dec 13, 2023

lukaseder commented Dec 21, 2023

lukaseder commented Dec 21, 2023

lukaseder commented Dec 21, 2023

MelleD commented Dec 21, 2023 • edited

lukaseder commented Dec 21, 2023

MelleD commented Dec 21, 2023 • edited

lukaseder commented Dec 21, 2023

MelleD commented Jan 22, 2024 • edited

lukaseder commented Jan 23, 2024 • edited

lukaseder commented Jan 23, 2024

lukaseder commented Jan 23, 2024

MelleD commented Jan 23, 2024

lukaseder commented Jan 23, 2024

MelleD commented Dec 21, 2023 •

edited

MelleD commented Dec 21, 2023 •

edited

MelleD commented Jan 22, 2024 •

edited

lukaseder commented Jan 23, 2024 •

edited