Strange problem with hibernate (2.1.2 ) and jboss ( 3.2.3 )

ko5tik · **Posted:** Fri Mar 26, 2004 11:15 am

Hi all,

I'm stuck.

I got:
- hibernate 2.1.2
- jboss 3.2.3
- java
--%<-------------
java version "1.4.1_03"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.1_03-b02)
Java HotSpot(TM) Client VM (build 1.4.1_03-b02, mixed mode)
---%<-------------

For a while my app runs just fine , but then out of the sudden:

Code:

2004-03-26 15:47:11,179 DEBUG [webwork.util.ServletValueStack] findValue() for: query="'/images/platform/logo_hddbi.gif'" {[id="/images/platform/l
2004-03-26 15:47:11,180 DEBUG [net.sf.hibernate.impl.SessionImpl] opened session
2004-03-26 15:47:11,180 DEBUG [net.sf.hibernate.transaction.JTATransaction] Looking for UserTransaction under: UserTransaction
2004-03-26 15:47:11,180 DEBUG [net.sf.hibernate.transaction.JTATransaction] Obtained UserTransaction
2004-03-26 15:47:11,180 ERROR [net.sf.hibernate.transaction.JTATransaction] Could not register Synchronization
javax.transaction.RollbackException: Already marked for rollback
        at org.jboss.tm.TransactionImpl.registerSynchronization(TransactionImpl.java:689)
        at net.sf.hibernate.transaction.JTATransaction.begin(JTATransaction.java:169)
        at net.sf.hibernate.transaction.JTATransactionFactory.beginTransaction(JTATransactionFactory.java:58)
        at net.sf.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:2195)
        at com.infodesire.infobit.hibernate.ThreadLocalSessionProvider.getSession(ThreadLocalSessionProvider.java:40)
        at com.infodesire.infobit.InfobitPool.flush(InfobitPool.java:198)
        at com.infodesire.infobit.filter.InfobitFilter.doFilter(InfobitFilter.java:131)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:213)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:193)
        at com.opensymphony.module.sitemesh.filter.PageFilter.parsePage(PageFilter.java:123)
        at com.opensymphony.module.sitemesh.filter.PageFilter.doFilter(PageFilter.java:66)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:213)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:193)
        at com.infodesire.webgui.filter.PortalFilter.doFilter(PortalFilter.java:203)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:213)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:193)
        at org.nanocontainer.servlet.ServletRequestContainerFilter.doFilter(ServletRequestContainerFilter.java:43)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:213)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:256)
        at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:643)
        at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:480)
        at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:995)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
        at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:643)
        at org.jboss.web.tomcat.security.JBossSecurityMgrRealm.invoke(JBossSecurityMgrRealm.java:220)
        at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:641)
        at org.apache.catalina.valves.CertificatesValve.invoke(CertificatesValve.java:246)
        at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:641)
        at org.jboss.web.tomcat.tc4.statistics.ContainerStatsValve.invoke(ContainerStatsValve.java:76)
        at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:641)
        at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:480)
        at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:995)
        at org.apache.catalina.core.StandardContext.invoke(StandardContext.java:2417)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:180)
        at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:643)

In my ThreadLocalSessionProvider I do following:

Code:

    public Session getSession() throws HibernateException {
        Session sess = (Session) _session.get();
        if (sess == null) {
            sess = getFactory().openSession();
            Transaction tr = sess.beginTransaction();
            _session.set(sess);
            _transaction.set(tr);
            if (_log.isDebugEnabled()) {
                _log.debug("created session and started new transaction");
            }
        }
        return sess;
    }

(_session is thread local, ind it was not there yet, so I
could not have done something criminal, or could I ? )

Funny thing is that I was unable to forrce this error on
---%<-------------
java version "1.4.1_02"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.1_02-b06)
Java HotSpot(TM) Client VM (build 1.4.1_02-b06, mixed mode)

---%<-------------
anybody seen something similar? any clues?

tia

sgwood · **Posted:** Fri Mar 26, 2004 11:37 am

It looks like you have another transaction running before that has committed, and you are trying to reuse the _session and _transaction.

Is that possible?

Sherman

ko5tik · **Posted:** Fri Mar 26, 2004 11:59 am

It's really difficult to say _session & _transaction are thread locals,

and exception happens in

Code:

Transaction tr = sess.beginTransaction();

( new session was obtained just before )

