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

Enhance troubleshooting support #74

Open
gberche-orange opened this issue Jul 20, 2022 · 5 comments
Open

Enhance troubleshooting support #74

gberche-orange opened this issue Jul 20, 2022 · 5 comments

Comments

@gberche-orange
Copy link

gberche-orange commented Jul 20, 2022 •
edited
Loading

As a springboot developer, in order to fix misconfigurations, I need to be able to troubleshoot when servicebinding fail to be injected

In this particular case, a K8S binding seems properly detected and injected, but the driver seems to not notice it and still be using the default datasource constructed from https://github.com/spring-projects/spring-petclinic/blob/3f8468432d86dcbd0cf4372e93e06d2f47aed26a/src/main/resources/application-postgres.properties#L1-L6

observed behavior

given a petclinic deployment from image quay.io/service-binding/spring-petclinic:latest with logging enabled

          env:
            - name: SPRING_PROFILES_ACTIVE
              value: postgres #! see https://github.com/spring-projects/spring-petclinic/blob/3f8468432d86dcbd0cf4372e93e06d2f47aed26a/src/main/resources/db/postgres/petclinic_db_setup_postgres.txt#L17
            - name: logging.level.org.springframework.cloud.bindings
              value: debug
            - name: logging.level.org.springframework
              value: debug
            - name: DEBUG #! Springboot debugging mode when context fails to load
              value: "true"

and an injected secret by https://github.com/redhat-developer/service-binding-operator

        volumeMounts:
        - mountPath: /bindings/static-spring-petclinic-postgresql
          name: static-spring-petclinic-postgresql

I see the following debug traces showing a binding-specific PropertySource from Kubernetes Service Bindings was created, but still the driver trying to connect to localhost:5432 whereas the binding IP address is 10.69.0.34

2022-07-20 12:11:12.545  INFO 1 --- [           main] .BindingSpecificEnvironmentPostProcessor : Creating binding-specific PropertySource from Kubernetes Service Bindings
[...]
2022-07-20 12:11:14.939  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
[...]
2022-07-20 12:11:15.033  INFO 1 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
[...]
2022-07-20 12:11:15.579 DEBUG 1 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'scriptDataSourceInitializer'
2022-07-20 12:11:15.579 DEBUG 1 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.jdbc.DataSourceInitializationConfiguration$SharedCredentialsDataSourceInitializationConfiguration'
2022-07-20 12:11:15.581 DEBUG 1 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'dataSource'
2022-07-20 12:11:15.581 DEBUG 1 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.jdbc.DataSourceConfiguration$Hikari'
2022-07-20 12:11:15.582 DEBUG 1 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'spring.datasource-org.springframework.boot.autoconfigure.jdbc.DataSourceProperties'
2022-07-20 12:11:15.605 DEBUG 1 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Autowiring by type from bean name 'dataSource' via factory method to bean named 'spring.datasource-org.springframework.boot.autoconfigure.jdbc.DataSourceProperties'
2022-07-20 12:11:15.633 DEBUG 1 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Autowiring by type from bean name 'scriptDataSourceInitializer' via factory method to bean named 'dataSource'
2022-07-20 12:11:15.633 DEBUG 1 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Autowiring by type from bean name 'scriptDataSourceInitializer' via factory method to bean named 'spring.datasource-org.springframework.boot.autoconfigure.jdbc.DataSourceProperties'
2022-07-20 12:11:15.645 DEBUG 1 --- [           main] o.s.jdbc.datasource.DataSourceUtils      : Fetching JDBC Connection from DataSource
2022-07-20 12:11:15.646  INFO 1 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
2022-07-20 12:11:16.716 ERROR 1 --- [           main] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Exception during pool initialization.

