0 Replies Latest reply on May 13, 2009 8:58 PM by Jonathan Tougas

    log from jboss CachedConnectionManager

    Jonathan Tougas Newbie

      I'm getting this log from the jboss CachedConnectionManager:


      12:26:21,065 INFO  [org.jboss.resource.connectionmanager.TxConnectionManager] throwable from unregister connection
      java.lang.IllegalStateException: Trying to return an unknown connection2! org.jboss.resource.adapter.jdbc.jdk6.WrappedConnectionJDK6@9b0a61
           at org.jboss.resource.connectionmanager.CachedConnectionManager.unregisterConnection(CachedConnectionManager.java:330)
           at org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener.connectionClosed(TxConnectionManager.java:720)
           at org.jboss.resource.adapter.jdbc.BaseWrapperManagedConnection.closeHandle(BaseWrapperManagedConnection.java:362)
           at org.jboss.resource.adapter.jdbc.WrappedConnection.close(WrappedConnection.java:155)
           at org.hibernate.connection.DatasourceConnectionProvider.closeConnection(DatasourceConnectionProvider.java:97)
           at org.hibernate.jdbc.ConnectionManager.closeConnection(ConnectionManager.java:474)
           at org.hibernate.jdbc.ConnectionManager.aggressiveRelease(ConnectionManager.java:429)
           at org.hibernate.jdbc.ConnectionManager.afterStatement(ConnectionManager.java:304)
           at org.hibernate.jdbc.ConnectionManager.flushEnding(ConnectionManager.java:503)
           at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:328)
           at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
           at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1027)
           at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:365)
           at org.hibernate.ejb.AbstractEntityManagerImpl$1.beforeCompletion(AbstractEntityManagerImpl.java:504)
           at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:101)
           at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:263)
           at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:86)
           at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
           at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1414)
           at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
           at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
           at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:162)
           at org.jboss.seam.transaction.UTTransaction.commit(UTTransaction.java:52)
           at org.jboss.seam.jsf.SeamPhaseListener.commitOrRollback(SeamPhaseListener.java:614)
           at org.jboss.seam.jsf.SeamPhaseListener.commitOrRollback(SeamPhaseListener.java:605)
           at org.jboss.seam.jsf.SeamPhaseListener.handleTransactionsAfterPhase(SeamPhaseListener.java:343)
           at org.jboss.seam.jsf.SeamPhaseListener.afterServletPhase(SeamPhaseListener.java:243)
           at org.jboss.seam.jsf.SeamPhaseListener.afterPhase(SeamPhaseListener.java:194)
           at com.sun.faces.lifecycle.Phase.handleAfterPhase(Phase.java:175)
           at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:114)
           at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:118)
           at javax.faces.webapp.FacesServlet.service(FacesServlet.java:265)



      This log only appears when this hibernate interceptor is configured in persistence.xml:



      public class HibernateInterceptor extends EmptyInterceptor {
      
           private static final long serialVersionUID = 3256223823628072455L;
      
           @Override
           public String onPrepareStatement(String sql) {
                getHelper().setSessionTimezone();
                return sql;
           }
      
           private IHibernateInterceptorHelper getHelper() {
                return (IHibernateInterceptorHelper)Component.getInstance(HibernateInterceptorHelper.class);
           }
      }




      @Name("hibernatehelper")
      @Stateless
      public class HibernateInterceptorHelper implements IHibernateInterceptorHelper {
      
           @In
           private EntityManager entityManager;
      
           public void setSessionTimezone() {
                Connection c = ((Session)entityManager.getDelegate()).connection();          
                try {
                     OracleConnection orac = (OracleConnection) c.unwrap(OracleConnection.class);               
                     String currentTZ = orac.getSessionTimeZone();
                     String vmTZ = TimeZone.getDefault().getID();
                     if (currentTZ == null || !currentTZ.equals(vmTZ) ) {
                          orac.setSessionTimeZone(vmTZ);
                     }
                     c.close();
                     c = null;
                } catch (SQLException e) {               
                     if( c != null ) {
                          try {c.close();} catch (SQLException e2) {}
                     }
                     throw new RuntimeException(e);
                }
           }
      }



      Also this only happens when submitting the login form of my application, other parts of the site are unaffected (it's still a prototype at the moment so it's very small):


          <h:form id="login">
              <rich:panel>
                  <f:facet name="header">Login</f:facet>
                  <p>Please login here</p>
                  <div class="dialog">
                      <h:panelGrid columns="2" rowClasses="prop" columnClasses="name,value">
                          <h:outputLabel for="username">Username</h:outputLabel>
                          <h:inputText id="username" value="#{credentials.username}"/>
                          <h:outputLabel for="password">Password</h:outputLabel>
                          <h:inputSecret id="password" value="#{credentials.password}"/>
                          <h:outputLabel for="rememberMe">Remember me</h:outputLabel>
                          <h:selectBooleanCheckbox id="rememberMe" value="#{identity.rememberMe}"/>
                      </h:panelGrid>
                  </div>
              </rich:panel>
              <div class="actionButtons">
                  <h:commandButton value="Login" action="#{identity.login}" />
              </div>
          </h:form>
      



      Also when I simulate the login form's action in a simple test case, the log does not appear. Here's the simulation:



           
              <h:form id="test">          
                       <h:commandButton action="#{test.testLogin}" value="TestLogin" />
              </h:form>
      
              public void testLogin() throws Exception {
                Credentials c = (Credentials)Component.getInstance("org.jboss.seam.security.credentials");
                c.setUsername("admin");
                c.setPassword("admin");
                Identity i = (Identity)Component.getInstance("org.jboss.seam.security.identity");
                i.login();
           }



      I also setup a bunch of tracing of the org.jboss.resource.connectionmanager and org.hibernate.jdbc.ConnectionManager log4j categories but the actual and simulated login actions are creating similar outputs so nothing obvious from these.


      Does anyone have any idea what is happening here? Should I even worry about this message?