Is autoconfig of db really working?
damzog opened this issue · 5 comments
damzog commented
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 commented
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 commented
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 commented
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 commented
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 commented
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?