Spring ContextCache should close evicted context before loading new context

Overview

Christoph Dreis opened SPR-16462 and commented

Hi,

This week we discovered that our integration tests were failing with error messages that told us the database tables were not existent. Our test setup uses Hibernate's create-drop facilities in order to build up the database and drop everything afterwards.

After quite some digging I found out that we reached the cache limit in DefaultContextCache. The problem for us here is that the eventual ApplicationContext.close() happening in DefaultContextCache.remove() can drop the database for the currently or upcoming tests when using create-drop.

While I increased the cache limit for now, I think this is a bug as the eldest ApplicationContext instances should be closed/removed at the end of the test instance, not at the beginning when a new one might be loaded/created and put into the LruCache. (Though it's probably the appropriate place to handle the cache size).

As I don't have a proper idea yet how to defer the ApplicationContext closing in DefaultContextCache, I would highly appreciate any ideas. :)

Cheers, Christoph

P.S.: I attached a reproduction project. Simply call mvn clean test and you should hopefully notice the test failures saying that the dummy account table doesn't exist.

Related Issues

35396

Affects: 4.3.14

Reference URL: https://github.com/dreis2211/spring-contextcacheclose-tests

Comment From: spring-projects-issues

Sam Brannen commented

Thanks for raising the issue.

We'll see if we can improve things here in time for Spring Framework 5.1.

In in the interim, I believe the best you can do is increase the cache size, as you've already done.

Comment From: spring-projects-issues

Sam Brannen commented

P.S.: I attached a reproduction project. Simply call mvn clean test and you should hopefully notice the test failures saying that the dummy account table doesn't exist.

Thanks for supplying the example project.

However... when I execute ./mvnw clean test or execute all tests within the project in Eclipse (4.7.2), all tests pass.

Do you still see errors when you execute ./mvnw clean test against your project?

Comment From: spring-projects-issues

Sam Brannen commented

By the way, the last cache statistics log entry is:

2018-02-07 14:28:51.844 DEBUG 55364 --- [           main] org.springframework.test.context.cache   : Spring test ApplicationContext cache statistics: [DefaultContextCache@39c87b42 size = 1, maxSize = 1, parentContextCount = 0, hitCount = 13, missCount = 2]

Comment From: spring-projects-issues

Sam Brannen commented

Could the cause of the behavior you experienced possibly be due to the fact that you enabled forking within your Maven build?

Comment From: spring-projects-issues

Sam Brannen commented

I'm struggling to reproduce the behavior you described.

Can you please update your example project so that it displays that behavior and let me know once you've done that, so that I can git pull your changes?

Cheers,

Sam

Comment From: spring-projects-issues

Christoph Dreis commented

Hi Sam,

thanks for taking care of this. I just cloned it again on a different machine and it still shows the faulty behaviour. (Both Windows machines if that helps). Enabling debug logging for maven shows the following (default) configuration for surefire:

[DEBUG] Configuring mojo 'org.apache.maven.plugins:maven-surefire-plugin:2.18.1:test' with basic configurator -->
[DEBUG]   (s) additionalClasspathElements = []
[DEBUG]   (s) basedir = X:\pathtomyrepo\spring-contextcacheclose-tests
[DEBUG]   (s) childDelegation = false
[DEBUG]   (s) classesDirectory = X:\pathtomyrepo\spring-contextcacheclose-tests\target\classes
[DEBUG]   (s) classpathDependencyExcludes = []
[DEBUG]   (s) dependenciesToScan = []
[DEBUG]   (s) disableXmlReport = false
[DEBUG]   (s) enableAssertions = true
[DEBUG]   (s) excludes = [**/Abstract*.java]
[DEBUG]   (f) forkCount = 1
[DEBUG]   (s) forkMode = once
[DEBUG]   (s) includes = [**/*Tests.java, **/*Test.java]
[DEBUG]   (s) junitArtifactName = junit:junit
[DEBUG]   (s) localRepository =       id: local

At a later point there is also the debug output about reuseForks being set to true

Comment From: spring-projects-issues

Sam Brannen commented

Strange... the -X debug output looks similar for me, but I don't get any errors.

The only difference I perceive is that you're on Windows, and I'm on macOS.

Comment From: spring-projects-issues

Christoph Dreis commented

In which order are the tests executed on your side? For me it's ContextCacheCloseFirstApplicationTests, ContextCacheCloseSecondApplicationTests, ContextCacheCloseThirdApplicationTests. Maybe it's different on your machine?

Comment From: spring-projects-issues

Sam Brannen commented

I just ran the tests on Windows 10 (via Virtual Box on my Mac... which took me almost an hour to be able to copy a file from), and I actually get the following failure.

2018-02-07 15:34:59.384 DEBUG 2528 --- [           main] org.springframework.test.context.cache   : Spring test ApplicationContext cache statistics: [DefaultContextCache@7a36c83a size = 1, maxSize = 1, parentContextCount = 0, hitCount = 13, missCount = 3]
Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 7.325 sec <<< FAILURE! - in com.example.contextcacheclose.ContextCacheCloseThirdApplicationTests
accountIsNotFound(com.example.contextcacheclose.ContextCacheCloseThirdApplicationTests)  Time elapsed: 0.044 sec  <<< ERROR!
org.springframework.dao.InvalidDataAccessResourceUsageException: could not prepare statement; SQL [select account0_.id as id1_0_0_, account0_.password as password2_0_0_, account0_.username as username3_0_0_ from account account0_ where account0_.id=?]; nested exception is org.hibernate.exception.SQLGrammarException: could not prepare statement
        at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
        at org.h2.message.DbException.get(DbException.java:179)
        at org.h2.message.DbException.get(DbException.java:155)
        at org.h2.command.Parser.readTableOrView(Parser.java:5552)
        at org.h2.command.Parser.readTableFilter(Parser.java:1266)
        at org.h2.command.Parser.parseSelectSimpleFromPart(Parser.java:1946)
        at org.h2.command.Parser.parseSelectSimple(Parser.java:2095)
        at org.h2.command.Parser.parseSelectSub(Parser.java:1940)
        at org.h2.command.Parser.parseSelectUnion(Parser.java:1755)
        at org.h2.command.Parser.parseSelect(Parser.java:1743)
        at org.h2.command.Parser.parsePrepared(Parser.java:449)
        at org.h2.command.Parser.parse(Parser.java:321)
        at org.h2.command.Parser.parse(Parser.java:293)
        at org.h2.command.Parser.prepareCommand(Parser.java:258)
        at org.h2.engine.Session.prepareLocal(Session.java:578)
        at org.h2.engine.Session.prepareCommand(Session.java:519)
        at org.h2.jdbc.JdbcConnection.prepareCommand(JdbcConnection.java:1204)
        at org.h2.jdbc.JdbcPreparedStatement.<init>(JdbcPreparedStatement.java:73)
        at org.h2.jdbc.JdbcConnection.prepareStatement(JdbcConnection.java:288)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
        at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
        at org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)
        at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
        at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
        at com.sun.proxy.$Proxy70.prepareStatement(Unknown Source)
        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:146)
        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:172)
        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:148)
        at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.prepareQueryStatement(AbstractLoadPlanBasedLoader.java:241)
        at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeQueryStatement(AbstractLoadPlanBasedLoader.java:185)
        at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:121)
        at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:86)
        at org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader.load(AbstractLoadPlanBasedEntityLoader.java:167)
        at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:4019)
        at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:508)
        at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:478)
        at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:219)
        at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:278)
        at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:121)
        at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:89)
        at org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:1129)
        at org.hibernate.internal.SessionImpl.access$2600(SessionImpl.java:164)
        at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.load(SessionImpl.java:2696)
        at org.hibernate.internal.SessionImpl.get(SessionImpl.java:975)
        at org.hibernate.jpa.spi.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:1075)
        at org.hibernate.jpa.spi.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:1039)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:298)
        at com.sun.proxy.$Proxy79.find(Unknown Source)
        at org.springframework.data.jpa.repository.support.SimpleJpaRepository.findOne(SimpleJpaRepository.java:241)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.executeMethodOn(RepositoryFactorySupport.java:513)
        at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.doInvoke(RepositoryFactorySupport.java:498)
        at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.invoke(RepositoryFactorySupport.java:475)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:56)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:282)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:136)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:133)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.data.repository.core.support.SurroundingTransactionDetectorMethodInterceptor.invoke(SurroundingTransactionDetectorMethodInterceptor.java:57)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
        at com.sun.proxy.$Proxy81.findOne(Unknown Source)
        at com.example.contextcacheclose.ContextCacheCloseThirdApplicationTests.accountIsNotFound(ContextCacheCloseThirdApplicationTests.java:22)

