hbm2ddl.autoupdate为update但未正常生效的

数据库使用的是Mysql5.5，原来使用了hibernate4。
最近同事在更新时，将hibernate4升级为hibernate5 并加入了c3p0，升级后发现连原来的数据库，运行时有如下报错，此外，业务功能一切都正常。

org.hibernate.tool.schema.spi.CommandAcceptanceException: Error executing DDL via JDBC Statement
    at org.hibernate.tool.schema.internal.exec.GenerationTargetToDatabase.accept(GenerationTargetToDatabase.java:67)
    at org.hibernate.tool.schema.internal.AbstractSchemaMigrator.applySqlString(AbstractSchemaMigrator.java:524)
    at org.hibernate.tool.schema.internal.AbstractSchemaMigrator.applySqlStrings(AbstractSchemaMigrator.java:470)
    at org.hibernate.tool.schema.internal.AbstractSchemaMigrator.createTable(AbstractSchemaMigrator.java:273)
    at org.hibernate.tool.schema.internal.GroupedSchemaMigratorImpl.performTablesMigration(GroupedSchemaMigratorImpl.java:71)
    at org.hibernate.tool.schema.internal.AbstractSchemaMigrator.performMigration(AbstractSchemaMigrator.java:203)
    at org.hibernate.tool.schema.internal.AbstractSchemaMigrator.doMigration(AbstractSchemaMigrator.java:110)
    at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.performDatabaseAction(SchemaManagementToolCoordinator.java:176)
    at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.process(SchemaManagementToolCoordinator.java:65)
    at org.hibernate.internal.SessionFactoryImpl.<init>(SessionFactoryImpl.java:478)
    at org.hibernate.boot.internal.SessionFactoryBuilderImpl.build(SessionFactoryBuilderImpl.java:423)
    at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:711)
    at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:727)
.......
Caused by: com.mysql.jdbc.exceptions.MySQLSyntaxErrorException: Table 'aaaa' already exists
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:936)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2985)
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1631)
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723)
    at com.mysql.jdbc.Connection.execSQL(Connection.java:3277)
    at com.mysql.jdbc.Connection.execSQL(Connection.java:3206)
    at com.mysql.jdbc.Statement.execute(Statement.java:727)
    at com.mchange.v2.c3p0.impl.NewProxyStatement.execute(NewProxyStatement.java:909)
    at org.hibernate.tool.schema.internal.exec.GenerationTargetToDatabase.accept(GenerationTargetToDatabase.java:54)
    ... 30 more

修改后的hibernate配置如下,除了新增了c3p0部分的配置外，其他项与修改前相同

        <!--C3P0配置 -->
        <property name="hibernate.connection.provider_class">org.hibernate.connection.C3P0ConnectionProvider</property>
        <property name="c3p0.max_size">20</property>     
        <property name="c3p0.min_size">1</property>
        <property name="c3p0.initialPoolSize">1</property>
        <property name="c3p0.timeout">120</property>
        <property name="c3p0.max_statements">100</property>
        <property name="c3p0.idle_test_period">120</property>     
        <property name="c3p0.acquire_increment">1</property>
        <property name="c3p0.validate">true</property>  
        <property name="c3p0.maxIdleTime">60</property>             
        <property name="c3p0.checkoutTimeout">100</property>        

        <!-- Database connection settings -->
        <property name="hibernate.connection.driver_class">com.mysql.jdbc.Driver</property>
        <property name="hibernate.connection.url">jdbc:mysql://127.0.0.1:3306/xxx</property>
        <property name="hibernate.connection.username">xxx</property>
        <property name="hibernate.connection.password">xxx</property>  
        <!-- JDBC connection pool (use the built-in) -->
        <property name="hibernate.connection.pool_size">1</property>
        <!-- SQL dialect -->
        <property name="hibernate.dialect">org.hibernate.dialect.MySQL5Dialect</property>        
        <!-- <property name="dialect">com.cetc7.dao.utils.dialect.SQLiteDialect</property> -->       
        <!-- Disable the second-level cache  -->
        <property name="hibernate.cache.provider_class">org.hibernate.cache.internal.NoCacheProvider</property>
        <!-- Echo all executed SQL to stdout -->
        <property name="hibernate.show_sql">false</property>        
        <property name="hibernate.format_sql">true</property>
        <!-- Drop and re-create the database schema on startup -->
        <property name="hibernate.hbm2ddl.auto">update</property>        
        <property name="hibernate.current_session_context_class">thread</property>
...

事实上hibernate已经配置了hbm2ddl.auto为update，不应该再去新建表的。
顺着Error executing DDL via JDBC Statement找了一圈，发现都是大家都是因为方言MySQL5Dialect写错为MySQLDialect引起的问题，然而这里也不存在。

怀疑要么是hibernate5与hibernate4的可能有些没注意到的差异，要么是c3p0部分的配置有误，尝试将c3p0去除，问题修复。

对c3p0的配置项过了一遍，将checkoutTimeout从100改为3000，问题修复。
猜测同事是没注意到单位是毫秒。

        <!--当连接池用完时客户端调用getConnection()后等待获取新连接的时间，超时后将抛出SQLException,如设为0则无限期等待。单位毫秒。Default: 0 -->    
        <!--<property name="c3p0.checkoutTimeout">100</property>100毫秒太短会引发database schema无法update的错误--> 
        <property name="c3p0.checkoutTimeout">3000</property>   

将这项配置去除，问题也修复，从日志中看到checkoutTimeout默认为0。
回头又看了一遍出错日志，发现出错日志的最前面就有下边这个建立连接超时的WARN，却被我直接忽略了。

2019-01-11 22:15:08:365 WARN [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.initiateService:132] HHH000342: Could not obtain connection to query metadata : An attempt by a client to checkout a Connection has timed out.
2019-01-11 22:15:08:378 INFO [org.hibernate.dialect.Dialect.<init>:156] HHH000400: Using dialect: org.hibernate.dialect.MySQL5Dialect
2019-01-11 22:15:08:399 INFO [org.hibernate.engine.jdbc.env.internal.LobCreatorBuilderImpl.makeLobCreatorBuilder:63] HHH000422: Disabling contextual LOB creation as connection was null

嗯，就是系统运行时，update配置有效，但由于建立连接时超时时间太短，连接失败，未查询到Table已经存在，就新建，然后也失败。