search

spring-cloud / spring-cloud-bindings

A library that exposes a rich Java language-binding and auto-configuration for CNB Bindings
Apache License 2.0
41 stars 31 forks source link

Enhance troubleshooting support #74

Open gberche-orange opened 2 years ago

gberche-orange commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

@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 commented 2 years ago

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