LazyInitializationException in the same session

zaleth81 · September 22, 2022, 10:54am

In order to enable lazy fetch across all pages of our web app, we have a custom SessionFactory that maps Hibernate Session to HTTPSession. The session is flushed every time a page is sent to JSP rendering. We’ve also made a proxy for Transaction to deal with the browser fetching our pages in multiple threads. Is there a way to get the Session ID that the lazy proxy is using to fetch needed embeddables?

Crash log (session here is from Session.getSessionIdentifier) of logging in and then clicking one of the tabs:

New HttpSession CE5DB17C075F12D3ED0D62EC5FF44DCB
11:21:21.851 [http-nio-8084-exec-55] WARN  org.hibernate.orm.connections.pooling - HHH10001002: Using Hibernate built-in connection pool (not for production use!)
<init> Locking ID java.util.concurrent.locks.ReentrantLock@5baf74ec[Locked by thread http-nio-8084-exec-55] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Transaction:getStatus()
Unlocking ID java.util.concurrent.locks.ReentrantLock@5baf74ec[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (rollback)
<init> Locking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Locked by thread http-nio-8084-exec-56] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Transaction:getStatus()
Unlocking ID java.util.concurrent.locks.ReentrantLock@3c7db4e1[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (rollback)
<init> Locking ID java.util.concurrent.locks.ReentrantLock@51f280ec[Locked by thread http-nio-8084-exec-56] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@51f280ec[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@51f280ec[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@51f280ec[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@51f280ec[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Transaction:getStatus()
Unlocking ID java.util.concurrent.locks.ReentrantLock@51f280ec[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (rollback)
<init> Locking ID java.util.concurrent.locks.ReentrantLock@3d92935[Locked by thread http-nio-8084-exec-61] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Transaction:getStatus()
Unlocking ID java.util.concurrent.locks.ReentrantLock@3d92935[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (rollback)
<init> Locking ID java.util.concurrent.locks.ReentrantLock@5b0368b4[Locked by thread http-nio-8084-exec-60] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Transaction:getStatus()
Unlocking ID java.util.concurrent.locks.ReentrantLock@5b0368b4[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (rollback)
<init> Locking ID java.util.concurrent.locks.ReentrantLock@528e4e8f[Locked by thread http-nio-8084-exec-66] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Transaction:getStatus()
Unlocking ID java.util.concurrent.locks.ReentrantLock@528e4e8f[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (rollback)
<init> Locking ID java.util.concurrent.locks.ReentrantLock@6fc88885[Locked by thread http-nio-8084-exec-63] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Transaction:getStatus()
Unlocking ID java.util.concurrent.locks.ReentrantLock@6fc88885[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (rollback)
<init> Locking ID java.util.concurrent.locks.ReentrantLock@2c5061c7[Locked by thread http-nio-8084-exec-56] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@2c5061c7[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@2c5061c7[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Transaction:getStatus()
Unlocking ID java.util.concurrent.locks.ReentrantLock@2c5061c7[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (rollback)
<init> Locking ID java.util.concurrent.locks.ReentrantLock@55c49da4[Locked by thread http-nio-8084-exec-60] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@55c49da4[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@55c49da4[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Transaction:getStatus()
Unlocking ID java.util.concurrent.locks.ReentrantLock@55c49da4[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (rollback)
<init> Locking ID java.util.concurrent.locks.ReentrantLock@3124491e[Locked by thread http-nio-8084-exec-64] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@3124491e[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@3124491e[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@3124491e[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@3124491e[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@3124491e[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@3124491e[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@3124491e[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@3124491e[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@3124491e[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@3124491e[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Transaction:getStatus()
Unlocking ID java.util.concurrent.locks.ReentrantLock@3124491e[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (rollback)
<init> Locking ID java.util.concurrent.locks.ReentrantLock@e10ff6e[Locked by thread http-nio-8084-exec-57] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Transaction:getStatus()
Unlocking ID java.util.concurrent.locks.ReentrantLock@e10ff6e[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (rollback)
<init> Locking ID java.util.concurrent.locks.ReentrantLock@777655d3[Locked by thread http-nio-8084-exec-57] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@777655d3[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@777655d3[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@777655d3[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@777655d3[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@777655d3[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@777655d3[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@777655d3[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@777655d3[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@777655d3[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@777655d3[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@777655d3[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
getTX Locking ID java.util.concurrent.locks.ReentrantLock@777655d3[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f
Unlocking ID java.util.concurrent.locks.ReentrantLock@777655d3[Unlocked] for session 038b5195-d1a2-405a-84e5-022a4af16b3f (commit)
11:21:33.435 [http-nio-8084-exec-68] TRACE org.hibernate.LazyInitializationException - failed to lazily initialize a collection of role: com.kobolde.rmm.jar.generic.License.productionProfiles, could not initialize proxy - no Session
org.hibernate.LazyInitializationException: failed to lazily initialize a collection of role: com.kobolde.rmm.jar.generic.License.productionProfiles, could not initialize proxy - no Session

Our Transaction class:

public class SyncTransaction extends TransactionImpl {
    
    private static final Map<SessionImpl,SyncTransaction> txMap = new HashMap<>();
    private static final ReentrantLock txLock = new ReentrantLock();
    
    public static synchronized SyncTransaction beginTransaction(SessionImpl session) {
        SyncTransaction tx = null;
        txLock.lock();
        try {
            if(txMap.containsKey(session)) {
                ReentrantLock lock = txMap.get(session).lock;
                System.out.println("Waiting on lock ID " + lock.toString());
                //HibernateUtil.printCallStack(6, 10);
                txLock.unlock();
                lock.lock(); // wait for previous transaction to finish
                lock.unlock();
                txLock.lock();
                System.out.println("Done waiting");
            }
            tx = new SyncTransaction(session);
            txMap.put(session, tx);
            if(!tx.isActive())
                tx.begin();
        } finally {
            txLock.unlock();
        }
        return tx;
    }
    
    public static SyncTransaction getOpenTransaction(SessionImpl session) {
        SyncTransaction ret = null;
        try {
            txLock.lock();
            if(txMap.containsKey(session))
                ret = txMap.get(session);
        } finally {
            txLock.unlock();
        }
        return ret;
    }
        
    public static SyncTransaction getTransaction(SessionImpl session) {
        SyncTransaction ret = null;
        try {
            txLock.lock();
            if(txMap.containsKey(session)) {
                ret = txMap.get(session);
                if(ret.lock.isLocked()) {
                    System.out.println("Waiting on lock ID " + ret.lock.toString());
                    //HibernateUtil.printCallStack(6, 10);
                    txLock.unlock();
                    ret.lock.lock(); // wait for previous transaction to finish
                    ret.lock.unlock();
                    txLock.lock();
                    System.out.println("Done waiting");
                }
                System.out.println("getTX Locking ID " + ret.lock.toString() + " for session " + ret.session.getSessionIdentifier());
                //HibernateUtil.printCallStack(2, 15);
                ret.lock.lock();
            }
        } finally {
            txLock.unlock();
        }
        return ret != null ? ret : beginTransaction(session);
    }
    
    public static void commit(Session session) {
        //if(session instanceof SessionImpl) {
            SessionImpl ses = (SessionImpl) session;
            try {
                txLock.lock();
                if(txMap.containsKey(ses)) {
                    SyncTransaction tx = txMap.get(ses);
                    txLock.unlock();
                    tx.doCommit();
                    txLock.lock();
                }
            } finally {
                txLock.unlock();
            }
        /*} else {
            System.out.println("Bad session sent to commit: " + session.getClass().getCanonicalName());
        }*/
    }
    
    private final ReentrantLock lock = new ReentrantLock();
    private final SessionImpl session;
    
    protected SyncTransaction(SessionImpl session) {
        super(session.getTransactionCoordinator(), session);
        this.session = session;
        lock.lock();
        System.out.println("<init> Locking ID " + lock.toString() + " for session " + session.getSessionIdentifier());
        //HibernateUtil.printCallStack(2, 15);
    }
    
    @Override
    public TransactionStatus getStatus() {
        System.out.println("Transaction:getStatus()");
        return super.getStatus();
    }
    
    @Override
    public void commit() {
        try {
            /*if(session.isDirty())
                session.flush();*/
            //super.commit();
        } finally {
            if(lock.isHeldByCurrentThread()) {
                lock.unlock();
                System.out.println("Unlocking ID " + lock.toString() + " for session " + session.getSessionIdentifier() + " (commit)");
            } else {
                //System.out.println("Commit for lock ID " + lock.toString() + " that is not held by me (" + Thread.currentThread().getName() + ")!");
            }
        }
    }
    
    public void doCommit() {
        System.out.println("doCommit() for session " + session.getSessionIdentifier());
        session.flush();
        super.commit();
        this.commit();
        try {
            txLock.lock();
            txMap.remove(session, this);
        } finally {
            txLock.unlock();
        }
    }
    
    @Override
    public void rollback() {
        try {
            super.rollback();
        } finally {
            if(lock.isHeldByCurrentThread()) {
                lock.unlock();
                System.out.println("Unlocking ID " + lock.toString() + " for session " + session.getSessionIdentifier() + " (rollback)");
            } else {
                //System.out.println("Rollback for lock ID " + lock.toString() + " that is not held by me (" + Thread.currentThread().getName() + ")!");
            }
            try {
                txLock.lock();
                txMap.remove(session, this);
            } finally {
                txLock.unlock();
            }
        }
    }
    
}

Session proxy, to return our Transaction:

    private class SessionOverride implements InvocationHandler {
        
        private final Session parent;
        
        public SessionOverride(Session session) {
            parent = session;
        }
        
        @Override
        public Object invoke(Object proxy, Method method, Object[] args) {
            if(method.getName().equals("close")) {
                return null;
            }
            if(method.getName().equals("beginTransaction")) {
                return SyncTransaction.beginTransaction((SessionImpl) parent);
            }
            if(method.getName().equals("getTransaction")) {
                return SyncTransaction.getTransaction((SessionImpl) parent);
            }
            try {
                return method.invoke(parent, args);
            } catch(Exception e) {
                System.out.println("Exception for session ID " + single.getHttpId(parent));
                e.printStackTrace();
                return null;
            }
        }
    }

Session management in the Factory:

    private SessionFactory internalFactory;
    private HashMap<String,Session> activeSessions;
    private HashMap<Session,Session> wrapSessions;
    private HashMap<Session,DelayedSessionClose> timers;
    private Timer timer;
    private SessionFactoryHeartbeat heartbeat;
    private final ReentrantLock sessionLock = new ReentrantLock();
    
    private Session doOpenSession() throws HibernateException {
        if(internalFactory == null) {
            throw new IllegalStateException("No internal factory has been created");
        }
        
        if(!HibernateUtil.useLazy())
            return internalFactory.openSession();
        
        String httpSession = null;
        try {
            ServletRequestAttributes attr = (ServletRequestAttributes) RequestContextHolder.currentRequestAttributes();
            httpSession = attr.getRequest().getSession(false).getId(); // true == allow create
        } catch(IllegalStateException e) {
            // can't load context, most likely doing unit tests
            return internalFactory.openSession();
        }
        if(httpSession == null || httpSession.isEmpty()) {
            return internalFactory.openSession();
        }
        
        Session session = activeSessions.get(httpSession);
        if(session == null) {
            session = internalFactory.openSession();
            session.setHibernateFlushMode(FlushMode.MANUAL);
            session.setDefaultReadOnly(true);
            Session wrap = (Session) Proxy.newProxyInstance(Session.class.getClassLoader(),
                    new Class[] { Session.class }, new SessionOverride(session));
            DelayedSessionClose dsc = new DelayedSessionClose(session, timer);
            // we store the original session, with its working close(), and return
            // the wrapped version where close() is a no-op.
            activeSessions.put(httpSession, session);
            wrapSessions.put(session, wrap);
            timers.put(session, dsc);
            return wrap;
        }
        timers.get(session).reset(); // tell the watchdog this session has had activity
        return wrapSessions.get(session); // return the wrapper
    }

I guess I must have messed up somewhere along the way, but I do not see where …

zaleth81 · September 22, 2022, 10:56am

The Hibernate TRACE log did not fit in my original post, so here it is:

11:21:32.934 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultInitializeCollectionEventListener - Initializing collection [com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]
11:21:32.935 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultInitializeCollectionEventListener - Checking second-level cache
11:21:32.935 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultInitializeCollectionEventListener - Collection not cached
11:21:32.935 [http-nio-8084-exec-68] DEBUG org.hibernate.loader.collection.plan.AbstractLoadPlanBasedCollectionInitializer - Loading collection: [com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]
11:21:32.935 [http-nio-8084-exec-68] DEBUG org.hibernate.SQL - select production0_.MATERIAL_GROUP_ID as material_group_id1_18_0_, production0_.SETTING_ID as setting_id2_18_0_, production1_.SETTING_ID as setting_id1_72_1_, production1_.SETTING_NAME as setting_name2_72_1_, production1_.MAIN_METAL as main_metal3_72_1_, production1_.METAL_COMP_ID as metal_comp_id4_72_1_, production1_.DEFAULT_ELEMENTS_ID as default_elements_i5_72_1_, production1_.DEFAULT_SLAG_ELEMENTS_ID as default_slag_eleme6_72_1_, production1_.THERMO_FACTORS as thermo_factors7_72_1_ from R020_PRODUCTION_RM_GROUP production0_ inner join R143_PRODUCTION_PROFILE production1_ on production0_.SETTING_ID=production1_.SETTING_ID where production0_.MATERIAL_GROUP_ID=?
11:21:32.935 [http-nio-8084-exec-68] TRACE org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl - Registering statement [oracle.jdbc.driver.OraclePreparedStatementWrapper@644bfdd9]
11:21:32.935 [http-nio-8084-exec-68] TRACE org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl - Registering last query statement [oracle.jdbc.driver.OraclePreparedStatementWrapper@644bfdd9]
11:21:32.938 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [BIGINT] - [51598]
11:21:32.938 [http-nio-8084-exec-68] TRACE org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader - Bound [2] parameters total
11:21:32.939 [http-nio-8084-exec-68] TRACE org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl - Registering result set [oracle.jdbc.driver.ForwardOnlyResultSet@65d97c64]
11:21:32.939 [http-nio-8084-exec-68] DEBUG org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader - Wrapping result set [oracle.jdbc.driver.ForwardOnlyResultSet@65d97c64]
11:21:32.939 [http-nio-8084-exec-68] TRACE org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader - Building columnName->columnIndex cache
11:21:32.939 [http-nio-8084-exec-68] DEBUG org.hibernate.loader.plan.exec.process.internal.ResultSetProcessorImpl - Preparing collection initializer : [com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]
11:21:32.939 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.LoadContexts - Constructing collection load context for result set [oracle.jdbc.driver.ForwardOnlyResultSet@65d97c64]
11:21:32.939 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.CollectionLoadContext - Starting attempt to find loading collection [[com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]]
11:21:32.939 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.LoadContexts - Attempting to locate loading collection entry [CollectionKey[com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]] in any result-set context
11:21:32.940 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.LoadContexts - Collection [CollectionKey[com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]] not located in load context
11:21:32.940 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.CollectionLoadContext - Collection not yet initialized; initializing
11:21:32.940 [http-nio-8084-exec-68] TRACE org.hibernate.loader.plan.exec.process.internal.ResultSetProcessorImpl - Processing result set
11:21:32.940 [http-nio-8084-exec-68] TRACE org.hibernate.loader.plan.exec.process.internal.ResultSetProcessorImpl - Starting ResultSet row #0
11:21:32.991 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([setting_id1_72_1_] : [BIGINT]) - [2]
11:21:32.991 [http-nio-8084-exec-68] TRACE org.hibernate.loader.plan.exec.process.internal.EntityReferenceInitializerImpl - hydrating entity state
11:21:32.991 [http-nio-8084-exec-68] TRACE org.hibernate.loader.plan.exec.process.internal.EntityReferenceInitializerImpl - Initializing object from ResultSet: [com.kobolde.rmm.jar.project.ProductionProfile#2]
11:21:32.991 [http-nio-8084-exec-68] TRACE org.hibernate.persister.entity.AbstractEntityPersister - Hydrating entity: [com.kobolde.rmm.jar.project.ProductionProfile#2]
11:21:32.991 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([setting_name2_72_1_] : [VARCHAR]) - [Cast Iron]
11:21:32.992 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([main_metal3_72_1_] : [VARCHAR]) - [Fe]
11:21:32.992 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([metal_comp_id4_72_1_] : [BIGINT]) - [1000]
11:21:32.992 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([default_elements_i5_72_1_] : [BIGINT]) - [1002]
11:21:32.992 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([default_slag_eleme6_72_1_] : [BIGINT]) - [1002]
11:21:32.992 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([thermo_factors7_72_1_] : [INTEGER]) - [0]
11:21:32.992 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([material_group_id1_18_0_] : [BIGINT]) - [51598]
11:21:32.992 [http-nio-8084-exec-68] DEBUG org.hibernate.loader.plan.exec.process.internal.CollectionReferenceInitializerImpl - Found row of collection: [com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]
11:21:32.992 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.CollectionLoadContext - Starting attempt to find loading collection [[com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]]
11:21:32.992 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.LoadContexts - Attempting to locate loading collection entry [CollectionKey[com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]] in any result-set context
11:21:32.992 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.LoadContexts - Collection [CollectionKey[com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]] located in load context
11:21:32.992 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.CollectionLoadContext - Found loading collection bound to current result set processing; reading row
11:21:32.992 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([setting_id2_18_0_] : [BIGINT]) - [2]
11:21:32.992 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Loading entity: [com.kobolde.rmm.jar.project.ProductionProfile#2]
11:21:32.992 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Attempting to resolve: [com.kobolde.rmm.jar.project.ProductionProfile#2]
11:21:32.992 [http-nio-8084-exec-68] TRACE org.hibernate.loader.plan.exec.process.internal.ResultSetProcessorImpl - Starting ResultSet row #1
11:21:32.992 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([setting_id1_72_1_] : [BIGINT]) - [3]
11:21:32.992 [http-nio-8084-exec-68] TRACE org.hibernate.loader.plan.exec.process.internal.EntityReferenceInitializerImpl - hydrating entity state
11:21:32.993 [http-nio-8084-exec-68] TRACE org.hibernate.loader.plan.exec.process.internal.EntityReferenceInitializerImpl - Initializing object from ResultSet: [com.kobolde.rmm.jar.project.ProductionProfile#3]
11:21:32.993 [http-nio-8084-exec-68] TRACE org.hibernate.persister.entity.AbstractEntityPersister - Hydrating entity: [com.kobolde.rmm.jar.project.ProductionProfile#3]
11:21:33.052 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([setting_name2_72_1_] : [VARCHAR]) - [Steel]
11:21:33.052 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([main_metal3_72_1_] : [VARCHAR]) - [Fe]
11:21:33.053 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([metal_comp_id4_72_1_] : [BIGINT]) - [1000]
11:21:33.053 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([default_elements_i5_72_1_] : [BIGINT]) - [1003]
11:21:33.053 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([default_slag_eleme6_72_1_] : [BIGINT]) - [1003]
11:21:33.053 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([thermo_factors7_72_1_] : [INTEGER]) - [0]
11:21:33.053 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([material_group_id1_18_0_] : [BIGINT]) - [51598]
11:21:33.054 [http-nio-8084-exec-68] DEBUG org.hibernate.loader.plan.exec.process.internal.CollectionReferenceInitializerImpl - Found row of collection: [com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]
11:21:33.054 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.CollectionLoadContext - Starting attempt to find loading collection [[com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]]
11:21:33.054 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.LoadContexts - Attempting to locate loading collection entry [CollectionKey[com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]] in any result-set context
11:21:33.054 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.LoadContexts - Collection [CollectionKey[com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]] located in load context
11:21:33.055 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.CollectionLoadContext - Found loading collection bound to current result set processing; reading row
11:21:33.055 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([setting_id2_18_0_] : [BIGINT]) - [3]
11:21:33.055 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Loading entity: [com.kobolde.rmm.jar.project.ProductionProfile#3]
11:21:33.055 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Attempting to resolve: [com.kobolde.rmm.jar.project.ProductionProfile#3]
11:21:33.055 [http-nio-8084-exec-68] TRACE org.hibernate.loader.plan.exec.process.internal.ResultSetProcessorImpl - Starting ResultSet row #2
11:21:33.056 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([setting_id1_72_1_] : [BIGINT]) - [4]
11:21:33.056 [http-nio-8084-exec-68] TRACE org.hibernate.loader.plan.exec.process.internal.EntityReferenceInitializerImpl - hydrating entity state
11:21:33.056 [http-nio-8084-exec-68] TRACE org.hibernate.loader.plan.exec.process.internal.EntityReferenceInitializerImpl - Initializing object from ResultSet: [com.kobolde.rmm.jar.project.ProductionProfile#4]
11:21:33.057 [http-nio-8084-exec-68] TRACE org.hibernate.persister.entity.AbstractEntityPersister - Hydrating entity: [com.kobolde.rmm.jar.project.ProductionProfile#4]
11:21:33.057 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([setting_name2_72_1_] : [VARCHAR]) - [Stainless steel]
11:21:33.058 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([main_metal3_72_1_] : [VARCHAR]) - [Fe]
11:21:33.058 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([metal_comp_id4_72_1_] : [BIGINT]) - [1000]
11:21:33.058 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([default_elements_i5_72_1_] : [BIGINT]) - [1004]
11:21:33.114 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([default_slag_eleme6_72_1_] : [BIGINT]) - [1004]
11:21:33.115 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([thermo_factors7_72_1_] : [INTEGER]) - [0]
11:21:33.115 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([material_group_id1_18_0_] : [BIGINT]) - [51598]
11:21:33.116 [http-nio-8084-exec-68] DEBUG org.hibernate.loader.plan.exec.process.internal.CollectionReferenceInitializerImpl - Found row of collection: [com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]
11:21:33.116 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.CollectionLoadContext - Starting attempt to find loading collection [[com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]]
11:21:33.116 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.LoadContexts - Attempting to locate loading collection entry [CollectionKey[com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]] in any result-set context
11:21:33.116 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.LoadContexts - Collection [CollectionKey[com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]] located in load context
11:21:33.117 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.CollectionLoadContext - Found loading collection bound to current result set processing; reading row
11:21:33.117 [http-nio-8084-exec-68] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - extracted value ([setting_id2_18_0_] : [BIGINT]) - [4]
11:21:33.117 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Loading entity: [com.kobolde.rmm.jar.project.ProductionProfile#4]
11:21:33.118 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Attempting to resolve: [com.kobolde.rmm.jar.project.ProductionProfile#4]
11:21:33.118 [http-nio-8084-exec-68] TRACE org.hibernate.loader.plan.exec.process.internal.ResultSetProcessorImpl - Done processing result set (3 rows)
11:21:33.118 [http-nio-8084-exec-68] TRACE org.hibernate.loader.plan.exec.process.internal.AbstractRowReader - Total objects hydrated: 3
11:21:33.119 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Resolving attributes for [com.kobolde.rmm.jar.project.ProductionProfile#2]
11:21:33.120 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `name` : value = Cast Iron
11:21:33.121 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`name`)  - enhanced for lazy-loading? - false
11:21:33.121 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `mainMetalElement` : value = Fe
11:21:33.122 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`mainMetalElement`)  - enhanced for lazy-loading? - false
11:21:33.123 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `defaultMaxComposition` : value = 1000
11:21:33.123 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`defaultMaxComposition`)  - enhanced for lazy-loading? - false
11:21:33.123 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Loading entity: [com.kobolde.rmm.jar.generic.MetalComposition#1000]
11:21:33.124 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Creating new proxy for entity
11:21:33.129 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `defaultElementsOrder` : value = 1002
11:21:33.129 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`defaultElementsOrder`)  - enhanced for lazy-loading? - false
11:21:33.129 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Loading entity: [com.kobolde.rmm.jar.generic.MetalComposition#1002]
11:21:33.177 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Creating new proxy for entity
11:21:33.177 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `defaultSlagElementsOrder` : value = 1002
11:21:33.177 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`defaultSlagElementsOrder`)  - enhanced for lazy-loading? - false
11:21:33.177 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Loading entity: [com.kobolde.rmm.jar.generic.SlagComposition#1002]
11:21:33.177 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Creating new proxy for entity
11:21:33.179 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `availableFactorSets` : value = NOT NULL COLLECTION
11:21:33.179 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`availableFactorSets`)  - enhanced for lazy-loading? - false
11:21:33.179 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.LoadContexts - Attempting to locate loading collection entry [CollectionKey[com.kobolde.rmm.jar.project.ProductionProfile.availableFactorSets#2]] in any result-set context
11:21:33.179 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.LoadContexts - Collection [CollectionKey[com.kobolde.rmm.jar.project.ProductionProfile.availableFactorSets#2]] not located in load context
11:21:33.179 [http-nio-8084-exec-68] TRACE org.hibernate.type.CollectionType - Created collection wrapper: [com.kobolde.rmm.jar.project.ProductionProfile.availableFactorSets#2]
11:21:33.179 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `thermoFactor` : value = 0
11:21:33.179 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`thermoFactor`)  - enhanced for lazy-loading? - false
11:21:33.179 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Done materializing entity [com.kobolde.rmm.jar.project.ProductionProfile#2]
11:21:33.179 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Resolving attributes for [com.kobolde.rmm.jar.project.ProductionProfile#3]
11:21:33.179 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `name` : value = Steel
11:21:33.179 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`name`)  - enhanced for lazy-loading? - false
11:21:33.179 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `mainMetalElement` : value = Fe
11:21:33.179 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`mainMetalElement`)  - enhanced for lazy-loading? - false
11:21:33.179 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `defaultMaxComposition` : value = 1000
11:21:33.179 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`defaultMaxComposition`)  - enhanced for lazy-loading? - false
11:21:33.179 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Loading entity: [com.kobolde.rmm.jar.generic.MetalComposition#1000]
11:21:33.179 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Entity proxy found in session cache
11:21:33.179 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `defaultElementsOrder` : value = 1003
11:21:33.179 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`defaultElementsOrder`)  - enhanced for lazy-loading? - false
11:21:33.179 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Loading entity: [com.kobolde.rmm.jar.generic.MetalComposition#1003]
11:21:33.179 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Creating new proxy for entity
11:21:33.240 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `defaultSlagElementsOrder` : value = 1003
11:21:33.240 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`defaultSlagElementsOrder`)  - enhanced for lazy-loading? - false
11:21:33.240 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Loading entity: [com.kobolde.rmm.jar.generic.SlagComposition#1003]
11:21:33.240 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Creating new proxy for entity
11:21:33.240 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `availableFactorSets` : value = NOT NULL COLLECTION
11:21:33.240 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`availableFactorSets`)  - enhanced for lazy-loading? - false
11:21:33.240 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.LoadContexts - Attempting to locate loading collection entry [CollectionKey[com.kobolde.rmm.jar.project.ProductionProfile.availableFactorSets#3]] in any result-set context
11:21:33.240 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.LoadContexts - Collection [CollectionKey[com.kobolde.rmm.jar.project.ProductionProfile.availableFactorSets#3]] not located in load context
11:21:33.240 [http-nio-8084-exec-68] TRACE org.hibernate.type.CollectionType - Created collection wrapper: [com.kobolde.rmm.jar.project.ProductionProfile.availableFactorSets#3]
11:21:33.240 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `thermoFactor` : value = 0
11:21:33.240 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`thermoFactor`)  - enhanced for lazy-loading? - false
11:21:33.241 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Done materializing entity [com.kobolde.rmm.jar.project.ProductionProfile#3]
11:21:33.241 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Resolving attributes for [com.kobolde.rmm.jar.project.ProductionProfile#4]
11:21:33.241 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `name` : value = Stainless steel
11:21:33.241 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`name`)  - enhanced for lazy-loading? - false
11:21:33.241 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `mainMetalElement` : value = Fe
11:21:33.241 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`mainMetalElement`)  - enhanced for lazy-loading? - false
11:21:33.241 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `defaultMaxComposition` : value = 1000
11:21:33.241 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`defaultMaxComposition`)  - enhanced for lazy-loading? - false
11:21:33.241 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Loading entity: [com.kobolde.rmm.jar.generic.MetalComposition#1000]
11:21:33.241 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Entity proxy found in session cache
11:21:33.241 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `defaultElementsOrder` : value = 1004
11:21:33.241 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`defaultElementsOrder`)  - enhanced for lazy-loading? - false
11:21:33.241 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Loading entity: [com.kobolde.rmm.jar.generic.MetalComposition#1004]
11:21:33.241 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Creating new proxy for entity
11:21:33.241 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `defaultSlagElementsOrder` : value = 1004
11:21:33.304 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`defaultSlagElementsOrder`)  - enhanced for lazy-loading? - false
11:21:33.304 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Loading entity: [com.kobolde.rmm.jar.generic.SlagComposition#1004]
11:21:33.304 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultLoadEventListener - Creating new proxy for entity
11:21:33.304 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `availableFactorSets` : value = NOT NULL COLLECTION
11:21:33.304 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`availableFactorSets`)  - enhanced for lazy-loading? - false
11:21:33.304 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.LoadContexts - Attempting to locate loading collection entry [CollectionKey[com.kobolde.rmm.jar.project.ProductionProfile.availableFactorSets#4]] in any result-set context
11:21:33.304 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.LoadContexts - Collection [CollectionKey[com.kobolde.rmm.jar.project.ProductionProfile.availableFactorSets#4]] not located in load context
11:21:33.304 [http-nio-8084-exec-68] TRACE org.hibernate.type.CollectionType - Created collection wrapper: [com.kobolde.rmm.jar.project.ProductionProfile.availableFactorSets#4]
11:21:33.304 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Processing attribute `thermoFactor` : value = 0
11:21:33.304 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Attribute (`thermoFactor`)  - enhanced for lazy-loading? - false
11:21:33.304 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.internal.TwoPhaseLoad - Done materializing entity [com.kobolde.rmm.jar.project.ProductionProfile#4]
11:21:33.304 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.LoadContexts - Attempting to locate loading collection entry [CollectionKey[com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]] in any result-set context
11:21:33.304 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.LoadContexts - Collection [CollectionKey[com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]] located in load context
11:21:33.304 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.CollectionLoadContext - Removing collection load entry [org.hibernate.engine.loading.internal.LoadingCollectionEntry<rs=oracle.jdbc.driver.ForwardOnlyResultSet@65d97c64, coll=[com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]>@333b5d4c]
11:21:33.305 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.loading.internal.CollectionLoadContext - 1 collections were found in result set for role: com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles
11:21:33.305 [http-nio-8084-exec-68] TRACE org.hibernate.engine.loading.internal.CollectionLoadContext - Ending loading collection [org.hibernate.engine.loading.internal.LoadingCollectionEntry<rs=oracle.jdbc.driver.ForwardOnlyResultSet@65d97c64, coll=[com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]>@333b5d4c]
11:21:33.305 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.loading.internal.CollectionLoadContext - Collection fully initialized: [com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles#51598]
11:21:33.305 [http-nio-8084-exec-68] DEBUG org.hibernate.engine.loading.internal.CollectionLoadContext - 1 collections initialized for role: com.kobolde.rmm.jar.material.RawMaterialGroup.productionProfiles
11:21:33.305 [http-nio-8084-exec-68] TRACE org.hibernate.loader.plan.exec.process.internal.ResultSetProcessingContextImpl - Skipping create subselects because there are fewer than 2 results, so query by key is more efficient.
11:21:33.305 [http-nio-8084-exec-68] TRACE org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl - Releasing statement [oracle.jdbc.driver.OraclePreparedStatementWrapper@644bfdd9]
11:21:33.305 [http-nio-8084-exec-68] TRACE org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl - Closing result set [oracle.jdbc.driver.ForwardOnlyResultSet@65d97c64]
11:21:33.367 [http-nio-8084-exec-68] TRACE org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl - Closing prepared statement [oracle.jdbc.driver.OraclePreparedStatementWrapper@644bfdd9]
11:21:33.367 [http-nio-8084-exec-68] TRACE org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl - Starting after statement execution processing [AFTER_TRANSACTION]
11:21:33.367 [http-nio-8084-exec-68] TRACE org.hibernate.engine.internal.StatefulPersistenceContext - Initializing non-lazy collections
11:21:33.367 [http-nio-8084-exec-68] DEBUG org.hibernate.loader.collection.plan.AbstractLoadPlanBasedCollectionInitializer - Done loading collection
11:21:33.367 [http-nio-8084-exec-68] TRACE org.hibernate.event.internal.DefaultInitializeCollectionEventListener - Collection initialized
11:21:33.435 [http-nio-8084-exec-68] TRACE org.hibernate.LazyInitializationException - failed to lazily initialize a collection of role: com.kobolde.rmm.jar.generic.License.productionProfiles, could not initialize proxy - no Session

zaleth81 · September 22, 2022, 11:57am

The License belongs to a UserGroup, to which a number of Users also belong. The User is loaded when logging in, and the License is needed in subpages to see what the user is allowed to do.
User.hbm.xml:

    <list cascade="save-update,delete, delete-orphan" lazy="true" name="userP" table="PROJECT_PERMISSION">
      <key column="user_id"/>
      <list-index column="PERM_POS"/>
      <one-to-many class="com.kobolde.rmm.jar.administration.UserGroupPermission"/>
    </list>

UserGroupPermission.hbm.xml:

    <many-to-one class="com.kobolde.rmm.jar.administration.UserGroup" column="USERGROUP_ID" lazy="proxy" name="group" not-null="true"/>
lazy="proxy" name="role" not-null="true"/>-->
    <many-to-one class="com.kobolde.rmm.jar.administration.PROJECTUser" column="USER_ID" lazy="proxy" name="owner"/>

UserGroup.hbm.xml:

    <many-to-one column="LICENSE_ID" lazy="proxy" name="license" unique="true"/>

beikov · September 22, 2022, 12:45pm

Please try reproducing your issue in an isolated test case(hibernate-test-case-templates/JPAUnitTestCase.java at main · hibernate/hibernate-test-case-templates · GitHub) so that we can discuss the topic on the basis of that. Proxies are detached from sessions when the session is closed, so whatever your code is doing, I guess you are closing the session too early. Also note that the Hibernate Session is not thread safe.

zaleth81 · September 22, 2022, 2:18pm

I found a solution, by proxying SessionImplementor instead of Session, I can sort the SyncTransactions on Session UUID instead of object (which understandably messed things up when it would sometimes be the interface proxy and sometimes the underlying SessionImpl).

Topic		Replies	Views
Problems when using multi-tenancy and lazy loading Hibernate ORM	6	1887	March 24, 2018
Upgrade from 5.4.10 to 5.4.11 up throws LazyInitializerException from Envers ToOneIdMapper Hibernate ORM	0	607	August 8, 2020
Getting SessionFactory/Session in WebApplication Hibernate ORM	3	372	February 19, 2021
Slightly customized LazyInitializer returns null in method.invoke() Hibernate ORM	5	1622	May 30, 2018
Re-introducing entity as proxied to the Session after "persist" a "new" object Hibernate ORM	2	317	March 13, 2023

LazyInitializationException in the same session

Related topics