org.postgresql.util.PSQLException: Connection to localhost: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:301) ~[postgresql-42.3.1.jar!/:42.3.1]
	at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:51) ~[postgresql-42.3.1.jar!/:42.3.1]
	at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:225) ~[postgresql-42.3.1.jar!/:42.3.1]
	at org.postgresql.Driver.makeConnection(Driver.java:466) ~[postgresql-42.3.1.jar!/:42.3.1]
	at org.postgresql.Driver.connect(Driver.java:265) ~[postgresql-42.3.1.jar!/:42.3.1]
	at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:138) ~[HikariCP-4.0.3.jar!/:na]
	at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:364) ~[HikariCP-4.0.3.jar!/:na]
	at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:206) ~[HikariCP-4.0.3.jar!/:na]
	at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:476) ~[HikariCP-4.0.3.jar!/:na]
	at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:561) ~[HikariCP-4.0.3.jar!/:na]
	at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:115) ~[HikariCP-4.0.3.jar!/:na]
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:112) ~[HikariCP-4.0.3.jar!/:na]
	at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:159) ~[spring-jdbc-5.3.14.jar!/:5.3.14]
	at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:117) ~[spring-jdbc-5.3.14.jar!/:5.3.14]
	at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:80) ~[spring-jdbc-5.3.14.jar!/:5.3.14]
	at org.springframework.jdbc.datasource.init.DatabasePopulatorUtils.execute(DatabasePopulatorUtils.java:52) ~[spring-jdbc-5.3.14.jar!/:5.3.14]
	at org.springframework.boot.jdbc.init.DataSourceScriptDatabaseInitializer.runScripts(DataSourceScriptDatabaseInitializer.java:90) ~[spring-boot-2.6.2.jar!/:2.6.2]
	at org.springframework.boot.sql.init.AbstractScriptDatabaseInitializer.runScripts(AbstractScriptDatabaseInitializer.java:145) ~[spring-boot-2.6.2.jar!/:2.6.2]
	at org.springframework.boot.sql.init.AbstractScriptDatabaseInitializer.applyScripts(AbstractScriptDatabaseInitializer.java:107) ~[spring-boot-2.6.2.jar!/:2.6.2]
	at org.springframework.boot.sql.init.AbstractScriptDatabaseInitializer.applySchemaScripts(AbstractScriptDatabaseInitializer.java:97) ~[spring-boot-2.6.2.jar!/:2.6.2]
	at org.springframework.boot.sql.init.AbstractScriptDatabaseInitializer.initializeDatabase(AbstractScriptDatabaseInitializer.java:75) ~[spring-boot-2.6.2.jar!/:2.6.2]
	at org.springframework.boot.sql.init.AbstractScriptDatabaseInitializer.afterPropertiesSet(AbstractScriptDatabaseInitializer.java:65) ~[spring-boot-2.6.2.jar!/:2.6.2]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1863) ~[spring-beans-5.3.14.jar!/:5.3.14]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1800) ~[spring-beans-5.3.14.jar!/:5.3.14]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:620) ~[spring-beans-5.3.14.jar!/:5.3.14]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:542) ~[spring-beans-5.3.14.jar!/:5.3.14]
	at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:335) ~[spring-beans-5.3.14.jar!/:5.3.14]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234) ~[spring-beans-5.3.14.jar!/:5.3.14]
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333) ~[spring-beans-5.3.14.jar!/:5.3.14]
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208) ~[spring-beans-5.3.14.jar!/:5.3.14]
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:322) ~[spring-beans-5.3.14.jar!/:5.3.14]
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208) ~[spring-beans-5.3.14.jar!/:5.3.14]
	at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1154) ~[spring-context-5.3.14.jar!/:5.3.14]
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:908) ~[spring-context-5.3.14.jar!/:5.3.14]
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:583) ~[spring-context-5.3.14.jar!/:5.3.14]
	at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:145) ~[spring-boot-2.6.2.jar!/:2.6.2]
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:730) ~[spring-boot-2.6.2.jar!/:2.6.2]
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:412) ~[spring-boot-2.6.2.jar!/:2.6.2]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:302) ~[spring-boot-2.6.2.jar!/:2.6.2]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1301) ~[spring-boot-2.6.2.jar!/:2.6.2]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1290) ~[spring-boot-2.6.2.jar!/:2.6.2]
	at org.springframework.samples.petclinic.PetClinicApplication.main(PetClinicApplication.java:32) ~[classes!/:2.6.0-SNAPSHOT]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]
	at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49) ~[petclinic.jar:2.6.0-SNAPSHOT]
	at org.springframework.boot.loader.Launcher.launch(Launcher.java:108) ~[petclinic.jar:2.6.0-SNAPSHOT]
	at org.springframework.boot.loader.Launcher.launch(Launcher.java:58) ~[petclinic.jar:2.6.0-SNAPSHOT]
	at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:88) ~[petclinic.jar:2.6.0-SNAPSHOT]
Caused by: java.net.ConnectException: Connection refused (Connection refused)
	at java.base/java.net.PlainSocketImpl.socketConnect(Native Method) ~[na:na]
	at java.base/java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:399) ~[na:na]
	at java.base/java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:242) ~[na:na]
	at java.base/java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:224) ~[na:na]
	at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[na:na]
	at java.base/java.net.Socket.connect(Socket.java:609) ~[na:na]
	at org.postgresql.core.PGStream.createSocket(PGStream.java:238) ~[postgresql-42.3.1.jar!/:42.3.1]
	at org.postgresql.core.PGStream.<init>(PGStream.java:98) ~[postgresql-42.3.1.jar!/:42.3.1]
	at org.postgresql.core.v3.ConnectionFactoryImpl.tryConnect(ConnectionFactoryImpl.java:100) ~[postgresql-42.3.1.jar!/:42.3.1]
	at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:215) ~[postgresql-42.3.1.jar!/:42.3.1]
	... 49 common frames omitted

