Monday, May 7, 2018

[google-cloud-sql-discuss] Enabling "Allow only SSL connection" option causes connection problem between SSL-configured Spring application and GC SQL instance

Hello,

I have Spring application which is running on Tomcat(7.0.68) at my local machine that uses Google Cloud SQL instance. Also I am using C3P0(0.9.1.2) as a connection pool. You can find a part of the DAOcontext.xml file and CATALINA_OPTS: 

.....
<bean id="dataSource" class="com.mchange.v2.c3p0.ComboPooledDataSource">
            <property name="driverClass" value="com.mysql.jdbc.Driver"/>
            <property name="jdbcUrl" value="jdbc:mysql://sql_instance_ip:3306/table_name?verifyServerCertificate=true&useSSL=true&requireSSL=true&trustCertificateKeyStoreUrl=file:/path/to/trustStore.jks&trustCertificateKeyStorePassword=****&characterEncoding=UTF-8&useUnicode=true&autoReconnect=true&useServerPrepStmts=false&rewriteBatchedStatements=true&failOverReadOnly=false&zeroDateTimeBehavior=convertToNull"/>
            <property name="user" value="***"/>
            <property name="password" value="****"/>
            <property name="acquireIncrement" value="1"/>
            <property name="initialPoolSize" value="1"/>
            <property name="minPoolSize" value="1"/>
            <property name="maxPoolSize" value="5"/>
            <property name="maxIdleTime" value="120"/>
</bean>
.....

CATALINA_OPTS="... -Djavax.net.ssl.keyStore=/path/to/keyStore.jks -Djavax.net.ssl.keyStorePassword=**** ..."
Kodu buraya girin...


These key stores are created from my SQL instance's certificate.
https://cloud.google.com/sql/docs/mysql/configure-ssl-instance 

When I disable "Allow only SSL connection" option from dashboard, my application runs without any DB connection problem. Also when I check connection between my application and SQL instance via WireShark, I see that packets are SSL encrypted. 


When I enable this option, my tomcat application gives these errors:

May 07, 2018 5:02:49 PM com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource getPoolManager
INFO: Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 1, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, dataSourceName -> ****, debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> com.mysql.jdbc.Driver, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> ****, idleConnectionTestPeriod -> 0, initialPoolSize -> 1, jdbcUrl -> jdbc:mysql://sql_instance_ip:3306/table_name?verifyServerCertificate=true&useSSL=true&requireSSL=true&trustCertificateKeyStoreUrl=file:/path/to/trustStore.jks&trustCertificateKeyStorePassword=****&characterEncoding=UTF-8&useUnicode=true&autoReconnect=true&useServerPrepStmts=false&rewriteBatchedStatements=true&failOverReadOnly=false&zeroDateTimeBehavior=convertToNull"/, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 120, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 5, maxStatements -> 0, maxStatementsPerConnection -> 0, minPoolSize -> 1, numHelperThreads -> 3, numThreadsAwaitingCheckoutDefaultUser -> 0, preferredTestQuery -> null, properties -> {user=******, password=******}, propertyCycle -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false ]
May 07, 2018 5:03:09 PM com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector run
WARNING: com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@274517d0 -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks!
May 07, 2018 5:03:09 PM com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector run
WARNING: com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@274517d0 -- APPARENT DEADLOCK!!! Complete Status:
Managed Threads: 3
Active Threads: 3
Active Tasks:
com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@68bff773 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1)
com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@67cb9623 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2)
com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@599d5f2f (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0)
Pending Tasks:
com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@1f0360c0
com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@890083c
Pool thread stack traces:
Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1,5,main]
java.lang.Thread.sleep(Native Method)
com.mysql.jdbc.ConnectionImpl.connectWithRetries(ConnectionImpl.java:2376)
com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2306)
com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:834)
com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:47)
sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
java.lang.reflect.Constructor.newInstance(Constructor.java:423)
com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:416)
com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:346)
com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:134)
com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:182)
com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:171)
com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:137)
com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1014)
com.mchange.v2.resourcepool.BasicResourcePool.access$800(BasicResourcePool.java:32)
com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask.run(BasicResourcePool.java:1810)
com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)
Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0,5,main]
java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
java.net.SocketInputStream.read(SocketInputStream.java:171)
java.net.SocketInputStream.read(SocketInputStream.java:141)
com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3116)
com.mysql.jdbc.MysqlIO.readPacket(MysqlIO.java:599)
com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:1086)
com.mysql.jdbc.ConnectionImpl.coreConnect(ConnectionImpl.java:2483)
com.mysql.jdbc.ConnectionImpl.connectWithRetries(ConnectionImpl.java:2324)
com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2306)
com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:834)
com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:47)
sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
java.lang.reflect.Constructor.newInstance(Constructor.java:423)
com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:416)
com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:346)
com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:134)
com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:182)
com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:171)
com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:137)
com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1014)
com.mchange.v2.resourcepool.BasicResourcePool.access$800(BasicResourcePool.java:32)
com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask.run(BasicResourcePool.java:1810)
com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)
Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2,5,main]
java.lang.Thread.sleep(Native Method)
com.mysql.jdbc.ConnectionImpl.connectWithRetries(ConnectionImpl.java:2376)
com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2306)
com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:834)
com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:47)
sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
java.lang.reflect.Constructor.newInstance(Constructor.java:423)
com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:416)
com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:346)
com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:134)
com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:182)
com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:171)
com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:137)
com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1014)
com.mchange.v2.resourcepool.BasicResourcePool.access$800(BasicResourcePool.java:32)
com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask.run(BasicResourcePool.java:1810)
com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)


May 07, 2018 5:04:09 PM com.mchange.v2.async.ThreadPoolAsynchronousRunner processReplacedThreads
WARNING: Task com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@68bff773 (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().
May 07, 2018 5:04:09 PM com.mchange.v2.async.ThreadPoolAsynchronousRunner processReplacedThreads
WARNING: Task com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@599d5f2f (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().
May 07, 2018 5:04:09 PM com.mchange.v2.async.ThreadPoolAsynchronousRunner processReplacedThreads

These error logs are not specific to this issue but they are similar to those I got when my application are not able to connect DB. Do you have any idea or advice about this issue? Is there anyone who use similar setup and encountered this problem?

Any kind of help and suggestion is highly appreciated! 

Thanks in advance.

--
You received this message because you are subscribed to the Google Groups "Google Cloud SQL discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-cloud-sql-discuss+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/google-cloud-sql-discuss/f93a832e-c614-4863-bf3d-85435b1ccd7d%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

No comments:

Post a Comment