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.
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.