2022-07-20 12:11:16.718  WARN 1 --- [           main] ConfigServletWebServerApplicationContext : Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'scriptDataSourceInitializer' defined in class path resource [org/springframework/boot/autoconfigure/jdbc/DataSourceInitializationConfiguration$SharedCredentialsDataSourceInitializationConfiguration.class]: Invocation of init method failed; nested exception is org.springframework.jdbc.datasource.init.UncategorizedScriptException: Failed to execute database script; nested exception is org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is org.postgresql.util.PSQLException: Connection to localhost:5432 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
2022-07-20 12:11:16.741  INFO 1 --- [           main] o.apache.catalina.core.StandardService   : Stopping service [Tomcat]

And the container exits immediately after springboot failed start, preventing manual inspection of the mounted bindings

After transiently adding the following command to the petclinic deployment

        command:
        - sh
        - -c
        - tail -f /dev/null

And ssh into the container and run the following commands

bash

bash-4.4$ find /bindings
/bindings
/bindings/static-spring-petclinic-postgresql
/bindings/static-spring-petclinic-postgresql/host
/bindings/static-spring-petclinic-postgresql/username
/bindings/static-spring-petclinic-postgresql/type
/bindings/static-spring-petclinic-postgresql/provider
/bindings/static-spring-petclinic-postgresql/port
/bindings/static-spring-petclinic-postgresql/password
/bindings/static-spring-petclinic-postgresql/..data
/bindings/static-spring-petclinic-postgresql/..2022_07_20_12_42_26.777702559
/bindings/static-spring-petclinic-postgresql/..2022_07_20_12_42_26.777702559/password
/bindings/static-spring-petclinic-postgresql/..2022_07_20_12_42_26.777702559/host
/bindings/static-spring-petclinic-postgresql/..2022_07_20_12_42_26.777702559/username
/bindings/static-spring-petclinic-postgresql/..2022_07_20_12_42_26.777702559/type
/bindings/static-spring-petclinic-postgresql/..2022_07_20_12_42_26.777702559/provider
/bindings/static-spring-petclinic-postgresql/..2022_07_20_12_42_26.777702559/port
find: Failed to restore initial working directory: /home/jboss: Permission denied

bash-4.4$ cat /bindings/static-spring-petclinic-postgresql/host
10.69.0.34

bash-4.4$ cat /bindings/static-spring-petclinic-postgresql/port
5432
@gberche-orange
Copy link
Author

Testing with the image: ghcr.io/vmware-tanzu/servicebinding/test/petclinic:20200922 proposed by default ...

https://github.com/vmware-tanzu/servicebinding/blob/d7727a7de9460f64eb3b32616cc2cebabe824a88/samples/spring-petclinic/workload.yaml#L35-L36

... fails with apparently missing postgresql driver

022-07-20 13:23:11.902  WARN 1 --- [           main] ConfigServletWebServerApplicationContext : Exception encountered during context initialization - cancelling refresh attempt: org.springframework.bean
s.factory.UnsatisfiedDependencyException: Error creating bean with name 'org.springframework.boot.autoconfigure.orm.jpa.HibernateJpaConfiguration': Unsatisfied dependency expressed through constructor pa
rameter 0; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'dataSource' defined in class path resource [org/springframework/boot/autoconfigure/j
dbc/DataSourceConfiguration$Hikari.class]: Bean instantiation via factory method failed; nested exception is org.springframework.beans.BeanInstantiationException: Failed to instantiate [com.zaxxer.hikari.HikariDataSource]: Factory method 'dataSource' threw exception; nested exception is java.lang.IllegalStateException: Cannot load driver class: org.postgresql.Driver
2022-07-20 13:23:11.919  INFO 1 --- [           main] org.ehcache.core.EhcacheManager          : Cache 'vets' removed from EhcacheManager.
2022-07-20 13:23:11.933  INFO 1 --- [           main] o.apache.catalina.core.StandardService   : Stopping service [Tomcat]
2022-07-20 13:23:12.004  INFO 1 --- [           main] ConditionEvaluationReportLoggingListener : 

