Introduction
Hi, this is Trueman, an Application Engineer working at Rakuten Group's Branch. I want to share a story about an issue that took 2 whole days of investigating and troubleshooting to resolve. Hopefully this can save you the time and frustration if you happen to run into the same problem. This technical problem and solution is sort of specific to the spring framework so if you're using something else it might not be that helpful, but maybe it can still give you some ideas of things to watch out for in general.
Initial Problem
Anyways, the story starts with our team adding some new tests to our SpringBatch test suite which all passed just fine. However, when we ran all of the tests (not just the new ones we added), we found some completely unrelated tests started to fail. Checking the error logs we found something like this:
Error Logs
Application Server Log
- Failed to load ApplicationContext
- java.lang.IllegalStateException: Failed to load ApplicationContext
- ...
- Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'entityManagerFactory' defined in class path resource [org/springframework/boot/autoconfigure/orm/jpa/HibernateJpaConfiguration.class]: Invocation of init method failed; nested exception is org.hibernate.service.spi.ServiceException: Unable to create requested service [org.hibernate.engine.jdbc.env.spi.JdbcEnvironment]
- ...
- Caused by: org.hibernate.service.spi.ServiceException: Unable to create requested service [org.hibernate.engine.jdbc.env.spi.JdbcEnvironment]
- ...
- Caused by: org.hibernate.HibernateException: Access to DialectResolutionInfo cannot be null when 'hibernate.dialect' not set
- at org.hibernate.engine.jdbc.dialect.internal.DialectFactoryImpl.determineDialect(DialectFactoryImpl.java:100)
The issue was actually exactly what the error message indicated (which might seem obvious in hindsight, but definitely wasn't at the time), test failed because application context couldn't load because SpringBoot couldn't figure out what dialect it should use for the DB queries.
Investigation
However, despite knowing what the "problem" was, trying to figure out what was causing the problem in a way we could resolve still involved chasing down several false leads. Eventually I followed the error stack trace, checking org.hibernate.engine.jdbc.dialect.internal.DialectFactoryImpl.determineDialect(DialectFactoryImpl.java:100) and put a breakpoint there. Then, I ran the tests on debug mode, and after hitting the breakpoint, I followed the stack trace back up, dropping frames when needed, and stepping forward/into slowly, eventually finding my way to this file: org/hibernate/engine/jdbc/env/internal/JdbcEnvironmentInitiator.java with this part of the code snippet "failing".
Java
- ...
- if ( useJdbcMetadata ) {
- final JdbcConnectionAccess jdbcConnectionAccess = buildJdbcConnectionAccess( configurationValues, registry );
- try {
- final Connection connection = jdbcConnectionAccess.obtainConnection();
- try {
- final DatabaseMetaData dbmd = connection.getMetaData();
- ...
- Dialect dialect = dialectFactory.buildDialect(
- configurationValues,
- new DialectResolutionInfoSource() {
- @Override
- public DialectResolutionInfo getDialectResolutionInfo() {
- try {
- return new DatabaseMetaDataDialectResolutionInfoAdapter( connection.getMetaData() );
As you can see, SpringBoot is trying to determine the dialect from the DB connection. For most of our tests, this part of loading the application contexts works just fine. However, for the context load that fails, this line also fails:
Java
- final Connection connection = jdbcConnectionAccess.obtainConnection();
It turns out that we weren't able to determine the dialect to load our application context because we couldn't connect to the database in the first place. But wait, our local MySql database that we use for local testing has a fairly large default max connection limit
MySQL
- show variables like 'max_connections';
- Variable_name, value
- max_connections, 151
And our maximum pool size is already set to a "reasonable" default:
application.properties
- spring.datasource.hikari.maximumPoolSize=20
So what's going on? It was at this point I suspected we were "leaking" db connections, ie. creating new ones without closing the old ones for some of our tests. Since all the tests passed before we added our new ones, I guessed we weren't too far over the limit and tried lowering the maximum pool size from 20 down to 10 (we really didn't need that many connections for our batch anyways).
(Temporary) Solution
application.properties
- spring.datasource.hikari.maximumPoolSize=10
It worked! By setting the maximum pool size down to 10, now even with our leaked connections, we still managed to stay under the maximum connection limit and all of the tests passed.
Obviously, this is a pretty terrible solution for the long term. All this does is kick the problem down the road until we add a few more tests that adds new db connections and we're right back where we started. So, back to investigation it is! But this time, with a clearer sense of direction as to what to search for.
Investigation (Again)
Now that I was able to get all of the tests passing, I could put a breakpoint on the last test and check the total number of active db connections just before the last test finishes.
MySQL
- show status like 'Threads_connected';
- Variable_name, value
- Threads_connected, 102
As you can see, even after cutting down the connections by half, we're still already very close to the 151 limit again. Anyways, being able to monitor the number of active connections like this is super useful. I can now get direct feedback on whether the changes I'm making is having a positive impact on fixing this problem!
A bit of googling highlighted the test annotations @SpringBean and @SpyBean as potential culprits for causing @SpringBootTest to create new application contexts (and hence new un-closed db connections). I tested the theory out by commenting out the tests using these one at a time and confirmed that the number of threads connected dropped by 10 at a time per modified test class. At this point, I was fairly certain about the root cause.
Root Cause
Using @SpyBean and/or @SpringBean for mocking causes SpringBoot to generate new application contexts for these test classes, acquiring another maximumPoolSize number of connections and not releasing any of them until after all tests are finished. This means that as more test classes using these are added, we get closer to the maximum db connection limit until we exceed it and the tests start to fail because the application context can no longer be created.
Solution
Once I confirmed the root cause, it was actually pretty easy to find the solution from this StackOverflow question/answer post: https://stackoverflow.com/questions/63843274/spring-boot-test-classes-not-letting-go-of-database-connections-after-finishin. Unfortunately, it still took me a bit of trial-and-error to actually confirm that the solution works as I was initially mislead into believing this wasn't a solution for us. The reason was because we already had many of our tests annotated with
Groovy
- @DirtiesContext(classMode = DirtiesContext.ClassMode.BEFORE_EACH_TEST_METHOD)
And my earlier experiments proved that they in fact did NOT clean up the open DB connections (commenting out the tests with both @SpyBean and @DirtiesContext still lowered the total number of open connections). Eventually I realized that the BEFORE_EACH_TEST_METHOD and BEFORE_CLASS ClassMode did not work to clean up open db connections.
Thankfully, the following two annotations worked both to clean up open db connections as well as to keep old tests passing:
Groovy
- @DirtiesContext(classMode = DirtiesContext.ClassMode.AFTER_CLASS)
and
- @DirtiesContext(classMode = DirtiesContext.ClassMode.AFTER_EACH_TEST_METHOD)
(Use this one if you need cache cleanup between tests on the same test class).
Conclusion
In the end, by changing the existing @DirtiesContext to use AFTER ClassMode instead of BEFORE ClassMode and adding @DirtiesContext to other tests with @SpringBean and @SpyBean, I was able to bring the total open connections at the last test down to 12 (10 for the connection pool of the SpringBoot batch, 1 for SpringBoot test, and 1 for monitoring the number of connections). As a nice side benefit, the recorded test runtime also dropped from just under 1.5min to just over 30 seconds. (Note that the true test runtime is actually a bit slower than the recorded one since for some reason the recorded test runtime excludes some times like the spring context startup time from its calculations)
Caution
You might be tempted, after reading this, to just add @DirtiesContext to every SpringBootTest. Absolutely do NOT do this! SpringBootTest under most circumstances will reuse the existing application context to save on startup time (which usually takes a second or two) between tests. Adding @DirtiesContext to a test will tell SpringBoot to scrap the old application context and use a new one. This means if you use it indiscriminately on all your tests, you'll be removing the main application context that you should be re-using too, adding huge overhead to your tests!
Adding @DirtiesContext to the tests with @SpyBean and @SpringBean didn't slow down the overall test suite since we already had to create new application contexts for them (meaning we already slowed the test down by adding Spring/SpyBean, so adding DirtiesContext didn't make things worse). But the aim should be to minimize the use of SpyBean and SpringBean (so you can re-use the main application context as much as possible), and only use SpyBean and SpringBean together with DirtiesContext if you have to.
Obligatory Plug
Thanks for reading. I hope this will be useful (or at least mildly entertaining) for you. If you’re interested in looking into and solving interesting problems like these, consider applying to join us at Rakuten.
