hi, i am trying to implement an audit interceptor based on the Java Persistence with Hibernate example in Ch. 12. however, i am not using EJB3. eventually, i would like to incorporate Spring, but for now am only using Hibernate and my own POJO. Hibernate updates my object changes correctly and increments the version. however, no audit occurs as onFlushDirty does not get called to initialize the updates collection. am i missing a property setting somewhere? i can see that the AbstractFlushingEventListener is being invoked in the Eclipse console output, however there is no call to the interceptor's onFlushDirty() method. from what i can tell the DefaultFlushEntityEventListener class does invoke the onFlushDirty method, but i cannot figure out how to invoke that listener. i have tried adding an event listener setting to my hibernate.cfg.xml, but that does not work either. any help would be greatly appreciated. thanks.


Hibernate version: 3.2

<hibernate-configuration>
<session-factory>
<property name="hibernate.cache.provider_class">org.hibernate.cache.HashtableCacheProvider</property>
<property name="hibernate.cache.region_prefix">hibernate.test</property>

<property name="hibernate.connection.driver_class">com.microsoft.sqlserver.jdbc.SQLServerDriver</property>
<property name="hibernate.dialect">org.hibernate.dialect.SQLServerDialect</property>

<property name="hibernate.format_sql">true</property>

<property name="hibernate.jdbc.batch_versioned_data">true</property>
<property name="hibernate.jdbc.use_streams_for_binary">true</property>

<property name="hibernate.max_fetch_depth">1</property>

<property name="hibernate.proxool.pool_alias">pool1</property>

<property name="hibernate.query.substitutions">yes 'Y', no 'N'</property>

<property name="current_session_context_class">thread</property>

<mapping resource="util/AuditPrd.hbm.xml" />
<mapping resource="ticket/ticket.hbm.xml" />

<event type="flush-entity">
<listener class="org.hibernate.event.def.DefaultFlushEntityEventListener" />
</event>
</session-factory>
</hibernate-configuration>


Mapping documents:
<hibernate-mapping>
<class
name="ticket.Ticket"
table="t_Tickets"
>

<id name="ticketRef" type="int">
<column name="Ticket_REF" />
<generator class="native" />
</id>
<version name="ticketVersion" column="Ticket_Version" />
<property name="timestamp" type="timestamp" >
<column name="Timestamp" length="8" />
</property>
<property name="typeRef" type="java.lang.Integer">
<column name="Type_REF" />
</property>
<property name="ticketName" type="string">
<column name="Ticket_Name" length="75" />
</property>

</class>
</hibernate-mapping>

<hibernate-mapping default-access="field">
<class name="util.AuditPrd" table="t_Audit_PRD" schema="dbo" catalog="dbPRD_Help">
<id name="auditRef" type="int">
<column name="Audit_REF" />
<generator class="native" />
</id>
<property name="auditPkey" type="int">
<column name="Audit_Pkey" length="23" />
</property>
<property name="auditTableChanged" type="string">
<column name="Audit_TableChanged" length="255" />
</property>
<property name="auditFieldChanged" type="string">
<column name="Audit_FieldChanged" length="255" />
</property>
<property name="auditOldValue" type="string">
<column name="Audit_OldValue" length="4000" />
</property>
<property name="auditNewValue" type="string">
<column name="Audit_NewValue" length="4000" />
</property>
<property name="auditComment" type="string">
<column name="Audit_Comment" length="2000" />
</property>
<property name="auditCreatedBy" type="string">
<column name="Audit_CreatedBy" length="2000" />
</property>
</class>
</hibernate-mapping>


Code between sessionFactory.openSession() and session.close():

try{

Transaction tx;
Ticket ticket;
TicketManager mgr = new TicketManager();

AuditInterceptor interceptor = new AuditInterceptor();

session = HibernateUtil.getSessionFactory().openSession(interceptor);

tx = session.beginTransaction();

interceptor.setSession(session);
interceptor.setUserId("cr9281");

ticket = mgr.loadTicket(24370);

ticket.setTimestamp(new Date());

tx.commit();

}
catch(Exception ex){
ex.printStackTrace(System.out);
}
finally{
HibernateUtil.getSessionFactory().close();
}


Interceptor:

package util;

import org.hibernate.*;
import java.util.*;
import java.io.Serializable;
import java.lang.reflect.Type;


public class AuditInterceptor extends EmptyInterceptor {


private Session session;
private String userId;
private Set inserts = new HashSet();
private Set updates = new HashSet();

public void setSession(Session session) {
this.session=session;
}

public void setUserId(String userId) {
this.userId=userId;
}


public boolean onSave(Object entity, Serializable id, Object[] state, String[] propertyNames, Type[] types) throws CallbackException {
if (entity instanceof Auditable) inserts.add(entity);
return false;
}


public boolean onFlushDirty(Object entity, Serializable id, Object[] currentState, Object[] previousState, String[] propertyNames, Type[] types) throws CallbackException {

System.out.println("onFlushDirty*********");

if (entity instanceof Auditable){
updates.add(entity);
System.out.println("added update********");
}

return false;

}

public void postFlush(Iterator iterator)throws CallbackException {

try {

for (Iterator it = updates.iterator(); it.hasNext();) {

System.out.println("iterating");
Auditable entity = (Auditable) it.next();
AuditLog.logAudit(entity, userId, session.connection());

}

}
catch(Exception ex){
ex.printStackTrace(System.out);
}
finally {
inserts.clear();
updates.clear();
}

}
}

Try doing session.flush explicitly since the flushmode is not set on session.

The findDirty method in the interceptor would be called for each entity. But onFlushDirty will not be called if findDirty returns false.

To see if your interceptor is being picked up correctly or not, try printing something in findDirty method.

i've tried to use a manual flush and it does not work. i added a findDirty() method, but it does not get called either. it appears to me that the problem has to do with the Listener, AbstractFlushingEventListener, as this class does not call onFlushDirty() or findDirty(). however, DefaultFlushEntityEventListener does call these methods. is there any way to change which listener is used? i've attached the console output:


09:37:38,343 INFO Environment:514 - Hibernate 3.2.5
09:37:38,353 INFO Environment:532 - loaded properties from resource hibernate.properties: {hibernate.transaction.flush_before_completion=true, hibernate.connection.driver_class=org.hsqldb.jdbcDriver, hibernate.transaction.auto_close_session=true, hibernate.cache.provider_class=org.hibernate.cache.HashtableCacheProvider, hibernate.max_fetch_depth=1, hibernate.dialect=org.hibernate.dialect.HSQLDialect, hibernate.jdbc.use_streams_for_binary=true, hibernate.format_sql=true, hibernate.query.substitutions=yes 'Y', no 'N', hibernate.proxool.pool_alias=pool1, hibernate.connection.username=sa, hibernate.cache.region_prefix=hibernate.test, hibernate.connection.url=jdbc:hsqldb:./build/db/hsqldb/hibernate, hibernate.bytecode.use_reflection_optimizer=false, hibernate.connection.password=****, hibernate.jdbc.batch_versioned_data=true, hibernate.connection.pool_size=1}
09:37:38,363 INFO Environment:563 - using java.io streams to persist binary types
09:37:38,374 INFO Environment:681 - Bytecode provider name : cglib
09:37:38,374 INFO Environment:598 - using JDK 1.4 java.sql.Timestamp handling
09:37:38,504 INFO Configuration:1426 - configuring from resource: /hibernate.cfg.xml
09:37:38,504 INFO Configuration:1403 - Configuration resource: /hibernate.cfg.xml
09:37:38,635 DEBUG DTDEntityResolver:38 - trying to resolve system-id [http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd]
09:37:38,635 DEBUG DTDEntityResolver:40 - recognized hibernate namespace; attempting to resolve on classpath under org/hibernate/
09:37:38,645 DEBUG DTDEntityResolver:50 - located [http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd] in classpath
09:37:38,685 DEBUG Configuration:1387 - hibernate.cache.provider_class=org.hibernate.cache.HashtableCacheProvider
09:37:38,685 DEBUG Configuration:1387 - hibernate.cache.region_prefix=hibernate.test
09:37:38,685 DEBUG Configuration:1387 - hibernate.connection.driver_class=com.microsoft.sqlserver.jdbc.SQLServerDriver
09:37:38,685 DEBUG Configuration:1387 - hibernate.connection.password=*************
09:37:38,695 DEBUG Configuration:1387 - hibernate.connection.pool_size=1
09:37:38,695 DEBUG Configuration:1387 - hibernate.connection.url=****************
09:37:38,695 DEBUG Configuration:1387 - hibernate.connection.username=***********
09:37:38,695 DEBUG Configuration:1387 - hibernate.dialect=org.hibernate.dialect.SQLServerDialect
09:37:38,695 DEBUG Configuration:1387 - hibernate.format_sql=true
09:37:38,695 DEBUG Configuration:1387 - hibernate.jdbc.batch_versioned_data=true
09:37:38,695 DEBUG Configuration:1387 - hibernate.jdbc.use_streams_for_binary=true
09:37:38,695 DEBUG Configuration:1387 - hibernate.max_fetch_depth=1
09:37:38,695 DEBUG Configuration:1387 - hibernate.proxool.pool_alias=pool1
09:37:38,695 DEBUG Configuration:1387 - hibernate.query.substitutions=yes 'Y', no 'N'
09:37:38,695 DEBUG Configuration:1387 - current_session_context_class=thread
09:37:38,695 DEBUG Configuration:1586 - null<-org.dom4j.tree.DefaultAttribute@127734f [Attribute: name resource value "util/AuditPrd.hbm.xml"]
09:37:38,695 INFO Configuration:553 - Reading mappings from resource : util/AuditPrd.hbm.xml
09:37:38,695 DEBUG DTDEntityResolver:38 - trying to resolve system-id [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd]
09:37:38,705 DEBUG DTDEntityResolver:40 - recognized hibernate namespace; attempting to resolve on classpath under org/hibernate/
09:37:38,705 DEBUG DTDEntityResolver:50 - located [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd] in classpath
09:37:38,855 INFO HbmBinder:300 - Mapping class: util.AuditPrd -> t_Audit_PRD
09:37:38,855 DEBUG HbmBinder:1270 - Mapped property: auditRef -> Audit_REF
09:37:38,875 DEBUG HbmBinder:1270 - Mapped property: auditPkey -> Audit_Pkey
09:37:38,875 DEBUG HbmBinder:1270 - Mapped property: auditTableChanged -> Audit_TableChanged
09:37:38,875 DEBUG HbmBinder:1270 - Mapped property: auditFieldChanged -> Audit_FieldChanged
09:37:38,875 DEBUG HbmBinder:1270 - Mapped property: auditOldValue -> Audit_OldValue
09:37:38,875 DEBUG HbmBinder:1270 - Mapped property: auditNewValue -> Audit_NewValue
09:37:38,875 DEBUG HbmBinder:1270 - Mapped property: auditComment -> Audit_Comment
09:37:38,875 DEBUG HbmBinder:1270 - Mapped property: auditCreatedBy -> Audit_CreatedBy
09:37:38,875 DEBUG Configuration:1586 - null<-org.dom4j.tree.DefaultAttribute@cf40f5 [Attribute: name resource value "ticket/ticket.hbm.xml"]
09:37:38,875 INFO Configuration:553 - Reading mappings from resource : ticket/ticket.hbm.xml
09:37:38,886 DEBUG DTDEntityResolver:38 - trying to resolve system-id [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd]
09:37:38,886 DEBUG DTDEntityResolver:40 - recognized hibernate namespace; attempting to resolve on classpath under org/hibernate/
09:37:38,886 DEBUG DTDEntityResolver:50 - located [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd] in classpath
09:37:38,926 INFO HbmBinder:300 - Mapping class: ticket.Ticket -> t_Tickets
09:37:38,926 DEBUG HbmBinder:1270 - Mapped property: ticketRef -> Ticket_REF
09:37:38,926 DEBUG HbmBinder:1270 - Mapped property: ticketVersion -> Ticket_Version
09:37:38,936 DEBUG HbmBinder:1270 - Mapped property: timestamp -> Timestamp
09:37:38,936 DEBUG HbmBinder:1270 - Mapped property: typeRef -> Type_REF
09:37:38,936 DEBUG HbmBinder:1270 - Mapped property: ticketName -> Ticket_Name
09:37:38,936 DEBUG Configuration:1642 - Event listeners: flush-entity=org.hibernate.event.def.DefaultFlushEntityEventListener
09:37:38,946 INFO Configuration:1541 - Configured SessionFactory: null
09:37:38,946 DEBUG Configuration:1542 - properties: {java.runtime.name=Java(TM) SE Runtime Environment, hibernate.connection.password=********, hibernate.cache.provider_class=org.hibernate.cache.HashtableCacheProvider, sun.boot.library.path=C:\Program Files\Java\jre1.6.0_02\bin, java.vm.version=1.6.0_02-b06, hibernate.proxool.pool_alias=pool1, hibernate.connection.username=******, hibernate.transaction.auto_close_session=true, java.vm.vendor=Sun Microsystems Inc., java.vendor.url=http://java.sun.com/, path.separator=;, java.vm.name=Java HotSpot(TM) Client VM, file.encoding.pkg=sun.io, user.country=US, sun.java.launcher=SUN_STANDARD, sun.os.patch.level=Service Pack 2, java.vm.specification.name=Java Virtual Machine Specification, user.dir=C:\Program Files\Java\workspace\Ticket, java.runtime.version=1.6.0_02-b06, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, hibernate.current_session_context_class=thread, java.endorsed.dirs=C:\Program Files\Java\jre1.6.0_02\lib\endorsed, os.arch=x86, java.io.tmpdir=C:\DOCUME~1\CLAYRO~1\LOCALS~1\Temp\, line.separator=
, java.vm.specification.vendor=Sun Microsystems Inc., user.variant=, os.name=Windows XP, hibernate.jdbc.batch_versioned_data=true, hibernate.cache.region_prefix=hibernate.test, sun.jnu.encoding=Cp1252, java.library.path=C:\Program Files\Java\jre1.6.0_02\bin;.;C:\WINNT\Sun\Java\bin;C:\WINNT\system32;C:\WINNT;C:\Program Files\Compaq\Compaq Management Agents\Dmi\Win32\Bin;C:\WINNT\system32;C:\WINNT;C:\WINNT\System32\Wbem;C:\Program Files\ATI Technologies\ATI Control Panel;C:\Program Files\Common Files\Roxio Shared\DLLShared;C:\Program Files\Microsoft SQL Server\80\Tools\BINN;c:\Program Files\Microsoft SQL Server\90\Tools\binn\;C:\WINNT\Microsoft.NET\Framework\v2.0.50727;C:\Program Files\QuickTime\QTSystem\;C:\Program Files\Java\jdk\bin;C:\Program Files\Java;C:\Program Files\Compaq\Compaq Management Agents\Dmi\Win32\Bin;C:\WINNT\system32;C:\WINNT;C:\WINNT\System32\Wbem;C:\Program Files\ATI Technologies\ATI Control Panel;C:\Program Files\Common Files\Roxio Shared\DLLShared;C:\Program Files\Microsoft SQL Server\80\Tools\BINN;c:\Program Files\Microsoft SQL Server\90\Tools\binn\;C:\WINNT\Microsoft.NET\Framework\v2.0.50727;C:\Program Files\QuickTime\QTSystem\;C:\Program Files\Java\jdk\bin;C:\Program Files\Java;C:\Program Files\Java\bin;C:\Program Files\IDM Computer Solutions\UltraEdit-32;, java.specification.name=Java Platform API Specification, java.class.version=50.0, hibernate.connection.pool_size=1, sun.management.compiler=HotSpot Client Compiler, os.version=5.1, user.home=C:\Documents and Settings\clayrowland, user.timezone=America/New_York, java.awt.printerjob=sun.awt.windows.WPrinterJob, file.encoding=Cp1252, java.specification.version=1.6, hibernate.format_sql=true, hibernate.connection.driver_class=com.microsoft.sqlserver.jdbc.SQLServerDriver, java.class.path=C:\Program Files\Java\lib\dom4j-1.6.1.jar;C:\Program Files\Java\apache-log4j-1.2.15\log4j-1.2.15.jar;C:\Program Files\Java\commons-logging-1.1\commons-logging-1.1.jar;C:\Program Files\Java\commons-collections-3.2\commons-collections-3.2.jar;C:\Program Files\Java\lib\hibernate3.jar;C:\Program Files\Java\sqljdbc_1.1\enu\sqljdbc.jar;C:\Program Files\Java\hibernate-3.2\lib\cglib-2.1.3.jar;C:\Program Files\Java\hibernate-3.2\lib\asm.jar;C:\Program Files\Java\hibernate-3.2\lib\jta.jar;C:\Program Files\Java\workspace\Ticket;C:\Program Files\Java\hibernate-3.2\lib\antlr-2.7.6.jar;C:\Program Files\Java\eclipse\plugins\org.jboss.ide.eclipse.jdt.aop.core_1.1.2.GA\jboss-aop.jar;C:\Program Files\Java\eclipse\plugins\org.jboss.ide.eclipse.jdt.aop.core_1.1.2.GA\jboss-common.jar;C:\Program Files\Java\eclipse\plugins\org.jboss.ide.eclipse.jdt.aop.core_1.1.2.GA\qdox.jar;C:\Program Files\Java\eclipse\plugins\org.jboss.ide.eclipse.jdt.aop.core_1.1.2.GA\concurrent.jar;C:\Program Files\Java\eclipse\plugins\org.jboss.ide.eclipse.jdt.aop.core_1.1.2.GA\trove.jar;C:\Program Files\Java\eclipse\plugins\org.jboss.ide.eclipse.jdt.aop.core_1.1.2.GA\javassist.jar;C:\Program Files\Java\eclipse\plugins\org.jboss.ide.eclipse.jdt.aop.core_1.1.2.GA\jboss-aspect-library.jar;C:\Program Files\Java\eclipse\plugins\org.jboss.ide.eclipse.jdt.aop.core_1.1.2.GA\bsh-1.3.0.jar, user.name=clayrowland, hibernate.bytecode.use_reflection_optimizer=false, hibernate.query.substitutions=yes 'Y', no 'N', current_session_context_class=thread, java.vm.specification.version=1.0, java.home=C:\Program Files\Java\jre1.6.0_02, sun.arch.data.model=32, hibernate.dialect=org.hibernate.dialect.SQLServerDialect, hibernate.connection.url=jdbc:sqlserver://************;database=dbprd_help;, user.language=en, java.specification.vendor=Sun Microsystems Inc., awt.toolkit=sun.awt.windows.WToolkit, java.vm.info=mixed mode, sharing, hibernate.transaction.flush_before_completion=true, hibernate.jdbc.use_streams_for_binary=true, java.version=1.6.0_02, java.ext.dirs=C:\Program Files\Java\jre1.6.0_02\lib\ext;C:\WINNT\Sun\Java\lib\ext, sun.boot.class.path=C:\Program Files\Java\jre1.6.0_02\lib\resources.jar;C:\Program Files\Java\jre1.6.0_02\lib\rt.jar;C:\Program Files\Java\jre1.6.0_02\lib\sunrsasign.jar;C:\Program Files\Java\jre1.6.0_02\lib\jsse.jar;C:\Program Files\Java\jre1.6.0_02\lib\jce.jar;C:\Program Files\Java\jre1.6.0_02\lib\charsets.jar;C:\Program Files\Java\jre1.6.0_02\classes, java.vendor=Sun Microsystems Inc., file.separator=\, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, sun.io.unicode.encoding=UnicodeLittle, sun.cpu.endian=little, hibernate.max_fetch_depth=1, sun.desktop=windows, sun.cpu.isalist=pentium_pro+mmx pentium_pro pentium+mmx pentium i486 i386 i86}
09:37:38,946 DEBUG Configuration:1285 - Preparing to build session factory with filters : {}
09:37:38,946 DEBUG Configuration:1120 - processing extends queue
09:37:38,946 DEBUG Configuration:1124 - processing collection mappings
09:37:38,946 DEBUG Configuration:1135 - processing native query and ResultSetMapping mappings
09:37:38,946 DEBUG Configuration:1143 - processing association property references
09:37:38,946 DEBUG Configuration:1165 - processing foreign key constraints
09:37:39,026 INFO DriverManagerConnectionProvider:41 - Using Hibernate built-in connection pool (not for production use!)
09:37:39,036 INFO DriverManagerConnectionProvider:42 - Hibernate connection pool size: 1
09:37:39,036 INFO DriverManagerConnectionProvider:45 - autocommit mode: false
09:37:39,237 INFO DriverManagerConnectionProvider:80 - using driver: com.microsoft.sqlserver.jdbc.SQLServerDriver at URL: jdbc:sqlserver://************;database=dbprd_help;
09:37:39,237 INFO DriverManagerConnectionProvider:83 - connection properties: {user=********, password=**********}
09:37:39,237 DEBUG DriverManagerConnectionProvider:109 - opening new JDBC connection
09:37:39,889 DEBUG DriverManagerConnectionProvider:115 - created connection to: jdbc:sqlserver://*********;database=dbprd_help;, Isolation Level: 2
09:37:39,920 INFO SettingsFactory:89 - RDBMS: Microsoft SQL Server, version: 8.00.2039
09:37:39,920 INFO SettingsFactory:90 - JDBC driver: Microsoft SQL Server 2005 JDBC Driver, version: 1.1.1501.101
09:37:39,970 INFO Dialect:152 - Using dialect: org.hibernate.dialect.SQLServerDialect
09:37:39,990 INFO TransactionFactoryFactory:31 - Using default transaction strategy (direct JDBC transactions)
09:37:40,000 INFO TransactionManagerLookupFactory:33 - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
09:37:40,010 INFO SettingsFactory:143 - Automatic flush during beforeCompletion(): enabled
09:37:40,010 INFO SettingsFactory:147 - Automatic session close at end of transaction: enabled
09:37:40,010 INFO SettingsFactory:162 - Scrollable result sets: enabled
09:37:40,010 DEBUG SettingsFactory:166 - Wrap result sets: disabled
09:37:40,010 INFO SettingsFactory:170 - JDBC3 getGeneratedKeys(): enabled
09:37:40,010 INFO SettingsFactory:178 - Connection release mode: auto
09:37:40,010 INFO SettingsFactory:202 - Maximum outer join fetch depth: 1
09:37:40,010 INFO SettingsFactory:205 - Default batch fetch size: 1
09:37:40,010 INFO SettingsFactory:209 - Generate SQL with comments: disabled
09:37:40,010 INFO SettingsFactory:213 - Order SQL updates by primary key: disabled
09:37:40,010 INFO SettingsFactory:217 - Order SQL inserts for batching: disabled
09:37:40,010 INFO SettingsFactory:386 - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
09:37:40,040 INFO ASTQueryTranslatorFactory:24 - Using ASTQueryTranslatorFactory
09:37:40,040 INFO SettingsFactory:225 - Query language substitutions: {yes='Y', no='N'}
09:37:40,040 INFO SettingsFactory:230 - JPA-QL strict compliance: disabled
09:37:40,040 INFO SettingsFactory:235 - Second-level cache: enabled
09:37:40,040 INFO SettingsFactory:239 - Query cache: disabled
09:37:40,040 INFO SettingsFactory:373 - Cache provider: org.hibernate.cache.HashtableCacheProvider
09:37:40,050 INFO SettingsFactory:254 - Optimize cache for minimal puts: disabled
09:37:40,050 INFO SettingsFactory:259 - Cache region prefix: hibernate.test
09:37:40,050 INFO SettingsFactory:263 - Structured second-level cache entries: disabled
09:37:40,060 INFO SettingsFactory:290 - Statistics: disabled
09:37:40,060 INFO SettingsFactory:294 - Deleted entity synthetic identifier rollback: disabled
09:37:40,060 INFO SettingsFactory:309 - Default entity-mode: pojo
09:37:40,060 INFO SettingsFactory:313 - Named query checking : enabled
09:37:40,211 INFO SessionFactoryImpl:161 - building session factory
09:37:40,211 DEBUG SessionFactoryImpl:173 - Session factory constructed with filter configurations : {}
09:37:40,211 DEBUG SessionFactoryImpl:177 - instantiating session factory with properties: {java.runtime.name=Java(TM) SE Runtime Environment, hibernate.connection.password=************, hibernate.cache.provider_class=org.hibernate.cache.HashtableCacheProvider, sun.boot.library.path=C:\Program Files\Java\jre1.6.0_02\bin, java.vm.version=1.6.0_02-b06, hibernate.proxool.pool_alias=pool1, hibernate.connection.username=************, hibernate.transaction.auto_close_session=true, java.vm.vendor=Sun Microsystems Inc., java.vendor.url=http://java.sun.com/, path.separator=;, java.vm.name=Java HotSpot(TM) Client VM, file.encoding.pkg=sun.io, user.country=US, sun.java.launcher=SUN_STANDARD, sun.os.patch.level=Service Pack 2, java.vm.specification.name=Java Virtual Machine Specification, user.dir=C:\Program Files\Java\workspace\Ticket, java.runtime.version=1.6.0_02-b06, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, hibernate.current_session_context_class=thread, java.endorsed.dirs=C:\Program Files\Java\jre1.6.0_02\lib\endorsed, os.arch=x86, java.io.tmpdir=C:\DOCUME~1\CLAYRO~1\LOCALS~1\Temp\, line.separator=
, java.vm.specification.vendor=Sun Microsystems Inc., user.variant=, os.name=Windows XP, hibernate.jdbc.batch_versioned_data=true, hibernate.cache.region_prefix=hibernate.test, sun.jnu.encoding=Cp1252, java.library.path=C:\Program Files\Java\jre1.6.0_02\bin;.;C:\WINNT\Sun\Java\bin;C:\WINNT\system32;C:\WINNT;C:\Program Files\Compaq\Compaq Management Agents\Dmi\Win32\Bin;C:\WINNT\system32;C:\WINNT;C:\WINNT\System32\Wbem;C:\Program Files\ATI Technologies\ATI Control Panel;C:\Program Files\Common Files\Roxio Shared\DLLShared;C:\Program Files\Microsoft SQL Server\80\Tools\BINN;c:\Program Files\Microsoft SQL Server\90\Tools\binn\;C:\WINNT\Microsoft.NET\Framework\v2.0.50727;C:\Program Files\QuickTime\QTSystem\;C:\Program Files\Java\jdk\bin;C:\Program Files\Java;C:\Program Files\Compaq\Compaq Management Agents\Dmi\Win32\Bin;C:\WINNT\system32;C:\WINNT;C:\WINNT\System32\Wbem;C:\Program Files\ATI Technologies\ATI Control Panel;C:\Program Files\Common Files\Roxio Shared\DLLShared;C:\Program Files\Microsoft SQL Server\80\Tools\BINN;c:\Program Files\Microsoft SQL Server\90\Tools\binn\;C:\WINNT\Microsoft.NET\Framework\v2.0.50727;C:\Program Files\QuickTime\QTSystem\;C:\Program Files\Java\jdk\bin;C:\Program Files\Java;C:\Program Files\Java\bin;C:\Program Files\IDM Computer Solutions\UltraEdit-32;, java.specification.name=Java Platform API Specification, java.class.version=50.0, hibernate.connection.pool_size=1, sun.management.compiler=HotSpot Client Compiler, os.version=5.1, user.home=C:\Documents and Settings\clayrowland, user.timezone=America/New_York, java.awt.printerjob=sun.awt.windows.WPrinterJob, java.specification.version=1.6, file.encoding=Cp1252, hibernate.format_sql=true, hibernate.connection.driver_class=com.microsoft.sqlserver.jdbc.SQLServerDriver, user.name=clayrowland, java.class.path=C:\Program Files\Java\lib\dom4j-1.6.1.jar;C:\Program Files\Java\apache-log4j-1.2.15\log4j-1.2.15.jar;C:\Program Files\Java\commons-logging-1.1\commons-logging-1.1.jar;C:\Program Files\Java\commons-collections-3.2\commons-collections-3.2.jar;C:\Program Files\Java\lib\hibernate3.jar;C:\Program Files\Java\sqljdbc_1.1\enu\sqljdbc.jar;C:\Program Files\Java\hibernate-3.2\lib\cglib-2.1.3.jar;C:\Program Files\Java\hibernate-3.2\lib\asm.jar;C:\Program Files\Java\hibernate-3.2\lib\jta.jar;C:\Program Files\Java\workspace\Ticket;C:\Program Files\Java\hibernate-3.2\lib\antlr-2.7.6.jar;C:\Program Files\Java\eclipse\plugins\org.jboss.ide.eclipse.jdt.aop.core_1.1.2.GA\jboss-aop.jar;C:\Program Files\Java\eclipse\plugins\org.jboss.ide.eclipse.jdt.aop.core_1.1.2.GA\jboss-common.jar;C:\Program Files\Java\eclipse\plugins\org.jboss.ide.eclipse.jdt.aop.core_1.1.2.GA\qdox.jar;C:\Program Files\Java\eclipse\plugins\org.jboss.ide.eclipse.jdt.aop.core_1.1.2.GA\concurrent.jar;C:\Program Files\Java\eclipse\plugins\org.jboss.ide.eclipse.jdt.aop.core_1.1.2.GA\trove.jar;C:\Program Files\Java\eclipse\plugins\org.jboss.ide.eclipse.jdt.aop.core_1.1.2.GA\javassist.jar;C:\Program Files\Java\eclipse\plugins\org.jboss.ide.eclipse.jdt.aop.core_1.1.2.GA\jboss-aspect-library.jar;C:\Program Files\Java\eclipse\plugins\org.jboss.ide.eclipse.jdt.aop.core_1.1.2.GA\bsh-1.3.0.jar, hibernate.bytecode.use_reflection_optimizer=false, hibernate.query.substitutions=yes 'Y', no 'N', current_session_context_class=thread, java.vm.specification.version=1.0, sun.arch.data.model=32, java.home=C:\Program Files\Java\jre1.6.0_02, hibernate.connection.url=jdbc:sqlserver://************;database=dbprd_help;, hibernate.dialect=org.hibernate.dialect.SQLServerDialect, java.specification.vendor=Sun Microsystems Inc., user.language=en, awt.toolkit=sun.awt.windows.WToolkit, java.vm.info=mixed mode, sharing, java.version=1.6.0_02, hibernate.jdbc.use_streams_for_binary=true, hibernate.transaction.flush_before_completion=true, java.ext.dirs=C:\Program Files\Java\jre1.6.0_02\lib\ext;C:\WINNT\Sun\Java\lib\ext, sun.boot.class.path=C:\Program Files\Java\jre1.6.0_02\lib\resources.jar;C:\Program Files\Java\jre1.6.0_02\lib\rt.jar;C:\Program Files\Java\jre1.6.0_02\lib\sunrsasign.jar;C:\Program Files\Java\jre1.6.0_02\lib\jsse.jar;C:\Program Files\Java\jre1.6.0_02\lib\jce.jar;C:\Program Files\Java\jre1.6.0_02\lib\charsets.jar;C:\Program Files\Java\jre1.6.0_02\classes, java.vendor=Sun Microsystems Inc., file.separator=\, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, sun.cpu.endian=little, sun.io.unicode.encoding=UnicodeLittle, sun.desktop=windows, hibernate.max_fetch_depth=1, sun.cpu.isalist=pentium_pro+mmx pentium_pro pentium+mmx pentium i486 i386 i86}
09:37:40,562 DEBUG AbstractEntityPersister:2738 - Static SQL for entity: util.AuditPrd
09:37:40,562 DEBUG AbstractEntityPersister:2743 - Version select: select Audit_REF from dbPRD_Help.dbo.t_Audit_PRD where Audit_REF =?
09:37:40,562 DEBUG AbstractEntityPersister:2746 - Snapshot select: select auditprd_.Audit_REF, auditprd_.Audit_Pkey as Audit2_0_, auditprd_.Audit_TableChanged as Audit3_0_, auditprd_.Audit_FieldChanged as Audit4_0_, auditprd_.Audit_OldValue as Audit5_0_, auditprd_.Audit_NewValue as Audit6_0_, auditprd_.Audit_Comment as Audit7_0_, auditprd_.Audit_CreatedBy as Audit8_0_ from dbPRD_Help.dbo.t_Audit_PRD auditprd_ where auditprd_.Audit_REF=?
09:37:40,562 DEBUG AbstractEntityPersister:2749 - Insert 0: insert into dbPRD_Help.dbo.t_Audit_PRD (Audit_Pkey, Audit_TableChanged, Audit_FieldChanged, Audit_OldValue, Audit_NewValue, Audit_Comment, Audit_CreatedBy, Audit_REF) values (?, ?, ?, ?, ?, ?, ?, ?)
09:37:40,562 DEBUG AbstractEntityPersister:2750 - Update 0: update dbPRD_Help.dbo.t_Audit_PRD set Audit_Pkey=?, Audit_TableChanged=?, Audit_FieldChanged=?, Audit_OldValue=?, Audit_NewValue=?, Audit_Comment=?, Audit_CreatedBy=? where Audit_REF=?
09:37:40,562 DEBUG AbstractEntityPersister:2751 - Delete 0: delete from dbPRD_Help.dbo.t_Audit_PRD where Audit_REF=?
09:37:40,562 DEBUG AbstractEntityPersister:2755 - Identity insert: insert into dbPRD_Help.dbo.t_Audit_PRD (Audit_Pkey, Audit_TableChanged, Audit_FieldChanged, Audit_OldValue, Audit_NewValue, Audit_Comment, Audit_CreatedBy) values (?, ?, ?, ?, ?, ?, ?)
09:37:40,582 DEBUG AbstractEntityPersister:2738 - Static SQL for entity: ticket.Ticket
09:37:40,582 DEBUG AbstractEntityPersister:2743 - Version select: select Ticket_Version from t_Tickets where Ticket_REF =?
09:37:40,582 DEBUG AbstractEntityPersister:2746 - Snapshot select: select ticket_.Ticket_REF, ticket_.Ticket_Version as Ticket2_1_, ticket_.Timestamp as Timestamp1_, ticket_.Type_REF as Type4_1_, ticket_.Ticket_Name as Ticket5_1_ from t_Tickets ticket_ where ticket_.Ticket_REF=?
09:37:40,582 DEBUG AbstractEntityPersister:2749 - Insert 0: insert into t_Tickets (Ticket_Version, Timestamp, Type_REF, Ticket_Name, Ticket_REF) values (?, ?, ?, ?, ?)
09:37:40,582 DEBUG AbstractEntityPersister:2750 - Update 0: update t_Tickets set Ticket_Version=?, Timestamp=?, Type_REF=?, Ticket_Name=? where Ticket_REF=? and Ticket_Version=?
09:37:40,582 DEBUG AbstractEntityPersister:2751 - Delete 0: delete from t_Tickets where Ticket_REF=? and Ticket_Version=?
09:37:40,592 DEBUG AbstractEntityPersister:2755 - Identity insert: insert into t_Tickets (Ticket_Version, Timestamp, Type_REF, Ticket_Name) values (?, ?, ?, ?)
09:37:40,622 DEBUG EntityLoader:79 - Static select for entity util.AuditPrd: select auditprd0_.Audit_REF as Audit1_0_0_, auditprd0_.Audit_Pkey as Audit2_0_0_, auditprd0_.Audit_TableChanged as Audit3_0_0_, auditprd0_.Audit_FieldChanged as Audit4_0_0_, auditprd0_.Audit_OldValue as Audit5_0_0_, auditprd0_.Audit_NewValue as Audit6_0_0_, auditprd0_.Audit_Comment as Audit7_0_0_, auditprd0_.Audit_CreatedBy as Audit8_0_0_ from dbPRD_Help.dbo.t_Audit_PRD auditprd0_ where auditprd0_.Audit_REF=?
09:37:40,622 DEBUG EntityLoader:79 - Static select for entity util.AuditPrd: select auditprd0_.Audit_REF as Audit1_0_0_, auditprd0_.Audit_Pkey as Audit2_0_0_, auditprd0_.Audit_TableChanged as Audit3_0_0_, auditprd0_.Audit_FieldChanged as Audit4_0_0_, auditprd0_.Audit_OldValue as Audit5_0_0_, auditprd0_.Audit_NewValue as Audit6_0_0_, auditprd0_.Audit_Comment as Audit7_0_0_, auditprd0_.Audit_CreatedBy as Audit8_0_0_ from dbPRD_Help.dbo.t_Audit_PRD auditprd0_ where auditprd0_.Audit_REF=?
09:37:40,632 DEBUG EntityLoader:79 - Static select for entity util.AuditPrd: select auditprd0_.Audit_REF as Audit1_0_0_, auditprd0_.Audit_Pkey as Audit2_0_0_, auditprd0_.Audit_TableChanged as Audit3_0_0_, auditprd0_.Audit_FieldChanged as Audit4_0_0_, auditprd0_.Audit_OldValue as Audit5_0_0_, auditprd0_.Audit_NewValue as Audit6_0_0_, auditprd0_.Audit_Comment as Audit7_0_0_, auditprd0_.Audit_CreatedBy as Audit8_0_0_ from dbPRD_Help.dbo.t_Audit_PRD auditprd0_ with (updlock, rowlock) where auditprd0_.Audit_REF=?
09:37:40,632 DEBUG EntityLoader:79 - Static select for entity util.AuditPrd: select auditprd0_.Audit_REF as Audit1_0_0_, auditprd0_.Audit_Pkey as Audit2_0_0_, auditprd0_.Audit_TableChanged as Audit3_0_0_, auditprd0_.Audit_FieldChanged as Audit4_0_0_, auditprd0_.Audit_OldValue as Audit5_0_0_, auditprd0_.Audit_NewValue as Audit6_0_0_, auditprd0_.Audit_Comment as Audit7_0_0_, auditprd0_.Audit_CreatedBy as Audit8_0_0_ from dbPRD_Help.dbo.t_Audit_PRD auditprd0_ with (updlock, rowlock) where auditprd0_.Audit_REF=?
09:37:40,632 DEBUG EntityLoader:79 - Static select for entity util.AuditPrd: select auditprd0_.Audit_REF as Audit1_0_0_, auditprd0_.Audit_Pkey as Audit2_0_0_, auditprd0_.Audit_TableChanged as Audit3_0_0_, auditprd0_.Audit_FieldChanged as Audit4_0_0_, auditprd0_.Audit_OldValue as Audit5_0_0_, auditprd0_.Audit_NewValue as Audit6_0_0_, auditprd0_.Audit_Comment as Audit7_0_0_, auditprd0_.Audit_CreatedBy as Audit8_0_0_ from dbPRD_Help.dbo.t_Audit_PRD auditprd0_ with (updlock, rowlock) where auditprd0_.Audit_REF=?
09:37:40,642 DEBUG EntityLoader:34 - Static select for action ACTION_MERGE on entity util.AuditPrd: select auditprd0_.Audit_REF as Audit1_0_0_, auditprd0_.Audit_Pkey as Audit2_0_0_, auditprd0_.Audit_TableChanged as Audit3_0_0_, auditprd0_.Audit_FieldChanged as Audit4_0_0_, auditprd0_.Audit_OldValue as Audit5_0_0_, auditprd0_.Audit_NewValue as Audit6_0_0_, auditprd0_.Audit_Comment as Audit7_0_0_, auditprd0_.Audit_CreatedBy as Audit8_0_0_ from dbPRD_Help.dbo.t_Audit_PRD auditprd0_ where auditprd0_.Audit_REF=?
09:37:40,642 DEBUG EntityLoader:34 - Static select for action ACTION_REFRESH on entity util.AuditPrd: select auditprd0_.Audit_REF as Audit1_0_0_, auditprd0_.Audit_Pkey as Audit2_0_0_, auditprd0_.Audit_TableChanged as Audit3_0_0_, auditprd0_.Audit_FieldChanged as Audit4_0_0_, auditprd0_.Audit_OldValue as Audit5_0_0_, auditprd0_.Audit_NewValue as Audit6_0_0_, auditprd0_.Audit_Comment as Audit7_0_0_, auditprd0_.Audit_CreatedBy as Audit8_0_0_ from dbPRD_Help.dbo.t_Audit_PRD auditprd0_ where auditprd0_.Audit_REF=?
09:37:40,642 DEBUG EntityLoader:79 - Static select for entity ticket.Ticket: select ticket0_.Ticket_REF as Ticket1_1_0_, ticket0_.Ticket_Version as Ticket2_1_0_, ticket0_.Timestamp as Timestamp1_0_, ticket0_.Type_REF as Type4_1_0_, ticket0_.Ticket_Name as Ticket5_1_0_ from t_Tickets ticket0_ where ticket0_.Ticket_REF=?
09:37:40,642 DEBUG EntityLoader:79 - Static select for entity ticket.Ticket: select ticket0_.Ticket_REF as Ticket1_1_0_, ticket0_.Ticket_Version as Ticket2_1_0_, ticket0_.Timestamp as Timestamp1_0_, ticket0_.Type_REF as Type4_1_0_, ticket0_.Ticket_Name as Ticket5_1_0_ from t_Tickets ticket0_ where ticket0_.Ticket_REF=?
09:37:40,642 DEBUG EntityLoader:79 - Static select for entity ticket.Ticket: select ticket0_.Ticket_REF as Ticket1_1_0_, ticket0_.Ticket_Version as Ticket2_1_0_, ticket0_.Timestamp as Timestamp1_0_, ticket0_.Type_REF as Type4_1_0_, ticket0_.Ticket_Name as Ticket5_1_0_ from t_Tickets ticket0_ with (updlock, rowlock) where ticket0_.Ticket_REF=?
09:37:40,642 DEBUG EntityLoader:79 - Static select for entity ticket.Ticket: select ticket0_.Ticket_REF as Ticket1_1_0_, ticket0_.Ticket_Version as Ticket2_1_0_, ticket0_.Timestamp as Timestamp1_0_, ticket0_.Type_REF as Type4_1_0_, ticket0_.Ticket_Name as Ticket5_1_0_ from t_Tickets ticket0_ with (updlock, rowlock) where ticket0_.Ticket_REF=?
09:37:40,642 DEBUG EntityLoader:79 - Static select for entity ticket.Ticket: select ticket0_.Ticket_REF as Ticket1_1_0_, ticket0_.Ticket_Version as Ticket2_1_0_, ticket0_.Timestamp as Timestamp1_0_, ticket0_.Type_REF as Type4_1_0_, ticket0_.Ticket_Name as Ticket5_1_0_ from t_Tickets ticket0_ with (updlock, rowlock) where ticket0_.Ticket_REF=?
09:37:40,642 DEBUG EntityLoader:34 - Static select for action ACTION_MERGE on entity ticket.Ticket: select ticket0_.Ticket_REF as Ticket1_1_0_, ticket0_.Ticket_Version as Ticket2_1_0_, ticket0_.Timestamp as Timestamp1_0_, ticket0_.Type_REF as Type4_1_0_, ticket0_.Ticket_Name as Ticket5_1_0_ from t_Tickets ticket0_ where ticket0_.Ticket_REF=?
09:37:40,642 DEBUG EntityLoader:34 - Static select for action ACTION_REFRESH on entity ticket.Ticket: select ticket0_.Ticket_REF as Ticket1_1_0_, ticket0_.Ticket_Version as Ticket2_1_0_, ticket0_.Timestamp as Timestamp1_0_, ticket0_.Type_REF as Type4_1_0_, ticket0_.Ticket_Name as Ticket5_1_0_ from t_Tickets ticket0_ where ticket0_.Ticket_REF=?
09:37:40,652 DEBUG SessionFactoryObjectFactory:39 - initializing class SessionFactoryObjectFactory
09:37:40,652 DEBUG SessionFactoryObjectFactory:76 - registered: 0752a9ce153ce32501153ce327220000 (unnamed)
09:37:40,652 INFO SessionFactoryObjectFactory:82 - Not binding factory to JNDI, no JNDI name configured
09:37:40,652 DEBUG SessionFactoryImpl:308 - instantiated session factory
09:37:40,652 DEBUG SessionFactoryImpl:392 - Checking 0 named HQL queries
09:37:40,652 DEBUG SessionFactoryImpl:412 - Checking 0 named SQL queries
09:37:40,733 DEBUG SessionImpl:220 - opened session at timestamp: 4877219678830592
09:37:40,733 DEBUG JDBCTransaction:54 - begin
09:37:40,733 DEBUG ConnectionManager:421 - opening JDBC connection
09:37:40,733 DEBUG JDBCTransaction:59 - current autocommit status: false
09:37:40,743 DEBUG SessionImpl:832 - initializing proxy: [ticket.Ticket#24370]
09:37:40,743 DEBUG Loader:1852 - loading entity: [ticket.Ticket#24370]
09:37:40,753 DEBUG AbstractBatcher:366 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
09:37:40,753 DEBUG SQL:401 -
select
ticket0_.Ticket_REF as Ticket1_1_0_,
ticket0_.Ticket_Version as Ticket2_1_0_,
ticket0_.Timestamp as Timestamp1_0_,
ticket0_.Type_REF as Type4_1_0_,
ticket0_.Ticket_Name as Ticket5_1_0_
from
t_Tickets ticket0_
where
ticket0_.Ticket_REF=?
09:37:40,903 DEBUG AbstractBatcher:382 - about to open ResultSet (open ResultSets: 0, globally: 0)
09:37:40,903 DEBUG Loader:1173 - result row: EntityKey[ticket.Ticket#24370]
09:37:40,913 DEBUG AbstractBatcher:389 - about to close ResultSet (open ResultSets: 1, globally: 1)
09:37:40,913 DEBUG AbstractBatcher:374 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
09:37:40,994 DEBUG TwoPhaseLoad:107 - resolving associations for [ticket.Ticket#24370]
09:37:41,004 DEBUG TwoPhaseLoad:206 - done materializing entity [ticket.Ticket#24370]
09:37:41,004 DEBUG StatefulPersistenceContext:790 - initializing non-lazy collections
09:37:41,004 DEBUG Loader:1883 - done entity load
preFlush********
09:37:41,004 DEBUG AbstractFlushingEventListener:111 - processing flush-time cascades
09:37:41,004 DEBUG AbstractFlushingEventListener:154 - dirty checking collections
09:37:41,024 DEBUG AbstractFlushingEventListener:85 - Flushed: 0 insertions, 1 updates, 0 deletions to 1 objects
09:37:41,024 DEBUG AbstractFlushingEventListener:91 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
09:37:41,024 DEBUG Printer:83 - listing entities:
09:37:41,024 DEBUG Printer:90 - ticket.Ticket{timestamp=2007-09-25 09:37:40, typeRef=99, ticketVersion=31, ticketName=please??, ticketRef=24370}
09:37:41,034 DEBUG AbstractBatcher:366 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
09:37:41,034 DEBUG SQL:401 -
update
t_Tickets
set
Ticket_Version=?,
Timestamp=?,
Type_REF=?,
Ticket_Name=?
where
Ticket_REF=?
and Ticket_Version=?
09:37:41,114 DEBUG AbstractBatcher:374 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
postFlush********
09:37:41,205 DEBUG JDBCTransaction:103 - commit
09:37:41,285 DEBUG JDBCTransaction:116 - committed JDBC Connection
09:37:41,285 DEBUG ConnectionManager:404 - aggressively releasing JDBC connection
09:37:41,285 DEBUG ConnectionManager:441 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
09:37:41,285 INFO SessionFactoryImpl:769 - closing
09:37:41,285 INFO DriverManagerConnectionProvider:147 - cleaning up connection pool: jdbc:sqlserver://************;database=dbprd_help;

I tried a similar thing without defining any event listeners in my config and it works for me. And I am not sure if your event listeners have anything to do with it. Can you try removing that from your config and see if it works? Normally for audits just defining a custom interceptor would do the trick.

One thing that i am not sure is that you are defining a hibernate default handler so im not sure what value add is there in that. Try creating your custom handler that inherits from DefaultFlushEntityEventListener. Then we can see if atleast the handler gets called.