Why does audit logging using the Hibernate Interceptor hang on SocketInputStream.socketRead0?

It puzzles me. I searched numerous forums for tips. In the postFlush method, I open a new hibernation session (v. 3.3 - also try v.3.5) using a separate factory session. I am using c3p0 v. 0.9 for the connection pool. I start a new transaction, save the auditLog object and commit the transaction. This works great for all of my entities. When you try to commit AuditLog after deleting the ChemoRegimen object, the application freezes (this also happens when creating and updating). No exception is thrown, but after pausing the thread, I find the following stack trace (this is a Swing application):

Thread [AWT-EventQueue-0] (Suspended) SocketInputStream.socketRead0(FileDescriptor, byte[], int, int, int) line: not available [native method] SocketInputStream.read(byte[], int, int) line: 129 VisibleBufferedInputStream.readMore(int) line: 145 VisibleBufferedInputStream.ensureBytes(int) line: 114 VisibleBufferedInputStream.read() line: 73 PGStream.ReceiveChar() line: 274 QueryExecutorImpl.processResults(ResultHandler, int) line: 1660 QueryExecutorImpl.execute(Query[], ParameterList[], ResultHandler, int, int, int) line: 407 Jdbc4PreparedStatement(AbstractJdbc2Statement).executeBatch() line: 2737 NewProxyPreparedStatement.executeBatch() line: 1723 BatchingBatcher.doExecuteBatch(PreparedStatement) line: 70 BatchingBatcher(AbstractBatcher).executeBatch() line: 268 ActionQueue.executeActions(List) line: 266 ActionQueue.executeActions() line: 167 DefaultFlushEventListener(AbstractFlushingEventListener).performExecutions(EventSource) line: 321 DefaultFlushEventListener.onFlush(FlushEvent) line: 50 SessionImpl.flush() line: 1027 SessionImpl.managedFlush() line: 365 JDBCTransaction.commit() line: 137 **[This is where I commit the auditLog]** MomsInterceptor.postFlush(Iterator) line: 254 DefaultFlushEventListener(AbstractFlushingEventListener).postFlush(SessionImplementor) line: 375 DefaultFlushEventListener.onFlush(FlushEvent) line: 51 SessionImpl.flush() line: 1027 SessionImpl.managedFlush() line: 365 JDBCTransaction.commit() line: 137 HibernateDAO.makeTransient(Entity) line: 119 ChemoServices.deleteChemoRegimen(ChemoRegimen, String, Session) line: 290 

I am using PostgreSQL 8.4 as a backend with jdbc4 driver 9.0. Postgresql.log shows [with my comments in brackets]:

[First, chemo_regimen deleted]

 2011-05-11 12:19:06 CDT moms postgres LOG: 00000: execute <unnamed>: delete from moms_chemo_regimen where crxreg_id=$1<BR> 

....
[Lots of cascading deletes]
...
[Then my transaction begins in an interceptor session]

 2011-05-11 12:19:06 CDT moms postgres LOG: 00000: execute S_1: BEGIN 2011-05-11 12:19:06 CDT moms postgres LOG: 00000: execute <unnamed>: select nextval ('moms_patient_change_log_seq') 

[Audit log entry inserted]

 2011-05-11 12:19:06 CDT moms postgres LOG: 00000: execute <unnamed>: insert into moms_patient_change_log (patclog_pat_id, patclog_action, patclog_reason, patclog_date, patclog_user_name, patclog_guid, patclog_id) values ($1, $2, $3, $4, $5, $6, $7) 2011-05-11 12:19:06 CDT moms postgres DETAIL: parameters: $1 = '17108', $2 = 'Deleted ChemoRegimen ABVD', $3 = NULL, $4 = '2011-05-11 12:19:06.813', $5 = 'daver', $6 = 'BFAA9D91-7A4E-835E-7A57-B72B2A79A4F1', $7 = '520' 

And it's all. The audit log insert operation never completes. The chemo deletion deal is also never completed. I can execute CRUD on ChemoRegimen when I don't test it. The following is a snippet of a ChemoRegimen object:

 public class ChemoRegimen extends MOMSEntity implements Auditable { public static final String UNSCHEDULED = "UNSCHEDULED"; private Date date = new Date(); private Patient patient; private WorkingProtocol protocol; private Physician approvingPhysician; private boolean canChangeCycles; private List<ChemoEncounter> chemoEncounters = new ArrayList<ChemoEncounter>(); private boolean complete; private Icdm icdm;<BR> ...<BR> } 

