New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Invalid cached query plan when busily making metadata changes #5511

Closed
fdlk opened this Issue Nov 10, 2016 · 4 comments

Comments

Projects
None yet
4 participants
@fdlk
Copy link
Member

fdlk commented Nov 10, 2016

Reproduce

Unsure. Got this twice today when running IntTypeEditing.java

Expected

Postgres jdbc queries always use the correct table metadata and tests succeed.

Observed

Test sometimes fails, complaining that the cached plan's result type has changed

com.google.common.util.concurrent.UncheckedExecutionException: org.molgenis.data.MolgenisDataException: ; nested exception is org.postgresql.util.PSQLException: ERROR: cached plan must not change result type

	at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2207)
	at com.google.common.cache.LocalCache.get(LocalCache.java:3953)
	at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3957)
	at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4875)
	at com.google.common.cache.LocalCache$LocalLoadingCache.getUnchecked(LocalCache.java:4881)
	at org.molgenis.data.cache.l2.L2Cache.get(L2Cache.java:92)
	at org.molgenis.data.cache.l2.L2CacheRepositoryDecorator.findOneById(L2CacheRepositoryDecorator.java:74)
	at org.molgenis.data.cache.l1.L1CacheRepositoryDecorator.findOneById(L1CacheRepositoryDecorator.java:85)
	at org.molgenis.data.elasticsearch.IndexedRepositoryDecorator.findOneById(IndexedRepositoryDecorator.java:112)
	at org.molgenis.data.AbstractRepositoryDecorator.findOneById(AbstractRepositoryDecorator.java:92)
	at org.molgenis.data.AbstractRepositoryDecorator.findOneById(AbstractRepositoryDecorator.java:92)
	at org.molgenis.data.EntityReferenceResolverDecorator.findOneById(EntityReferenceResolverDecorator.java:117)
	at org.molgenis.data.listeners.EntityListenerRepositoryDecorator.findOneById(EntityListenerRepositoryDecorator.java:105)
	at org.molgenis.data.validation.RepositoryValidationDecorator.findOneById(RepositoryValidationDecorator.java:156)
	at org.molgenis.data.AbstractRepositoryDecorator.findOneById(AbstractRepositoryDecorator.java:92)
	at org.molgenis.data.RepositorySecurityDecorator.findOneById(RepositorySecurityDecorator.java:95)
	at org.molgenis.data.transaction.TransactionalRepositoryDecorator.lambda$findOneById$6(TransactionalRepositoryDecorator.java:88)
	at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:133)
	at org.molgenis.data.transaction.TransactionalRepositoryDecorator.findOneById(TransactionalRepositoryDecorator.java:88)
	at org.molgenis.data.support.DataServiceImpl.findOneById(DataServiceImpl.java:80)
	at org.molgenis.data.support.DataServiceImpl$$FastClassBySpringCGLIB$$2e5f77dc.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:649)
	at org.molgenis.data.support.DataServiceImpl$$EnhancerBySpringCGLIB$$d4502c4f.findOneById(<generated>)
	at org.molgenis.integrationtest.platform.datatypeediting.IntTypeEditing.getActualValue(IntTypeEditing.java:255)
	at org.molgenis.integrationtest.platform.datatypeediting.IntTypeEditing.testValidConversions(IntTypeEditing.java:179)
	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.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:80)
	at org.testng.internal.MethodInvocationHelper$1.runTestMethod(MethodInvocationHelper.java:182)
	at org.springframework.test.context.testng.AbstractTestNGSpringContextTests.run(AbstractTestNGSpringContextTests.java:171)
	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.testng.internal.MethodInvocationHelper.invokeHookable(MethodInvocationHelper.java:194)
	at org.testng.internal.Invoker.invokeMethod(Invoker.java:707)
	at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:901)
	at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1231)
	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127)
	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111)
	at org.testng.TestRunner.privateRun(TestRunner.java:767)
	at org.testng.TestRunner.run(TestRunner.java:617)
	at org.testng.SuiteRunner.runTest(SuiteRunner.java:334)
	at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:329)
	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:291)
	at org.testng.SuiteRunner.run(SuiteRunner.java:240)
	at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
	at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86)
	at org.testng.TestNG.runSuitesSequentially(TestNG.java:1198)
	at org.testng.TestNG.runSuitesLocally(TestNG.java:1123)
	at org.testng.TestNG.run(TestNG.java:1031)
	at org.testng.IDEARemoteTestNG.run(IDEARemoteTestNG.java:72)
	at org.testng.RemoteTestNGStarter.main(RemoteTestNGStarter.java:124)
	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 com.intellij.rt.execution.application.AppMain.main(AppMain.java:147)
