BUG來源
根據https://spring.io/guides/gs/accessing-data-mysql/進行操作,
照抄教程中的:
spring.datasource.driver-class-name =com.mysql.jdbc.Driver
mvn package成功,IDEA運行JAR成功,但是在(git bash/ win10命令行)中通過java指令運行JAR失敗。
可能的原因及解決辦法
沒有正確加載驅動類。
將
spring.datasource.driver-class-name =com.mysql.jdbc.Driver
修改為
spring.datasource.driver-class-name =com.mysql.cj.jdbc.Driver
依據是程序在測試階段,以及成功執行JAR時日志中的相關提示和警告(WARN)。
BUG探究
發現執行mvn package -DskipTests時,數據庫里沒有表。
執行mvn package后,數據庫里多了兩個hibernate_sequence和user表
證明這兩張表是在測試階段生產的,測試階段並沒有報錯,
但是等到執行java -jar target/accessingdatamysql-0.0.1-SNAPSHOT.jar時卻報錯誤
經過實驗證明,執行JAVA指令前,不管數據庫里面有沒表都報同樣的錯誤,且執行JAVA指令的過程中,並不生成表
BUG的進一步探究
是什么導致測試階段不報錯,但是運行JAR時卻報錯?
精簡版測試階段日志:
[INFO] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode. [INFO] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 49 ms. Found 1 JPA repository interfaces. Loading class `com.mysql.jdbc.Driver'. This is deprecated. The new driver class is `com.mysql.cj.jdbc.Driver'. The driver is automatically registered via the SPI and manual loading of the driver class is generally unnecessary. [INFO] o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [name: default] [INFO] org.hibernate.Version : HHH000412: Hibernate ORM core version 5.6.5.Final [INFO] o.hibernate.annotations.common.Version : HCANN000001: Hibernate Commons Annotations {5.1.2.Final} [INFO] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting... [WARN] com.zaxxer.hikari.util.DriverDataSource : Registered driver with driverClassName=com.mysql.jdbc.Driver was not found, trying direct instantiation. [INFO] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed. [INFO] org.hibernate.dialect.Dialect : HHH000400: Using dialect: org.hibernate.dialect.MySQL57Dialect [INFO] o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform] [INFO] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default' [WARN] 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 [INFO] c.e.a.AccessingdatamysqlApplicationTests : Started AccessingdatamysqlApplicationTests in 5.115 seconds (JVM running for 6.501)
本想打印執行java -jar target/accessingdatamysql-0.0.1-SNAPSHOT.jar后的錯誤日志,但是接下來發生了一個讓我非常意外的事情。
因為我本來是在WIN10環境下用Git Bash執行java -jar target/accessingdatamysql-0.0.1-SNAPSHOT.jar指令的,這樣輸出到控制台的日志沒有高亮,不方便閱讀。
因此,為了更清楚地看錯誤日志,我用IntelliJ IDEA Community Edition 2021.3.1重新去跑這個JAR包,沒想到竟然沒有報任何錯誤。就成功執行了。
並且在執行之后MySQL里確實新創建了hibernate_sequence和user表,證明確實連上了數據庫。
觀察到IDEA是用下面這個指令跑的程序:
"C:\xxx\java.exe" -Dfile.encoding=GBK -jar D:\xxxx\accessingdatamysql\target\accessingdatamysql-0.0.1-SNAPSHOT.jar
因此推測之前之所以報錯,很可能是文件的字符集問題,於是用上面的指令在Git Bash下又跑一次程序:
java -Dfile.encoding=GBK -jar target/accessingdatamysql-0.0.1-SNAPSHOT.jar
沒想還是報了原來的錯誤,看着冗長難以閱讀的錯誤日志,我選擇用WIN10原裝命令行再去跑這個程序(以上為Git Bash的執行結果)。結果是無論是加-Dfile.encoding=GBK還是不加,都報了原來的錯誤。我一怒之下,在命令行下采用絕對路徑執行,就是原原本本拷貝IDEA的指令:
"C:\Program Files\Java\jdk1.8.0_101\bin\java.exe" -Dfile.encoding=GBK -jar D:\xxxxxx\accessingdatamysql\target\accessingdatamysql-0.0.1-SNAPSHOT.jar
沒想到執行成功了,而且數據庫里確實多了兩張表。
經過檢查,本地JAVA指令確實對應"C:\Program Files\Java\jdk1.8.0_101\bin\java.exe"(環境變量一致、版本一致):
java -version java version "1.8.0_101" Java(TM) SE Runtime Environment (build 1.8.0_101-b13) Java HotSpot(TM) 64-Bit Server VM (build 25.101-b13, mixed mode)
於是在好奇心的驅使下,我又用java指令+絕對路徑執行:
java -Dfile.encoding=GBK -jar D:\xxx\accessingdatamysql\target\accessingdatamysql-0.0.1-SNAPSHOT.jar
結果還是報了原來的錯誤,再嘗試:
"java.exe" -Dfile.encoding=GBK -jar D:\xxx\accessingdatamysql\target\accessingdatamysql-0.0.1-SNAPSHOT.jar
仍然報原來的錯誤。又一次用:
"C:\Program Files\Java\jdk1.8.0_101\bin\java.exe" -Dfile.encoding=GBK -jar D:\xxx\accessingdatamysql\target\accessingdatamysql-0.0.1-SNAPSHOT.jar
還是成功的。沒有報任何錯誤,數據里也多出了兩張表。我感到非常不可思議。又執行:
"C:\Program Files\Java\jdk1.8.0_101\bin\java.exe" -Dfile.encoding=GBK -jar accessingdatamysql-0.0.1-SNAPSHOT.jar
還是成功了。我繼續執行:
"C:\Program Files\Java\jdk1.8.0_101\bin\java.exe" -jar accessingdatamysql-0.0.1-SNAPSHOT.jar
依然成功。
百思不得其解,我甚至重新配了一遍環境變量,也不能夠解決問題。
至於通過"C:\Program Files\Java\jdk1.8.0_101\bin\java.exe"和"java.exe"執行程序的區別,網上也沒有相關的資料。
回到錯誤日志
只好回到原來的思路,老老實實分析一下執行java -jar target/accessingdatamysql-0.0.1-SNAPSHOT.jar后的錯誤日志:
[INFO].s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode. [INFO].s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 57 ms. Found 1 JPA repository interfaces. [INFO]省略嵌入式湯姆貓的初始化過程 [INFO]w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 3521 ms [INFO]o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [name: default] [INFO]org.hibernate.Version : HHH000412: Hibernate ORM core version 5.6.5.Final [INFO]o.hibernate.annotations.common.Version : HCANN000001: Hibernate Commons Annotations {5.1.2.Final} [INFO]com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting... [INFO]com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Driver does not support get/set network timeout for connections. (com.mysql.jdbc.Connection.getNetworkTimeout()I) [ERROR]com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to execute isValid() for connection, configure connection test query (com.mysql.jdbc.Connection.isValid(I)Z). [WARN]ConfigServletWebServerApplicationContext : Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'entityManagerFactory' defined in class path resource [org/springframework/boot/autoconfigure/orm/jpa/HibernateJpaConfiguration.class]: Invocation of init method failed; nested exception is java.lang.AbstractMethodError: com.mysql.jdbc.Connection.isValid(I)Z [INFO]o.apache.catalina.core.StandardService : Stopping service [Tomcat] [INFO]ConditionEvaluationReportLoggingListener : Error starting ApplicationContext. To display the conditions report re-run your application with 'debug' enabled. 08.472[ERROR]o.s.boot.SpringApplication : Application run failed org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'entityManagerFactory' defined in class path resource [org/springframework/boot/autoconfigure/orm/jpa/HibernateJpaConfiguration.class]: Invocation of init method failed; nested exception is java.lang.AbstractMethodError: com.mysql.jdbc.Connection.isValid(I)Z at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1804) ~[spring-beans-5.3.16.jar!/:5.3.16] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:620) ~[spring-beans-5.3.16.jar!/:5.3.16] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:542) ~[spring-beans-5.3.16.jar!/:5.3.16] 此處省略20多行 Caused by: java.lang.AbstractMethodError: com.mysql.jdbc.Connection.isValid(I)Z at com.zaxxer.hikari.pool.PoolBase.checkValidationSupport(PoolBase.java:464) ~[HikariCP-4.0.3.jar!/:na] at com.zaxxer.hikari.pool.PoolBase.checkDriverSupport(PoolBase.java:447) ~[HikariCP-4.0.3.jar!/:na] at com.zaxxer.hikari.pool.PoolBase.setupConnection(PoolBase.java:416) ~[HikariCP-4.0.3.jar!/:na] at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:369) ~[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] 此處省略20多行 ... 24 common frames omitted
也就是說,調用抽象方法com.mysql.jdbc.Connection.isValid(I)Z發生了錯誤。
根據正確執行的日志中的:Loading class `com.mysql.jdbc.Driver'. This is deprecated. The new driver class is `com.mysql.cj.jdbc.Driver'. The driver is automatically registered via the SPI and manual loading of the driver class is generally unnecessary.
推測是由於某種原因,在用java指令執行JAR時沒有正確地加載驅動類。
因此將
spring.datasource.driver-class-name =com.mysql.jdbc.Driver
修改為
spring.datasource.driver-class-name =com.mysql.cj.jdbc.Driver
保存之后通過mvn clean以及mvn package -DskipTests重新編譯打包程序,並通過IDEA運行打包后的程序。正常運行且不報Loading class `com.mysql.jdbc.Driver'. This is deprecated. The new driver class is `com.mysql.cj.jdbc.Driver'. The driver is automatically registered via the SPI and manual loading of the driver class is generally unnecessary.
通過mvn clean package再執行一遍,測試階段日志也不再報[WARN] com.zaxxer.hikari.util.DriverDataSource : Registered driver with driverClassName=com.mysql.jdbc.Driver was not found, trying direct instantiation.
清空數據庫里新創建的兩張表,cd到target文件夾下執行
java -jar accessingdatamysql-0.0.1-SNAPSHOT.jar
這次終於沒問題了。