This is my interceptor:

 public class MomsInterceptor extends EmptyInterceptor { private static Logger logger = Logger.getLogger( MomsInterceptor.class.getName() ); private static Configuration configuration; private static SessionFactory sessionFactory; //Create the initial SessionFactory from the default configuration files static { initSessionFactory(); } public static void initSessionFactory() { try { configuration = new Configuration().configure(); sessionFactory = configuration.buildSessionFactory(); } catch ( Throwable ex ) { // We have to catch Throwable, otherwise we will miss // NoClassDefFoundError and other subclasses of Error logger.severe( "Building SessionFactory failed - " + ex.getMessage() ); System.err.println( "Building SessionFactory failed - " + ex.getMessage() ); throw new ExceptionInInitializerError( ex.getMessage() ); } } private Set<Auditable> inserts = new HashSet<Auditable>(); private Set<UpdatedEntity> updates = new HashSet<UpdatedEntity>(); private Set<Auditable> deletes = new HashSet<Auditable>(); private boolean audit; public MomsInterceptor(boolean audit) { super(); this.audit = audit; } private class UpdatedEntity { private Auditable auditable; private String[] propertyNames; private Object[] currentState; private Object[] previousState; private Type[] types; public UpdatedEntity( Auditable auditable, String[] propertyNames, Type[] types, Object[] currentState, Object[] previousState ) { super(); this.auditable = auditable; this.propertyNames = propertyNames; this.currentState = currentState; this.previousState = previousState; this.types = types; } public Auditable getAuditable() { return auditable; } public String[] getPropertyNames() { return propertyNames; } public Object[] getCurrentState() { return currentState; } public Object[] getPreviousState() { return previousState; } public Type[] getTypes() { return types; } /** * Return the previous value of the property name prop or null if the property name is not found. * @param prop * @return */ public Object getPrevious( String prop ) { int i = 0; for ( String name : propertyNames ) { if ( prop.equals( name ) ) return previousState[i]; i++; } return null; } } public boolean onSave( Object entity, Serializable id, Object[] state, String[] propertyNames, Type[] types ) throws CallbackException { boolean modified = false; if ( entity instanceof MutableEntity ) // Update create info. { MutableEntity me = (MutableEntity)entity; int i = findPropertyNameIndex( "createUser", propertyNames ); if ( i >= 0 ) state[i] = SessionController.userName; i = findPropertyNameIndex( "modifyUser", propertyNames ); if ( i >= 0 ) state[i] = SessionController.userName; modified = true; if ( audit && entity instanceof Auditable ) inserts.add( (Auditable)entity ); } return modified; } private int findPropertyNameIndex( String name, String[] propertyNames ) { int i = -1; if ( propertyNames.length == 0 ) return i; for ( String p : propertyNames ) { i++; if ( p.equals( name ) ) return i; } return -1; } public boolean onFlushDirty( Object entity, Serializable id, Object[] currentState, Object[] previousState, String[] propertyNames, Type[] types ) throws CallbackException { boolean modified = false; if ( entity instanceof MutableEntity ) // Update modify info. { MutableEntity me = (MutableEntity)entity; int i = findPropertyNameIndex( "modifyUser", propertyNames ); if ( i >= 0 ) currentState[i] = SessionController.userName; i = findPropertyNameIndex( "modifyDate", propertyNames ); if ( i >= 0 ) currentState[i] = new Date(); modified = true; if ( audit && entity instanceof Auditable ) updates.add( new UpdatedEntity( (Auditable)entity, propertyNames, types, currentState, previousState ) ); } return modified; } @Override public void onDelete( Object entity, Serializable id, Object[] state, String[] propertyNames, Type[] types ) { if ( audit && entity instanceof Auditable ) deletes.add( (Auditable)entity ); } @Override public void postFlush( Iterator iterator ) throws CallbackException { if ( inserts.isEmpty() && deletes.isEmpty() && updates.isEmpty() ) return; Session session = sessionFactory.openSession(); session.setFlushMode( FlushMode.COMMIT ); session.beginTransaction(); try { String action = null; for ( Auditable entity : inserts ) { action = "Created " + entity.getClass().getSimpleName() + " " + entity.toString(); session.save( new PatientChangeLog( entity.getPatient(), action, entity.getReason(), SessionController.userName ) ); } for ( Auditable entity : deletes ) { action = "Deleted " + entity.getClass().getSimpleName() + " " + entity.toString(); session.save( new PatientChangeLog( entity.getPatient(), action, entity.getReason(), SessionController.userName ) ); } for ( UpdatedEntity entity : updates ) { Auditable a = entity.getAuditable(); StringBuffer actionBuf = new StringBuffer( "Updated " + a.getClass().getSimpleName() + " " + a.toString() + ": changed " ); int count = 0; for ( int i = 0; i < entity.getPropertyNames().length; i++ ) { String prop = entity.getPropertyNames()[i]; Type type = entity.getTypes()[i]; Object curValue = entity.getCurrentState()[i]; Object prevValue = entity.getPreviousState()[i]; //Don't consider the id field or the metadata fields. if ( prop.equals( "id" ) || prop.equals( "createUser" ) || prop.equals( "createDate" ) || prop.equals( "modifyUser" ) || prop.equals( "modifyDate" ) || prop.equals( "guid" ) ) continue; if ( prevValue == null ) prevValue = new String( "" ); if ( curValue == null ) curValue = new String( "" ); if ( !prevValue.equals( curValue ) ) { if ( count > 0 ) actionBuf.append( " and " ); actionBuf.append( prop ).append( " from '" ).append( prevValue ).append( "' to '" ).append( curValue ).append( "'" ); count++; } } Patient p = (Patient)entity.getPrevious( "patient" ); //In case the patient is changed, tie it to the previous patient. session.save( new PatientChangeLog( p, actionBuf.toString(), a.getReason(), SessionController.userName ) ); } session.getTransaction().commit(); } catch ( HibernateException e ) { try { session.getTransaction().rollback(); } catch ( Exception hex ) { throw new RuntimeException( hex ); } throw new RuntimeException( e ); } finally { inserts.clear(); updates.clear(); deletes.clear(); session.close(); } } } 

Any help would be greatly appreciated.

+4
source share
3 answers

Unable to find suitable documentation for using Hibernate events instead of Envers, I decided to move the code from MyInterceptor.postFlush() to MyInterceptor.afterTransactionCompletion() . Thus, the current transaction was completed before I opened a new session / transaction to record the audit log. Thanks for your help in getting this.

+2
source

It clearly looks like a dead end between transactions: an audit transaction expects some resources blocked by the main transactions, but the main transaction cannot be committed because the interceptor lock is blocked.

It might be more conceptually clean to perform audit actions in a single transaction, although the Interceptor mechanism does not allow this. Instead, you can use events - at least Envers uses them for auditing.

+1
source

I would suggest that you are stuck in a database between an audit transaction and a Chemo transaction.

0
source

All Articles