Here is my servlet filter:

Code:

    public void doFilter(ServletRequest req, ServletResponse res, FilterChain chain)
         throws IOException, ServletException {

        // do not filter if we already checked this request
        if (req.getAttribute(_filteredKey) != null) {
            if (_log.isDebugEnabled()) {
                _log.debug("already present. passthrough");
            }
            chain.doFilter(req, res);
            return;
        }
        else {
            req.setAttribute(_filteredKey, Boolean.TRUE);
        }

        if (_log.isDebugEnabled()) {
            _log.debug("not yet. do filter");
        }
        // be sure that we flush/close pool in any case
        try {
            chain.doFilter(req, res);
        } catch(Exception ex) {
         _log.error("exception from infobitn filter: ",ex);
      }
      finally {
         // exception comes from here
         InfobitConfiguration.getInstance().getPool(_poolName).flush();
        }
    }

pool I'm flushing:

Code:

    /**
     * flush given pool. close / flush / commit active session if any new
     * session will be started afterwards.
     */
    public void flush() {
        Session sess = null;
        SessionProvider sp = null;
        try {
            sp = getSessionProvider();
            sess = sp.getSession();
            sp.returnCloseSession(sess);
        } catch (Exception ex) {
            rollback();
            _log.error("error occured while flushing infobit pool", ex);
        } finally {
            if (sp != null) {
                sp.resetSession();
            }
        }

    }

And session provider:

Code:

public class ThreadLocalSessionProvider extends BaseSessionProvider {
    private static Log _log = LogFactory.getLog(ThreadLocalSessionProvider.class);

    ThreadLocal     _session = new ThreadLocal();
    ThreadLocal     _transaction = new ThreadLocal();


    /**
     * Gets the Session attribute of the DefaultSessionProvider object
     *
     * @return                        The Session value
     * @exception HibernateException  Description of Exception
     */
    public Session getSession() throws HibernateException {
        Session sess = (Session) _session.get();
        if (sess == null) {
            sess = getFactory().openSession();
            Transaction tr = sess.beginTransaction();
            _session.set(sess);
            _transaction.set(tr);
            if (_log.isDebugEnabled()) {
                _log.debug("created session and started new transaction");
            }
        }
        return sess;
    }


    /**
     * rollback current transaction. shall be called in case of any hibernate
     * exception
     *
     * @exception HibernateException  Description of Exception
     */
    public void rollback() throws HibernateException {
        Transaction tr = (Transaction) _transaction.get();
        if (tr != null) {
            tr.rollback();
        }
        _transaction.set(null);
    }


    /**
     * give session back without disconnecting
     *
     * @param sess  session to be returned
     */
    public void returnSession(Session sess) {
    }


    /**
     * reset session if any
     */
    public void resetSession() {
        _session.set(null);
        _transaction.set(null);
    }


    /**
     * give session back and close it
     *
     * @param sess                    session to be closed
     * @exception HibernateException  may be thrown by hibernate
     */
    public void returnCloseSession(Session sess) throws HibernateException {
        Transaction tr = (Transaction) _transaction.get();
        if (tr != null && !tr.wasCommitted() && !tr.wasRolledBack()) {
            tr.commit();
            _transaction.set(null);
        }
        sess.close();
        _session.set(null);
        if (_log.isDebugEnabled()) {
            _log.debug("returned session and closed it");
        }
    }
}

Strange enough, I'm unable to manifest this problem on my local machine ( only difference is java version ) ...

ko5tik · **Posted:** Fri Mar 26, 2004 12:02 pm

I'm getting occasional warnings:

17:59:18,642 WARN [TxConnectionManager] Prepare called on a local tx. Use of local transactions on a jta transaction with more than one branch may result in inconsistent data in some cases of failure.
1

( though they seem not to be dangerous )

ko5tik · **Posted:** Fri Mar 26, 2004 1:20 pm

Code:

19:09:49,836 WARN  [TransactionImpl] Transaction TransactionImpl:XidImpl [FormatId=257, GlobalId=oscar//1859, BranchQual=] timed out. status=STATUS_ACTIVE
19:09:49,837 ERROR [ThreadPool] Unexpected exception
java.lang.InterruptedException
        at java.lang.Object.wait(Native Method)
        at java.lang.Object.wait(Object.java:426)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:653)
        at java.lang.Thread.run(Thread.java:536)

seems to be precursor of all the problems...