Caused by: org.molgenis.data.MolgenisDataException: ; nested exception is org.postgresql.util.PSQLException: ERROR: cached plan must not change result type
	at org.molgenis.data.postgresql.PostgreSqlExceptionTranslator.doTranslate(PostgreSqlExceptionTranslator.java:79)
	at org.molgenis.data.postgresql.PostgreSqlExceptionTranslator.doTranslate(PostgreSqlExceptionTranslator.java:41)
	at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:73)
	at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:660)
	at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:695)
	at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:727)
	at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:737)
	at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:787)
	at org.molgenis.data.postgresql.PostgreSqlRepository$1.getBatch(PostgreSqlRepository.java:415)
	at org.molgenis.data.support.BatchingQueryResult.getBatch(BatchingQueryResult.java:36)
	at org.molgenis.data.support.BatchingQueryResult.getBatch(BatchingQueryResult.java:14)
	at org.molgenis.util.BatchingIterable$1.nextBatch(BatchingIterable.java:138)
	at org.molgenis.util.BatchingIterable$1.hasNext(BatchingIterable.java:58)
	at java.util.Spliterators$IteratorSpliterator.tryAdvance(Spliterators.java:1811)
	at java.util.Spliterators$1Adapter.hasNext(Spliterators.java:681)
	at org.molgenis.data.postgresql.PostgreSqlRepository.findOne(PostgreSqlRepository.java:152)
	at org.molgenis.data.postgresql.PostgreSqlRepository.findOneById(PostgreSqlRepository.java:166)
	at org.molgenis.data.cache.l2.L2Cache$1.load(L2Cache.java:186)
	at org.molgenis.data.cache.l2.L2Cache$1.load(L2Cache.java:177)
	at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3542)
	at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2323)
	at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2286)
	at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2201)
	... 60 more
Caused by: org.postgresql.util.PSQLException: ERROR: cached plan must not change result type
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2458)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2158)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:291)
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:432)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:358)
	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:171)
	at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:119)
	at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:353)
	at org.springframework.jdbc.core.JdbcTemplate$1.doInPreparedStatement(JdbcTemplate.java:703)
	at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:644)
	... 79 more

@fdlk fdlk added this to the Sprint 93 milestone Nov 10, 2016

@fdlk

This comment has been minimized.

Copy link
Member Author

fdlk commented Nov 10, 2016

See also #5508 and pgjdbc/pgjdbc#451

@fdlk fdlk added 2.0-RC and removed bug-unclear labels Nov 10, 2016

@dennishendriksen

This comment has been minimized.

Copy link
Contributor

dennishendriksen commented Nov 11, 2016

Are you running PostgreSQL 9.6.1? Do you see the same behavior if you add autosave=ALWAYS to db_uri in molgenis-server.properties?

@dennishendriksen dennishendriksen modified the milestones: Sprint 93, Sprint 94 Nov 11, 2016

@dennishendriksen dennishendriksen added 2.0 bug and removed 2.0-RC labels Nov 14, 2016

@fdlk

This comment has been minimized.

Copy link
Member Author

fdlk commented Nov 14, 2016

This was 9.6.0.

@jjettenn jjettenn modified the milestone: Sprint 94 Nov 15, 2016

@mark-de-haan

This comment has been minimized.

Copy link
Contributor

mark-de-haan commented Nov 17, 2016

db_uri=jdbc\:postgresql\://localhost/molgenis_integration_test?reWriteBatchedInserts=true&autosave=ALWAYS
prevents this error. Bootstrapping on IT startup does take a bit longer, but tests are run faster

mark-de-haan added a commit to mark-de-haan/molgenis that referenced this issue Nov 17, 2016

mark-de-haan added a commit to mark-de-haan/molgenis that referenced this issue Nov 18, 2016

mark-de-haan added a commit to mark-de-haan/molgenis that referenced this issue Nov 21, 2016

fdlk added a commit that referenced this issue Nov 22, 2016

Merge pull request #5598 from Mark-de-Haan/fix/5511
Fix #5511 Invalid cached query plan when busily making metadata changes

@jjettenn jjettenn closed this in f385a14 Nov 30, 2016

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment