search

fabric8io / docker-maven-plugin

Maven plugin for running and creating Docker images
https://dmp.fabric8.io
Apache License 2.0
1.88k stars 643 forks source link

wait on log ending too fast, would be nice to be able to add some delay #608

Open liufuyang opened 8 years ago

liufuyang commented 8 years ago

Description

We have this problem for some time with several recent version of our plug-in, which is that:

We have errors then such as: Caused by: com.zaxxer.hikari.pool.HikariPool$PoolInitializationException: Failed to initialize pool: FATAL: the database system is starting up

Solution?

It would be nice to be able to add some option to set the delay after some log has appear.

Other info ...

rhuss commented 8 years ago

Thanks for the bug report. It sounds a bit strange that the application which starts after the DB startup runs into such a race condition, since the dependent container is to be started only after the database container is up, so there are at least several seconds until a datasource eventually hits the database.

Do you have a log trace of the failing case ? (maybe with '-Ddocker.verbose=true' set) Ideally of courrse would be the project (or a stripped down version) itself so that I could reproduce it.

BTW, with d-m-p version are you using ?

liufuyang commented 8 years ago

Thanks for the feedback, what is d-m-p?

Oh, maybe I forgot to mention, normally it is okay on the localhost, but this problem show up more often on jenkins (we use version 2.7.1).

It is very strange to me that in most cases it is okay. However days ago one of my colleague had a branch and we tried several build on jenkins and it all failed due to this error. We had to change the pom file to remove wait on log, and use a fixed wait time to let build job pass.

Unfortunately the logs on jenkins are gone as we only keep several recent builds. If I encounter this issue again (maybe later we put this option back again see if it happens) then I will give you more info here.

liufuyang commented 7 years ago

Hmm... it randomly happened on our build job server again, here are part of the logs showing from the CI build job:

11:05:43 -------------------------------------------------------
11:05:43  T E S T S
11:05:43 -------------------------------------------------------
11:05:43 Running com.tradeshift.company.profile.persistence.impl.ProfileFieldDaoImplTest
11:05:43 company-profile-postgres-dao-test> done
11:05:43 company-profile-postgres-dao-test> server started
11:05:43 company-profile-postgres-dao-test> CREATE DATABASE
11:05:43 company-profile-postgres-dao-test> 
11:05:43 company-profile-postgres-dao-test> CREATE ROLE
11:05:43 company-profile-postgres-dao-test> 
11:05:43 company-profile-postgres-dao-test> 
11:05:43 company-profile-postgres-dao-test> /docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*
11:05:43 company-profile-postgres-dao-test> 
11:05:43 company-profile-postgres-dao-test> LOG:  received fast shutdown request
11:05:43 company-profile-postgres-dao-test> LOG:  aborting any active transactions
11:05:43 company-profile-postgres-dao-test> waiting for server to shut down...LOG:  autovacuum launcher shutting down
11:05:43 company-profile-postgres-dao-test> .LOG:  shutting down
11:05:43 company-profile-postgres-dao-test> LOG:  database system is shut down
11:05:44 company-profile-postgres-dao-test> done
11:05:44 company-profile-postgres-dao-test> server stopped
11:05:44 company-profile-postgres-dao-test> 
11:05:44 company-profile-postgres-dao-test> PostgreSQL init process complete; ready for start up.
11:05:44 company-profile-postgres-dao-test> 
11:05:44 company-profile-postgres-dao-test> LOG:  database system was shut down at 2016-11-25 11:05:43 UTC
11:05:44 company-profile-postgres-dao-test> LOG:  MultiXact member wraparound protections are now enabled
11:05:44 company-profile-postgres-dao-test> LOG:  autovacuum launcher started
11:05:44 company-profile-postgres-dao-test> LOG:  database system is ready to accept connections
11:05:45 company-profile-postgres-dao-test> ERROR:  relation "public.databasechangeloglock" does not exist at character 22
11:05:45 company-profile-postgres-dao-test> STATEMENT:  select count(*) from public.databasechangeloglock
11:05:47 Tests run: 21, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 3.281 sec <<< FAILURE! - in com.tradeshift.company.profile.persistence.impl.ProfileFieldDaoImplTest
11:05:47 setFieldValueSharing__given_valueId_saves_sharedWithCompanyAccountIds(com.tradeshift.company.profile.persistence.impl.ProfileFieldDaoImplTest)  Time elapsed: 0.01 sec  <<< ERROR!
11:05:47 java.lang.IllegalStateException: Failed to load ApplicationContext
11:05:47    at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:124)
11:05:47    at org.springframework.test.context.support.DefaultTestContext.getApplicationContext(DefaultTestContext.java:83)
11:05:47    at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.injectDependencies(DependencyInjectionTestExecutionListener.java:117)
11:05:47    at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.prepareTestInstance(DependencyInjectionTestExecutionListener.java:83)
11:05:47    at org.springframework.boot.test.autoconfigure.SpringBootDependencyInjectionTestExecutionListener.prepareTestInstance(SpringBootDependencyInjectionTestExecutionListener.java:44)
11:05:47    at org.springframework.test.context.TestContextManager.prepareTestInstance(TestContextManager.java:230)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.createTest(SpringJUnit4ClassRunner.java:228)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner$1.runReflectiveCall(SpringJUnit4ClassRunner.java:287)
11:05:47    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.methodBlock(SpringJUnit4ClassRunner.java:289)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:247)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:94)
11:05:47    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
11:05:47    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
11:05:47    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
11:05:47    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
11:05:47    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
11:05:47    at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61)
11:05:47    at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70)
11:05:47    at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:191)
11:05:47    at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264)
11:05:47    at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153)
11:05:47    at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124)
11:05:47    at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200)
11:05:47    at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153)
11:05:47    at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)
11:05:47 Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'liquibase' defined in class path resource [org/springframework/boot/autoconfigure/liquibase/LiquibaseAutoConfiguration$LiquibaseConfiguration.class]: Invocation of init method failed; nested exception is com.zaxxer.hikari.pool.HikariPool$PoolInitializationException: Failed to initialize pool: Connection to localhost:54320 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
11:05:47    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1583)
11:05:47    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:545)
11:05:47    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:482)
11:05:47    at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306)
11:05:47    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
11:05:47    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302)
11:05:47    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197)
11:05:47    at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:751)
11:05:47    at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:861)
11:05:47    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:541)
11:05:47    at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:761)
11:05:47    at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:371)
11:05:47    at org.springframework.boot.SpringApplication.run(SpringApplication.java:315)
11:05:47    at org.springframework.boot.test.context.SpringBootContextLoader.loadContext(SpringBootContextLoader.java:111)
11:05:47    at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContextInternal(DefaultCacheAwareContextLoaderDelegate.java:98)
11:05:47    at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:116)
11:05:47    at org.springframework.test.context.support.DefaultTestContext.getApplicationContext(DefaultTestContext.java:83)
11:05:47    at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.injectDependencies(DependencyInjectionTestExecutionListener.java:117)
11:05:47    at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.prepareTestInstance(DependencyInjectionTestExecutionListener.java:83)
11:05:47    at org.springframework.boot.test.autoconfigure.SpringBootDependencyInjectionTestExecutionListener.prepareTestInstance(SpringBootDependencyInjectionTestExecutionListener.java:44)
11:05:47    at org.springframework.test.context.TestContextManager.prepareTestInstance(TestContextManager.java:230)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.createTest(SpringJUnit4ClassRunner.java:228)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner$1.runReflectiveCall(SpringJUnit4ClassRunner.java:287)
11:05:47    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.methodBlock(SpringJUnit4ClassRunner.java:289)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:247)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:94)
11:05:47    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
11:05:47    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
11:05:47    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
11:05:47    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
11:05:47    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
11:05:47    at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61)
11:05:47    at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70)
11:05:47    at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:191)
11:05:47    at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264)
11:05:47    at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153)
11:05:47    at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124)
11:05:47    at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200)
11:05:47    at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153)
11:05:47    at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)
11:05:47 Caused by: com.zaxxer.hikari.pool.HikariPool$PoolInitializationException: Failed to initialize pool: Connection to localhost:54320 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
11:05:47    at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:516)
11:05:47    at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:118)
11:05:47    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:94)
11:05:47    at liquibase.integration.spring.SpringLiquibase.afterPropertiesSet(SpringLiquibase.java:388)
11:05:47    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1642)
11:05:47    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1579)
11:05:47    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:545)
11:05:47    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:482)
11:05:47    at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306)
11:05:47    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
11:05:47    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302)
11:05:47    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197)
11:05:47    at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:751)
11:05:47    at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:861)
11:05:47    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:541)
11:05:47    at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:761)
11:05:47    at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:371)
11:05:47    at org.springframework.boot.SpringApplication.run(SpringApplication.java:315)
11:05:47    at org.springframework.boot.test.context.SpringBootContextLoader.loadContext(SpringBootContextLoader.java:111)
11:05:47    at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContextInternal(DefaultCacheAwareContextLoaderDelegate.java:98)
11:05:47    at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:116)
11:05:47    at org.springframework.test.context.support.DefaultTestContext.getApplicationContext(DefaultTestContext.java:83)
11:05:47    at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.injectDependencies(DependencyInjectionTestExecutionListener.java:117)
11:05:47    at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.prepareTestInstance(DependencyInjectionTestExecutionListener.java:83)
11:05:47    at org.springframework.boot.test.autoconfigure.SpringBootDependencyInjectionTestExecutionListener.prepareTestInstance(SpringBootDependencyInjectionTestExecutionListener.java:44)
11:05:47    at org.springframework.test.context.TestContextManager.prepareTestInstance(TestContextManager.java:230)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.createTest(SpringJUnit4ClassRunner.java:228)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner$1.runReflectiveCall(SpringJUnit4ClassRunner.java:287)
11:05:47    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.methodBlock(SpringJUnit4ClassRunner.java:289)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:247)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:94)
11:05:47    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
11:05:47    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
11:05:47    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
11:05:47    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
11:05:47    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
11:05:47    at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61)
11:05:47    at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70)
11:05:47    at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:191)
11:05:47    at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264)
11:05:47    at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153)
11:05:47    at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124)
11:05:47    at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200)
11:05:47    at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153)
11:05:47    at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)
11:05:47 Caused by: org.postgresql.util.PSQLException: Connection to localhost:54320 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
11:05:47    at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:265)
11:05:47    at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:54)
11:05:47    at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:218)
11:05:47    at org.postgresql.Driver.makeConnection(Driver.java:407)
11:05:47    at org.postgresql.Driver.connect(Driver.java:275)
11:05:47    at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:95)
11:05:47    at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:101)
11:05:47    at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:316)
11:05:47    at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:506)
11:05:47    at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:118)
11:05:47    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:94)
11:05:47    at liquibase.integration.spring.SpringLiquibase.afterPropertiesSet(SpringLiquibase.java:388)
11:05:47    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1642)
11:05:47    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1579)
11:05:47    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:545)
11:05:47    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:482)
11:05:47    at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306)
11:05:47    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
11:05:47    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302)
11:05:47    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197)
11:05:47    at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:751)
11:05:47    at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:861)
11:05:47    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:541)
11:05:47    at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:761)
11:05:47    at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:371)
11:05:47    at org.springframework.boot.SpringApplication.run(SpringApplication.java:315)
11:05:47    at org.springframework.boot.test.context.SpringBootContextLoader.loadContext(SpringBootContextLoader.java:111)
11:05:47    at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContextInternal(DefaultCacheAwareContextLoaderDelegate.java:98)
11:05:47    at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:116)
11:05:47    at org.springframework.test.context.support.DefaultTestContext.getApplicationContext(DefaultTestContext.java:83)
11:05:47    at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.injectDependencies(DependencyInjectionTestExecutionListener.java:117)
11:05:47    at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.prepareTestInstance(DependencyInjectionTestExecutionListener.java:83)
11:05:47    at org.springframework.boot.test.autoconfigure.SpringBootDependencyInjectionTestExecutionListener.prepareTestInstance(SpringBootDependencyInjectionTestExecutionListener.java:44)
11:05:47    at org.springframework.test.context.TestContextManager.prepareTestInstance(TestContextManager.java:230)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.createTest(SpringJUnit4ClassRunner.java:228)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner$1.runReflectiveCall(SpringJUnit4ClassRunner.java:287)
11:05:47    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.methodBlock(SpringJUnit4ClassRunner.java:289)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:247)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:94)
11:05:47    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
11:05:47    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
11:05:47    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
11:05:47    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
11:05:47    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
11:05:47    at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61)
11:05:47    at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70)
11:05:47    at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:191)
11:05:47    at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264)
11:05:47    at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153)
11:05:47    at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124)
11:05:47    at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200)
11:05:47    at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153)
11:05:47    at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)
11:05:47 Caused by: java.net.ConnectException: Connection refused
11:05:47    at java.net.PlainSocketImpl.socketConnect(Native Method)
11:05:47    at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
11:05:47    at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
11:05:47    at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
11:05:47    at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
11:05:47    at java.net.Socket.connect(Socket.java:589)
11:05:47    at org.postgresql.core.PGStream.<init>(PGStream.java:64)
11:05:47    at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:147)
11:05:47    at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:54)
11:05:47    at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:218)
11:05:47    at org.postgresql.Driver.makeConnection(Driver.java:407)
11:05:47    at org.postgresql.Driver.connect(Driver.java:275)
11:05:47    at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:95)
11:05:47    at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:101)
11:05:47    at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:316)
11:05:47    at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:506)
11:05:47    at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:118)
11:05:47    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:94)
11:05:47    at liquibase.integration.spring.SpringLiquibase.afterPropertiesSet(SpringLiquibase.java:388)
11:05:47    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1642)
11:05:47    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1579)
11:05:47    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:545)
11:05:47    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:482)
11:05:47    at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306)
11:05:47    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
11:05:47    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302)
11:05:47    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197)
11:05:47    at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:751)
11:05:47    at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:861)
11:05:47    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:541)
11:05:47    at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:761)
11:05:47    at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:371)
11:05:47    at org.springframework.boot.SpringApplication.run(SpringApplication.java:315)
11:05:47    at org.springframework.boot.test.context.SpringBootContextLoader.loadContext(SpringBootContextLoader.java:111)
11:05:47    at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContextInternal(DefaultCacheAwareContextLoaderDelegate.java:98)
11:05:47    at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:116)
11:05:47    at org.springframework.test.context.support.DefaultTestContext.getApplicationContext(DefaultTestContext.java:83)
11:05:47    at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.injectDependencies(DependencyInjectionTestExecutionListener.java:117)
11:05:47    at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.prepareTestInstance(DependencyInjectionTestExecutionListener.java:83)
11:05:47    at org.springframework.boot.test.autoconfigure.SpringBootDependencyInjectionTestExecutionListener.prepareTestInstance(SpringBootDependencyInjectionTestExecutionListener.java:44)
11:05:47    at org.springframework.test.context.TestContextManager.prepareTestInstance(TestContextManager.java:230)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.createTest(SpringJUnit4ClassRunner.java:228)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner$1.runReflectiveCall(SpringJUnit4ClassRunner.java:287)
11:05:47    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.methodBlock(SpringJUnit4ClassRunner.java:289)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:247)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:94)
11:05:47    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
11:05:47    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
11:05:47    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
11:05:47    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
11:05:47    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
11:05:47    at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61)
11:05:47    at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70)
11:05:47    at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
11:05:47    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:191)
11:05:47    at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264)
11:05:47    at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153)
11:05:47    at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124)
11:05:47    at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200)
11:05:47    at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153)
11:05:47    at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)
rhuss commented 7 years ago

