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