flyway / flyway-test-extensions

Apache License 2.0
129 stars 35 forks source link

org.postgresql.util.PSQLException: ERROR: cached plan must not change result type #44

Closed esetnik closed 5 years ago

esetnik commented 7 years ago

I randomly receive the following error when running my tests on CI. It does not happen locally. I believe it is a race condition related to dropping a type.

Stack trace from gradle ./gradlew clean test

 org.springframework.orm.jpa.JpaSystemException: could not extract ResultSet; nested exception is org.hibernate.exception.GenericJDBCException: could not extract ResultSet
        at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:333)
        at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:244)
        at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.translateExceptionIfPossible(AbstractEntityManagerFactoryBean.java:488)
        at org.springframework.dao.support.ChainedPersistenceExceptionTranslator.translateExceptionIfPossible(ChainedPersistenceExceptionTranslator.java:59)
        at org.springframework.dao.support.DataAccessUtils.translateIfNecessary(DataAccessUtils.java:213)
        at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:147)
        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.$Proxy179.findByUsernameOrEmailEager(Unknown Source)
        at io.sumu.backend.user.UserServiceImpl.findByUsernameOrEmail(UserServiceImpl.java:166)
        at sun.reflect.GeneratedMethodAccessor259.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
        at org.springframework.cache.interceptor.CacheInterceptor$1.invoke(CacheInterceptor.java:52)
        at org.springframework.cache.interceptor.CacheAspectSupport.invokeOperation(CacheAspectSupport.java:345)
        at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:408)
        at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:327)
        at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:61)
        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.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
        at com.sun.proxy.$Proxy193.findByUsernameOrEmail(Unknown Source)
        at io.sumu.backend.security.FacebookAuthenticationProvider.retrieveUser(FacebookAuthenticationProvider.java:199)
        at io.sumu.backend.security.FacebookAuthenticationProvider.authenticate(FacebookAuthenticationProvider.java:84)
        at org.springframework.security.authentication.ProviderManager.authenticate(ProviderManager.java:174)
        at io.sumu.backend.security.FacebookLoginFilter.attemptAuthentication(FacebookLoginFilter.java:55)
        at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:212)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:200)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at io.sumu.backend.security.StatelessAuthenticationFilter.doFilter(StatelessAuthenticationFilter.java:28)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:64)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177)
        at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:134)
        at org.springframework.test.web.servlet.MockMvc.perform(MockMvc.java:155)
        at io.sumu.backend.user.FacebookLoginTests.createsNewUser_whenLoggingInWithFacebook_withoutExistingUserMatchingEmail(FacebookLoginTests.java:111)

        Caused by:
        org.hibernate.exception.GenericJDBCException: could not extract ResultSet
            at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:47)
            at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:111)
            at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:97)
            at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:69)
            at org.hibernate.loader.Loader.getResultSet(Loader.java:2178)
            at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1941)
            at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1903)
            at org.hibernate.loader.Loader.doQuery(Loader.java:948)
            at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:351)
            at org.hibernate.loader.Loader.doList(Loader.java:2702)
            at org.hibernate.loader.Loader.doList(Loader.java:2685)
            at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2517)
            at org.hibernate.loader.Loader.list(Loader.java:2512)
            at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:502)
            at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:384)
            at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:216)
            at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1490)
            at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1445)
            at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1414)
            at org.hibernate.query.Query.getResultList(Query.java:146)
            at org.springframework.data.jpa.repository.query.JpaQueryExecution$CollectionExecution.doExecute(JpaQueryExecution.java:121)
            at org.springframework.data.jpa.repository.query.JpaQueryExecution.execute(JpaQueryExecution.java:85)
            at org.springframework.data.jpa.repository.query.AbstractJpaQuery.doExecute(AbstractJpaQuery.java:116)
            at org.springframework.data.jpa.repository.query.AbstractJpaQuery.execute(AbstractJpaQuery.java:106)
            at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.doInvoke(RepositoryFactorySupport.java:483)
            at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.invoke(RepositoryFactorySupport.java:461)
            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)
            ... 46 more

            Caused by:
            org.postgresql.util.PSQLException: ERROR: cached plan must not change result type
                at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2477)
                at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2190)
                at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:300)
                at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:428)
                at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:354)
                at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:169)
                at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:117)
                at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source)
                at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
                at java.lang.reflect.Method.invoke(Method.java:498)
                at org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:114)
                at com.sun.proxy.$Proxy105.executeQuery(Unknown Source)
                at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:60)
                ... 76 more