Ok, is you setup then, that you only start the DB container and run the tests from within Maven directly against the DB ? It also looks like that the containers are started in parallel to running your tests, so that sort of race seems to happen quite likely. (If it would be serial, I would expect some other line markers in the log between starting the test and starting the container). Could you past the whole Maven run to gist.github.com ?

Without the pom.xml this is hard to say. What you could also try is to add some delay before starting your tests (which should have the same effect).

btw, d-m-p stands for docker-maven-plugin (so, this plugin ;-)

liufuyang commented 7 years ago

Okay I think I found the problem. When I turn off the wait on logs, the db has log like this:

11:21:45 [INFO] --- docker-maven-plugin:0.17.1:start (start) @ persistence ---
11:21:46 [INFO] DOCKER> [tradeshift-docker-postgres95:0b91e51] "company-profile-postgres-dao-test": Start container c2b61dc683b8
11:21:46 [INFO] DOCKER> [tradeshift-docker-postgres95:0b91e51] "company-profile-postgres-dao-test": Pausing for 25000 ms
11:21:46 company-profile-postgres-dao-test> The files belonging to this database system will be owned by user "postgres".
11:21:46 company-profile-postgres-dao-test> This user must also own the server process.
11:21:46 company-profile-postgres-dao-test> 
11:21:46 company-profile-postgres-dao-test> The database cluster will be initialized with locale "en_US.utf8".
11:21:46 company-profile-postgres-dao-test> The default database encoding has accordingly been set to "UTF8".
11:21:46 company-profile-postgres-dao-test> The default text search configuration will be set to "english".
11:21:46 company-profile-postgres-dao-test> 
11:21:46 company-profile-postgres-dao-test> Data page checksums are disabled.
11:21:46 company-profile-postgres-dao-test> 
11:21:46 company-profile-postgres-dao-test> fixing permissions on existing directory /var/lib/postgresql/data ... ok
11:21:46 company-profile-postgres-dao-test> creating subdirectories ... ok
11:21:46 company-profile-postgres-dao-test> selecting default max_connections ... 100
11:21:46 company-profile-postgres-dao-test> selecting default shared_buffers ... 128MB
11:21:46 company-profile-postgres-dao-test> selecting dynamic shared memory implementation ... posix
11:21:46 company-profile-postgres-dao-test> creating configuration files ... ok
11:21:47 company-profile-postgres-dao-test> creating template1 database in /var/lib/postgresql/data/base/1 ... ok
11:21:47 company-profile-postgres-dao-test> initializing pg_authid ... ok
11:21:47 company-profile-postgres-dao-test> initializing dependencies ... ok
11:21:47 company-profile-postgres-dao-test> creating system views ... ok
11:21:47 company-profile-postgres-dao-test> loading system objects' descriptions ... ok
11:21:47 company-profile-postgres-dao-test> creating collations ... ok
11:21:47 company-profile-postgres-dao-test> creating conversions ... ok
11:21:47 company-profile-postgres-dao-test> creating dictionaries ... ok
11:21:47 company-profile-postgres-dao-test> setting privileges on built-in objects ... ok
11:21:47 company-profile-postgres-dao-test> creating information schema ... ok
11:21:47 company-profile-postgres-dao-test> loading PL/pgSQL server-side language ... ok
11:21:47 company-profile-postgres-dao-test> vacuuming database template1 ... ok
11:21:47 company-profile-postgres-dao-test> copying template1 to template0 ... ok
11:21:47 company-profile-postgres-dao-test> copying template1 to postgres ... ok
11:21:47 company-profile-postgres-dao-test> syncing data to disk ... ok
11:21:47 company-profile-postgres-dao-test> 
11:21:47 company-profile-postgres-dao-test> Success. You can now start the database server using:
11:21:47 company-profile-postgres-dao-test> 
11:21:47 company-profile-postgres-dao-test> pg_ctl -D /var/lib/postgresql/data -l logfile start
11:21:47 company-profile-postgres-dao-test> 
11:21:47 company-profile-postgres-dao-test> 
11:21:47 company-profile-postgres-dao-test> WARNING: enabling "trust" authentication for local connections
11:21:47 company-profile-postgres-dao-test> You can change this by editing pg_hba.conf or using the option -A, or
11:21:47 company-profile-postgres-dao-test> --auth-local and --auth-host, the next time you run initdb.
11:21:47 company-profile-postgres-dao-test> waiting for server to start....LOG:  database system was shut down at 2016-11-25 11:21:47 UTC
11:21:47 company-profile-postgres-dao-test> LOG:  MultiXact member wraparound protections are now enabled
11:21:47 company-profile-postgres-dao-test> LOG:  autovacuum launcher started
11:21:47 company-profile-postgres-dao-test> LOG:  database system is ready to accept connections
11:21:48 company-profile-postgres-dao-test> done
11:21:48 company-profile-postgres-dao-test> server started
11:21:49 company-profile-postgres-dao-test> CREATE DATABASE
11:21:49 company-profile-postgres-dao-test> 
11:21:49 company-profile-postgres-dao-test> CREATE ROLE
11:21:49 company-profile-postgres-dao-test> 
11:21:49 company-profile-postgres-dao-test> 
11:21:49 company-profile-postgres-dao-test> /docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*
11:21:49 company-profile-postgres-dao-test> 
11:21:49 company-profile-postgres-dao-test> LOG:  received fast shutdown request
11:21:49 company-profile-postgres-dao-test> LOG:  aborting any active transactions
11:21:49 company-profile-postgres-dao-test> waiting for server to shut down...LOG:  autovacuum launcher shutting down
11:21:49 company-profile-postgres-dao-test> .LOG:  shutting down
11:21:49 company-profile-postgres-dao-test> LOG:  database system is shut down
11:21:50 company-profile-postgres-dao-test> done
11:21:50 company-profile-postgres-dao-test> server stopped
11:21:50 company-profile-postgres-dao-test> 
11:21:50 company-profile-postgres-dao-test> PostgreSQL init process complete; ready for start up.
11:21:50 company-profile-postgres-dao-test> 
11:21:50 company-profile-postgres-dao-test> LOG:  database system was shut down at 2016-11-25 11:21:49 UTC
11:21:50 company-profile-postgres-dao-test> LOG:  MultiXact member wraparound protections are now enabled
11:21:50 company-profile-postgres-dao-test> LOG:  autovacuum launcher started
11:21:50 company-profile-postgres-dao-test> LOG:  database system is ready to accept connections

