Reputation: 356

MySQL Hibernate Exception

i recently updated from mysql-connector-java 5.1.22 to 5.1.23. After that my application is constantly crashing on update or delete of persisted objects.

Mysql Connectors up to 5.1.22 (including 5.1.22) are working fine. MySQL Connectors from 5.1.23 (including 5.1.23) are not working.

Cause of the Problem seems to be the Time stamp i use for Optimistic locking. Optimistic locking with a Version seems to work fine. But i can't change the whole application and i need the Time stamp fields.

The changelog of 5.1.23 states the following bugfix:

If a timestamp value was passed through prepared statement parameters, fractional-second precision was stripped off, even if the underlying field (such as VARCHAR(255)) could store the full value. A workaround was to convert the timestamp value to a string when specifying the prepared statement argument, for example prepped_stmt.setString(1,time_stamp.toString(). This was partly fixed in 5.1.19, but that fix did not cover the case with the setting useLegacyDatetimeCode=true. (Bug #11750017, Bug #40279, Bug #60584)

I suspect this is the cause of my problems. Any ideas how to solve the problem? I appended a simple sample code causing the error.

---Exception

Jul 02, 2014 9:18:34 AM org.hibernate.annotations.common.reflection.java.JavaReflectionManager <clinit>
INFO: HCANN000001: Hibernate Commons Annotations {4.0.4.Final}
Jul 02, 2014 9:18:34 AM org.hibernate.Version logVersion
INFO: HHH000412: Hibernate Core {4.3.5.Final}
Jul 02, 2014 9:18:34 AM org.hibernate.cfg.Environment <clinit>
INFO: HHH000206: hibernate.properties not found
Jul 02, 2014 9:18:34 AM org.hibernate.cfg.Environment buildBytecodeProvider
INFO: HHH000021: Bytecode provider name : javassist
Jul 02, 2014 9:18:34 AM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure
WARN: HHH000402: Using Hibernate built-in connection pool (not for production use!)
Jul 02, 2014 9:18:34 AM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000401: using driver [com.mysql.jdbc.Driver] at URL [jdbc:mysql://localhost:3306/hibernatedb?useFastDateParsing=false]
Jul 02, 2014 9:18:34 AM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000046: Connection properties: {user=root, password=****}
Jul 02, 2014 9:18:34 AM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000006: Autocommit mode: false
Jul 02, 2014 9:18:34 AM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure
INFO: HHH000115: Hibernate connection pool size: 1 (min=1)
Jul 02, 2014 9:18:34 AM org.hibernate.dialect.Dialect <init>
INFO: HHH000400: Using dialect: org.hibernate.dialect.MySQLDialect
Jul 02, 2014 9:18:34 AM org.hibernate.engine.transaction.internal.TransactionFactoryInitiator initiateService
INFO: HHH000399: Using default transaction strategy (direct JDBC transactions)
Jul 02, 2014 9:18:34 AM org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory <init>
INFO: HHH000397: Using ASTQueryTranslatorFactory
Jul 02, 2014 9:18:35 AM org.hibernate.tool.hbm2ddl.SchemaExport execute
INFO: HHH000227: Running hbm2ddl schema export
Jul 02, 2014 9:18:35 AM org.hibernate.tool.hbm2ddl.SchemaExport execute
INFO: HHH000230: Schema export complete
MyPersistentObject (2014-07-02 09:18:35.0) : First persistent object
MyPersistentObject (2014-07-02 09:18:35.0) : A second persistent object
org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect) : [MyPersistentObject#2]
    at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:2541)
    at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:3403)
    at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:3630)
    at org.hibernate.action.internal.EntityDeleteAction.execute(EntityDeleteAction.java:114)
    at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:463)
    at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:349)
    at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:350)
    at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56)
    at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1222)
    at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:425)
    at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.beforeTransactionCommit(JdbcTransaction.java:101)
    at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.commit(AbstractTransactionImpl.java:177)
    at HibernateExample.manipulatePersistentObjects(HibernateExample.java:143)
    at HibernateExample.main(HibernateExample.java:15)
