Is autoconfig of db really working?

[damzog]

I have pushed the app to cloud foundry and bound it to a mysql database. However when I start the app and look at the database there is now table available. Am I missing something?

Thanks, Joda

[dmikusa]

Did you restart the app after binding? That is a requirement.

Also, can you include the output of cf push and cf logs so that we can see more about what has happened? Thanks

[scottfrederick]

Detection of a bound service requires that the credentials meet certain criteria. For a MySQL database, you can view the VCAP_SERVICES environment variable for the app (for example, with cf env) and compare the credentials to the criteria here.

[damzog]

Hi @dmikusa-pivotal and @scottfrederick ,

thanks for answering! Yes I did bind and restart. From the logs it seams that the binding is discovered "Found db", see below. I have bound phpmyadmin to the same datasource to check but the database (scheme) is empty. Could it be due to missing priviliges on the db side? But I guess I would see errors in the log if that was the case, right?

 2022-03-22T17:34:20.54+0100 [CELL/0] OUT Cell c4310ea3-3ffe-44bb-b46d-cfa8539872fd destroying container for instance 7d8c4077-3e6d-4735-41bf-882c
   2022-03-22T17:34:20.69+0100 [CELL/0] OUT Downloaded droplet (95.6M)
   2022-03-22T17:34:20.78+0100 [CELL/0] OUT Starting health monitoring of container
   2022-03-22T17:34:21.01+0100 [APP/PROC/WEB/0] OUT JVM Memory Configuration: -Xmx401545K -Xss1M -XX:ReservedCodeCacheSize=240M -XX:MaxDirectMemorySize=10M -XX:MaxMetaspaceSize=135030K
   2022-03-22T17:34:21.10+0100 [PROXY/0] OUT Exit status 137
   2022-03-22T17:34:22.14+0100 [APP/PROC/WEB/0] OUT   .   ____          _            __ _ _
   2022-03-22T17:34:22.14+0100 [APP/PROC/WEB/0] OUT  /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
   2022-03-22T17:34:22.14+0100 [APP/PROC/WEB/0] OUT ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
   2022-03-22T17:34:22.15+0100 [APP/PROC/WEB/0] OUT  \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
   2022-03-22T17:34:22.15+0100 [APP/PROC/WEB/0] OUT   '  |____| .__|_| |_|_| |_\__, | / / / /
   2022-03-22T17:34:22.15+0100 [APP/PROC/WEB/0] OUT  =========|_|==============|___/=/_/_/_/
   2022-03-22T17:34:22.15+0100 [APP/PROC/WEB/0] OUT  :: Spring Boot ::                (v2.5.5)
   2022-03-22T17:34:22.23+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:22.234  INFO 15 --- [           main] .m.c.SpringApplicationContextInitializer : Found services db
   2022-03-22T17:34:22.23+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:22.237  INFO 15 --- [           main] .m.c.SpringApplicationContextInitializer : Setting service profile mysql
   2022-03-22T17:34:22.24+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:22.243  INFO 15 --- [           main] o.c.samples.music.Application            : Starting Application using Java 1.8.0_322 on 748bdc4a-a95c-4725-7f88-abf6 with PID 15 (/home/vcap/app/BOOT-INF/classes started by vcap in /home/vcap/app)
   2022-03-22T17:34:22.24+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:22.244  INFO 15 --- [           main] o.c.samples.music.Application            : The following profiles are active: http2,mysql
   2022-03-22T17:34:22.36+0100 [CELL/0] OUT Cell c4310ea3-3ffe-44bb-b46d-cfa8539872fd successfully destroyed container for instance 7d8c4077-3e6d-4735-41bf-882c
   2022-03-22T17:34:23.39+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:23.398  INFO 15 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Multiple Spring Data modules found, entering strict repository configuration mode!
   2022-03-22T17:34:23.40+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:23.400  INFO 15 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
   2022-03-22T17:34:23.61+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:23.610  INFO 15 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 200 ms. Found 1 JPA repository interfaces.
   2022-03-22T17:34:24.26+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:24.262  INFO 15 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
   2022-03-22T17:34:24.27+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:24.276  INFO 15 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
   2022-03-22T17:34:24.27+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:24.276  INFO 15 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.53]
   2022-03-22T17:34:24.34+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:24.343  INFO 15 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
   2022-03-22T17:34:24.34+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:24.343  INFO 15 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 2033 ms
   2022-03-22T17:34:24.96+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:24.966  INFO 15 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
   2022-03-22T17:34:25.19+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:25.193  INFO 15 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Start completed.
   2022-03-22T17:34:25.25+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:25.252  INFO 15 --- [           main] o.hibernate.jpa.internal.util.LogHelper  : HHH000204: Processing PersistenceUnitInfo [name: default]
   2022-03-22T17:34:25.34+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:25.341  INFO 15 --- [           main] org.hibernate.Version                    : HHH000412: Hibernate ORM core version 5.4.32.Final
   2022-03-22T17:34:25.54+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:25.548  INFO 15 --- [           main] o.hibernate.annotations.common.Version   : HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
   2022-03-22T17:34:25.69+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:25.698  INFO 15 --- [           main] org.hibernate.dialect.Dialect            : HHH000400: Using dialect: org.hibernate.dialect.H2Dialect
   2022-03-22T17:34:26.41+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:26.414  INFO 15 --- [           main] o.h.e.t.j.p.i.JtaPlatformInitiator       : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
   2022-03-22T17:34:26.42+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:26.425  INFO 15 --- [           main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
   2022-03-22T17:34:26.87+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:26.874  WARN 15 --- [           main] JpaBaseConfiguration$JpaWebConfiguration : spring.jpa.open-in-view is enabled by default. Therefore, database queries may be performed during view rendering. Explicitly configure spring.jpa.open-in-view to disable this warning
   2022-03-22T17:34:27.15+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:27.150  INFO 15 --- [           main] o.s.b.a.w.s.WelcomePageHandlerMapping    : Adding welcome page: class path resource [static/index.html]
   2022-03-22T17:34:27.65+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:27.656  INFO 15 --- [           main] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 13 endpoint(s) beneath base path '/actuator'
   2022-03-22T17:34:27.69+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:27.697  INFO 15 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
   2022-03-22T17:34:27.71+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:27.711  INFO 15 --- [           main] o.c.samples.music.Application            : Started Application in 6.114 seconds (JVM running for 6.784)
   2022-03-22T17:34:29.30+0100 [CELL/0] OUT Container became healthy
   2022-03-22T17:34:40.07+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:40.069  INFO 15 --- [nio-8080-exec-3] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
   2022-03-22T17:34:40.07+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:40.070  INFO 15 --- [nio-8080-exec-3] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
   2022-03-22T17:34:40.07+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:40.072  INFO 15 --- [nio-8080-exec-3] o.s.web.servlet.DispatcherServlet        : Completed initialization in 2 ms
   2022-03-22T17:34:40.13+0100 [RTR/5] OUT spring-music-excellent-tiger-oi.apps.de1.bosch-iot-cloud.com - [2022-03-22T16:34:40.027539829Z] "GET / HTTP/1.1" 200 0 2020 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:91.0) Gecko/20100101 Firefox/91.0" ......................