Error starting ApplicationContext. To display the conditions report re-run your application with 'debug' enabled.
2022-07-20 13:23:12.013 ERROR 1 --- [           main] o.s.boot.SpringApplication               : Application run failed

org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'org.springframework.boot.autoconfigure.orm.jpa.HibernateJpaConfiguration': Unsatisfied dependency expressed through constructor parameter 0; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'dataSource' defined in class path resource [org/springframework/boot/autoconfigure/jdbc/DataSourceConfiguration$Hikari.class]: Bean instantiation via factory method failed; nested exception is org.springframework.beans.BeanInstantiationException: Failed to instantiate [com.zaxxer.hikari.HikariDataSource]: Factory method 'dataSource' threw exception; nested exception is java.lang.IllegalStateException: Cannot load driver class: org.postgresql.Driver

Likely would need to rebuild the image with paketo buildpacks and a postgres profile ?

@gberche-orange
Copy link
Author

when adding the TRACE=true environment variable, other relevant traces get displayed but did not yet help me diagnose nor fix the issue

16:00:41.906 DEBUG o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'spring.datasource-org.springframework.boot.autoconfigure.jdbc.DataSourceProperties'
16:00:41.906 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Creating instance of bean 'spring.datasource-org.springframework.boot.autoconfigure.jdbc.DataSourceProperties'
16:00:41.906 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
16:00:41.906 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.cache.config.internalJCacheAdvisor'
16:00:41.906 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
16:00:41.907 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.boot.context.properties.BoundConfigurationProperties'
16:00:41.911 TRACE o.s.util.PropertyPlaceholderHelper       : Resolved placeholder 'database'
16:00:41.916 TRACE o.s.util.PropertyPlaceholderHelper       : Resolved placeholder 'database'
16:00:41.917 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL:jdbc:postgresql://localhost/petclinic' in PropertySource 'configurationProperties'
16:00:41.917 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL:jdbc:postgresql://localhost/petclinic' in PropertySource 'kubernetesServiceBindingSpecific'
16:00:41.917 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL:jdbc:postgresql://localhost/petclinic' in PropertySource 'kubernetesServiceBindingFlattened'
16:00:41.917 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL:jdbc:postgresql://localhost/petclinic' in PropertySource 'servletConfigInitParams'
16:00:41.917 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL:jdbc:postgresql://localhost/petclinic' in PropertySource 'servletContextInitParams'
16:00:41.917 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL:jdbc:postgresql://localhost/petclinic' in PropertySource 'systemProperties'
16:00:41.917 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL:jdbc:postgresql://localhost/petclinic' in PropertySource 'systemEnvironment'
16:00:41.917 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL:jdbc:postgresql://localhost/petclinic' in PropertySource 'random'
16:00:41.917 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL:jdbc:postgresql://localhost/petclinic' in PropertySource 'Config resource 'class path resource [application-postgres.properties]' via location 'optional:classpath:/''
16:00:41.917 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL:jdbc:postgresql://localhost/petclinic' in PropertySource 'Config resource 'class path resource [application.properties]' via location 'optional:classpath:/''
16:00:41.917 TRACE ySourcesPropertyResolver$DefaultResolver : Could not find key 'POSTGRES_URL:jdbc:postgresql://localhost/petclinic' in any property source
16:00:41.917 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL' in PropertySource 'configurationProperties'
16:00:41.918 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL' in PropertySource 'kubernetesServiceBindingSpecific'
16:00:41.918 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL' in PropertySource 'kubernetesServiceBindingFlattened'
16:00:41.918 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL' in PropertySource 'servletConfigInitParams'
16:00:41.918 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL' in PropertySource 'servletContextInitParams'
16:00:41.918 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL' in PropertySource 'systemProperties'
16:00:41.918 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL' in PropertySource 'systemEnvironment'
16:00:41.918 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL' in PropertySource 'random'
16:00:41.918 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL' in PropertySource 'Config resource 'class path resource [application-postgres.properties]' via location 'optional:classpath:/''
16:00:41.918 TRACE ySourcesPropertyResolver$DefaultResolver : Searching for key 'POSTGRES_URL' in PropertySource 'Config resource 'class path resource [application.properties]' via location 'optional:classpath:/''
16:00:41.918 TRACE ySourcesPropertyResolver$DefaultResolver : Could not find key 'POSTGRES_URL' in any property source
16:00:41.918 TRACE o.s.util.PropertyPlaceholderHelper       : Resolved placeholder 'POSTGRES_URL:jdbc:postgresql://localhost/petclinic'
16:00:41.918 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Invoking afterPropertiesSet() on bean with name 'spring.datasource-org.springframework.boot.autoconfigure.jdbc.DataSourceProperties'
16:00:41.925 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
16:00:41.925 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.cache.config.internalJCacheAdvisor'
16:00:41.925 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
16:00:41.925 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
16:00:41.925 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.cache.config.internalJCacheAdvisor'
16:00:41.925 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
16:00:41.928 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Finished creating instance of bean 'spring.datasource-org.springframework.boot.autoconfigure.jdbc.DataSourceProperties'
16:00:41.928 DEBUG o.s.b.f.s.DefaultListableBeanFactory     : Autowiring by type from bean name 'dataSource' via factory method to bean named 'spring.datasource-org.springframework.boot.autoconfigure.jdbc.DataSourceProperties'
16:00:41.940 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.boot.context.properties.BoundConfigurationProperties'
16:00:41.976 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
16:00:41.976 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.cache.config.internalJCacheAdvisor'
16:00:41.976 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
16:00:41.976 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
16:00:41.976 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.cache.config.internalJCacheAdvisor'
16:00:41.976 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
16:00:41.982 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Finished creating instance of bean 'dataSource'
16:00:41.983 TRACE o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'spring.datasource-org.springframework.boot.autoconfigure.jdbc.DataSourceProperties'

