Spring Boot tests hangs after 2.1.3.RELEASE -> 2.1.4.RELEASE upgrade (H2 regression)

[daggerok]

Hello,

After 2.1.3.RELEASE -> 2.1.4.RELEASE upgrade our tests starts hangs after success execution without any errors on GitLab CI as well as locally with gradle run from ommand line. Running from IDEA still works fine. I cannot see anything unusual from logs, only these lines is available before it hangs after success test execution:

GitLab CI:

rest.auth.REST API GET authorization tests > should show fallback response on any 404 GET requests() PASSED
2019-04-10 12:54:22.305  INFO 597 --- [      Thread-86] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2019-04-10 12:54:22.306  INFO 597 --- [      Thread-27] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2019-04-10 12:54:22.306  INFO 597 --- [      Thread-64] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'

same happening if I'm running tests locally with gradle test command

I cannot share code base because of NDA, but we are using WebFlux REST API + WebFluxSecurity on a web layer and H2 in-memory DB together with spring-data-jpa for persistent layer.

after enabling debug mode, I found this repeatable logs from Hikari pool

2019-04-10 17:00:29.408  INFO 7108 --- [      Thread-80] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2019-04-10 17:00:29.408 DEBUG 7108 --- [      Thread-80] o.hibernate.internal.SessionFactoryImpl  : HHH000031: Closing
2019-04-10 17:00:29.408 DEBUG 7108 --- [      Thread-80] o.h.type.spi.TypeConfiguration$Scope     : Un-scoping TypeConfiguration [org.hibernate.type.spi.TypeConfiguration$Scope@c25162b7] from SessionFactory [org.hibernate.internal.SessionFactoryImpl@1cac9993]
2019-04-10 17:00:29.409  INFO 7108 --- [      Thread-31] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2019-04-10 17:00:29.409  INFO 7108 --- [      Thread-59] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2019-04-10 17:00:29.409 DEBUG 7108 --- [      Thread-31] o.hibernate.internal.SessionFactoryImpl  : HHH000031: Closing
2019-04-10 17:00:29.409 DEBUG 7108 --- [      Thread-59] o.hibernate.internal.SessionFactoryImpl  : HHH000031: Closing
2019-04-10 17:00:29.410 DEBUG 7108 --- [      Thread-59] o.h.type.spi.TypeConfiguration$Scope     : Un-scoping TypeConfiguration [org.hibernate.type.spi.TypeConfiguration$Scope@9a066eba] from SessionFactory [org.hibernate.internal.SessionFactoryImpl@3f4e04a4]
2019-04-10 17:00:29.410 DEBUG 7108 --- [      Thread-31] o.h.type.spi.TypeConfiguration$Scope     : Un-scoping TypeConfiguration [org.hibernate.type.spi.TypeConfiguration$Scope@93c84a9] from SessionFactory [org.hibernate.internal.SessionFactoryImpl@c3be385d]
2019-04-10 17:00:29.411 DEBUG 7108 --- [      Thread-80] o.h.s.i.AbstractServiceRegistryImpl      : Implicitly destroying ServiceRegistry on de-registration of all child ServiceRegistries
2019-04-10 17:00:29.411 DEBUG 7108 --- [      Thread-80] o.h.b.r.i.BootstrapServiceRegistryImpl   : Implicitly destroying Boot-strap registry on de-registration of all child ServiceRegistries
2019-04-10 17:00:29.411 DEBUG 7108 --- [      Thread-59] o.h.s.i.AbstractServiceRegistryImpl      : Implicitly destroying ServiceRegistry on de-registration of all child ServiceRegistries
2019-04-10 17:00:29.411 DEBUG 7108 --- [      Thread-31] o.h.s.i.AbstractServiceRegistryImpl      : Implicitly destroying ServiceRegistry on de-registration of all child ServiceRegistries
2019-04-10 17:00:29.412 DEBUG 7108 --- [      Thread-59] o.h.b.r.i.BootstrapServiceRegistryImpl   : Implicitly destroying Boot-strap registry on de-registration of all child ServiceRegistries
2019-04-10 17:00:29.412 DEBUG 7108 --- [      Thread-31] o.h.b.r.i.BootstrapServiceRegistryImpl   : Implicitly destroying Boot-strap registry on de-registration of all child ServiceRegistries
2019-04-10 17:00:34.766 DEBUG 7108 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0)
2019-04-10 17:00:48.943 DEBUG 7108 --- [l-2 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-2 - Pool stats (total=10, active=1, idle=9, waiting=0)
2019-04-10 17:00:55.478 DEBUG 7108 --- [l-3 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-3 - Pool stats (total=10, active=1, idle=9, waiting=0)
2019-04-10 17:01:04.768 DEBUG 7108 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0)
2019-04-10 17:01:18.946 DEBUG 7108 --- [l-2 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-2 - Pool stats (total=10, active=1, idle=9, waiting=0)
2019-04-10 17:01:25.480 DEBUG 7108 --- [l-3 housekeeper] com.zaxxer.hikari.pool.HikariPool        : 

# waiting some time....

2019-04-10 17:29:48.159 DEBUG 7108 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-3 - Added connection conn39: url=jdbc:h2:mem:db user=SYSTEM
2019-04-10 17:29:49.098 DEBUG 7108 --- [l-2 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-2 - Pool stats (total=10, active=1, idle=9, waiting=0)
2019-04-10 17:29:50.835 DEBUG 7108 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-2 - Closing connection conn16: url=jdbc:h2:mem:db user=SYSTEM: (connection has passed maxLifetime)
2019-04-10 17:29:50.836 DEBUG 7108 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-2 - Added connection conn40: url=jdbc:h2:mem:db user=SYSTEM
2019-04-10 17:29:55.625 DEBUG 7108 --- [l-3 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-3 - Pool stats (total=10, active=1, idle=9, waiting=0)
2019-04-10 17:29:57.325 DEBUG 7108 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection conn4: url=jdbc:h2:mem:db user=SYSTEM: (connection has passed maxLifetime)
2019-04-10 17:29:57.328 DEBUG 7108 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection conn41: url=jdbc:h2:mem:db user=SYSTEM
2019-04-10 17:29:57.922 DEBUG 7108 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-3 - Closing connection conn27: url=jdbc:h2:mem:db user=SYSTEM: (connection has passed maxLifetime)
2019-04-10 17:29:57.925 DEBUG 7108 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-3 - Added connection conn42: url=jdbc:h2:mem:db user=SYSTEM
2019-04-10 17:29:58.023 DEBUG 7108 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-2 - Closing connection conn12: url=jdbc:h2:mem:db user=SYSTEM: (connection has passed maxLifetime)
2019-04-10 17:29:58.025 DEBUG 7108 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-2 - Added connection conn43: url=jdbc:h2:mem:db user=SYSTEM
2019-04-10 17:29:58.045 DEBUG 7108 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection conn1: url=jdbc:h2:mem:db user=SYSTEM: (connection has passed maxLifetime)
2019-04-10 17:29:58.046 DEBUG 7108 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection conn44: url=jdbc:h2:mem:db user=SYSTEM
2019-04-10 17:29:58.558 DEBUG 7108 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-2 - Closing connection conn17: url=jdbc:h2:mem:db user=SYSTEM: (connection has passed maxLifetime)
2019-04-10 17:29:58.558 DEBUG 7108 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-2 - Added connection conn45: url=jdbc:h2:mem:db user=SYSTEM
2019-04-10 17:29:58.628 DEBUG 7108 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-3 - Closing connection conn24: url=jdbc:h2:mem:db user=SYSTEM: (connection has passed maxLifetime)
2019-04-10 17:29:58.629 DEBUG 7108 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-3 - Added connection conn46: url=jdbc:h2:mem:db user=SYSTEM
2019-04-10 17:30:00.001 DEBUG 7108 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-2 - Closing connection conn18: url=jdbc:h2:mem:db user=SYSTEM: (connection has passed maxLifetime)
2019-04-10 17:30:00.004 DEBUG 7108 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-2 - Added connection conn47: url=jdbc:h2:mem:db user=SYSTEM
2019-04-10 17:30:02.647 DEBUG 7108 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection conn7: url=jdbc:h2:mem:db user=SYSTEM: (connection has passed maxLifetime)
2019-04-10 17:30:02.648 DEBUG 7108 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection conn48: url=jdbc:h2:mem:db user=SYSTEM
2019-04-10 17:30:03.476 DEBUG 7108 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-2 - Closing connection conn15: url=jdbc:h2:mem:db user=SYSTEM: (connection has passed maxLifetime)
2019-04-10 17:30:03.477 DEBUG 7108 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-2 - Added connection conn49: url=jdbc:h2:mem:db user=SYSTEM
2019-04-10 17:30:04.919 DEBUG 7108 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0)
2019-04-10 17:30:10.240 DEBUG 7108 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-2 - Closing connection conn11: url=jdbc:h2:mem:db user=SYSTEM: (connection has passed maxLifetime)
2019-04-10 17:30:10.242 DEBUG 7108 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-2 - Added connection conn50: url=jdbc:h2:mem:db user=SYSTEM
2019-04-10 17:30:16.023 DEBUG 7108 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-2 - Closing connection conn19: url=jdbc:h2:mem:db user=SYSTEM: (connection has passed maxLifetime)
2019-04-10 17:30:16.024 DEBUG 7108 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-2 - Added connection conn51: url=jdbc:h2:mem:db user=SYSTEM
2019-04-10 17:30:16.462 DEBUG 7108 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-2 - Closing connection conn14: url=jdbc:h2:mem:db user=SYSTEM: (connection has passed maxLifetime)
2019-04-10 17:30:16.463 DEBUG 7108 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-2 - Added connection conn52: url=jdbc:h2:mem:db user=SYSTEM

# Killed / skipped rest

I'm really not sure what is going wrong. but with spring-boot 2.1.3.RELEASE everything was work correctly...

update 1

I have reduced max-lifetime to 3000 and even to 0:

spring:
  datasource:
    hikari:
      max-lifetime: 3000

but it doesn't helped me to solve a problem, so I reduced idle-timeout down to 3 sec:

spring:
  datasource:
    hikari:
      idle-timeout: 3000

... and now my tests randomly worked locally but issue still wasn't solved

update 2

Finally I found root cause. It was dev-tools runtime dependency... so I removed it and now test back to normal

Not sure if issue can be closed, seems like additional Gradle jvmargs tuning is required when using DevTools

---

Regards,
Maksim

[philwebb]

It's quite hard to say if this is a problem in Spring Boot, or if it's related to a dependency upgrade. It sounds like it might be am issue with Hikari, but without a sample to reproduce the problem it's almost impossible to say.

One thing you could try is upgrading Spring Boot but then downgrading Hikari, H2 and any other database components to the previous versions. This might help identify if the problem is in one of those libraries or not.

Other than that, I think we'll really need a way to reproduce the problem ourselves locally so we can debug things.

[daggerok]

Hello @philwebb

Here my steps:

1. I reduced Hikari leak detection threshold down to 3 sec and enabled debug:

spring:
  profiles:
    active: h2
  datasource:
    hikari:
      leak-detection-threshold: 3000
logging:
  level:
    root: 'debug'

2. started tests with gradle test command and saw devtools package in exception stack-trace on leak attempt

3. so I assume that problem can be with DevTools. I Found it in my Gradle dependencies runtime configuration, removed and re-run twice GitLab CI pipeline.

Now tests are back to normal

Don't know how to fix it in different way, but I'm Okay with that solution.
I will close that issue, but I can re-open later if other people will face with similar behavior

In fact, we have quite a big mono repo with 60+/- sub modules, so maybe in such situations default configurations works not very well. Maybe on small project this issue will never occur

---

Regards

[KurtMar]

Reducing the leak detection as mentioned above I also found devtools in the stack trace. I was able to solve the issue by downgrading H2 from 1.4.199 to 1.4.197: testCompile("com.h2database:h2:1.4.197")

[snicoll]

@KurtMar thank you. We've got other reports pointing to H2 so I've flagged this one for team attention to see what we can do about it.

[sdeleuze]

Same issue on https://spring.io/guides/tutorials/spring-boot-kotlin/ when upgrading to Boot 2.1.4 or 2.2.0 milestones or snapshots. I can avoid the issue by setting H2 to 1.4.197 as pointed out by @KurtMar. That's a pretty annoying issue that would maybe justify downgrading to H2 1.4.197 until they fix the regression (not sure if they have a bug tracker).

[sdeleuze]

Also maybe not related, but H2 1.4.198 had significant API changes, see r2dbc/r2dbc-h2#51.

[wilkinsona]

While the hang and API changes are unfortunate, I don't think we should get ourselves into the position of being stuck on an outdated version of H2. @KurtMar or @sdeleuze can you please open an H2 issue so that this can be resolved upstream?

[sdeleuze]

For some reasons, I can't reproduce the issue this morning with Boot 2.2 snapshots and H2 1.4.198 or 1.4.199. @KurtMar Could you please provide them a repro?

[philwebb]

I'm going to close this one here since from our side there's very little that we can do. @KurtMar if you raise an H2 issue, would you be so kind as to provide a link here so that people who stumble on this issue can find it.

[KurtMar]

What I found so far is that running the tests individually will not hang, but running all the tests will. This can be observed in https://github.com/spring-guides/tut-spring-boot-kotlin by updating Spring Boot to 2.1.4 and running ./gradlew test. I believe it has something to do with multi threading. This is confirmed by setting spring.datasource.url=jdbc:h2:mem:test;MULTI_THREADED=FALSE, which will also solve the issue. Perhaps this would be the correct workaround for now. Edit: I really can't say what effects it would have, so let's leave that opinion out even though it's the solution that works best for me.

I have created an issue in the h2 repo: h2database/h2database#1870.

[wilkinsona]

Thanks, @KurtMar. The H2 issue has been marked as a duplicate of h2database/h2database#1841 which has been fixed but not yet released.

The problem is a deadlock in H2 when multiple shutdown commands are issued on separate threads. This happens once all the tests have been run and the JVM is exiting. The contexts' shutdown hooks run in parallel and close the contexts which, in turn, shuts down H2. A workaround noted in h2database/h2database#1841 is to use @DirtiesContext.

The SHUTDOWN command is being issued due to DevTools. Strictly speaking, DevTools should not be running as it's a test. Thanks to @mbhave, that's been improved in 2.2 (#5307) and should no longer be the case.

With Spring Boot versions prior to 2.2, Gradle users can avoid DevTools being on the test runtime classpath by using the recommend configuration:

configurations {
	developmentOnly
	runtimeClasspath {
		extendsFrom developmentOnly
	}
}
dependencies {
	developmentOnly("org.springframework.boot:spring-boot-devtools")
}

Unfortunately, there is no equivalent configuration for Maven users.

[sdeleuze]

I removed the devtools dependency in the branch I use for my upcoming talk, that's why I was not able to reproduce the issue. Thanks for the detailed explanation @wilkinsona and for the devtools improvement @mbhave.