[scottfrederick]

These lines do indicate that the bound database service is detected and a connection is configured:

   2022-03-22T17:34:22.23+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:22.234  INFO 15 --- [           main] .m.c.SpringApplicationContextInitializer : Found services db
   2022-03-22T17:34:22.23+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:22.237  INFO 15 --- [           main] .m.c.SpringApplicationContextInitializer : Setting service profile mysql
...
   2022-03-22T17:34:22.24+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:22.244  INFO 15 --- [           main] o.c.samples.music.Application            : The following profiles are active: http2,mysql

I don't see any errors in the startup logs, so it's difficult to tell what else might be going on.

[dmikusa]

What's weird, is that the Hibernate dialect is H2. It's a MySQL DB, so I'd think it would use a MySQL dialect. I don't have a CF env at the moment to test that though.

22T17:34:25.54+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:25.548  INFO 15 --- [           main] o.hibernate.annotations.common.Version   : HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
2022-03-22T17:34:25.69+0100 [APP/PROC/WEB/0] OUT 2022-03-22 16:34:25.698  INFO 15 --- [           main] org.hibernate.dialect.Dialect            : HHH000400: Using dialect: org.hibernate.dialect.H2Dialect

You might try one of these options to force a MySQL dialect.

Who is the service provider for your MySQL DB? Or are you using a user-provided service?