@gberche-orange
Copy link
Author

Finally, the root cause of my issue was that the K8S binding secret was missing the jdbc-url and database values.

Reading the documentation at
https://github.com/spring-cloud/spring-cloud-bindings#postgresql-rdbms, it was not clear to me whether database was indeed required to get the spring.datasource.url property defined.

Property Value
spring.datasource.url {jdbc-url} or if not set then jdbc:postgres://{host}:{port}/{database}. If a binding for {sslmode}, {sslrootcert}, or {options} are set, the value is appended as properties to the generated URL.

As a result, the spring.datasource.url=${POSTGRES_URL:jdbc:postgresql://localhost/petclinic} from petclinic was always used

https://github.com/spring-projects/spring-petclinic/blob/3f8468432d86dcbd0cf4372e93e06d2f47aed26a/src/main/resources/application-postgres.properties#L2

Defining an empty database field into the K8S secret fixed the problem.

I think it would much help to add a debug trace in spring-cloud-bindings which lists the keys being inserted into the PropertySource, potentially omitting the values for security reasons.

@dmikusa
Copy link
Contributor

dmikusa commented Jul 21, 2022

@gberche-orange Thanks for reaching out. Glad you were able to resolve the issue.

I'm a little surprised that it required all of those properties to be set. I could possibly see it just filling in an empty value if it's not present. What's more surprising is that if they are not all set it just quietly skips the operation. I really believe that if you're going to require those fields you should at least pop up some sort of warning, or probably more appropriate fail.

That said, I'm pretty sure this is the code that enforces that requirement.

I'll drop a quick PR in to update the README to indicate it's all or none for the JDBC URLs.

Beyond that, I totally agree that we can do better with logging and debugging. I'll leave this issue open as a feature request to log the property keys at debug level & to log the length of the property value. That should give a clue about what's set but not leak the value. Does that seem reasonable?

@gberche-orange
Copy link
Author

Thanks @dmikusa-pivotal for looking into this issue. Your proposant of doc update and more friendly logging seems good to me !

dmikusa pushed a commit that referenced this issue Jul 21, 2022
Clarify that JDBC/R2DBC generated URLs
c959f86 
If allowing the mapping to generate a JDBC/R2DBC URL then all three of the fields are required, the host, port and database. If even one is not set, the information will not be mapped and the default value for the property will be used.

Reference: #74

Signed-off-by: Daniel Mikusa <[email protected]>
@dmikusa dmikusa mentioned this issue Jul 21, 2022
Merged
dmikusa pushed a commit that referenced this issue Jul 25, 2022
Clarify that JDBC/R2DBC generated URLs
0631b41 
If allowing the mapping to generate a JDBC/R2DBC URL then all three of the fields are required, the host, port and database. If even one is not set, the information will not be mapped and the default value for the property will be used.

Reference: #74

Signed-off-by: Daniel Mikusa <[email protected]>
dmikusa pushed a commit that referenced this issue Jul 25, 2022
Clarify that JDBC/R2DBC generated URLs (#75)
f807774 
If allowing the mapping to generate a JDBC/R2DBC URL then all three of the fields are required, the host, port and database. If even one is not set, the information will not be mapped and the default value for the property will be used.

Reference: #74

Signed-off-by: Daniel Mikusa <[email protected]>
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
2 participants
@dmikusa @gberche-orange