Spring Boot Application shuts down if database is not available during runtime (Resolved))

Camunda 7 Topics Discussion & Questions
1

Hi,
we run camunda with spring boot starter and a postgres db.
I observed already 2 times, if the database is away during runtime, the application is shut down.

But nobody called kill or anything so I am curios:

  • which part of application is initiating the shut down?
  • maybe the HikariPool if it can not get a connection in a certain time? (~ 20 minutes between first errors and shut down)

[JobExecutor[org.camunda.bpm.engine.spring.components.jobexecutor.SpringJobExecutor]] WARN org.postgresql.jdbc.PgConnection - Validating connection. org.postgresql.util.PSQLException: FATAL: terminating connection due to administrator command at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2412) at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2125) at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:297) 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.executeUpdate(PgPreparedStatement.java:136) at org.postgresql.jdbc.PgConnection.isValid(PgConnection.java:1306) at com.zaxxer.hikari.pool.PoolBase.isConnectionAlive(PoolBase.java:150) at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:172) at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:148) at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) at ...org.camunda.bpm.engine.impl.jobexecutor.SequentialJobAcquisitionRunnable.run(SequentialJobAcquisitionRunnable.java:60) at java.lang.Thread.run(Thread.java:748) Mar 17 02:21:42.375 [HikariPool-1 connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@33d0bae: (connection is dead) Mar 17 02:21:42.376 [JobExecutor[org.camunda.bpm.engine.spring.components.jobexecutor.SpringJobExecutor]] WARN org.postgresql.jdbc.PgConnection - Validating connection. org.postgresql.util.PSQLException: FATAL: terminating connection due to administrator command

    ...
    ...

    	
    Mar 17 02:43:00.903 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Cannot acquire connection from data source
    org.postgresql.util.PSQLException: Connection to 10.10.10.10:5432 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
            at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:265)
            at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:49)
            at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:194)
            at org.postgresql.Driver.makeConnection(Driver.java:431)
            at org.postgresql.Driver.connect(Driver.java:247)
            at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:117)
            at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:123)
            at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:365)
            at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:194)
            at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:460)
            at com.zaxxer.hikari.pool.HikariPool.access$100(HikariPool.java:71)
            at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:699)
            at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:685)
            at java.util.concurrent.FutureTask.run(FutureTask.java:266)
            at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
            at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
            at java.lang.Thread.run(Thread.java:748)
    Caused by: java.net.ConnectException: Connection refused (Connection refused)
            at java.net.PlainSocketImpl.socketConnect(Native Method)
            at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
            at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
            at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
            at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
            at java.net.Socket.connect(Socket.java:589)
            at org.postgresql.core.PGStream.<init>(PGStream.java:62)
            at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:144)
            ... 16 common frames omitted
    Mar 17 02:43:01.194 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=1, active=1, idle=0, waiting=1)
    Mar 17 02:43:11.119 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@4b4a55a5
    Mar 17 02:43:11.119 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After adding stats (total=2, active=2, idle=0, waiting=0)
    Mar 17 02:43:11.124 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@458db2bc
    Mar 17 02:43:11.127 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@41b23ed5
    Mar 17 02:43:11.127 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After adding stats (total=4, active=2, idle=2, waiting=0)
    Mar 17 02:43:11.130 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@4b0b887
    Mar 17 02:43:11.130 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After adding stats (total=5, active=2, idle=3, waiting=0)
    Mar 17 02:43:11.133 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@1dce22c9
    Mar 17 02:43:11.133 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After adding stats (total=6, active=2, idle=4, waiting=0)
    Mar 17 02:43:11.136 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@35fe7b9e
    Mar 17 02:43:11.136 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After adding stats (total=7, active=2, idle=5, waiting=0)
    Mar 17 02:43:11.139 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@656abf62
    Mar 17 02:43:11.139 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After adding stats (total=8, active=2, idle=6, waiting=0)
    Mar 17 02:43:11.143 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@649f47c8
    Mar 17 02:43:11.143 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After adding stats (total=9, active=2, idle=7, waiting=0)
    Mar 17 02:43:11.145 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@8abe9f8
    Mar 17 02:43:11.145 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After adding stats (total=10, active=2, idle=8, waiting=0)
    Mar 17 02:43:18.909 [pool-1-thread-1] INFO  c.a.s.c.s.s.m.r.PollInboxService - Parsing: 0 messages
    Mar 17 02:43:31.194 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0)
    Mar 17 02:44:01.195 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0)
    Mar 17 02:44:18.965 [pool-1-thread-1] INFO  c.a.s.c.s.s.m.r.PollInboxService - Parsing: 0 messages
    Mar 17 02:44:31.195 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0)
    Mar 17 02:44:55.684 [Thread-4] INFO  o.s.b.w.s.c.AnnotationConfigServletWebServerApplicationContext - Closing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@1ed4004b: startup date [Tue Feb 26 10:50:42 CET 2019]; root of context hierarchy
    Mar 17 02:44:56.826 [Thread-4] INFO  org.camunda.bpm.container - ENGINE-08051 Process application null undeployed
    Mar 17 02:44:56.829 [Thread-4] INFO  o.s.j.e.a.AnnotationMBeanExporter - Unregistering JMX-exposed beans on shutdown
    Mar 17 02:44:56.830 [Thread-4] INFO  o.s.j.e.a.AnnotationMBeanExporter - Unregistering JMX-exposed beans
    Mar 17 02:44:56.832 [Thread-4] INFO  o.s.jdbc.datasource.init.ScriptUtils - Executing SQL script from class path resource [dropView.sql]
    Mar 17 02:44:57.035 [Thread-4] INFO  o.s.jdbc.datasource.init.ScriptUtils - Executed SQL script from class path resource [dropView.sql] in 203 ms.
    Mar 17 02:44:57.036 [Thread-4] INFO  org.camunda.bpm.engine.jobexecutor - ENGINE-14015 Shutting down the JobExecutor[org.camunda.bpm.engine.spring.components.jobexecutor.SpringJobExecutor]
    Mar 17 02:44:57.036 [JobExecutor[org.camunda.bpm.engine.spring.components.jobexecutor.SpringJobExecutor]] INFO  org.camunda.bpm.engine.jobexecutor - ENGINE-14020 JobExecutor[org.camunda.bpm.engine.spring.components.jobexecutor.SpringJobExecutor] stopped job acquisition
    Mar 17 02:44:57.040 [Thread-4] INFO  org.camunda.bpm.engine - ENGINE-00007 Process Engine default closed
    Mar 17 02:44:57.040 [Thread-4] INFO  o.s.s.c.ThreadPoolTaskExecutor - Shutting down ExecutorService 'camundaTaskExecutor'
    Mar 17 02:44:57.041 [Thread-4] INFO  o.s.o.j.LocalContainerEntityManagerFactoryBean - Closing JPA EntityManagerFactory for persistence unit 'default'
    Mar 17 02:44:57.042 [Thread-4] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown initiated...
    Mar 17 02:44:57.042 [Thread-4] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Before shutdown stats (total=10, active=2, idle=8, waiting=0)
    Mar 17 02:44:57.045 [HikariPool-1 connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@458db2bc: (connection evicted)
    Mar 17 02:44:57.045 [HikariPool-1 connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@41b23ed5: (connection evicted)
    Mar 17 02:44:57.046 [HikariPool-1 connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@4b0b887: (connection evicted)
    Mar 17 02:44:57.046 [HikariPool-1 connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@1dce22c9: (connection evicted)
    Mar 17 02:44:57.047 [HikariPool-1 connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@35fe7b9e: (connection evicted)
    Mar 17 02:44:57.048 [HikariPool-1 connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@656abf62: (connection evicted)
    Mar 17 02:44:57.048 [HikariPool-1 connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@649f47c8: (connection evicted)
    Mar 17 02:44:57.049 [HikariPool-1 connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@8abe9f8: (connection evicted)
    Mar 17 02:44:57.050 [Thread-4] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After shutdown stats (total=0, active=0, idle=0, waiting=0)
    Mar 17 02:44:57.050 [Thread-4] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown completed.

Spring-Boot: (v2.0.6.RELEASE)
Camunda BPM: (v7.9.0)
Camunda BPM Spring Boot Starter: (v3.0.0)

2

Hi @timguy,

Camunda can not be used without a relational Database.

So it is the normal behaviour, that the application shuts down, when the DB is not accessible anymore.

Regards
Michael

3

Sorry everything clarified. Was not only the DB Server which was restarted but also the applications machine itself :sleeping:
Anyway - if an application runs and the database is away - my expectation is, yes it can produce a lot of error logs and try again and again but it should never shut down and give up.

Thanks anyway

4

Hi @timguy,

indeed, with the correct configuration of the connection pool, this is possible. Try the testOnBorrow property of the connection pool. Default is false.

Hope this helps, Ingo

1 Like
5

thanks, application continues as expected - even with db outage. The shutdown really came only because of machine shutdown. As db machine was restarted as well it looked like the cause for the issue.

There is no testOnBorrow with Hikari Pool (https://stackoverflow.com/questions/53870473/hikari-and-test-on-borrow-option) but as described also not needed.
Thanks