I’m trying to confirm the correct connection string for a remote postgres server that’s served over TLS using a non-standard port. This is what I have:
I’m having trouble starting the server but wanted to rule the connection string out
Below is the tomcat log at startup:
09-Nov-2022 14:42:01.844 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deploying web application archive [/home/dhis/tomcat-dhis/webapps/ROOT.war]
* INFO 2022-11-09T15:45:13,610 System property dhis2.home not set (LogOnceLogger.java [localhost-startStop-1])
* INFO 2022-11-09T15:45:13,633 Environment variable DHIS2_HOME not set (LogOnceLogger.java [localhost-startStop-1])
* INFO 2022-11-09T15:45:13,634 Directory /opt/dhis2 cannot be created (LogOnceLogger.java [localhost-startStop-1])
09-Nov-2022 14:42:20.375 SEVERE [localhost-startStop-1] org.apache.catalina.core.ContainerBase.addChildInternal ContainerBase.addChild: start:
org.apache.catalina.LifecycleException: Failed to start component [StandardEngine[Catalina].StandardHost[localhost].StandardContext[]]
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:167)
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:754)
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:730)
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:734)
at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:980)
at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1852)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.lang.IllegalStateException: Properties could not be loaded
at org.hisp.dhis.external.conf.DefaultDhisConfigurationProvider.loadDhisConf(DefaultDhisConfigurationProvider.java:344)
at org.hisp.dhis.external.conf.DefaultDhisConfigurationProvider.init(DefaultDhisConfigurationProvider.java:114)
at org.hisp.dhis.webapi.servlet.DhisWebApiWebAppInitializer.getConfig(DhisWebApiWebAppInitializer.java:119)
at org.hisp.dhis.webapi.servlet.DhisWebApiWebAppInitializer.onStartup(DhisWebApiWebAppInitializer.java:62)
at org.springframework.web.SpringServletContainerInitializer.onStartup(SpringServletContainerInitializer.java:174)
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5225)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
... 10 more
Caused by: org.hisp.dhis.external.location.LocationManagerException: External directory not set
at org.hisp.dhis.external.location.DefaultLocationManager.buildDirectory(DefaultLocationManager.java:243)
at org.hisp.dhis.external.location.DefaultLocationManager.getFileForReading(DefaultLocationManager.java:173)
at org.hisp.dhis.external.location.DefaultLocationManager.getInputStream(DefaultLocationManager.java:146)
at org.hisp.dhis.external.location.DefaultLocationManager.getInputStream(DefaultLocationManager.java:139)
at org.hisp.dhis.external.conf.DefaultDhisConfigurationProvider.loadDhisConf(DefaultDhisConfigurationProvider.java:333)
... 16 more
09-Nov-2022 14:42:20.378 SEVERE [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Error deploying web application archive [/home/dhis/tomcat-dhis/webapps/ROOT.war]
java.lang.IllegalStateException: ContainerBase.addChild: start: org.apache.catalina.LifecycleException: Failed to start component [StandardEngine[Catalina].StandardHost[localhost].StandardContext[]]
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:758)
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:730)
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:734)
at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:980)
at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1852)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
09-Nov-2022 14:42:20.379 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/home/dhis/tomcat-dhis/webapps/ROOT.war] has finished in [18,535] ms
OK, some notes - there were two things that weren’t as they should be
firstly the DHIS2_HOME variable wasn’t being picked up despite it being added to bin/setenv.sh. I had to open shell as the dhis user, manually set the DHIS2_HOME environment using export and then run the startup.sh script.
secondly (and I may have seen this before), but the permissions appeared to be properly set on the /home/dhis/config/ directory when doing an ls -l as root, but when doing the same as the dhis user, it was showing this:
-??? ? ? ? ? ? dhis.conf
d??? ? ? ? ? ? files
I recreated the config file and the files directory as the dhis user and they seem to be working again, though why the DHIS2_HOME variable is not being read from bin/setenv.sh when starting tomcat I have no idea. I’m following a vanilla install from here: Installation - DHIS2 Documentation
One random guess: in the dhis2 installation document, somehow export was missing when they mentioned, could that be a reason in your case. I did encounter such an issue before
Notice - no export in the beginning
JAVA_HOME='/usr/lib/jvm/java-11-openjdk-amd64/'
JAVA_OPTS='-Xms4000m -Xmx7000m'
DHIS2_HOME='/home/dhis/config'```
Spot on Jins… always the small things! I’ll add it to Jira.
That explains the variable issue, though I think there’s still an issue with the connection string. Now I’m getting this:
* INFO 2022-11-10T12:53:34,272 Hibernate configuration loaded: dialect: 'org.hisp.dhis.hibernate.dialect.DhisPostgresDialect', region factory: 'org.hibernate.cache.ehcache.EhCacheRegionFactory', connection pool max size: null (DefaultHibernateConfigurationProvider.java [localhost-startStop-1])
* WARN 2022-11-10T12:54:05,731 com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@3b7d4aa6 -- Acquisition Attempt Failed!!! Clearing pending acquires. While trying to acquire a needed new resource, we failed to succeed more than the maximum number of allowed acquisition attempts (30). Last acquisition attempt exception: (Slf4jMLog.java [C3P0PooledConnectionPoolManager[identityToken->z8kfsxasqyn2p2exdtbc|113bff40]-HelperThread-#0])
org.postgresql.util.PSQLException: Could not open SSL root certificate file /home/dhis/.postgresql/root.crt.
at org.postgresql.ssl.LibPQFactory.<init>(LibPQFactory.java:156) ~[postgresql-42.2.19.jar:42.2.19]
at org.postgresql.core.SocketFactoryFactory.getSslSocketFactory(SocketFactoryFactory.java:61) ~[postgresql-42.2.19.jar:42.2.19]
at org.postgresql.ssl.MakeSSL.convert(MakeSSL.java:34) ~[postgresql-42.2.19.jar:42.2.19]
at org.postgresql.core.v3.ConnectionFactoryImpl.enableSSL(ConnectionFactoryImpl.java:534) ~[postgresql-42.2.19.jar:42.2.19]
at org.postgresql.core.v3.ConnectionFactoryImpl.tryConnect(ConnectionFactoryImpl.java:149) ~[postgresql-42.2.19.jar:42.2.19]
at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:213) ~[postgresql-42.2.19.jar:42.2.19]
at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:51) ~[postgresql-42.2.19.jar:42.2.19]
at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:223) ~[postgresql-42.2.19.jar:42.2.19]
at org.postgresql.Driver.makeConnection(Driver.java:465) ~[postgresql-42.2.19.jar:42.2.19]
at org.postgresql.Driver.connect(Driver.java:264) ~[postgresql-42.2.19.jar:42.2.19]
at com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:175) ~[c3p0-0.9.5.5.jar:0.9.5.5]
at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:220) ~[c3p0-0.9.5.5.jar:0.9.5.5]
at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:206) ~[c3p0-0.9.5.5.jar:0.9.5.5]
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:203) ~[c3p0-0.9.5.5.jar:0.9.5.5]
at com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1176) ~[c3p0-0.9.5.5.jar:0.9.5.5]
at com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1163) ~[c3p0-0.9.5.5.jar:0.9.5.5]
at com.mchange.v2.resourcepool.BasicResourcePool.access$700(BasicResourcePool.java:44) ~[c3p0-0.9.5.5.jar:0.9.5.5]
at com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1908) [c3p0-0.9.5.5.jar:0.9.5.5]
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696) [mchange-commons-java-0.2.19.jar:0.2.19]
Caused by: java.io.FileNotFoundException: /home/dhis/.postgresql/root.crt (No such file or directory)
at java.io.FileInputStream.open0(Native Method) ~[?:?]
at java.io.FileInputStream.open(FileInputStream.java:219) ~[?:?]
at java.io.FileInputStream.<init>(FileInputStream.java:157) ~[?:?]
at java.io.FileInputStream.<init>(FileInputStream.java:112) ~[?:?]
at org.postgresql.ssl.LibPQFactory.<init>(LibPQFactory.java:153) ~[postgresql-42.2.19.jar:42.2.19]
... 18 more
* WARN 2022-11-10T12:54:05,747 Having failed to acquire a resource, com.mchange.v2.resourcepool.BasicResourcePool@3004e0a5 is interrupting all Threads waiting on a resource to check out. Will try again in response to new client requests. (Slf4jMLog.java [C3P0PooledConnectionPoolManager[identityToken->z8kfsxasqyn2p2exdtbc|113bff40]-HelperThread-#0])
* WARN 2022-11-10T12:54:05,728 com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@3ecf3d3f -- Acquisition Attempt Failed!!! Clearing pending acquires. While trying to acquire a needed new resource, we failed to succeed more than the maximum number of allowed acquisition attempts (30). Last acquisition attempt exception: (Slf4jMLog.java [C3P0PooledConnectionPoolManager[identityToken->z8kfsxasqyn2p2exdtbc|113bff40]-HelperThread-#1])
org.postgresql.util.PSQLException: Could not open SSL root certificate file /home/dhis/.postgresql/root.crt.
So there’s a certificate issue I need to look into - given it’s the first time I’ve connected to a remote SQL server using TLS, I’ll be googling a bit.
Thanks for the help!
I have ?ssl=true on the connection string but have not tried sslmode=require
I’ll try that some time today and revert, thanks @Jason
I suspect I just need to get the certificate from the PSQL server side and incorporate it to the tomcat machine but I’ll confirm soon.
EDIT Spot on @jason you’re a legend. I had no idea I could use it in the connection string like that. Problem solved!
…that said I will incorporate the server certificate to mitigate potential MITM