2018-02-07 15:34:59.523  INFO 2528 --- [      Thread-10] ationConfigEmbeddedWebApplicationContext : Closing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@61c5fd78: startup date [Wed Feb 07 15:34:52 CET 2018]; root of context hierarchy
2018-02-07 15:34:59.545  INFO 2528 --- [      Thread-10] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2018-02-07 15:34:59.546  INFO 2528 --- [      Thread-10] org.hibernate.tool.hbm2ddl.SchemaExport  : HHH000227: Running hbm2ddl schema export
2018-02-07 15:34:59.546  INFO 2528 --- [      Thread-10] org.hibernate.tool.hbm2ddl.SchemaExport  : HHH000230: Schema export complete

Results :

Tests in error:
  ContextCacheCloseThirdApplicationTests.accountIsNotFound:22 ▒ InvalidDataAccessResourceUsage

Tests run: 3, Failures: 0, Errors: 1, Skipped: 0

[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------

Is that the same error you get?

Comment From: spring-projects-issues

Sam Brannen commented

OK...... I am now able to reproduce the error on a Mac as well.

It was indeed the execution order of the test classes.

So at least I will now have something to investigate without having to work in Windows inside a Virtual Box. ;-)

Comment From: spring-projects-issues

Christoph Dreis commented

The error above is indeed what I see (Actually I see a bit more because the stack is a bit longer on my end - I assume the VirtualBox setup has a different stack length configured.) E.g.

