search

GoogleCloudPlatform / cloud-sql-jdbc-socket-factory

A collection of Java libraries for connecting securely to Cloud SQL
Apache License 2.0
234 stars 119 forks source link

Postgres IAM Authentication is flaky: "org.postgresql.util.PSQLException: The connection attempt failed." #565

Closed ghost closed 3 years ago

ghost commented 3 years ago

Describe the issue It seems the connection is closed because of authentication issue. JDBC establishes connection to SQL (for example: jdbc:postgresql:///test?cloudSqlInstance=CONNECTION_NAME&socketFactory=com.google.cloud.sql.postgres.SocketFactory), authorization passes through IAM (using service account key). Initial Pool Size is 10.

We updated PostgresSQL JDBC Driver and GCP dependencies to current versions, but it didn't solve the problem. We tried to downgrade our application, but the problem remains.

We don’t have egress firewall rules. In GCP PostgreSQL/IAM/VPC flow logs we do not find errors regarding the problem.

JDBC Driver Version? Reproduced on 42.2.18 and 42.2.23 JDBC 42

OS Version? Debian Buster (coming from Docker image tomcat:jdk11-openjdk-slim)

Java Version? Java 11 OpenJDK (coming from Docker image tomcat:jdk11-openjdk-slim)

PostgreSQL Version? We use GCP PostgreSQL 13.

To Reproduce: While connecting to DB sometimes we receive failure approximately every tenth startup or reboot. We cannot reproduce issue with built-in authentication (using username/password).

Stacktrace (successful attempt):

Jul 26, 2021 12:27:55 AM org.postgresql.Driver connect FINE: Connecting with URL: jdbc:postgresql:///test?cloudSqlInstance=CONNECTION_NAME&socketFactory=com.google.cloud.sql.postgres.SocketFactory&loggerLevel=TRACE&loggerFile=/usr/local/tomcat/logs/pgjdbc-trace.log Jul 26, 2021 12:27:55 AM org.postgresql.jdbc.PgConnection FINE: PostgreSQL JDBC Driver 42.2.18 Jul 26, 2021 12:27:55 AM org.postgresql.jdbc.PgConnection setDefaultFetchSize FINE: setDefaultFetchSize = 0 Jul 26, 2021 12:27:55 AM org.postgresql.jdbc.PgConnection setPrepareThreshold FINE: setPrepareThreshold = 5 Jul 26, 2021 12:27:55 AM org.postgresql.core.v3.ConnectionFactoryImpl openConnectionImpl FINE: Trying to establish a protocol version 3 connection to :5432 Jul 26, 2021 12:27:58 AM org.postgresql.core.Encoding FINEST: Creating new Encoding UTF-8 with fastASCIINumbers true Jul 26, 2021 12:27:58 AM org.postgresql.core.Encoding FINEST: Creating new Encoding UTF-8 with fastASCIINumbers true Jul 26, 2021 12:27:58 AM org.postgresql.core.Encoding FINEST: Creating new Encoding UTF-8 with fastASCIINumbers true Jul 26, 2021 12:27:58 AM org.postgresql.core.v3.ConnectionFactoryImpl tryConnect FINE: Receive Buffer Size is 65,536 Jul 26, 2021 12:27:58 AM org.postgresql.core.v3.ConnectionFactoryImpl tryConnect FINE: Send Buffer Size is 23,040 Jul 26, 2021 12:27:58 AM org.postgresql.core.v3.ConnectionFactoryImpl enableSSL FINEST: FE=> SSLRequest Jul 26, 2021 12:27:58 AM org.postgresql.core.v3.ConnectionFactoryImpl enableSSL FINEST: <=BE SSLRefused Jul 26, 2021 12:27:58 AM org.postgresql.core.v3.ConnectionFactoryImpl sendStartupPacket FINEST: FE=> StartupPacket(user=psql-test@PROJECT-ID.iam, database=test, client_encoding=UTF8, DateStyle=ISO, TimeZone=Europe, extra_float_digits=2) Jul 26, 2021 12:27:58 AM org.postgresql.core.v3.ConnectionFactoryImpl doAuthentication FINEST: <=BE AuthenticationReqPassword Jul 26, 2021 12:27:58 AM org.postgresql.core.v3.ConnectionFactoryImpl doAuthentication FINEST: FE=> Password(password=) Jul 26, 2021 12:27:58 AM org.postgresql.core.v3.ConnectionFactoryImpl doAuthentication FINEST: <=BE AuthenticationOk Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveParameterStatus FINEST: <=BE ParameterStatus(application_name = ) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveParameterStatus FINEST: <=BE ParameterStatus(client_encoding = UTF8) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveParameterStatus FINEST: <=BE ParameterStatus(DateStyle = ISO, MDY) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveParameterStatus FINEST: <=BE ParameterStatus(integer_datetimes = on) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveParameterStatus FINEST: <=BE ParameterStatus(IntervalStyle = postgres) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveParameterStatus FINEST: <=BE ParameterStatus(is_superuser = off) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveParameterStatus FINEST: <=BE ParameterStatus(server_encoding = UTF8) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveParameterStatus FINEST: <=BE ParameterStatus(server_version = 13.2) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveParameterStatus FINEST: <=BE ParameterStatus(session_authorization = psql-test@PROJECT-ID.iam) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveParameterStatus FINEST: <=BE ParameterStatus(standard_conforming_strings = on) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveParameterStatus FINEST: <=BE ParameterStatus(TimeZone = Europe) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl readStartupMessages FINEST: <=BE BackendKeyData(pid=1,143,ckey=-808,165,441) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveRFQ FINEST: <=BE ReadyForQuery(I) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl execute FINEST: simple execute, handler=org.postgresql.core.SetupQueryRunner$SimpleResultHandler@d032512, maxRows=0, fetchSize=0, flags=1,047 Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl sendParse FINEST: FE=> Parse(stmt=null,query="SET extra_float_digits = 3",oids={}) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl sendBind FINEST: FE=> Bind(stmt=null,portal=null) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl sendExecute FINEST: FE=> Execute(portal=null,limit=1) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl sendSync FINEST: FE=> Sync Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl processResults FINEST: <=BE ParseComplete [null] Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl processResults FINEST: <=BE BindComplete [unnamed] Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveCommandStatus FINEST: <=BE CommandStatus(SET) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveRFQ FINEST: <=BE ReadyForQuery(I) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl execute FINEST: simple execute, handler=org.postgresql.core.SetupQueryRunner$SimpleResultHandler@39eba9c4, maxRows=0, fetchSize=0, flags=1,047 Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl sendParse FINEST: FE=> Parse(stmt=null,query="SET application_name = 'PostgreSQL JDBC Driver'",oids={}) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl sendBind FINEST: FE=> Bind(stmt=null,portal=null) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl sendExecute FINEST: FE=> Execute(portal=null,limit=1) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl sendSync FINEST: FE=> Sync Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl processResults FINEST: <=BE ParseComplete [null] Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl processResults FINEST: <=BE BindComplete [unnamed] Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveParameterStatus FINEST: <=BE ParameterStatus(application_name = PostgreSQL JDBC Driver) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveCommandStatus FINEST: <=BE CommandStatus(SET) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveRFQ FINEST: <=BE ReadyForQuery(I) Jul 26, 2021 12:27:59 AM org.postgresql.jdbc.PgConnection FINEST: types using binary send = TIMESTAMPTZ,OID_ARRAY,UUID,BYTEA_ARRAY,INT2_ARRAY,INT4_ARRAY,BYTEA,TEXT_ARRAY,TIMETZ,INT8,INT2,INT4,VARCHAR_ARRAY,INT8_ARRAY,POINT,TIMESTAMP,TIME,BOX,FLOAT4,FLOAT8,FLOAT4_ARRAY,FLOAT8_ARRAY Jul 26, 2021 12:27:59 AM org.postgresql.jdbc.PgConnection FINEST: types using binary receive = TIMESTAMPTZ,OID_ARRAY,UUID,BYTEA_ARRAY,INT2_ARRAY,INT4_ARRAY,BYTEA,TEXT_ARRAY,TIMETZ,INT8,INT2,INT4,VARCHAR_ARRAY,INT8_ARRAY,POINT,DATE,TIMESTAMP,TIME,BOX,FLOAT4,FLOAT8,FLOAT4_ARRAY,FLOAT8_ARRAY Jul 26, 2021 12:27:59 AM org.postgresql.jdbc.PgConnection FINEST: integer date/time = true Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl execute FINEST: simple execute, handler=org.postgresql.jdbc.PgStatement$StatementResultHandler@729b432b, maxRows=0, fetchSize=0, flags=17 Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl sendParse FINEST: FE=> Parse(stmt=null,query="select 1",oids={}) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl sendBind FINEST: FE=> Bind(stmt=null,portal=null) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl sendDescribePortal FINEST: FE=> Describe(portal=null) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl sendExecute FINEST: FE=> Execute(portal=null,limit=0) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl sendSync FINEST: FE=> Sync Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl processResults FINEST: <=BE ParseComplete [null] Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl processResults FINEST: <=BE BindComplete [unnamed] Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveFields FINEST: <=BE RowDescription(1) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveFields FINEST: Field(?column?,INT4,4,T) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl processResults FINEST: <=BE DataRow(len=1) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveCommandStatus FINEST: <=BE CommandStatus(SELECT 1) Jul 26, 2021 12:27:59 AM org.postgresql.core.v3.QueryExecutorImpl receiveRFQ FINEST: <=BE ReadyForQuery(I) Jul 26, 2021 12:27:59 AM org.postgresql.core.QueryExecutorBase close FINEST: FE=> Terminates ... ...

Stacktrace (unsuccessful attempt):

Jul 26, 2021 1:40:56 AM org.postgresql.Driver connect FINE: Connecting with URL: jdbc:postgresql:///test?cloudSqlInstance=CONNECTION_NAME&socketFactory=com.google.cloud.sql.postgres.SocketFactory&loggerLevel=TRACE&loggerFile=/usr/local/tomcat/logs/pgjdbc-trace.log Jul 26, 2021 1:40:56 AM org.postgresql.jdbc.PgConnection FINE: PostgreSQL JDBC Driver 42.2.18 Jul 26, 2021 1:40:56 AM org.postgresql.jdbc.PgConnection setDefaultFetchSize FINE: setDefaultFetchSize = 0 Jul 26, 2021 1:40:56 AM org.postgresql.jdbc.PgConnection setPrepareThreshold FINE: setPrepareThreshold = 5 Jul 26, 2021 1:40:56 AM org.postgresql.core.v3.ConnectionFactoryImpl openConnectionImpl FINE: Trying to establish a protocol version 3 connection to :5432 Jul 26, 2021 1:40:58 AM org.postgresql.core.Encoding FINEST: Creating new Encoding UTF-8 with fastASCIINumbers true Jul 26, 2021 1:40:58 AM org.postgresql.core.Encoding FINEST: Creating new Encoding UTF-8 with fastASCIINumbers true Jul 26, 2021 1:40:58 AM org.postgresql.core.Encoding FINEST: Creating new Encoding UTF-8 with fastASCIINumbers true Jul 26, 2021 1:40:58 AM org.postgresql.core.v3.ConnectionFactoryImpl tryConnect FINE: Receive Buffer Size is 65,536 Jul 26, 2021 1:40:58 AM org.postgresql.core.v3.ConnectionFactoryImpl tryConnect FINE: Send Buffer Size is 23,040 Jul 26, 2021 1:40:58 AM org.postgresql.core.v3.ConnectionFactoryImpl enableSSL FINEST: FE=> SSLRequest Jul 26, 2021 1:40:58 AM org.postgresql.core.v3.ConnectionFactoryImpl enableSSL FINEST: <=BE SSLRefused Jul 26, 2021 1:40:58 AM org.postgresql.core.v3.ConnectionFactoryImpl sendStartupPacket FINEST: FE=> StartupPacket(user=psql-test@PROJECT-ID.iam, database=test, client_encoding=UTF8, DateStyle=ISO, TimeZone=Europe, extra_float_digits=2) Jul 26, 2021 1:40:58 AM org.postgresql.core.v3.ConnectionFactoryImpl doAuthentication FINEST: <=BE AuthenticationReqPassword Jul 26, 2021 1:40:58 AM org.postgresql.core.v3.ConnectionFactoryImpl doAuthentication FINEST: FE=> Password(password=) Jul 26, 2021 1:40:58 AM org.postgresql.Driver connect FINE: Connection error: org.postgresql.util.PSQLException: The connection attempt failed. at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:315) at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:51) at org.postgresql.jdbc.PgConnection.(PgConnection.java:225) at org.postgresql.Driver.makeConnection(Driver.java:465) at org.postgresql.Driver.connect(Driver.java:264) at org.leaframework.hibernate.BasicDataSource$GoogleDriverConnectionFactory.createConnection(BasicDataSource.java:267) at org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:294) at org.leaframework.hibernate.BasicDataSource.validateConnectionFactory(BasicDataSource.java:278) at org.leaframework.hibernate.BasicDataSource.createDataSource(BasicDataSource.java:185) at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880) at org.leaframework.hibernate.BasicDataSource.getConnection(BasicDataSource.java:61) at org.leaframework.hibernate.MultitenantDataSource.getConnection(MultitenantDataSource.java:270) at org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:82) at org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:84) at org.hibernate.cfg.Configuration.buildSettings(Configuration.java:2073) at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1298) at org.leaframework.context.LeafHibernateConfiguration.buildSessionFactory(LeafHibernateConfiguration.java:716) at org.springframework.orm.hibernate3.LocalSessionFactoryBean.newSessionFactory(LocalSessionFactoryBean.java:799) at org.leaframework.context.LeafSessionFactoryBean.newSessionFactory(LeafSessionFactoryBean.java:304) at org.leaframework.context.LeafSessionFactoryBean.newSessionFactory(LeafSessionFactoryBean.java:68) at org.springframework.orm.hibernate3.LocalSessionFactoryBean.buildSessionFactory(LocalSessionFactoryBean.java:733) at org.springframework.orm.hibernate3.AbstractSessionFactoryBean.afterPropertiesSet(AbstractSessionFactoryBean.java:211) at org.leaframework.context.LeafSessionFactoryBean.afterPropertiesSet(LeafSessionFactoryBean.java:202) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1288) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1257) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:438) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory$1.run(AbstractAutowireCapableBeanFactory.java:383) at java.base/java.security.AccessController.doPrivileged(Native Method) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:353) at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:245) at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:169) at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:242) at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:164) at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBeansOfType(DefaultListableBeanFactory.java:299) at org.springframework.beans.factory.BeanFactoryUtils.beansOfTypeIncludingAncestors(BeanFactoryUtils.java:270) at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.detectPersistenceExceptionTranslators(PersistenceExceptionTranslationInterceptor.java:122) at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.(PersistenceExceptionTranslationInterceptor.java:78) at org.springframework.dao.annotation.PersistenceExceptionTranslationAdvisor.(PersistenceExceptionTranslationAdvisor.java:70) at org.springframework.dao.annotation.PersistenceExceptionTranslationPostProcessor.setBeanFactory(PersistenceExceptionTranslationPostProcessor.java:96) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1248) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:438) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory$1.run(AbstractAutowireCapableBeanFactory.java:383) at java.base/java.security.AccessController.doPrivileged(Native Method) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:353) at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:245) at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:169) at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:242) at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:164) at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:888) at org.springframework.context.support.AbstractApplicationContext.registerBeanPostProcessors(AbstractApplicationContext.java:585) at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:351) at org.springframework.web.context.ContextLoader.createWebApplicationContext(ContextLoader.java:261) at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:199) at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:45) at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4768) at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5230) at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:728) at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:700) at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:696) at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1185) at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:1933) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75) at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:118) at org.apache.catalina.startup.HostConfig.deployDirectories(HostConfig.java:1095) at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:477) at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1618) at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:319) at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123) at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:423) at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:366) at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:948) at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:835) at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1398) at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1388) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75) at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140) at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:921) at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:263) at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) at org.apache.catalina.core.StandardService.startInternal(StandardService.java:437) at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:934) at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) at org.apache.catalina.startup.Catalina.start(Catalina.java:772) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:345) at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:476) Caused by: java.io.EOFException at org.postgresql.core.PGStream.receiveChar(PGStream.java:443) at org.postgresql.core.v3.ConnectionFactoryImpl.doAuthentication(ConnectionFactoryImpl.java:598) at org.postgresql.core.v3.ConnectionFactoryImpl.tryConnect(ConnectionFactoryImpl.java:161) at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:213) ... 94 more

Jul 26, 2021 1:41:54 AM org.postgresql.Driver connect FINE: Connecting with URL: jdbc:postgresql:///test?cloudSqlInstance=CONNECTION_NAME&socketFactory=com.google.cloud.sql.postgres.SocketFactory&loggerLevel=TRACE&loggerFile=/usr/local/tomcat/logs/pgjdbc-trace.log Jul 26, 2021 1:41:54 AM org.postgresql.jdbc.PgConnection FINE: PostgreSQL JDBC Driver 42.2.18 Jul 26, 2021 1:41:54 AM org.postgresql.jdbc.PgConnection setDefaultFetchSize FINE: setDefaultFetchSize = 0 Jul 26, 2021 1:41:54 AM org.postgresql.jdbc.PgConnection setPrepareThreshold FINE: setPrepareThreshold = 5 Jul 26, 2021 1:41:54 AM org.postgresql.core.v3.ConnectionFactoryImpl openConnectionImpl FINE: Trying to establish a protocol version 3 connection to :5432 Jul 26, 2021 1:41:54 AM org.postgresql.core.Encoding FINEST: Creating new Encoding UTF-8 with fastASCIINumbers true Jul 26, 2021 1:41:54 AM org.postgresql.core.Encoding FINEST: Creating new Encoding UTF-8 with fastASCIINumbers true Jul 26, 2021 1:41:54 AM org.postgresql.core.v3.ConnectionFactoryImpl tryConnect FINE: Receive Buffer Size is 65,536 Jul 26, 2021 1:41:54 AM org.postgresql.core.v3.ConnectionFactoryImpl tryConnect FINE: Send Buffer Size is 23,040 Jul 26, 2021 1:41:54 AM org.postgresql.core.v3.ConnectionFactoryImpl enableSSL FINEST: FE=> SSLRequest Jul 26, 2021 1:41:54 AM org.postgresql.core.v3.ConnectionFactoryImpl enableSSL FINEST: <=BE SSLRefused Jul 26, 2021 1:41:54 AM org.postgresql.core.v3.ConnectionFactoryImpl sendStartupPacket FINEST: FE=> StartupPacket(user=psql-test@PROJECT-ID.iam, database=test, client_encoding=UTF8, DateStyle=ISO, TimeZone=Europe, extra_float_digits=2) Jul 26, 2021 1:41:54 AM org.postgresql.core.v3.ConnectionFactoryImpl doAuthentication FINEST: <=BE AuthenticationReqPassword Jul 26, 2021 1:41:54 AM org.postgresql.core.v3.ConnectionFactoryImpl doAuthentication FINEST: FE=> Password(password=) Jul 26, 2021 1:41:54 AM org.postgresql.Driver connect FINE: Connection error: org.postgresql.util.PSQLException: The connection attempt failed. at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:315) at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:51) at org.postgresql.jdbc.PgConnection.(PgConnection.java:225) at org.postgresql.Driver.makeConnection(Driver.java:465) at org.postgresql.Driver.connect(Driver.java:264) at org.leaframework.hibernate.BasicDataSource$GoogleDriverConnectionFactory.createConnection(BasicDataSource.java:267) at org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:294) at org.leaframework.hibernate.BasicDataSource.validateConnectionFactory(BasicDataSource.java:278) at org.leaframework.hibernate.BasicDataSource.createDataSource(BasicDataSource.java:185) at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880) at org.leaframework.hibernate.BasicDataSource.getConnection(BasicDataSource.java:61) at org.leaframework.hibernate.MultitenantDataSource.getConnection(MultitenantDataSource.java:270) at org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:82) at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:423) at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144) at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:119) at org.leaframework.context.LeafFactory.openSession(LeafFactory.java:1579) at org.leaframework.context.LeafFactory.openSession(LeafFactory.java:1523) at org.leaframework.context.LeafFactory.openSession(LeafFactory.java:125) at org.springframework.orm.hibernate3.SessionFactoryUtils.doGetSession(SessionFactoryUtils.java:317) at org.springframework.orm.hibernate3.SessionFactoryUtils.getSession(SessionFactoryUtils.java:233) at org.springframework.orm.hibernate3.HibernateTemplate.getSession(HibernateTemplate.java:424) at org.springframework.orm.hibernate3.HibernateTemplate.execute(HibernateTemplate.java:361) at org.springframework.orm.hibernate3.HibernateTemplate.execute(HibernateTemplate.java:338) at org.leaframework.context.LeafSessionFactoryBean.updateDatabaseSchema(LeafSessionFactoryBean.java:445) at org.springframework.orm.hibernate3.LocalSessionFactoryBean.afterSessionFactoryCreation(LocalSessionFactoryBean.java:828) at org.leaframework.context.LeafSessionFactoryBean.afterSessionFactoryCreation(LeafSessionFactoryBean.java:377) at org.springframework.orm.hibernate3.AbstractSessionFactoryBean.afterPropertiesSet(AbstractSessionFactoryBean.java:213) at org.leaframework.context.LeafSessionFactoryBean.afterPropertiesSet(LeafSessionFactoryBean.java:202) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1288) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1257) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:438) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory$1.run(AbstractAutowireCapableBeanFactory.java:383) at java.base/java.security.AccessController.doPrivileged(Native Method) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:353) at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:245) at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:169) at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:242) at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:164) at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBeansOfType(DefaultListableBeanFactory.java:299) at org.springframework.beans.factory.BeanFactoryUtils.beansOfTypeIncludingAncestors(BeanFactoryUtils.java:270) at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.detectPersistenceExceptionTranslators(PersistenceExceptionTranslationInterceptor.java:122) at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.(PersistenceExceptionTranslationInterceptor.java:78) at org.springframework.dao.annotation.PersistenceExceptionTranslationAdvisor.(PersistenceExceptionTranslationAdvisor.java:70) at org.springframework.dao.annotation.PersistenceExceptionTranslationPostProcessor.setBeanFactory(PersistenceExceptionTranslationPostProcessor.java:96) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1248) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:438) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory$1.run(AbstractAutowireCapableBeanFactory.java:383) at java.base/java.security.AccessController.doPrivileged(Native Method) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:353) at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:245) at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:169) at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:242) at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:164) at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:888) at org.springframework.context.support.AbstractApplicationContext.registerBeanPostProcessors(AbstractApplicationContext.java:585) at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:351) at org.springframework.web.context.ContextLoader.createWebApplicationContext(ContextLoader.java:261) at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:199) at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:45) at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4768) at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5230) at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:728) at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:700) at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:696) at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1185) at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:1933) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75) at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:118) at org.apache.catalina.startup.HostConfig.deployDirectories(HostConfig.java:1095) at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:477) at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1618) at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:319) at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123) at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:423) at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:366) at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:948) at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:835) at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1398) at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1388) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75) at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140) at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:921) at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:263) at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) at org.apache.catalina.core.StandardService.startInternal(StandardService.java:437) at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:934) at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) at org.apache.catalina.startup.Catalina.start(Catalina.java:772) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:345) at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:476) Caused by: java.io.EOFException at org.postgresql.core.PGStream.receiveChar(PGStream.java:443) at org.postgresql.core.v3.ConnectionFactoryImpl.doAuthentication(ConnectionFactoryImpl.java:598) at org.postgresql.core.v3.ConnectionFactoryImpl.tryConnect(ConnectionFactoryImpl.java:161) at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:213) ... 100 more

Any help would be appreciated.

shubha-rajan commented 3 years ago

Thanks for opening this issue @unleftie . We've been noticing this flakiness in our IAM authentication integration tests over the past few week as well. We'll spend some time this week investigating and keep you updated on this issue.

shubha-rajan commented 3 years ago

I was able to get this error to appear 6 times while running a sample application overnight. And it does seem like the error occurs during authentication. One possibility is that the auth token being used to authenticate is invalid or null due to a race condition somewhere. I'll investigate further and let you know what I find.

shubha-rajan commented 3 years ago

UPDATE 2: We have identified the root cause of this issue.

The problem isn't with the connector or the Postgres instance, but with the Oauth2 tokens being used to authenticate. Sometimes, when requesting a token, we get a token that's padded to 1024 characters, like this: image (8) When that happens, connection attempts keep failing until the next token refresh. On the postgres instance, the logs for the connection attempts look like this: image I did some googling, and the invalid message length error can happen if a password is over 995 characters. Since the login uses the OAuth token for the password, that makes sense as to why we're getting that error. What I don't understand is why sometimes we get padded tokens and sometimes we just get normal tokens and then the connection attempt works. The errors stopped as soon as the token refreshed again: image

We are noticing the same issue in our Cloud SQL Python connector. For now, our plan is to patch the connector to strip the access token before adding it to requests, and escalate the token issue to get it fixed.

shubha-rajan commented 3 years ago

Note: Leaving this issue open until the underlying issue is fixed and we can remove the temporary patch in #566