MyPersistentObject (2014-07-02 09:18:35.0) : First persistent object
MyPersistentObject (2014-07-02 09:18:35.0) : A second persistent object
Jul 02, 2014 9:18:35 AM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl stop
INFO: HHH000030: Cleaning up connection pool [jdbc:mysql://localhost:3306/hibernatedb?useFastDateParsing=false]

---main class

import org.hibernate.boot.registry.StandardServiceRegistryBuilder;
import org.hibernate.service.ServiceRegistry;

public class HibernateExample {
    private final org.hibernate.SessionFactory _sessionFactory;
    private MyPersistentObject _myPersistentObject1;
    private MyPersistentObject _myPersistentObject2;
    private MyPersistentObject _myPersistentObject3;

    final static public void main(final String arguments[]) {
        HibernateExample example;
        example = new HibernateExample();
        example.createPersistentObjects();
        example.readAndDisplayPersistentObjects();
        example.manipulatePersistentObjects();
        example.readAndDisplayPersistentObjects();
        example.cleanup();
    }

    private HibernateExample() {
        org.hibernate.cfg.Configuration configuration;

        java.util.logging.Logger.getLogger("org.hibernate").setLevel(java.util.logging.Level.SEVERE); // Supress
        // Hibernate's
        // excessive
        // output

        configuration = new org.hibernate.cfg.Configuration();
        configuration.setProperty("hibernate.dialect", "org.hibernate.dialect.MySQLDialect"); // Customize
        // this
        // for
        // your
        // particular
        // RDBMS
        configuration.setProperty("hibernate.connection.driver_class", "com.mysql.jdbc.Driver"); // Customize
        // this
        // for
        // your
        // particular
        // RDBMS

        // configuration.setProperty("hibernate.connection.url",
        // "jdbc:mysql://localhost:3306/hibernatedb?useLegacyDatetimeCode=true");
        // // Customize

        configuration.setProperty("hibernate.connection.url",
                "jdbc:mysql://localhost:3306/hibernatedb?useFastDateParsing=false"); // Customize

        // this
        // for
        // your
        // particular
        // RDBMS
        configuration.setProperty("hibernate.connection.username", "root"); // Customize
        // this
        // for
        // your
        // particular
        // RDBMS
        configuration.setProperty("hibernate.connection.password", "root"); // Customize
        // this
        // for
        // your
        // particular
        // RDBMS
        // installation
        configuration.setProperty("hibernate.connection.pool_size", "1"); // Customize
        // this
        // for
        // your
        // particular
        // RDBMS
        // installation
        configuration.setProperty("hibernate.cache.provider_class", "org.hibernate.cache.internal.NoCacheProvider"); // This
        // is
        // not
        // ready
        // for
        // prime-time
        configuration.setProperty("hibernate.show_sql", "false"); // Tell
        // hibernate
        // to not
        // echo the
        // SQL
        configuration.setProperty("hibernate.hbm2ddl.auto", "create");

        configuration.setProperty("useLegacyDatetimeCode", "true");

        configuration.addAnnotatedClass(MyPersistentObject.class);

        // configuration.configure();
        final ServiceRegistry serviceRegistry = new StandardServiceRegistryBuilder().applySettings(
                configuration.getProperties()).build();
        this._sessionFactory = configuration.buildSessionFactory(serviceRegistry);

    }

    final private void createPersistentObjects() {
        org.hibernate.Session session;
        boolean committed;
        org.hibernate.Transaction transaction;

        session = this._sessionFactory.openSession();

        try {
            committed = false;
            transaction = session.beginTransaction();

            try {
                this._myPersistentObject1 = new MyPersistentObject("First persistent object", new java.util.Date());
                session.save(this._myPersistentObject1);

                this._myPersistentObject2 = new MyPersistentObject("A second persistent object", new java.util.Date());
                session.save(this._myPersistentObject2);

                transaction.commit();
                session.flush();
                committed = true;
            } finally {
                if (!committed) {
                    transaction.rollback();
                }
            }
        } finally {
            session.close();
        }
    }

    final private void manipulatePersistentObjects() {
        org.hibernate.Session session;
        org.hibernate.Transaction transaction;

        session = this._sessionFactory.openSession();

        try {
            transaction = session.beginTransaction();

            this._myPersistentObject3 = new MyPersistentObject("A third persistent object", new java.util.Date());
            // session.save(this._myPersistentObject3);

            session.delete(this._myPersistentObject2);

            transaction.commit();
            session.flush();
        } catch (final Exception e) {
            e.printStackTrace();
        } finally {

            session.close();
        }
    }

    final private void readAndDisplayPersistentObjects() {
        org.hibernate.Session session;
        java.util.List<MyPersistentObject> result;

        session = this._sessionFactory.openSession();

        try {
            session.beginTransaction();

            result = (session.createQuery("from MyPersistentObject").list());

            for (final MyPersistentObject persistentObject : result) {
                System.out.println("MyPersistentObject (" + persistentObject.getDate() + ") : "
                        + persistentObject.getTitle());
            }

            session.getTransaction().commit();
            session.flush();
        } catch (final Exception e) {
            e.printStackTrace();
        } finally {
            session.close();
        }
    }

    final private void cleanup() {
        if (this._sessionFactory != null) {
            this._sessionFactory.close();
        }
    }
}

---Object

import java.util.Calendar;

import javax.persistence.PrePersist;
import javax.persistence.PreUpdate;
import javax.persistence.Version;

@javax.persistence.Entity
public class MyPersistentObject {

    @javax.persistence.Id
    @javax.persistence.GeneratedValue(generator = "increment")
    @org.hibernate.annotations.GenericGenerator(name = "increment", strategy = "increment")
    private Long _persistenceID;
    private String _title;
    @javax.persistence.Temporal(javax.persistence.TemporalType.TIMESTAMP)
    @javax.persistence.Column(name = "OBJECT_DATE")
    private java.util.Date _date;

    @Version
    private Calendar timestemp;

    // Hibernate needs a no-argument constructor
    private MyPersistentObject() {
    }

    // for application use, to create new persistent objects
    public MyPersistentObject(final String title, final java.util.Date date) {
        this._title = title;
        this._date = date;
    }

    public java.util.Date getDate() {
        return this._date;
    }

    public String getTitle() {
        return this._title;
    }

    @PrePersist
    protected void onCreate() {
        System.out.println("create");
    }

    @PreUpdate
    protected void onUpdate() {
        System.out.println("update");
    }
}

---pom

<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>
    <groupId>Hibernate34Migrate</groupId>
    <artifactId>Hibernate34Migrate</artifactId>
    <version>0.0.1-SNAPSHOT</version>

    <dependencies>
        <dependency>
            <groupId>org.hibernate</groupId>
            <artifactId>hibernate-core</artifactId>
            <version>4.3.5.Final</version>
            <type>jar</type>
            <scope>compile</scope>
        </dependency>
        <dependency>
            <groupId>org.hibernate</groupId>
            <artifactId>hibernate-ehcache</artifactId>
            <version>4.3.5.Final</version>
            <type>jar</type>
            <scope>compile</scope>
        </dependency>
        <dependency>
            <groupId>mysql</groupId>
            <artifactId>mysql-connector-java</artifactId>
            <version>5.1.31</version>
        </dependency>
    </dependencies>
</project>

Upvotes: 4

Answers (3)

Vlad Mihalcea

Reputation: 153820

I suggest you use the more reliable incremental version:
```
 @Version
 private short version;
```
Hibernate can handle deleting detached entities (In manipulatePersistentObjects(), the this._myPersistentObject2 is detached, being loaded in a different closed session), but JPA doesn't allow this behaviour.
You shouldn't flush after commit. If you are using AUTO flush mode, you don;t even have to call flush, since commit should trigger a flush too.

Upvotes: 0

Master Slave

Reputation: 28539

Kudos for Devabc, an excellent explanation. In fact the described issue is already reported as a hibernate issue

https://hibernate.atlassian.net/browse/HHH-3822 and related https://hibernate.atlassian.net/browse/HHH-9444, but more interestingly, a fix is suggested for mysql DB > 5.6.4. Basically, the proposal is to use a new Dialect implementation an extension of the MySQL5InnoDBDialect and register a convertor

public class ImprovedMySQL56Dialect extends MySQL5InnoDBDialect {

    public ImprovedMySQL56Dialect() {
        super();
        // http://dev.mysql.com/doc/refman/5.6/en/fractional-seconds.html
        registerColumnType( Types.TIMESTAMP, "datetime(6)" );
    }
}

its described in https://hibernate.atlassian.net/browse/HHH-8401

Upvotes: 0

Devabc

Reputation: 5271

Background info

MySQL < 5.6.4 doesn't support the storage of fractions

Before MySQL 5.6.4, MySQL did support some functions that are able to operate on fractions of a second, but MySQL didn't support the storage of fractions:

http://dev.mysql.com/doc/refman/5.6/en/fractional-seconds.html

However, when MySQL stores a value into a column of any temporal data type, it discards any fractional part and does not store it.

MySQL 5.6.4 and up expands fractional seconds support for TIME, DATETIME, and TIMESTAMP values, with up to microseconds (6 digits) precision:

To define a column that includes a fractional seconds part, use the syntax >type_name(fsp), where type_name is TIME, DATETIME, or TIMESTAMP, and fsp is the fractional seconds precision. For example:

CREATE TABLE t1 (t TIME(3), dt DATETIME(6));

MySQL Connector/J < 5.1.23 stripped off fractions

http://dev.mysql.com/doc/relnotes/connector-j/en/news-5-1-23.html

If a timestamp value was passed through prepared statement parameters, fractional-second precision was stripped off, even if the underlying field (such as VARCHAR(255)) could store the full value. A workaround was to convert the timestamp value to a string when specifying the prepared statement argument, for example prepped_stmt.setString(1,time_stamp.toString(). This was partly fixed in 5.1.19, but that fix did not cover the case with the setting useLegacyDatetimeCode=true. (Bug #11750017, Bug #40279, Bug #60584)

Problem: Hibernate uses 3 fraction digits ignoring MySQL

When Hibernate inserts an object that supports versioning into the database, it does something like this:

2014-nov-07;20:32:05.775 TRACE org.hibernate.engine.internal.Versioning - Seeding: 2014-11-07 20:32:05.774
2014-nov-07;20:32:05.786 TRACE org.hibernate.persister.entity.AbstractEntityPersister - Version: 7-11-14 20:32
2014-nov-07;20:32:05.787 DEBUG org.hibernate.SQL - insert into A (b_id, version) values (?, ?)
Hibernate: insert into A (b_id, version) values (?, ?)
2014-nov-07;20:32:05.799 TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [BIGINT] - [null]
2014-nov-07;20:32:05.799 TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [2] as [TIMESTAMP] - [2014-11-07 20:32:05.774]

So Hibernate seems to use internally 3 digits for fractional second precision and also tries to store the fraction into the database, even when the MySQL version doesn't support it.

When using the older Connector/J, the fractions are stripped off and the datetime (with second precision) is stored. When entity A is changed, Hibernate performs optimistic locking, and something like this happens:

2014-nov-07;20:32:05.822 DEBUG org.hibernate.internal.util.EntityPrinter - entities.B{id=27}
2014-nov-07;20:32:05.822 DEBUG org.hibernate.internal.util.EntityPrinter - entities.A{b=entities.B#27, id=29, version=2014-11-07 20:32:05.774}
2014-nov-07;20:32:05.825 TRACE org.hibernate.persister.entity.AbstractEntityPersister - Updating entity: [entities.A#29]
2014-nov-07;20:32:05.825 TRACE org.hibernate.persister.entity.AbstractEntityPersister - Existing version: 7-11-14 20:32 -> New version:7-11-14 20:32
2014-nov-07;20:32:05.825 DEBUG org.hibernate.SQL - update A set b_id=?, version=? where id=? and version=?
Hibernate: update A set b_id=?, version=? where id=? and version=?
2014-nov-07;20:32:05.826 TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [BIGINT] - [27]
2014-nov-07;20:32:05.826 TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [2] as [TIMESTAMP] - [2014-11-07 20:32:05.82]
2014-nov-07;20:32:05.826 TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [3] as [BIGINT] - [29]
2014-nov-07;20:32:05.826 TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [4] as [TIMESTAMP] - [2014-11-07 20:32:05.774]

(Not sure why Hibernate shows "20:32:05.82" as binding parameter, I would expect it to be a higher version, so maybe it truncate zeros and means "20:32:05.820", which is the same a the log fraction.)

But because the older Connector/J strips off the fraction in both the insert statement followed by also the Hibernate versioning update statement (in which the fraction is stripped from the SQL-WHERE clause), it doesn't cause the problem yet.

But when the new version (>= 5.1.23) of Connector/J is used, the fractions are preserved and do reach the database. This basically isn't a problem yet, it is even better than without fractions, because it is safer in terms of concurrency. But when the database column has type "DATETIME" (Hibernate default) which means "DATETIME(0)", which has no fractions, then the Hibernate versioning problem will occur, because

update A set b_id=?, version=? where id=? and version=?

will result in 0 updates, causing Hibernate to think that the "row was updated or deleted by another transaction".

Solution 1 (tested): add fractions to the column

Change the column type from "DATETIME" to "DATETIME(3)". This is probably a safe operation because MySQL simply appends fractions 000 to the datetimes.

For completeness, also add this to the versioned timestamp instance variable:

@Column(columnDefinition = "datetime(3)")

Solution 2 (tested): let MySQL generate the date version

If you don't want to add fractions to the column, but letting the database generate versions is no problem, then you can use the following approach:

Add the following to the verioned timestamp instance variable:

@Generated(GenerationTime.ALWAYS)

This will let Hibernate use the database column to generate versions.

Then change the column type from "datetime" to:

DATETIME DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP

This solution doesn't use fractions and thus is dangerous in terms of concurrency, even though is was normal behavior in Hibernate combined with using MySQL Connector/J < 5.1.23 or MySQL Server < 5.6.4.

Solution 3: use dedicated version numbers instead of datetimes

See http://docs.jboss.org/hibernate/orm/4.3/devguide/en-US/html/ch05.html#d5e1246

This is safe in terms of concurrency, but less convenient if you need the update-datetime anyway.

Discussion

It's a bit difficult to say whether this is a Hibernate bug. The best solution would be if Hibernate would automatically test whether the MySQL environment supports fractional datetime columns and if so, default to "datetime(3)" columns instead of "datetime". Or Hibernate should remove fractions from its internal versioning when the MySQL environment doesn't support it, but that is a bit dangerous in terms of concurrency.

Note

When using TemporalType.TIMESTAMP, Hibernates MySQL5InnoDBDialect doesn't use MySQL's TIMESTAMP, but uses DATETIME instead.

Upvotes: 2