Lifecycle:

public class MigrationLifecycle implements FlywayCallback {
  @Override
  public void beforeClean(Connection connection) {
    try {
      connection.prepareStatement("DROP EXTENSION IF EXISTS \"hstore\"; DROP EXTENSION IF EXISTS \"postgis\" CASCADE; DROP SCHEMA IF EXISTS \"analytics\" CASCADE;").execute();
    } catch (SQLException e) {
      throw new RuntimeException("message:" + e.getMessage(), e.getCause());
    }
  }

  @Override
  public void afterClean(Connection connection) {
    try {
      // uuid-ossp has to be dropped after clean since some tables require the extension to be present
      connection.prepareStatement("DROP EXTENSION IF EXISTS \"uuid-ossp\";").execute();
    } catch (SQLException e) {
      throw new RuntimeException("message:" + e.getMessage(), e.getCause());
    }
  }

  @Override
  public void beforeMigrate(Connection connection) {

  }

  @Override
  public void afterMigrate(Connection connection) {

  }

  @Override
  public void beforeEachMigrate(Connection connection, MigrationInfo info) {

  }

  @Override
  public void afterEachMigrate(Connection connection, MigrationInfo info) {

  }

  @Override
  public void beforeValidate(Connection connection) {

  }

  @Override
  public void afterValidate(Connection connection) {

  }

  @Override
  public void beforeBaseline(Connection connection) {

  }

  @Override
  public void afterBaseline(Connection connection) {

  }

  @Override
  public void beforeRepair(Connection connection) {

  }

  @Override
  public void afterRepair(Connection connection) {

  }

  @Override
  public void beforeInfo(Connection connection) {

  }

  @Override
  public void afterInfo(Connection connection) {

  }
}

Spring Boot Application:

  @Bean(initMethod = "migrate")
  @ConfigurationProperties(prefix = "flyway")
  public Flyway flyway(DataSource dataSource) {
    Flyway flyway = new Flyway();
    flyway.setDataSource(dataSource);
    flyway.setSqlMigrationPrefix("");
    flyway.setSchemas("public", "analytics");
    flyway.setCallbacks(new MigrationLifecycle());
    return flyway;
  }

Test

@RunWith(SpringRunner.class)
@SpringBootTest(webEnvironment = RANDOM_PORT, properties = {"management.port=0"})
@ActiveProfiles("test")
@TestExecutionListeners(value = FlywayTestExecutionListener.class, mergeMode = MERGE_WITH_DEFAULTS)
@FlywayTest
@Transactional
public abstract class AbstractWebIntegrationTest {
FlorianGWE commented 7 years ago

First of all I have no expirence with Postgres and usage of Extensions.

First a list of questions may be we can find the issue:

  1. Which version of Spring Boot, Flyway and FlywayTest you use?
  2. I do not understand your MigrationLifecycle. Why these statements not part of your normal Database setup scripts, so it will be done with each Test setup, or is this your solution only for the test setup?
  3. Do you habe one or more Test classes?
  4. Is the test setup so that no test is run parallel? This is important for database tests with clean.
  5. Who add the extensions that should be dropped?

If it is a race condition so I would be add some logging to see under which condition the error occured.

  1. add logging in your Lifecycle Implementation
  2. set logger org.flywaydb.test to debug
FlorianGWE commented 5 years ago

Two years no response -> close issue

esetnik commented 5 years ago

Sorry about the lack of response. I no longer use Flyway so I can't comment on this issue further. Thanks for closing!