I'm using simplified version of audit logging interceptor presented in
http://www.hibernate.org/318.html.
Everything looks ok at first sight but closing audit session does not cause succesful commiting db transaction. In new session audit table is locked during accessign because of "unfinished" audit transaction.
If audit table is locked then probably transaction has beeing commited, and it's db problem.
Any clues?
Testing environment
Hibernate version: 2.1.8
Mapping for audit table:
<class name="smst.ims.claims.audit.AuditTrailOperation" table="claimsATOperations">
<id name="id" type="long" column="id" unsaved-value="0">
<generator class="native"/>
</id>
<property name="userName"/>
<property name="operation"/>
<property name="entityClass"/>
<property name="entityId"/>
<property name="loggedDate"/>
</class>
Code between sessionFactory.openSession() and session.close():
public void postFlush(Iterator arg0) throws CallbackException {
if(inserts.size()==0&&updates.size()==0&&deletes.size()==0)return;
smst.common.Log.debug("In postFlush of AuditLogInterceptor..");
Session session=null;
try {
//using another sessionFactory than usual DAO
session = getSessionFactory().openSession();
} catch (HibernateException e1) {
Log.error(e1);
}
try {
for (Iterator itr = inserts.iterator(); itr.hasNext();) {
AuditTrailOperation atop= (AuditTrailOperation) itr.next();
atop.setEntityId(getObjectId(atop.getEntity()));
session.save(atop);
}
for (Iterator itr = updates.iterator(); itr.hasNext();) {
AuditTrailOperation atop= (AuditTrailOperation) itr.next();
session.save(atop);
}
for (Iterator itr = deletes.iterator(); itr.hasNext();) {
AuditTrailOperation atop= (AuditTrailOperation) itr.next();
session.save(atop);
}
} catch (HibernateException e) {
throw new CallbackException(e);
} finally {
inserts.clear();
updates.clear();
deletes.clear();
try {
session.flush();
session.close();
smst.common.Log.debug("postFlush session closed");
} catch (HibernateException e2) {
Log.error(e2);
}
}
database: MSDE (mssql jdbc driver)
I used simple auditable entity creation, saving through hiberante and after closing sessions, checking audit table by sql select. Below are debug logs with comments:
[INFO] Environment - -Hibernate 2.1.8
[INFO] Environment - -hibernate.properties not found
[INFO] Environment - -using CGLIB reflection optimizer
[INFO] Environment - -using JDK 1.4 java.sql.Timestamp handling
[INFO] Configuration - -configuring from file: hibernate.test.cfg.xml
[INFO] Configuration - -Mapping resource: smst/ims/claims/db-mapping.xml
[INFO] Binder - -Mapping class: smst.ims.claims.Claim -> claims
.....
[INFO] Configuration - -Configured SessionFactory: null
[INFO] Configuration - -processing one-to-many association mappings
[INFO] Configuration - -processing one-to-one association property references
[INFO] Configuration - -processing foreign key constraints
[INFO] Dialect - -Using dialect: net.sf.hibernate.dialect.SQLServerDialect
[INFO] SettingsFactory - -Use outer join fetching: true
[INFO] ConnectionProviderFactory - -Initializing connection provider: com.opensourceconnections.msjdbcproxy.HibernateProvider
[INFO] DriverManagerConnectionProvider - -Using Hibernate built-in connection pool (not for production use!)
[INFO] DriverManagerConnectionProvider - -Hibernate connection pool size: 20
[INFO] DriverManagerConnectionProvider - -using driver: com.microsoft.jdbc.sqlserver.SQLServerDriver at URL: jdbc:microsoft:sqlserver://192.168.1.1;DatabaseName=claims_test;SelectMethod=cursor
[INFO] TransactionManagerLookupFactory - -No TransactionManagerLookup configured (in JTA environment, use of process level read-write cache is not recommended)
[INFO] SettingsFactory - -Use scrollable result sets: true
[INFO] SettingsFactory - -Use JDBC3 getGeneratedKeys(): false
[INFO] SettingsFactory - -Optimize cache for minimal puts: false
[INFO] SettingsFactory - -echoing all SQL to stdout
[INFO] SettingsFactory - -Query language substitutions: {}
[INFO] SettingsFactory - -cache provider: net.sf.hibernate.cache.EhCacheProvider
[INFO] Configuration - -instantiating and configuring caches
[WARN] Configurator - -No configuration found. Configuring ehcache from ehcache-failsafe.xml found in the classpath: jar:file:/D:/projekty/_tomek/claims/web/WEB-INF/lib/ehcache-0.9.jar!/ehcache-failsafe.xml
[INFO] SessionFactoryImpl - -building session factory
[INFO] SessionFactoryObjectFactory - -Not binding factory to JNDI, no JNDI name configured
-- here is my auditable entity inserted into db
2005-12-30 11:33:56 [DEBUG] Opening hibernate session
Hibernate: insert into claims (claimNumber) values (?) select scope_identity()
[DEBUG]In postFlush of AuditLogInterceptor..
[INFO] Configuration - -processing one-to-many association mappings
[INFO] Configuration - -processing one-to-one association property references
[INFO] Configuration - -processing foreign key constraints
[INFO] Dialect - -Using dialect: net.sf.hibernate.dialect.SQLServerDialect
[INFO] SettingsFactory - -Use outer join fetching: true
[INFO] ConnectionProviderFactory - -Initializing connection provider: com.opensourceconnections.msjdbcproxy.HibernateProvider
[INFO] DriverManagerConnectionProvider - -Using Hibernate built-in connection pool (not for production use!)
[INFO] DriverManagerConnectionProvider - -Hibernate connection pool size: 20
[INFO] DriverManagerConnectionProvider - -using driver: com.microsoft.jdbc.sqlserver.SQLServerDriver at URL: jdbc:microsoft:sqlserver://192.168.1.1;DatabaseName=claims_test;SelectMethod=cursor
[INFO] TransactionManagerLookupFactory - -No TransactionManagerLookup configured (in JTA environment, use of process level read-write cache is not recommended)
[INFO] SettingsFactory - -Use scrollable result sets: true
[INFO] SettingsFactory - -Use JDBC3 getGeneratedKeys(): false
[INFO] SettingsFactory - -Optimize cache for minimal puts: false
[INFO] SettingsFactory - -echoing all SQL to stdout
[INFO] SettingsFactory - -Query language substitutions: {}
[INFO] SettingsFactory - -cache provider: net.sf.hibernate.cache.EhCacheProvider
[INFO] Configuration - -instantiating and configuring caches
[INFO] SessionFactoryImpl - -building session factory
--- here is insert into audit table generated by hibernate ---
[INFO] SessionFactoryObjectFactory - -Not binding factory to JNDI, no JNDI name configuredHibernate: insert into claimsATOperations (userName, operation, entityClass, entityId, loggedDate) values (?, ?, ?, ?, ?) select scope_identity()
[WARN] JDBCExceptionReporter - -SQL Warning: 0, SQLState:
[WARN] JDBCExceptionReporter - -[Microsoft][SQLServer 2000 Driver for JDBC]Database changed to claims_test
[WARN] JDBCExceptionReporter - -SQL Warning: 0, SQLState:
[WARN] JDBCExceptionReporter - -[Microsoft][SQLServer 2000 Driver for JDBC][SQLServer]Changed database context to 'claims_test'.
[WARN] JDBCExceptionReporter - -SQL Warning: 0, SQLState:
[WARN] JDBCExceptionReporter - -[Microsoft][SQLServer 2000 Driver for JDBC]Language changed to us_english
[WARN] JDBCExceptionReporter - -SQL Warning: 0, SQLState: [DEBUG]postFlush session closed
2005-12-30 11:34:02 [DEBUG] End of request, closing hibernate session.
--- audit session is closed ---
[WARN] JDBCExceptionReporter - -[Microsoft][SQLServer 2000 Driver for JDBC][SQLServer]Changed language setting to us_english.
[WARN] JDBCExceptionReporter - -SQL Warning: 0, SQLState:
[WARN] JDBCExceptionReporter - -[Microsoft][SQLServer 2000 Driver for JDBC]Database changed to claims_test
[WARN] JDBCExceptionReporter - -SQL Warning: 0, SQLState:
[WARN] JDBCExceptionReporter - -[Microsoft][SQLServer 2000 Driver for JDBC][SQLServer]Changed database context to 'claims_test'.
[WARN] JDBCExceptionReporter - -SQL Warning: 0, SQLState:
[WARN] JDBCExceptionReporter - -[Microsoft][SQLServer 2000 Driver for JDBC]Language changed to us_english
[WARN] JDBCExceptionReporter - -SQL Warning: 0, SQLState:
[WARN] JDBCExceptionReporter - -[Microsoft][SQLServer 2000 Driver for JDBC][SQLServer]Changed language setting to us_english.
2005-12-30 11:34:02 [DEBUG] Opening hibernate session
--- in other session i'm executing sql on audit table
2005-12-30 11:34:02 [DEBUG] SQL: select count(*) from claimsATOperations where operation=? and entityClass=? and entityId=?<
ARGS=[I,smst.ims.claims.Claim,22]
--- and it hangs up till timeout