Which is showing that there are two logs like database system is ready to accept connections. The db somehow shutdown itself after first lot. I don't think it is our docker-maven-plugin's issue now :)

BTW, is there any way to wait for a second log showing up?

liufuyang commented 7 years ago

And this is the maven setup:

<plugin>
                        <groupId>io.fabric8</groupId>
                        <artifactId>docker-maven-plugin</artifactId>
                        <inherited>false</inherited>
                        <configuration>
                            <images>
                                <image>
                                    <name>postgres:95</name>
                                    <alias>company-profile-postgres-dao-test</alias>
                                    <run>
                                        <namingStrategy>alias</namingStrategy>
                                        <env>
                                            <POSTGRES_DB>company-profile</POSTGRES_DB>
                                            <POSTGRES_USER>xxx</POSTGRES_USER>
                                            <POSTGRES_PASSWORD>xxx</POSTGRES_PASSWORD>
                                        </env>
                                        <ports>
                                            <port>${dao.pg.port}:5432</port>
                                        </ports>
                                        <wait>
                                            <!--<log>database system is ready to accept connections</log>-->
                                            <time>25000</time>
                                        </wait>
                                        <log>
                                            <color>cyan</color>
                                        </log>
                                    </run>
                                </image>
                            </images>
                        </configuration>
                        <executions>
                            <execution>
                                <id>start</id>
                                <phase>pre-integration-test</phase>
                                <goals>
                                    <goal>start</goal>
                                </goals>
                            </execution>
                            <execution>
                                <id>stop</id>
                                <phase>post-integration-test</phase>
                                <goals>
                                    <goal>stop</goal>
                                </goals>
                            </execution>
                            <execution>
                                <id>remove</id>
                                <phase>post-integration-test</phase>
                                <goals>
                                    <goal>stop</goal>
                                    <goal>remove</goal>
                                </goals>
                            </execution>
                        </executions>
                    </plugin>
rhuss commented 7 years ago

no, unfortunately its not that sophisticated ;-)

Maybe you could try to wait for is shut down which happens 2 seconds later then first 'ready to accept' and which might be already long enough for getting the spring test container up ?

liufuyang commented 7 years ago

yeah, I will try that, thanks for the help :)

michael-simons commented 7 years ago

Thinking about a race condition was the first impression I had, too… Doesn't happen usually if you use the failsafe plugin and run integration tests with Spring Boot (they take at my machines long enough to boot), but during unit tests… The reason behind this is exactly #628, Postgres starts up 2 times. First time only on socket to initialize db and run init scripts if you provide them, then restart on network.

rhuss commented 7 years ago

I just added multi line matching so that you can wait now (forthcoming release 0.20.1) with 

"(?s)ready to accept connections.*ready to accept connections"

so that the checks wait until of the second connection string appears.

michael-simons commented 7 years ago

Works fine for me. Thank you very much!