title: Why does audit logging using Hibernate Interceptor hang at SocketInputStream.socketRead0?
body: <p>This is baffling to me.  I have searched numerous forums for clues.  In the postFlush method, I open a new hibernate (v. 3.3 - also tried v.3.5) session using a distinct session factory.  I use c3p0 v. 0.9 for connection pooling.  I start a new transaction, save the auditLog object, and commit the transaction.  This works beautifully for all my entities save one.  When attempting to commit the auditLog after deleting a ChemoRegimen entity, the application hangs (this also happens with create and update).  No exception is thrown, but upon suspending the thread I find the following stack trace (this is a Swing app):</p>
  
  <pre><code>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   
  </code></pre>
  
  <p>I am using PostgreSQL 8.4 as the backend with the 9.0 jdbc4 driver.  The postgresql.log shows [with my comments in brackets]:</p>
  
  <p><strong>[First, the chemo_regimen is deleted]</strong><BR></p>
  
  <pre><code>2011-05-11 12:19:06 CDT moms postgres LOG:  00000: execute &lt;unnamed&gt;: delete from moms_chemo_regimen where crxreg_id=$1&lt;BR&gt;
  </code></pre>
  
  <p>....<BR>
  <strong>[A lot of cascaded deletes]</strong><BR>
  ...<BR>
  <strong>[Then, my transaction begins in the interceptor session]</strong><BR></p>
  
  <pre><code>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 &lt;unnamed&gt;: select nextval ('moms_patient_change_log_seq')
  </code></pre>
  
  <p><strong>[The audit-log record is inserted]</strong><BR></p>
  
  <pre><code>2011-05-11 12:19:06 CDT moms postgres LOG:  00000: execute &lt;unnamed&gt;: 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'
  </code></pre>
  
  <p>And that is it.  The audit-log insert transaction never completes. The transaction to delete the chemo-regimen also is never committed. I am able to perform CRUD on ChemoRegimen fine when not auditing it.  A snippet of the ChemoRegimen entity is below:</p>
  
  <pre><code>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&lt;ChemoEncounter&gt; chemoEncounters = new ArrayList&lt;ChemoEncounter&gt;();
    private boolean complete;
    private Icdm icdm;&lt;BR&gt;
    ...&lt;BR&gt;
  }
  </code></pre>
  
  <p>This is my interceptor:</p>
  
  <pre><code>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&lt;Auditable&gt; inserts = new HashSet&lt;Auditable&gt;();
    private Set&lt;UpdatedEntity&gt; updates = new HashSet&lt;UpdatedEntity&gt;();
    private Set&lt;Auditable&gt; deletes = new HashSet&lt;Auditable&gt;();
    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 &gt;= 0 )
          state[i] = SessionController.userName;
        i = findPropertyNameIndex( "modifyUser", propertyNames );
        if ( i &gt;= 0 )
          state[i] = SessionController.userName;
        modified = true;
  
        if ( audit &amp;&amp; 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 &gt;= 0 )
          currentState[i] = SessionController.userName;
        i = findPropertyNameIndex( "modifyDate", propertyNames );
        if ( i &gt;= 0 )
          currentState[i] = new Date();
        modified = true;
  
        if ( audit &amp;&amp; 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 &amp;&amp; entity instanceof Auditable )
        deletes.add( (Auditable)entity );
    }
  
    @Override
    public void postFlush( Iterator iterator ) throws CallbackException
    {
      if ( inserts.isEmpty() &amp;&amp; deletes.isEmpty() &amp;&amp; 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 &lt; 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 &gt; 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();
      }
    }
  }
  </code></pre>
  
  <p>Any help would be greatly appreciated.</p>