Skip to content
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.

Sign up for GitHub

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

Jump to bottom

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

Open
liufuyang opened this issue Nov 3, 2016 · 11 comments
Open

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

liufuyang opened this issue Nov 3, 2016 · 11 comments

Comments

@liufuyang
Copy link

liufuyang commented Nov 3, 2016 •
edited
Loading

Description

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

  • Setup:
    If my maven job is to use this plug-in to spin up a postgres docker container then run some dao tests against the postgres database. And the plug-in is set as wait on log such as: 
    <wait>
          <log>database system is ready to accept connections</log>
          <time>20000</time>
</wait>
  • Problem:
    Then occasionally, maybe 30% to 50% of the time (sometimes more frequent), that those dao tests cannot be carried out because when spring boots up the datasource immediately after the database container showing log database system is ready to accept connections, the datasource cannot connect onto database (it seems still need some micro delay to be ready).

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

  • Maven version (mvn -v) :
Listening for transport dt_socket at address: 63099
Apache Maven 3.3.9 (bb52d8502b132ec0a5a3f4c09453c07478323dc5; 2015-11-10T17:41:47+01:00)
Maven home: /usr/local/Cellar/maven/3.3.9/libexec
Java version: 1.8.0_72, vendor: Oracle Corporation
Java home: /Library/Java/JavaVirtualMachines/jdk1.8.0_72.jdk/Contents/Home/jre
Default locale: en_US, platform encoding: UTF-8
OS name: "mac os x", version: "10.12.1", arch: "x86_64", family: "mac"
  • Docker version :
    Docker version 1.11.2, build b9f10c9
@rhuss
Copy link
Collaborator

rhuss commented Nov 11, 2016

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
Copy link
Author

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
Copy link
Author

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
Copy link
Collaborator

rhuss commented Nov 25, 2016

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
Copy link
Author

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
Copy link
Author

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
Copy link
Collaborator

rhuss commented Nov 25, 2016

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
Copy link
Author

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

@miszobi miszobi mentioned this issue Dec 1, 2016
Closed
@michael-simons
Copy link
Contributor

michael-simons commented Mar 25, 2017 •
edited
Loading

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 added a commit to rhuss/docker-maven-plugin that referenced this issue Mar 25, 2017
@rhuss
Add multiline log matching
efa0c87 
This is related to fabric8io#628 and fabric8io#608 and should fix both issues.

Also, some refactoring has been performed for the wait checkers which were extracted into an extra package.
@rhuss rhuss mentioned this issue Mar 25, 2017
Merged
@rhuss
Copy link
Collaborator

rhuss commented Mar 25, 2017

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
Copy link
Contributor

Works fine for me. Thank you very much!

rgbj pushed a commit to rgbj/docker-maven-plugin that referenced this issue Jun 21, 2017
@rhuss
Add multiline log matching
87a4028 
This is related to fabric8io#628 and fabric8io#608 and should fix both issues.

Also, some refactoring has been performed for the wait checkers which were extracted into an extra package.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@rhuss @liufuyang @michael-simons