8 Replies Latest reply on Oct 3, 2011 1:47 PM by Sicco Naets

    Possible bug in AuditReader.find()

    Sicco Naets Newbie

      I'm auditing some order data using Hibernate envers and Spring (hibernate version 3.6.7.Final, Spring version 3.0.6.RELEASE). The auditing part works fine - I can see revisions getting created as objects are created, modified and deleted. I've also customized the RevisionEntity to capture some additional data (who made the change) and that is getting stored properly as well.

       

      However, I'd now like to start retrieving some of the audit data. I've written methods to get a list of revisions for a given domain object; get the revision entity metadata for a given revision (so I know when the change was made and who made it) and I now want to implement a method that will allow me to retrieve revision x for a given domain object. And that's where I'm running into a problem.


      Here's the set up - I'm auditing an object named "ProvisioningOrder". In my testing, I first persist a Provisioning Order in the database; and then I modify it. This creates two revisions: revision 1 is where the provisioning order is created, revision 2 is where the order is modified. Looking at the data in the audit tables, everything is there and it's all correct.

       

      I then run a small unit test that retrieves the existing revision numbers for the ProvisioningOrder and then for each revision number, grabs the revision entity, prints it to console; and then grabs the actual revision instance and prints it to console as well.

       

      I correctly get a list of revision numbers, containing "1" and "2".

       

      I correctly get a list of Revision Entitiies which show when revision 1 and 2 were created and who made the change

       

      But when I try to get the actual revisions 1 and 2 of my provisioning order, I respectively get "null" for revision 1 and an error for revision 2 (specifically, it's complaining that a dependent object (e911Info) with identifier 1 does not exist; even though it does exist in the database).

       

      I think I know where the problem lies too: I turned on tracing on the Hibernate queries that get run, and the query that's getting run against the audit table when I execute  getReader().find(ProvisioningOrder.class, id, revisionNumber); is wrong. It runs:

       

       

      DEBUG org.hibernate.SQL:logStatement select provisioni0_.id as id11_, provisioni0_.REV as REV11_, provisioni0_.REVTYPE as REVTYPE11_, provisioni0_.title as title11_, provisioni0_.end_customer as end5_11_, provisioni0_.creation_date as creation6_11_, provisioni0_.requested_date as requested7_11_, provisioni0_.completed_date as completed8_11_, provisioni0_.csa_id as csa9_11_, provisioni0_.type as type11_, provisioni0_.status as status11_, provisioni0_.creator as creator11_, provisioni0_.address_id as address13_11_, provisioni0_.e911_id as e14_11_, provisioni0_.did_request_id as did15_11_, provisioni0_.directory_listing_id as directory16_11_ from audit_tpn_prov_order provisioni0_ where (provisioni0_.REV=(select max(provisioni1_.REV) from audit_tpn_prov_order provisioni1_ where (provisioni1_.REV<=? )and(provisioni0_.id=provisioni1_.id )))and(provisioni0_.REVTYPE<>? )and(provisioni0_.id=? )

      2011-09-28 10:11:47 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder:bind binding parameter [1] as [BIGINT] - 2

      2011-09-28 10:11:47 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder:bind binding parameter [3] as [BIGINT] - 1

      2011-09-28 10:11:47 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder:bind binding parameter [2] as [VARBINARY] - DEL

       

      Note the parameter binding... parameter 2 is getting bound with the value "DEL". The problem is that this parameter is getting bound to provisioni0_REVTYPE<>?. In other words, the query AuditReader.find() is generating is trying to find rows in the audit table where the REVTYPE is NOT a delete. However, envers normally stores the REVTYPE as a number (0,1 and 2 respectively). Running a query that essentially is SELECT * from audit_table where REVTYPE <> 'DEL' will never return a result.

       

      If I manually run this query myself against the database, it finds no results. If, instead, I change the 'DEL' with '2' (which is correct), the query correctly returns revision 1.

       

      So to me, it seems as if envers is generating a flawed SQL query when running AuditReader.find() - any ideas on how to fix this?

       


      Source code below:

       

      Hibernate mapping for ProvisioningOrder:

       

       

      <?xml version="1.0"?>

      <!DOCTYPE hibernate-mapping PUBLIC "-//Hibernate/Hibernate Mapping DTD 3.0//EN"

      "http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">

      <!-- Generated 14-May-2010 4:17:41 PM by Hibernate Tools 3.2.4.GA -->

      <hibernate-mapping>

          <class name="com.thinkingphones.provorders.model.ProvisioningOrder" table="tpn_prov_order">

          <cache usage="read-write"/>

              <id name="id" type="java.lang.Long">

                  <column name="id" />

                   <generator class="identity" />

              </id>

              <many-to-one name="addressInfo" class="com.thinkingphones.provorders.model.AddressInfo" fetch="join" cascade="all" unique="true">

                        <column name="address_id"/>

              </many-to-one>

              <many-to-one name="e911Info" class="com.thinkingphones.provorders.model.E911Info" cascade="all" fetch="join" unique="true">

                        <column name="e911_id"/>

              </many-to-one>

              <many-to-one name="didRequest" class="com.thinkingphones.provorders.model.DIDRequest" cascade="all" fetch="join" unique="true">

                        <column name="did_request_id"/>

              </many-to-one>

              <many-to-one name="directoryListingInfo" class="com.thinkingphones.provorders.model.DirectoryListingInfo" cascade="all" fetch="join">

                        <column name="directory_listing_id"/>

              </many-to-one>

              <property name="title" type="string" not-null="true">

                  <column name="title" length="255" />

              </property>

              <property name="endCustomer" type="string">

                        <column name="end_customer" length="255"/>

              </property>

              <property name="creationDate" type="timestamp" not-null="true">

                  <column name="creation_date" />

              </property>

              <property name="requestedDate" type="timestamp">

                        <column name="requested_date"/>

              </property>

              <property name="completedDate" type="timestamp">

                        <column name="completed_date"/>

              </property>

              <property name="csaID" type="java.lang.Long">

                        <column name="csa_id"/>

              </property>

              <property name="type">

                        <column name="type" length="20" not-null="true" />

                        <type name="org.hibernate.type.EnumType">

                                  <param name="enumClass">

                                            com.thinkingphones.provorders.model.ProvisioningOrderType

                                  </param>

                                  <param name="type">12</param>

                        </type>

              </property>

              <property name="status">

                        <column name="status" length="20" not-null="true" />

                        <type name="org.hibernate.type.EnumType">

                                  <param name="enumClass">

                                            com.thinkingphones.provorders.model.ProvisioningOrderStatus

                                  </param>

                                  <param name="type">12</param>

                        </type>

              </property>

              <property name="creatorID" type="string">

                        <column name="creator" length="255"/>

              </property>

              <list name="commentList" table="tpn_prov_order_list_comment" fetch="subselect" lazy="false" cascade="all">

                              <key column="prov_order_id" not-null="true" />

                              <list-index column="list_index"/>

                              <many-to-many column="comment_id" class="com.thinkingphones.provorders.model.Comment" />

                          </list>

          </class>

      </hibernate-mapping>

       

      SessionFactory in Spring:

       

       

      <!-- define Hibernate Session factories -->

                          <bean id="sessionFactory"

                                    class="org.springframework.orm.hibernate3.LocalSessionFactoryBean">

                                              <property name="dataSource" ref="datasource"/>

                                              <property name="mappingResources">

                                                        <list>

                                                                  <value>hibernate/AddressInfo.hbm.xml</value>

                                                                  <value>hibernate/Comment.hbm.xml</value>

                                                                  <value>hibernate/DIDRequest.hbm.xml</value>

                                                                  <value>hibernate/DIDReservation.hbm.xml</value>

                                                                  <value>hibernate/DirectoryListingInfo.hbm.xml</value>

                                                                  <value>hibernate/E911Info.hbm.xml</value>

                                                                  <value>hibernate/ProvisioningOrder.hbm.xml</value>

                                                                  <value>hibernate/RevisionEntity.hbm.xml</value>

                                                        </list>

                                              </property>

                                              <property name="hibernateProperties">

                                                        <props>

                                                                  <prop key="hibernate.dialect">org.hibernate.dialect.MySQLDialect</prop>

                                                                  <prop key="hibernate.cache.provider_class">org.hibernate.cache.EhCacheProvider</prop>

                                                                  <prop key="hibernate.show.sql">true</prop>

                                                                  <prop key="hibernate.query.factory_class">org.hibernate.hql.classic.ClassicQueryTranslatorFactory</prop> 

                                                                  <prop key="org.hibernate.envers.audit_table_prefix">audit_</prop>

                                                                  <prop key="org.hibernate.envers.audit_table_suffix"></prop>

                                                                  <prop key="org.hibernate.envers.store_data_at_delete">true</prop>

                                                        </props>

                                              </property>

                                              <property name="eventListeners">

                                                        <map>

                                                                  <entry key="post-insert" value-ref="enversListener" />

                                                      <entry key="post-update" value-ref="enversListener" />

                                                      <entry key="post-delete" value-ref="enversListener" />

                                                      <entry key="pre-collection-update" value-ref="enversListener" />

                                                      <entry key="pre-collection-remove" value-ref="enversListener" />

                                                      <entry key="post-collection-recreate" value-ref="enversListener" />

                                                        </map>

                                              </property>

                          </bean>

       

       

      DAO Object to query revision data:

       

      public abstract class AbstractDomainObjectDAO<T extends DomainObject<?>> extends HibernateDaoSupport implements DomainObjectDAO<T> {

       

                @Override

                public Long persistNew(T dataObject) {

                          LOGGER.debug("Persisting " + dataObject + " to Hibernate");

                          Long id = (Long)this.getHibernateTemplate().save(dataObject);

       

                          return id;

                }

       

       

                @Override

                public T fetchObject(Serializable id) {

                          return this.getHibernateTemplate().get(this.getDomainObjectClass(), id);

                }

       

       

                @Override

                public T update(T dataObject) {

                          LOGGER.debug("Saving " +dataObject + " back to persistence store.");

                          T mergedObject = this.getHibernateTemplate().merge(dataObject);

       

                          return mergedObject;

                }

       

       

                @Override

                public T remove(T dataObject) {

                          LOGGER.debug("Deleting "+ dataObject + " from persistence store.");

                          this.getHibernateTemplate().delete(dataObject);

                          return dataObject;

                }

       

                @Override

                public T getRevision(Serializable id, Long revisionNumber) throws NotAuditedException, RevisionDoesNotExistException

                {

                          LOGGER.debug("Loading " + getDomainObjectClass() +"(" + id+") at revision "+ revisionNumber);

                          return getReader().find(getDomainObjectClass(), id, revisionNumber);

                }

       

                @Override

                public Number getCurrentRevisionNumber(Serializable id) throws RevisionDoesNotExistException

                {

                          return getReader().getRevisionNumberForDate(new Date());

                }

       

                @Override

                public RevisionEntity getRevisionEntity(Long revisionNumber) throws RevisionDoesNotExistException

                {

       

                          RevisionEntity entity =this.getHibernateTemplate().get(RevisionEntity.class, revisionNumber);

                          return entity;

                }

       

                @Override

                public List<Number> getRevisionNumbers(Serializable id) throws NotAuditedException

                {

                          return getReader().getRevisions(getDomainObjectClass(), id);

                }

       

       

       

                @SuppressWarnings("unchecked")

                public Class<T> getDomainObjectClass()

                {

                          Class<?> c = this.getClass();

              Type superTypeClass = c.getGenericSuperclass();

              if (ParameterizedType.class.isAssignableFrom(superTypeClass.getClass()))

              {

                              ParameterizedType superclass = (ParameterizedType) superTypeClass;

                              return (Class<T>) superclass.getActualTypeArguments()[0];

              }

              else

              {

                              throw new IllegalArgumentException("Cannot determine parameterized class!");

              }

       

       

                }

       

                protected AuditReader getReader()

                {

                          Session session = this.getSession();

                          AuditReader reader = AuditReaderFactory.get(session);

                          return reader;

                }

       

      Unit Test to replicate problem:

       

      @ContextConfiguration("classpath:spring/testContext.xml")

      public class RevisionTests extends SpringTest{

       

       

                private static final Logger LOGGER  = LoggerFactory.getLogger(RevisionTests.class);

                protected ProvisioningOrderDAO dao;

       

                @Parameters({"id"})

                @Test(groups="id")

                public void doTest(Long id)

                {

                          List<Number> revisionNumberList = dao.getRevisionNumbers(id);

       

                          for(Number revisionNumber : revisionNumberList)

                          {

                                    LOGGER.debug("Revision " + revisionNumber.intValue());

                                    RevisionEntity entity = dao.getRevisionEntity(revisionNumber.longValue());

       

                                    LOGGER.debug("Revision Entity:" +entity.toString());

       

                                    ProvisioningOrder order = dao.getRevision(id, revisionNumber.longValue());

                                    LOGGER.debug("Revision object:" + order);

                          }

       

                }

       

       

                /**

                 * @return the dao

                 */

                public ProvisioningOrderDAO getDao() {

                          return dao;

                }

       

       

                /**

                 * @param dao the dao to set

                 */

                @Resource(name="provisioningOrderDAO")

                public void setDao(ProvisioningOrderDAO dao) {

                          this.dao = dao;

                }

       

      }

        • 1. Re: Possible bug in AuditReader.find()
          Sicco Naets Newbie

          Ok, after digging through the envers source code, I think I've found the problem:

           

          In the class org.hibernate.envers.query.impl.EntitiesAtRevisionQuery, line 91 (inside the list method) reads:

           

               qb.getRootParameters().addWhereWithParam(verEntCfg.getRevisionTypePropName(), "<>", RevisionType.DEL);

           

          This line adds the logic for selection revisions that are not deletes to the query I quoted ealier; by adding a root "WHERE" parameter to org.hibernate.envers.tools.query.QueryBuilder (the qb in this snippet of code).

           

          Eventually, the queryBuilder is used to create a hibernate query; and I suspect what's happening is that is simply calls .toString() on RevisionType.DEL; which would result in the word 'DEL' getting bound as that parameter (which, as we saw earlier, returns no results.)


          I think the correct fix would be to replace that line with:

           

                qb.getRootParameters().addWhereWithParam(verEntCfg.getRevisionTypePropName(), "<>", RevisionType.DEL.getRepresentation());

           

          This would return a Byte object containing the correct numerical representation of RevisionType.DEL and allow the query to work.

          • 2. Re: Possible bug in AuditReader.find()
            Adam Warski Master

            This is really weird, it looks like in your case Hibernate may incorrectly convert the enum to a number.

            Now we only need to find out why it happens so Especially that it works in all other places (haven't heard about such a problem before).

             

            You are using a regular MySQL, right? Version 5? Anything other that you would consider unusual in your setup?


            Adam

            • 3. Re: Possible bug in AuditReader.find()
              Sicco Naets Newbie

              Aaah, so it's not how it's querying the data that's the problem; it's how it's persisting it? And yeah, it didn't make sense to me that this would be a bug... AuditReader.find() is pretty basic, other people would have to have run into it. So yeah, something about my environment no doubt; but what?

               

              I'm using MySQL 5.1.42. The application is actually a webservice app using CXF. It's deployed on Tomcat 7.0.21, using JDK 1.6.0_22 We do have a fairly large application stack and we've put all the jars in the container while the spring and hibernate mapping files are in the webapp. But I don't think that's particularly unusual.

               

              Initially, I had created the audit tables manually. When I ran in to this auditing problem; I dropped the audit tables and the main domain object tables and had hibernate create them from the mapping files instead by setting the hiberate.hbm2ddl.auto flag. Just to rule that out, really. In both cases, REVTYPE ended up being a TINYINT.

               

              Here is the provisioning order audit table:

               

              CREATE TABLE `audit_tpn_prov_order` (

                `id` bigint(20) NOT NULL,

                `REV` bigint(20) NOT NULL,

                `REVTYPE` tinyint(4) default NULL,

                `title` varchar(255) default NULL,

                `end_customer` varchar(255) default NULL,

                `creation_date` datetime default NULL,

                `requested_date` datetime default NULL,

                `completed_date` datetime default NULL,

                `csa_id` bigint(20) default NULL,

                `type` varchar(20) default NULL,

                `status` varchar(20) default NULL,

                `creator` varchar(255) default NULL,

                `address_id` bigint(20) default NULL,

                `e911_id` bigint(20) default NULL,

                `did_request_id` bigint(20) default NULL,

                `directory_listing_id` bigint(20) default NULL,

                PRIMARY KEY  (`id`,`REV`),

                KEY `FK6D2E74C9EB66ED70` (`REV`),

                CONSTRAINT `FK6D2E74C9EB66ED70` FOREIGN KEY (`REV`) REFERENCES `tpn_prov_order_rev_info` (`revision_id`)

              ) ENGINE=InnoDB DEFAULT CHARSET=latin1;

               

               

              I did try just now changing the data type of REVTYPE to enum('ADD','MOD',DEL'). When I did that, envers  blows up trying to persist to the table with the following exception:

               

               

              org.springframework.dao.DataIntegrityViolationException: Hibernate flushing: Could not execute JDBC batch upd

              ate; SQL [insert into audit_tpn_prov_order (REVTYPE, title, end_customer, creation_date, requested_date, completed_date,

              csa_id, type, status, creator, address_id, e911_id, did_request_id, directory_listing_id, id, REV) values (?, ?, ?, ?,

              ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)]; Data truncated for column 'REVTYPE' at row 1; nested exception is java.sql.BatchUp

              dateException: Data truncated for column 'REVTYPE' at row 1

               

               

              So I suspect it has to be a TINYINT; but maybe hibernate is having problems converting to and from the RevisionType enum? And if so, why?

               

              The only other thing I can think of is that it's some hibernate version problem.. maybe an incompatibility between two jars? Like I said - we're pulling in a lot of stuff into the container...

               

               

              For hibernate specifically, I see the following jars:

               

               

              hibernate-commons-annotations-3.2.0.Final.jar

              hibernate-core-3.6.7.Final.jar

              hibernate-ehcache-3.6.7.Final.jar

              hibernate-entitymanager-3.6.7.Final.jar

              hibernate-envers-3.6.7.Final.jar

              hibernate-jpa-2.0-api-1.0.1.Final.jar

              hibernate-tools-3.2.0.ga.jar

               

              We're managing the container jars via a parent POM project that all out other projects inherit. I took a look at the hibernate dependencies but it seems like the lower versions like hibernate-tools.3.2.0 are getting pulled in transiently by the 3.6.7.Final release. So I don't think that's the problem either.

               

              The full set of jars in the container is:

               

               

               

              28/09/2011  02:37 PM           248,639 annogen-0.1.0.jar

              28/09/2011  02:37 PM         1,289,806 ant-1.7.0.jar

              28/09/2011  02:37 PM            11,734 ant-launcher-1.7.0.jar

              28/09/2011  02:37 PM           445,288 antlr-2.7.7.jar

              28/09/2011  02:37 PM             4,467 aopalliance-1.0.jar

              28/09/2011  02:37 PM            43,581 asm-3.3.1.jar

              28/09/2011  02:37 PM         8,802,159 aspectjtools-1.6.8.jar

              28/09/2011  02:37 PM           473,285 asterisk-java-1.0.0.M3.jar

              28/09/2011  02:37 PM           427,742 axiom-api-1.2.11.jar

              28/09/2011  02:37 PM           159,057 axiom-dom-1.2.11.jar

              28/09/2011  02:37 PM           122,415 axiom-impl-1.2.11.jar

              28/09/2011  02:37 PM           689,180 axis2-adb-1.6.0.jar

              28/09/2011  02:37 PM           179,618 axis2-adb-codegen-1.6.0.jar

              28/09/2011  02:37 PM           254,358 axis2-codegen-1.6.0.jar

              28/09/2011  02:37 PM            16,422 axis2-fastinfoset-1.6.0.jar

              28/09/2011  02:37 PM            27,739 axis2-java2wsdl-1.6.0.jar

              28/09/2011  02:37 PM            28,679 axis2-jaxbri-1.6.0.jar

              28/09/2011  02:37 PM           741,267 axis2-jaxws-1.6.0.jar

              28/09/2011  02:37 PM            47,452 axis2-jaxws-api-1.4.1.jar

              28/09/2011  02:37 PM            14,737 axis2-jws-api-1.4.1.jar

              28/09/2011  02:37 PM         1,040,584 axis2-kernel-1.6.0.jar

              28/09/2011  02:37 PM           430,582 axis2-metadata-1.6.0.jar

              28/09/2011  02:37 PM            13,728 axis2-mtompolicy-1.6.0.jar

              28/09/2011  02:37 PM            89,063 axis2-saaj-1.6.0.jar

              28/09/2011  02:37 PM            31,136 axis2-saaj-api-1.4.1.jar

              28/09/2011  02:37 PM            11,453 axis2-spring-1.6.0.jar

              28/09/2011  02:37 PM           152,386 axis2-transport-http-1.6.0.jar

              28/09/2011  02:37 PM            16,106 axis2-transport-local-1.6.0.jar

              28/09/2011  02:37 PM           331,716 backport-util-concurrent-3.1.jar

              28/09/2011  02:37 PM         1,719,483 bcprov-jdk16-1.45.jar

              28/09/2011  02:37 PM           281,694 bsh-2.0b4.jar

              28/09/2011  02:37 PM           278,682 cglib-2.2.jar

              28/09/2011  02:37 PM           232,019 commons-beanutils-1.8.3.jar

              28/09/2011  02:37 PM            41,123 commons-cli-1.2.jar

              28/09/2011  02:37 PM            58,160 commons-codec-1.4.jar

              28/09/2011  02:37 PM           575,389 commons-collections-3.2.1.jar

              28/09/2011  02:37 PM            13,619 commons-daemon-1.0.1.jar

              28/09/2011  02:37 PM           160,519 commons-dbcp-1.4.jar

              28/09/2011  02:37 PM           196,768 commons-digester-2.1.jar

              28/09/2011  02:37 PM            76,685 commons-discovery-0.4.jar

              28/09/2011  02:37 PM            57,779 commons-fileupload-1.2.1.jar

              28/09/2011  02:37 PM           305,001 commons-httpclient-3.1.jar

              28/09/2011  02:37 PM           109,043 commons-io-1.4.jar

              28/09/2011  02:37 PM           279,193 commons-lang-2.5.jar

              28/09/2011  02:37 PM           197,067 commons-net-2.0.jar

              28/09/2011  02:37 PM            96,221 commons-pool-1.5.4.jar

              28/09/2011  02:37 PM           362,717 commons-vfs-1.0.jar

              28/09/2011  02:37 PM         5,578,682 cxf-bundle-2.4.2.jar

              28/09/2011  02:37 PM           313,898 dom4j-1.6.1.jar

              28/09/2011  02:37 PM           233,018 dozer-5.3.1.jar

              28/09/2011  02:37 PM         1,006,424 ehcache-core-2.4.3.jar

              28/09/2011  02:37 PM           573,345 ehcache-terracotta-2.2.0.jar

              28/09/2011  02:37 PM           291,834 FastInfoset-1.2.7.jar

              28/09/2011  02:37 PM           802,494 freemarker-2.3.8.jar

              28/09/2011  02:37 PM            60,214 geronimo-jaxws_2.2_spec-1.0.jar

              28/09/2011  02:37 PM            29,445 geronimo-saaj_1.3_spec-1.0.1.jar

              28/09/2011  02:37 PM            96,323 geronimo-servlet_3.0_spec-1.0.jar

              28/09/2011  02:37 PM            14,611 geronimo-ws-metadata_2.0_spec-1.1.2.jar

              28/09/2011  02:37 PM         1,190,462 h2-1.2.143.jar

              28/09/2011  02:37 PM         1,138,816 hazelcast-1.9.2.2.jar

              28/09/2011  02:37 PM           139,320 hazelcast-client-1.9.2.2.jar

              28/09/2011  02:37 PM            31,586 hazelcast-hibernate-1.9.2.2.jar

              28/09/2011  02:37 PM            19,090 hazelcast-spring-1.9.2.2.jar

              28/09/2011  02:37 PM            71,283 hibernate-commons-annotations-3.2.0.Final.jar

              28/09/2011  02:37 PM         3,113,971 hibernate-core-3.6.7.Final.jar

              28/09/2011  02:37 PM            11,280 hibernate-ehcache-3.6.7.Final.jar

              28/09/2011  02:37 PM           421,596 hibernate-entitymanager-3.6.7.Final.jar

              28/09/2011  02:37 PM           319,701 hibernate-envers-3.6.7.Final.jar

              28/09/2011  02:37 PM           102,661 hibernate-jpa-2.0-api-1.0.1.Final.jar

              28/09/2011  02:37 PM           349,357 hibernate-tools-3.2.0.ga.jar

              28/09/2011  02:37 PM           292,893 httpclient-4.0.3.jar

              28/09/2011  02:37 PM           181,041 httpcore-4.1.jar

              28/09/2011  02:37 PM           195,783 httpcore-nio-4.1.jar

              28/09/2011  02:37 PM            20,184 httpcore-niossl-4.0-alpha6.jar

              28/09/2011  02:37 PM         1,130,070 itext-2.1.7.jar

              28/09/2011  02:37 PM            13,417 javacsv-2.0.jar

              28/09/2011  02:37 PM           633,312 javassist-3.12.0.GA.jar

              28/09/2011  02:37 PM           647,917 javassist-3.14.0-GA.jar

              28/09/2011  02:37 PM            25,176 javatar-2.5.jar

              28/09/2011  02:37 PM            89,967 jaxb-api-2.1.jar

              28/09/2011  02:37 PM           876,610 jaxb-impl-2.1.13.jar

              28/09/2011  02:37 PM         3,103,700 jaxb-xjc-2.1.13.jar

              28/09/2011  02:37 PM           226,915 jaxen-1.1.1.jar

              28/09/2011  02:37 PM           317,042 jaxme-0.3.1.jar

              28/09/2011  02:37 PM           509,137 jaxws-tools-2.1.3.jar

              28/09/2011  02:37 PM            17,306 jcl-over-slf4j-1.6.0.jar

              28/09/2011  02:37 PM           543,044 joda-time-1.6.2.jar

              28/09/2011  02:37 PM           871,260 js-1.7R2.jar

              28/09/2011  02:37 PM             5,848 jsr250-api-1.0.jar

              28/09/2011  02:37 PM            44,263 jsr311-api-1.0.jar

              28/09/2011  02:37 PM           414,240 jstl-1.2.jar

              28/09/2011  02:37 PM            15,071 jta-1.1.jar

              28/09/2011  02:37 PM           249,028 jtidy-r8-20060801.jar

              28/09/2011  02:37 PM           237,047 junit-4.8.1.jar

              28/09/2011  02:37 PM           743,361 jxl-2.6.10.jar

              28/09/2011  02:37 PM            48,521 jzlib-1.0.7.jar

              29/09/2011  11:09 AM                 0 list.txt

              28/09/2011  02:37 PM           238,358 logback-classic-0.9.24.jar

              28/09/2011  02:37 PM           300,550 logback-core-0.9.24.jar

              28/09/2011  02:37 PM           434,923 mail-1.4.2.jar

              28/09/2011  02:37 PM           635,088 mybatis-3.0.5.jar

              28/09/2011  02:37 PM             9,402 mybatis-hazelcast-1.0.0-RC1.jar

              28/09/2011  02:37 PM           767,492 mysql-connector-java-5.1.13.jar

              28/09/2011  02:37 PM            70,663 neethi-3.0.1.jar

              28/09/2011  02:37 PM         1,289,630 opensaml-2.4.1.jar

              28/09/2011  02:37 PM           564,457 openws-1.4.1.jar

              28/09/2011  02:37 PM            65,261 oro-2.0.8.jar

              28/09/2011  02:37 PM           106,577 p6spy-1.3.jar

              28/09/2011  02:37 PM           510,170 postgresql-8.4-701.jdbc4.jar

              28/09/2011  02:37 PM           445,651 quartz-1.8.4.jar

              28/09/2011  02:37 PM           212,117 rampart-core-1.3.jar

              28/09/2011  02:37 PM           156,070 rampart-policy-1.3.jar

              28/09/2011  02:37 PM            68,502 rampart-trust-1.3.jar

              28/09/2011  02:37 PM            18,817 saaj-api-1.3.jar

              28/09/2011  02:37 PM           278,145 saaj-impl-1.3.2.jar

              28/09/2011  02:37 PM            18,470 scannotation-1.0.2.jar

              28/09/2011  02:37 PM           278,281 serializer-2.7.1.jar

              28/09/2011  02:37 PM            25,496 slf4j-api-1.6.0.jar

              28/09/2011  02:37 PM           321,428 spring-aop-3.0.6.RELEASE.jar

              28/09/2011  02:37 PM            53,082 spring-asm-3.0.6.RELEASE.jar

              28/09/2011  02:37 PM            35,557 spring-aspects-3.0.6.RELEASE.jar

              28/09/2011  02:37 PM           556,590 spring-beans-3.0.6.RELEASE.jar

              28/09/2011  02:37 PM           670,258 spring-context-3.0.6.RELEASE.jar

              28/09/2011  02:37 PM           101,450 spring-context-support-3.0.6.RELEASE.jar

              28/09/2011  02:37 PM           382,184 spring-core-3.0.6.RELEASE.jar

              28/09/2011  02:37 PM           169,752 spring-expression-3.0.6.RELEASE.jar

              28/09/2011  02:37 PM           386,033 spring-jdbc-3.0.6.RELEASE.jar

              28/09/2011  02:37 PM           185,408 spring-jms-3.0.6.RELEASE.jar

              28/09/2011  02:37 PM           224,641 spring-ldap-core-1.3.0.RELEASE.jar

              28/09/2011  02:37 PM           334,743 spring-orm-3.0.6.RELEASE.jar

              28/09/2011  02:37 PM            61,379 spring-oxm-3.0.6.RELEASE.jar

              28/09/2011  02:37 PM           205,276 spring-test-3.0.6.RELEASE.jar

              28/09/2011  02:37 PM           231,913 spring-tx-3.0.6.RELEASE.jar

              28/09/2011  02:37 PM           398,149 spring-web-3.0.6.RELEASE.jar

              28/09/2011  02:37 PM           419,488 spring-webmvc-3.0.6.RELEASE.jar

              28/09/2011  02:37 PM           175,647 spring-webmvc-portlet-3.0.6.RELEASE.jar

              28/09/2011  02:37 PM           393,259 standard-1.1.2.jar

              28/09/2011  02:37 PM            23,346 stax-api-1.0-2.jar

              28/09/2011  02:37 PM           182,112 stax2-api-3.1.1.jar

              28/09/2011  02:37 PM         1,856,504 svnkit-1.3.4.jar

              28/09/2011  02:37 PM        12,586,245 terracotta-toolkit-1.0-runtime-1.0.0.jar

              28/09/2011  02:37 PM           526,452 testng-5.14.jar

              28/09/2011  02:37 PM            35,898 tiles-api-2.2.2.jar

              28/09/2011  02:37 PM           161,001 tiles-core-2.2.2.jar

              28/09/2011  02:37 PM            21,175 tiles-el-2.2.2.jar

              28/09/2011  02:37 PM            50,740 tiles-jsp-2.2.2.jar

              28/09/2011  02:37 PM            59,739 tiles-servlet-2.2.2.jar

              28/09/2011  02:37 PM            11,552 tiles-servlet-wildcard-2.2.2.jar

              28/09/2011  02:37 PM            24,466 tiles-template-2.2.2.jar

              28/09/2011  02:37 PM         4,458,998 vaadin-6.6.6.jar

              28/09/2011  02:37 PM           421,339 velocity-1.6.4.jar

              28/09/2011  02:37 PM           150,102 woden-api-1.0M9.jar

              28/09/2011  02:37 PM           186,268 woden-impl-commons-1.0M9.jar

              28/09/2011  02:37 PM            48,704 woden-impl-dom-1.0M9.jar

              28/09/2011  02:37 PM           483,862 woodstox-core-asl-4.0.8.jar

              28/09/2011  02:37 PM           148,429 wsdl4j-1.6.2.jar

              28/09/2011  02:37 PM           323,799 wss4j-1.5.8.jar

              28/09/2011  02:37 PM           524,224 wstx-asl-3.2.9.jar

              28/09/2011  02:37 PM         3,176,148 xalan-2.7.1.jar

              28/09/2011  02:37 PM           194,354 xml-apis-1.3.04.jar

              28/09/2011  02:37 PM            84,091 xml-resolver-1.2.jar

              28/09/2011  02:37 PM         2,694,049 xmlbeans-2.4.0.jar

              28/09/2011  02:37 PM           160,085 xmlschema-core-2.0.jar

              28/09/2011  02:37 PM           450,163 xmlsec-1.4.4.jar

              28/09/2011  02:37 PM           610,447 xmltooling-1.3.1.jar

              • 4. Re: Possible bug in AuditReader.find()
                Adam Warski Master

                Now that's a lot of dependencies!


                Anyway, tinyint is the correct column type.

                If you take a look at org.hibernate.envers.entities.RevisionTypeType, that's where the mapping is. Maybe you can try to debug if during the find(), the nullSafeSet is called? (I think it should). That's basically the place where RevisionType.getRepresentation is called to convert an enum into a number.

                 

                Adam

                • 5. Re: Possible bug in AuditReader.find()
                  Sicco Naets Newbie

                  Hey Adam,

                   

                   

                  I took your advice and rigged up the whole thing in Eclipse, so I could put some breakpoints in and run it in debug mode. I took some several hours and some serious sleuthing, butI think I've figured out what's going on... there IS a bug in the envers code; but I think most databases can safely handle the bug whereas apparently, the version of MySQL I'm on can't.Bear with me, and I'll explain what I found....

                   

                   

                  For my testing, I create an order (rev 1), then modify the same order (rev 2) and then query Envers for revision 1 of that order via the AuditReader.find() method.

                   

                   

                  First of all - I can see that the RevisionTypeType.NullSafeSet() method is correctly getting called when the audit entry is persisted; both for rev 1 and rev 2. But for the AuditReader.find() method, RevisionTypeType.NullSafeSet() is never called. Instead, what happens is this (I'm glossing over several intermediate steps for the sake of legibility)

                   

                   

                  Line 91 of org.hibernate.envers.query.impl.EntitiesAtRevisionQuery.list():

                   

                   

                  qb.getRootParameters().addWhereWithParam(verEntCfg.getRevisionTypePropName(), "<>", RevisionType.DEL);

                   

                   

                    RevisionType.DEL is added as a root parameter to the queryBuilder. If you look through the call stack for this method; you can see that the Enum instance RevisionType.DEL is added as a raw object value for the REVTYPE parameter (which has a localQueryParamName of "_p0").

                   

                   

                  Line 430 of org.hibernate.impl.AbstractQueryImpl.setParameter():

                   

                   

                  setParameter( name, val, determineType( name, val ) );

                   

                   

                    the "_p0" parameter is set with the value RevisionType.DEL. As part of this call, the org.hibernate.type.Type of RevisionType.DEL is determined.

                   

                  Method org.hibernate.type.TypeFactory.byClass()

                   

                   

                  public Type byClass(Class clazz, Properties parameters)

                   

                    This method is supposed to determine the hibernate Type of a given Class. It checks for a number of things; I suspect what SHOULD be happening is this:

                   

                  if ( UserType.class.isAssignableFrom( clazz ) ) {

                    return custom( (Class<UserType>) clazz, parameters );

                   

                    }

                   

                    However, because RevisionType does not implement UserType, instead it comes back with this:

                   

                    if ( Serializable.class.isAssignableFrom( clazz ) ) {

                    return serializable( clazz );

                    }

                   

                    In other words, the RevisionType parameter is classified as a generic "org.hibernate.type.SerializableType<T>" (where T is org.hibernate.envers.RevisionType).

                   

                  Line 1919 of the org.hibernate.loader.Loader

                   

                   

                  typedval.getType().nullSafeSet( statement, typedval.getValue(), locs[i] + startIndex, session );

                   

                   

                   

                    The RevisionType.DEL instance is retrieved from HashMap of named parameters and the Type is identified as being a SerializableType<T>. NullSafeSet is called on SerializableType. If you look throught the logic for this,

                   

                   

                  Line 95 of  org.hibernate.type.descriptor.java.SerializableTypeDescriptor: UnWrap Method

                   

                   

                  public <X> X unwrap(T value, Class<X> type, WrapperOptions options)

                   

                    This method actually "unwraps" the SerializableType. If you look at the body of the method, you can see that what it does is use an org.hibernate.util.SerializableHelper to serialize the parameter value (in this case, the org.hibernate.envers.RevisionType instance).

                   

                  So here's the short version: when you call AuditReader.list(); a query parameter gets added that says, in effect: "give me every revision that is not of type RevisionType.DEL". Hibernate tries to determine the mapping type of RevisionType and because it does not implement UserType, it classifies it as the fallback "SerializableType". It then serializes the enum instance to a byte array and binds that to the query.

                   

                   

                  In other words: the query that's getting run is: select max(rev) from [audit_table] where REVTYPE <> [serialized RevisionType.DEL].

                   

                   

                  I am certain this is what's happening - I was able to "follow" the RevisionType.DEL instance all the way through the entire stack trace and I can see where it gets serialized. So, clearly, this is a bug.

                   

                   

                  The question is why no one else is seeing this problem. I now think it isn't anything in my java enviroment. Rather, I think that other versions of databases may be handling the "where REVTYPE <> [serialize object]" part of the query differently. Technically, MySQL should just return all of the rows in the table, since clearly no value in the REVTYPE column will match that serialized object. However, I've noticed with my version of MySQL that if I for instance run a query like this:

                   

                   

                  select max(provisioni1_.REV) from audit_tpn_prov_order provisioni1_ where (provisioni1_.REV<=1 ) AND (provisioni1_.REVTYPE <>2 )and(provisioni1_.id=1)

                   

                   

                  , I get back "1", but if I change the query to

                   

                   

                  select max(provisioni1_.REV) from audit_tpn_prov_order provisioni1_ where (provisioni1_.REV<=1 ) AND (provisioni1_.REVTYPE <>'DEL')and(provisioni1_.id=1)

                   

                   

                  I get back no results, even though clearly no REVTYPE value matches the word 'DEL'. I've tried this with both the innoDB and MyISAM engine and the behavior is the same; but perhaps other databases work differently? It's the only thing I can think of....

                  • 6. Re: Possible bug in AuditReader.find()
                    Sicco Naets Newbie

                    Some more looking at this....

                     

                    first of all, apparently, someone else had the exact same problem:

                     

                    http://community.jboss.org/message/4857

                     

                     

                    He's using oracle so the behavior is different (he actually gets an exception) whereas I simply get wrong data; but  the underlying cause is the same: RevisionType.DEL is not correctly getting translated as part of  the query.

                     


                    Secondly, I took another look at how hibernate determines the type of a specific query parameter. Before it actually gets to the TypeFactory I mentioned above, if first checks with org.hibernate.type.TypeResolver. Only if it can't find anything in there does it fall back to the TypeFactory.

                     

                    Now, the TypeResolver has a  number of so-called "TypeRegistries", which is where custom user types get registered. So for instance, this is where the mapping of RevisionType -> RevisionTypeType would be done. I'm not entirely sure how this TypeResolver gets populated with custom user types, but maybe that's the problem: maybe for some reason the RevisionTypeType failed to register. Maybe a classloading problem or something? Any idea how the RevisionTypeType is supposed to get in there?

                    • 7. Re: Possible bug in AuditReader.find()
                      Adam Warski Master

                      Hmm, so I think the problem starts as you write when org.hibernate.type.TypeFactory.byClass is called, which should return RevisionTypeType (which does implement UserType). So maybe the registry is broken ... You are deploying to Tomcat? There are no other Hibernate jars in the container?

                       

                      I just checked locally and the nullSafeSet *is* called in my case. So it seems something is wrong with the custom type registration. Maybe you could debug how the custom type registration proceed in your case?

                       

                      Adam

                      • 8. Re: Possible bug in AuditReader.find()
                        Sicco Naets Newbie

                        Hey Adam,

                         

                        all of my hibernate jars are in the Tomcat container lib. They are:

                         

                        hibernate-commons-annotations-3.2.0.Final.jar

                        hibernate-core-3.6.7.Final.jar

                        hibernate-ehcache-3.6.7.Final.jar

                        hibernate-entitymanager-3.6.7.Final.jar

                        hibernate-envers-3.6.7.Final.jar

                        hibernate-jpa-2.0-api-1.0.1.Final.jar

                        hibernate-tools-3.2.0.ga.jar

                         

                        The hibernate mapping files are in the deployed webapp (as are the spring files). Hibernate doesn't seem to have a problem with that, but then again - maybe that's what's breaking envers? Should they all be in the same place? I.e. either both the hibernate jars and the mapping files in the container OR both of them in the webapp?

                         

                        That's obviously a less than ideal situation - I'd prefer to have to deploy the hibernate jars in the container but allow different apps to maintain their own mapping.

                         

                        Yeah, debugging how the RevisionTypeType gets registered would be a good idea, but I have a couple of questions:

                         

                        1) Which one is supposed to resolve the RevisionTypeType? Is it the TypeFactory or the TypeResolver? The Loader first checks the TypeResolver and only falls back to the TypeFactory when it can't find it in there, so I think it's actually the TypeResolver that's supposed to have a reference to RevisionTypeType.
                        2) How is the RevisionTypeType normally registered? I know that normally, custom UserTypes are registered by virtue of being referenced in a mapping file (or annotation on a domain object). But there is no mapping file per se for the audit tables so how does Hibernate know to load RevisionTypeType? If I knew that, then I'd know where to put my debug breakpoints...

                        3) I'm wondering.. is there some way I could manually force RevisionTypeType  to get registered? I.e. create some class that gets loaded when Spring starts and manually registeres RevisionTypeType. Any idea how to do that? I have to confess some of this stuff is beyond the limit of my hibernate knowledge...