Table "ACCOUNT" not found; SQL statement:
select account0_.id as id1_0_0_, account0_.password as password2_0_0_, account0_.username as username3_0_0_ from account account0_ where account0_.id=? [42102-196]

But anyhow. Great to see that the reproduction case is working for you now.

Comment From: sbrannen

Update

Issue #35396 inspired me to take another look at this.

So, I spiked a proof of concept in the following feature branch.

https://github.com/spring-projects/spring-framework/compare/main...sbrannen:spring-framework:issues/gh-21007-context-cache-evict-before-put

Comment From: sbrannen

@dreis2211, I just wanted to bring the above proof of concept to your attention, since you originally reported this issue on Jira.

Comment From: dreis2211

@sbrannen Thanks for the update. I won't be able to test this really, but cool to see movement in this area

Comment From: novitzkee

Hi, for what's it worth I should be able to test it. I can reproduce the problem using spring 7.x with repo mentioned in issue #35396. I will try to build @sbrannen's fork from source into local maven repo and see if issue goes away with this change.

Will post updates if I succeed.

Comment From: sbrannen

@novitzkee, thanks so much for your enthusiasm and offering to test the branch!

But... please hold off on testing.

I realized that my proof of concept is broken. 🤦

Changing the order in which the evicted context is closed and the new context is stored in the cache is a good start, but it is only part of the puzzle.

I also need to ensure that the new context is loaded/refreshed after the evicted context is closed.

That logic will likely need to reside in DefaultCacheAwareContextLoaderDelegate.loadContext(...) with some form of collaboration with the ContextCache to determine the least recently used (LRU) context to evict from the cache.

So, I'll go back to the drawing board and post back here once I have something viable.

Comment From: novitzkee

@sbrannen, sure, no problem.

Comment From: sbrannen

@novitzkee, I updated the aforementioned feature branch with a proposal that appears to work.

Thus, if you're feeling brave and willing to help test with your own project, that would be warmly welcomed! 😎

Comment From: sbrannen

@novitzkee, there's no need for you to test this with your repo.

I just tested it using a clone of your repo and your reproduction.sh script with Spring Framework 7.0.0-SNAPSHOT built locally, and your tests pass.

Comment From: novitzkee

@sbrannen, nice, thanks! Is there any chance this fix will be included in versions older than 7.x ?

Comment From: sbrannen

@sbrannen, nice, thanks!

👍

Is there any chance this fix will be included in versions older than 7.x ?

No, I don't foresee how that would be possible.

As you can see in the feature branch, the fix requires major changes to the implementations of DefaultCacheAwareContextLoaderDelegate and DefaultContextCache and requires a new computeIfAbsent() method in the ContextCache API.

However, there are two possible workarounds for versions prior to 7.x.

When using an embedded HSQL or H2 database, use a randomly generated database name. For details, see Generating Unique Names for Embedded Databases in the reference manual.
As mentioned in the description of this issue, you can increase the maximum size of the context cache.

Granted, the latter may not be a viable "solution" for you.

.