-->
These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

View unanswered posts | View active topics


Board index » Hibernate & Java Persistence » Hibernate Users

All times are UTC - 5 hours [ DST ]


Forum locked This topic is locked, you cannot edit posts or make further replies.  Page 1 of 1
  [ 5 posts ] 
  Previous topic | Next topic 
Author Message
AndreasH
 Post subject: Open Session In View: ehcache & LazyInitializationExcept
PostPosted: Fri Feb 09, 2007 10:28 am 
Newbie

Joined: Fri Jul 14, 2006 7:32 am
Posts: 9
Hi!

Hibernate-Version: 3.1.3, 3.2.2

I'm working on a web application using Hibernate and the "Open Session In View" pattern: I have a HibernateFilter class mapped as ServletFilter for all servlets. The doFilter() method starts the Hibernate transaction using the "current session", calls the next filter in the chain and then closes the transaction (with commit or rollback), just as described in the "Open Session In View" document on the website or in the Java Persistance with Hibernate book.

This works fine as long as I do not enable the second level cache. With the second level cache (ehcache) enabled, under rare circumstances I get the well-known "LazyInitializationException" right in the middle of the application.

Note that Hibernate is able to retrieve several entities using lazy loading in this request, before it hits the exception. In the debugger we see that the session object is in "open" state (attribute closed==false) all the time before suddenly it changes into "closed" state (attribute closed==true) but we can not see anyone closing the session (we set a breakpoint on AbstractSessionImpl#setClosed(), it is never called before the exception occurs, only afterwards when the filter is doing the rollback)

Here are some logs from the application with comments:
Code:
2007-02-09 14:13:26,488 [co.xss.emcs.db.HibernateFilter:DEBUG] Begin transaction for request http://tolstoi.intern.xss.co.at:8080/emcs-demo/Multiline.do from host 192.168.162.51
2007-02-09 14:13:26,489 [org.hibernate.impl.SessionImpl:DEBUG] opened session at timestamp: 4796525799378944
2007-02-09 14:13:26,490 [t.co.xss.emcs.db.HibernateUtil:DEBUG] beginTransaction: transaction 18733613 (active=false,commited=false,rolledback=false), Hibernate session 14608098 (connected=n/a,dirty=n/a,open=true)


You can see how the transaction gets started and the Hibernate session gets opened in the HibernateFilter#doFilter() method.

Then some work is done inside the application. Several DAO's are constructed and used to load entities from the database. All DAO's are using the same "current session" (hash-code 14608098)

Code:
2007-02-09 14:13:26,497 [org.hibernate.impl.SessionImpl:DEBUG] checking session dirtiness
2007-02-09 14:13:26,499 [t.co.xss.emcs.db.HibernateUtil:DEBUG] getSession: Hibernate session 14608098 (connected=true,dirty=false,open=true)
2007-02-09 14:13:26,505 [org.hibernate.impl.SessionImpl:DEBUG] checking session dirtiness
2007-02-09 14:13:26,507 [t.co.xss.emcs.db.HibernateUtil:DEBUG] getSession: Hibernate session 14608098 (connected=true,dirty=false,open=true)
2007-02-09 14:13:26,511 [org.hibernate.impl.SessionImpl:DEBUG] checking session dirtiness
2007-02-09 14:13:26,514 [t.co.xss.emcs.db.HibernateUtil:DEBUG] getSession: Hibernate session 14608098 (connected=true,dirty=false,open=true)
2007-02-09 14:13:26,518 [mestellenparameterDAOHibernate:DEBUG] at.co.xss.emcs.dao.hibernate.ProbenahmestellenparameterDAOHibernate@27d9e5.findBy(pns=20, pspez=17)
2007-02-09 14:13:26,520 [org.hibernate.impl.SessionImpl:DEBUG] checking session dirtiness
2007-02-09 14:13:26,522 [t.co.xss.emcs.db.HibernateUtil:DEBUG] getSession: Hibernate session 14608098 (connected=true,dirty=false,open=true)
2007-02-09 14:13:26,548 [mestellenparameterDAOHibernate:DEBUG] got 1 PNSPAR (28ms)
2007-02-09 14:13:26,549 [mestellenparameterDAOHibernate:DEBUG] at.co.xss.emcs.dao.hibernate.ProbenahmestellenparameterDAOHibernate@27d9e5.findBy(pns=48, pspez=17)
2007-02-09 14:13:26,552 [mestellenparameterDAOHibernate:DEBUG] got 1 PNSPAR (1ms)
2007-02-09 14:13:26,554 [.apache.jsp.jsps.multiline_jsp: INFO] Starting multiline.jsp
2007-02-09 14:13:26,559 [org.hibernate.impl.SessionImpl:DEBUG] checking session dirtiness
2007-02-09 14:13:26,561 [t.co.xss.emcs.db.HibernateUtil:DEBUG] getSession: Hibernate session 14608098 (connected=true,dirty=false,open=true)
2007-02-09 14:13:26,564 [org.hibernate.impl.SessionImpl:DEBUG] initializing proxy: [at.co.xss.emcs.model.Parameter#4]
2007-02-09 14:13:26,567 [org.hibernate.impl.SessionImpl:DEBUG] initializing proxy: [at.co.xss.emcs.model.Visualisierung#3]
2007-02-09 14:13:26,569 [org.hibernate.impl.SessionImpl:DEBUG] initializing proxy: [at.co.xss.emcs.model.Einheit#3780]
2007-02-09 14:13:26,577 [org.hibernate.impl.SessionImpl:DEBUG] checking session dirtiness
2007-02-09 14:13:26,580 [t.co.xss.emcs.db.HibernateUtil:DEBUG] getSession: Hibernate session 14608098 (connected=true,dirty=false,open=true)
2007-02-09 14:13:26,584 [org.hibernate.impl.SessionImpl:DEBUG] checking session dirtiness
2007-02-09 14:13:26,586 [t.co.xss.emcs.db.HibernateUtil:DEBUG] getSession: Hibernate session 14608098 (connected=true,dirty=false,open=true)
2007-02-09 14:13:26,591 [org.hibernate.impl.SessionImpl:DEBUG] checking session dirtiness
2007-02-09 14:13:26,593 [t.co.xss.emcs.db.HibernateUtil:DEBUG] getSession: Hibernate session 14608098 (connected=true,dirty=false,open=true)
2007-02-09 14:13:26,597 [org.hibernate.impl.SessionImpl:DEBUG] checking session dirtiness
2007-02-09 14:13:26,599 [t.co.xss.emcs.db.HibernateUtil:DEBUG] getSession: Hibernate session 14608098 (connected=true,dirty=false,open=true)
2007-02-09 14:13:26,604 [org.hibernate.impl.SessionImpl:DEBUG] checking session dirtiness
2007-02-09 14:13:26,606 [t.co.xss.emcs.db.HibernateUtil:DEBUG] getSession: Hibernate session 14608098 (connected=true,dirty=false,open=true)
2007-02-09 14:13:26,609 [org.hibernate.impl.SessionImpl:DEBUG] checking session dirtiness
2007-02-09 14:13:26,610 [t.co.xss.emcs.db.HibernateUtil:DEBUG] getSession: Hibernate session 14608098 (connected=true,dirty=false,open=true)
2007-02-09 14:13:26,613 [mestellenparameterDAOHibernate:DEBUG] at.co.xss.emcs.dao.hibernate.ProbenahmestellenparameterDAOHibernate@510bb7.findBy(pns=20, pspez=17, aggr=1MW, card=mv, zrtyp=ONLINE)
2007-02-09 14:13:26,614 [org.hibernate.impl.SessionImpl:DEBUG] checking session dirtiness
2007-02-09 14:13:26,615 [t.co.xss.emcs.db.HibernateUtil:DEBUG] getSession: Hibernate session 14608098 (connected=true,dirty=false,open=true)
2007-02-09 14:13:26,617 [mestellenparameterDAOHibernate:DEBUG] got 1 PNSPAR (3ms)
2007-02-09 14:13:26,618 [org.hibernate.impl.SessionImpl:DEBUG] initializing proxy: [at.co.xss.emcs.model.Parameterspezifikation#17]
2007-02-09 14:13:26,620 [org.hibernate.impl.SessionImpl:DEBUG] initializing proxy: [at.co.xss.emcs.model.Visualisierung#2]


Now it get's interesting: on of the DAO's is trying to get a list of entities from the database. Those entities have several other entities associated which are then loaded on the first access to the corresponding getter method.
This works fine for several entities, but then suddenly throws a LIE (note that we are still inside the request handler, we did not close the session so far!):

Code:
2007-02-09 14:13:26,622 [hibernate.MesswertDAOHibernate:DEBUG] at.co.xss.emcs.dao.hibernate.MesswertDAOHibernate@1cab87f.getList(pns=20, pspez=17, aggr=1MW, card=mv, zrtyp=ONLINE, from=Fri Feb 02 13:00:00 CET 2007, to=Fri Feb 09 13:00:00 CET 2007, itype=OPEN_BOTH)
2007-02-09 14:13:26,623 [org.hibernate.impl.SessionImpl:DEBUG] checking session dirtiness
2007-02-09 14:13:26,624 [t.co.xss.emcs.db.HibernateUtil:DEBUG] getSession: Hibernate session 14608098 (connected=true,dirty=false,open=true)
2007-02-09 14:13:26,780 [org.hibernate.impl.SessionImpl:DEBUG] initializing proxy: [at.co.xss.emcs.model.Zeitreihe#3340]
2007-02-09 14:13:26,782 [org.hibernate.impl.SessionImpl:DEBUG] initializing proxy: [at.co.xss.emcs.model.Probenahmestelle#20]
2007-02-09 14:13:26,784 [org.hibernate.impl.SessionImpl:DEBUG] initializing proxy: [at.co.xss.emcs.model.Untersuchungsgebiet#10]
2007-02-09 14:13:26,856 [co.xss.emcs.db.HibernateFilter:ERROR] request http://tolstoi.intern.xss.co.at:8080/emcs-demo/Multiline.do from host 192.168.162.51 - doFilter failed with exception org.apache.jasper.JasperException: could not initialize proxy - the owning Session was closed
org.apache.jasper.JasperException: could not initialize proxy - the owning Session was closed
        at org.apache.jasper.servlet.JspServletWrapper.handleJspException(JspServletWrapper.java:512)
        at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:377)
        at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:314)
        at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:264)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:672)
        at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:463)
        at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:398)
        at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:301)
        at org.apache.struts.action.RequestProcessor.doForward(RequestProcessor.java:1085)
        at org.apache.struts.action.RequestProcessor.processForwardConfig(RequestProcessor.java:398)
        at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:241)
        at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1196)
        at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:414)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:689)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at at.co.xss.emcs.db.HibernateFilter.doFilter(HibernateFilter.java:172)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
        at org.apache.coyote.http11.Http11AprProcessor.process(Http11AprProcessor.java:833)
        at org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:639)
        at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1285)
        at java.lang.Thread.run(Thread.java:595)


As an exception was thrown inside the request handler, our filter tries to roll back the transaction in the "catch" clause. As we are printing some information about the transaction and the session state, you can see that at least here the session (hash-code 14608098) is still (or again?) "open" and "connected". This is also the only place where the session is actively closed and the AbstractSessionImpl#setClosed() method gets called (checked with a breakpoint in the debugger)

Code:
2007-02-09 14:13:26,858 [org.hibernate.impl.SessionImpl:DEBUG] checking session dirtiness
2007-02-09 14:13:26,860 [t.co.xss.emcs.db.HibernateUtil:DEBUG] rollbackTransaction: transaction 18733613 (active=true,commited=false,rolledback=false), Hibernate session 14608098 (connected=true,dirty=false,open=true)
2007-02-09 14:13:26,863 [org.hibernate.impl.SessionImpl:DEBUG] after transaction completion
2007-02-09 14:13:26,864 [org.hibernate.impl.SessionImpl:DEBUG] automatically closing session
2007-02-09 14:13:26,865 [org.hibernate.impl.SessionImpl:DEBUG] closing session


The full (internal) exception stack trace from this event looks like this:
Code:
org.hibernate.LazyInitializationException: could not initialize proxy - the owning Session was closed
        at org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:60)
        at org.hibernate.proxy.AbstractLazyInitializer.getImplementation(AbstractLazyInitializer.java:111)
        at org.hibernate.proxy.pojo.cglib.CGLIBLazyInitializer.invoke(CGLIBLazyInitializer.java:140)
        at at.co.xss.emcs.model.Untersuchungsgebiet$$EnhancerByCGLIB$$7494130e.getCode(<generated>)
        at at.co.xss.emcs.model.Untersuchungsgebiet.equals(Untersuchungsgebiet.java:165)
        at sun.reflect.GeneratedMethodAccessor216.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:585)
        at org.hibernate.proxy.pojo.cglib.CGLIBLazyInitializer.invoke(CGLIBLazyInitializer.java:147)
        at at.co.xss.emcs.model.Untersuchungsgebiet$$EnhancerByCGLIB$$7494130e.equals(<generated>)
        at at.co.xss.emcs.model.Probenahmestelle.equals(Probenahmestelle.java:444)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:585)
        at org.hibernate.proxy.pojo.cglib.CGLIBLazyInitializer.invoke(CGLIBLazyInitializer.java:147)
        at at.co.xss.emcs.model.Probenahmestelle$$EnhancerByCGLIB$$5e79c540.equals(<generated>)
        at at.co.xss.emcs.model.Probenahmestellenparameter.equals(Probenahmestellenparameter.java:447)
        at at.co.xss.emcs.model.Zeitreihe.equals(Zeitreihe.java:256)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:585)
        at org.hibernate.proxy.pojo.cglib.CGLIBLazyInitializer.invoke(CGLIBLazyInitializer.java:147)
        at at.co.xss.emcs.model.Zeitreihe$$EnhancerByCGLIB$$82b0c703.equals(<generated>)
        at org.hibernate.util.EqualsHelper.equals(EqualsHelper.java:10)
        at org.hibernate.type.AbstractType.isEqual(AbstractType.java:108)
        at org.hibernate.type.ComponentType.isEqual(ComponentType.java:125)
        at org.hibernate.cache.CacheKey.equals(CacheKey.java:51)
        at java.util.HashMap.eq(HashMap.java:299)
        at java.util.HashMap.getEntry(HashMap.java:398)
        at java.util.LinkedHashMap.get(LinkedHashMap.java:273)
        at net.sf.ehcache.store.MemoryStore.get(MemoryStore.java:130)
        at net.sf.ehcache.Cache.searchInMemoryStore(Cache.java:819)
        at net.sf.ehcache.Cache.get(Cache.java:654)
        at org.hibernate.cache.EhCache.get(EhCache.java:74)
        at org.hibernate.cache.ReadWriteCache.put(ReadWriteCache.java:153)
        at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:156)
        at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:842)
        at org.hibernate.loader.Loader.doQuery(Loader.java:717)
        at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)
        at org.hibernate.loader.Loader.doList(Loader.java:2211)
        at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2095)
        at org.hibernate.loader.Loader.list(Loader.java:2090)
        at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:375)
        at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:338)
        at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:172)
        at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1121)
        at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)
        at at.co.xss.emcs.dao.hibernate.MesswertDAOHibernate.getList(MesswertDAOHibernate.java:520)
        at at.co.xss.emcs.tg.data.AbstractEmcsXYDataset.readData(AbstractEmcsXYDataset.java:165)
        at at.co.xss.emcs.tg.data.MultilineXYDataset.readSeries(MultilineXYDataset.java:231)
        at at.co.xss.emcs.tg.data.MultilineXYDataset.readData(MultilineXYDataset.java:216)
        at at.co.xss.emcs.tg.dsp.AbstractEmcsDatasetProducer.produceDataset(AbstractEmcsDatasetProducer.java:174)
        at at.co.xss.emcs.tg.dsp.AbstractEmcsDatasetProducer.produceDataset(AbstractEmcsDatasetProducer.java:123)
        at de.laures.cewolf.taglib.DataContainer.getDataset(DataContainer.java:53)
        at de.laures.cewolf.taglib.SimpleChartDefinition.getDataset(SimpleChartDefinition.java:34)
        at de.laures.cewolf.taglib.SimpleChartDefinition.produceChart(SimpleChartDefinition.java:30)
        at de.laures.cewolf.taglib.AbstractChartDefinition.getChart(AbstractChartDefinition.java:121)
        at de.laures.cewolf.taglib.ChartImageDefinition.ensureRendered(ChartImageDefinition.java:137)
        at de.laures.cewolf.taglib.ChartImageDefinition.getBytes(ChartImageDefinition.java:131)
        at de.laures.cewolf.storage.SerializableChartImage.<init>(SerializableChartImage.java:49)
        at de.laures.cewolf.storage.ClusterableSessionStorage.getCacheObject(ClusterableSessionStorage.java:40)
        at de.laures.cewolf.storage.AbstractSessionStorage.storeChartImage(AbstractSessionStorage.java:88)
        at de.laures.cewolf.storage.AbstractSessionStorage.storeChartImage(AbstractSessionStorage.java:60)
        at de.laures.cewolf.taglib.tags.ChartImgTag.doStartTag(ChartImgTag.java:79)
        at org.apache.jsp.jsps.multiline_jsp._jspx_meth_cewolf_img_0(multiline_jsp.java:403)
        at org.apache.jsp.jsps.multiline_jsp._jspService(multiline_jsp.java:257)
        at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:97)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:334)
        at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:314)
        at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:264)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:672)
        at org.apache.catalina.core.ApplicationDispatcher.doInclude(ApplicationDispatcher.java:574)
        at org.apache.catalina.core.ApplicationDispatcher.include(ApplicationDispatcher.java:499)
        at org.apache.jasper.runtime.JspRuntimeLibrary.include(JspRuntimeLibrary.java:966)
        at org.apache.jsp.jsps.evaluation_jsp._jspService(evaluation_jsp.java:187)
        at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:97)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:334)
        at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:314)
        at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:264)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:672)
        at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:463)
        at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:398)
        at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:301)
        at org.apache.struts.action.RequestProcessor.doForward(RequestProcessor.java:1085)
        at org.apache.struts.action.RequestProcessor.processForwardConfig(RequestProcessor.java:398)
        at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:241)
        at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1196)
        at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:414)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:689)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at at.co.xss.emcs.db.HibernateFilter.doFilter(HibernateFilter.java:172)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
        at org.apache.coyote.http11.Http11AprProcessor.process(Http11AprProcessor.java:833)
        at org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:639)
        at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1285)
        at java.lang.Thread.run(Thread.java:595)


To me this is confusing: how can the session get closed when nobody is actively closing it? And how can it become open again after the exception was thrown when nobody actively opens it?
And why does this only happen when we enable the second level cache? (it also does not happen when we set "lazy=true" on all the entities, but this seems to be obvious)

Finally: what are we doing wrong here and how can we solve the problem?
Any idea, anyone?
Top
 Profile  
 
AndreasH
 Post subject: more debugging information...
PostPosted: Fri Feb 09, 2007 1:45 pm 
Newbie

Joined: Fri Jul 14, 2006 7:32 am
Posts: 9
Hi!

I just reproduced the problem with Hibernate loglevel set to DEBUG and now have more information, but still no clue what's going on...

Here are the logs from the last actions before the exception.

Our application is trying to read a collection of entities from the database (measurement values for a specific time series over a specific period of time) using the getList() method from the corresponding DAO:

Code:
2007-02-09 17:55:58,696 [hibernate.MesswertDAOHibernate:DEBUG] at.co.xss.emcs.dao.hibernate.MesswertDAOHibernate@fcc070.getList(pns=20, pspez=17, aggr=1MW, card=mv, zrtyp=ONLINE, from=Fri Feb 02 17:00:00 CET 2007, to=Fri Feb 09 17:00:00 CET 2007, itype=OPEN_BOTH)
2007-02-09 17:55:58,697 [t$TransactionProtectionWrapper:DEBUG] allowing proxied method [getTransaction] to proceed to real session
2007-02-09 17:55:58,698 [t$TransactionProtectionWrapper:DEBUG] allowing proxied method [hashCode] to proceed to real session
2007-02-09 17:55:58,699 [t$TransactionProtectionWrapper:DEBUG] allowing proxied method [isConnected] to proceed to real session
2007-02-09 17:55:58,700 [t$TransactionProtectionWrapper:DEBUG] allowing proxied method [isDirty] to proceed to real session
2007-02-09 17:55:58,701 [org.hibernate.impl.SessionImpl:DEBUG] checking session dirtiness
2007-02-09 17:55:58,702 [.AbstractFlushingEventListener:DEBUG] flushing session
2007-02-09 17:55:58,703 [.AbstractFlushingEventListener:DEBUG] processing flush-time cascades
2007-02-09 17:55:58,704 [.AbstractFlushingEventListener:DEBUG] dirty checking collections
2007-02-09 17:55:58,705 [.AbstractFlushingEventListener:DEBUG] Flushing entities and processing referenced collections
2007-02-09 17:55:58,706 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Probenahmestellenparameter.attributes#3339], was: [at.co.xss.emcs.model.Probenahmestellenparameter.attributes#3339] (uninitialized)
2007-02-09 17:55:58,707 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Probenahmestellenparameter.zr#3339], was: [at.co.xss.emcs.model.Probenahmestellenparameter.zr#3339] (uninitialized)
2007-02-09 17:55:58,708 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Probenahmestellenparameter.attributes#3583], was: [at.co.xss.emcs.model.Probenahmestellenparameter.attributes#3583] (uninitialized)
2007-02-09 17:55:58,710 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Probenahmestellenparameter.zr#3583], was: [at.co.xss.emcs.model.Probenahmestellenparameter.zr#3583] (uninitialized)
2007-02-09 17:55:58,711 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameterspezifikation.attributes#13], was: [at.co.xss.emcs.model.Parameterspezifikation.attributes#13] (uninitialized)
2007-02-09 17:55:58,712 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameterspezifikation.probenahmestellenparameter#13], was: [at.co.xss.emcs.model.Parameterspezifikation.probenahmestellenparameter#13] (uninitialized)
2007-02-09 17:55:58,713 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameter.parameterspezifikationen#4], was: [at.co.xss.emcs.model.Parameter.parameterspezifikationen#4] (uninitialized)
2007-02-09 17:55:58,714 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameter.einheiten#4], was: [at.co.xss.emcs.model.Parameter.einheiten#4] (uninitialized)
2007-02-09 17:55:58,715 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameter.attributes#4], was: [at.co.xss.emcs.model.Parameter.attributes#4] (uninitialized)
2007-02-09 17:55:58,716 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameterspezifikation.attributes#17], was: [at.co.xss.emcs.model.Parameterspezifikation.attributes#17] (uninitialized)
2007-02-09 17:55:58,718 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameterspezifikation.probenahmestellenparameter#17], was: [at.co.xss.emcs.model.Parameterspezifikation.probenahmestellenparameter#17] (uninitialized)
2007-02-09 17:55:58,719 [.AbstractFlushingEventListener:DEBUG] Processing unreferenced collections
2007-02-09 17:55:58,720 [.AbstractFlushingEventListener:DEBUG] Scheduling collection removes/(re)creates/updates
2007-02-09 17:55:58,721 [.AbstractFlushingEventListener:DEBUG] Flushed: 0 insertions, 0 updates, 0 deletions to 11 objects
2007-02-09 17:55:58,722 [.AbstractFlushingEventListener:DEBUG] Flushed: 0 (re)creations, 0 updates, 0 removals to 11 collections
2007-02-09 17:55:58,723 [  org.hibernate.pretty.Printer:DEBUG] listing entities:
2007-02-09 17:55:58,724 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Zeitreihentyp{code=ONLINE, kommentar=Online-Messwert, name=Online, id=1}
2007-02-09 17:55:58,725 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Visualisierung{komma=1, logarithmic=false, skalmax=40.0, kommentar=Visualisierungsoptionen f?r Lufttemperatur, einheit=at.co.xss.emcs.model.Einheit#3782, skalmin=-20.0, grenzwerte=null, id=2, publish=true}
2007-02-09 17:55:58,726 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Cardinality{code=mv, label=[Ljava.lang.String;@105f83, position=null, kommentar=Ein einzelner Messwert, count=1, name=Einzelmesswert, id=3}
2007-02-09 17:55:58,727 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Parameterspezifikation{code=std, attributes=<uninitialized>, vis=at.co.xss.emcs.model.Visualisierung#2, probenahmestellenparameter=<uninitialized>, position=6.0, par=at.co.xss.emcs.model.Parameter#8, kommentar=Meteo, name=Standard, id=17}
2007-02-09 17:55:58,728 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Probenahmestellenparameter{attributes=<uninitialized>, vis=at.co.xss.emcs.model.Visualisierung#2, zr=<uninitialized>, pspez=at.co.xss.emcs.model.Parameterspezifikation#17, pns=at.co.xss.emcs.model.Probenahmestelle#20, kommentar=Created by numbis_import, id=3339}
2007-02-09 17:55:58,730 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Visualisierung{komma=0, logarithmic=false, skalmax=300.0, kommentar=Visualisierungsoptionen f?r Ozon, einheit=at.co.xss.emcs.model.Einheit#3780, skalmin=0.0, grenzwerte=at.co.xss.emcs.model.Grenzwertsatz#1, id=3, publish=true}
2007-02-09 17:55:58,731 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Parameterspezifikation{code=std, attributes=<uninitialized>, vis=at.co.xss.emcs.model.Visualisierung#3, probenahmestellenparameter=<uninitialized>, position=3.0, par=at.co.xss.emcs.model.Parameter#4, kommentar=null, name=Standard, id=13}
2007-02-09 17:55:58,732 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Parameter{code=O3, attributes=<uninitialized>, vis=at.co.xss.emcs.model.Visualisierung#3, parameterspezifikationen=<uninitialized>, einheiten=<uninitialized>, position=3.0, kommentar=null, name=Ozon, id=4}
2007-02-09 17:55:58,733 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Probenahmestellenparameter{attributes=<uninitialized>, vis=at.co.xss.emcs.model.Visualisierung#2, zr=<uninitialized>, pspez=at.co.xss.emcs.model.Parameterspezifikation#17, pns=at.co.xss.emcs.model.Probenahmestelle#48, kommentar=Created by numbis_import, id=3583}
2007-02-09 17:55:58,734 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Aggregation{code=1MW, aa=at.co.xss.emcs.model.Aggregationsart#2, position=null, ai=at.co.xss.emcs.model.Aggregationsintervall#2, kommentar=, name=Stundenmittelwert, id=3}
2007-02-09 17:55:58,735 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Einheit{code=?g/m?, label=[?g/m?], position=null, kommentar=null, name=Mikrogramm pro Kubikmeter, id=3780}
2007-02-09 17:55:58,736 [DefaultDirtyCheckEventListener:DEBUG] session not dirty
2007-02-09 17:55:58,737 [t$TransactionProtectionWrapper:DEBUG] allowing proxied method [isOpen] to proceed to real session
2007-02-09 17:55:58,761 [t.co.xss.emcs.db.HibernateUtil:DEBUG] getSession: Hibernate session 11505600 (connected=true,dirty=false,open=true)
2007-02-09 17:55:58,762 [t$TransactionProtectionWrapper:DEBUG] allowing proxied method [createQuery] to proceed to real session
2007-02-09 17:55:58,763 [te.engine.query.QueryPlanCache:DEBUG] located HQL query plan in cache (from Messwert mv where mv.id.zr.pnspar.pns=:pns and mv.id.zr.pnspar.pspez=:pspez and mv.id.zr.aggr=:aggr and mv.id.zr.card=:card and mv.id.zr.zrtyp=:zrtyp and (mv.id.ts >= :from and mv.id.ts <= :to or mv.id.ts = (select max(mv2.id.ts) from Messwert mv2 where mv2.id.zr.pnspar.pns=:pns and mv2.id.zr.pnspar.pspez=:pspez and mv2.id.zr.aggr=:aggr and mv2.id.zr.card=:card and mv2.id.zr.zrtyp=:zrtyp and mv2.id.ts<:from) or mv.id.ts = (select min(mv2.id.ts) from Messwert mv2 where mv2.id.zr.pnspar.pns=:pns and mv2.id.zr.pnspar.pspez=:pspez and mv2.id.zr.aggr=:aggr and mv2.id.zr.card=:card and mv2.id.zr.zrtyp=:zrtyp and mv2.id.ts>:to)) order by mv.id.ts)
2007-02-09 17:55:58,765 [te.engine.query.QueryPlanCache:DEBUG] located HQL query plan in cache (from Messwert mv where mv.id.zr.pnspar.pns=:pns and mv.id.zr.pnspar.pspez=:pspez and mv.id.zr.aggr=:aggr and mv.id.zr.card=:card and mv.id.zr.zrtyp=:zrtyp and (mv.id.ts >= :from and mv.id.ts <= :to or mv.id.ts = (select max(mv2.id.ts) from Messwert mv2 where mv2.id.zr.pnspar.pns=:pns and mv2.id.zr.pnspar.pspez=:pspez and mv2.id.zr.aggr=:aggr and mv2.id.zr.card=:card and mv2.id.zr.zrtyp=:zrtyp and mv2.id.ts<:from) or mv.id.ts = (select min(mv2.id.ts) from Messwert mv2 where mv2.id.zr.pnspar.pns=:pns and mv2.id.zr.pnspar.pspez=:pspez and mv2.id.zr.aggr=:aggr and mv2.id.zr.card=:card and mv2.id.zr.zrtyp=:zrtyp and mv2.id.ts>:to)) order by mv.id.ts)
2007-02-09 17:55:58,766 [.AbstractFlushingEventListener:DEBUG] flushing session
2007-02-09 17:55:58,767 [.AbstractFlushingEventListener:DEBUG] processing flush-time cascades
2007-02-09 17:55:58,768 [.AbstractFlushingEventListener:DEBUG] dirty checking collections
2007-02-09 17:55:58,768 [.AbstractFlushingEventListener:DEBUG] Flushing entities and processing referenced collections
2007-02-09 17:55:58,770 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Probenahmestellenparameter.attributes#3339], was: [at.co.xss.emcs.model.Probenahmestellenparameter.attributes#3339] (uninitialized)
2007-02-09 17:55:58,771 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Probenahmestellenparameter.zr#3339], was: [at.co.xss.emcs.model.Probenahmestellenparameter.zr#3339] (uninitialized)
2007-02-09 17:55:58,772 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Probenahmestellenparameter.attributes#3583], was: [at.co.xss.emcs.model.Probenahmestellenparameter.attributes#3583] (uninitialized)
2007-02-09 17:55:58,773 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Probenahmestellenparameter.zr#3583], was: [at.co.xss.emcs.model.Probenahmestellenparameter.zr#3583] (uninitialized)
2007-02-09 17:55:58,774 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameterspezifikation.attributes#13], was: [at.co.xss.emcs.model.Parameterspezifikation.attributes#13] (uninitialized)
2007-02-09 17:55:58,775 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameterspezifikation.probenahmestellenparameter#13], was: [at.co.xss.emcs.model.Parameterspezifikation.probenahmestellenparameter#13] (uninitialized)
2007-02-09 17:55:58,776 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameter.parameterspezifikationen#4], was: [at.co.xss.emcs.model.Parameter.parameterspezifikationen#4] (uninitialized)
2007-02-09 17:55:58,777 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameter.einheiten#4], was: [at.co.xss.emcs.model.Parameter.einheiten#4] (uninitialized)
2007-02-09 17:55:58,778 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameter.attributes#4], was: [at.co.xss.emcs.model.Parameter.attributes#4] (uninitialized)
2007-02-09 17:55:58,779 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameterspezifikation.attributes#17], was: [at.co.xss.emcs.model.Parameterspezifikation.attributes#17] (uninitialized)
2007-02-09 17:55:58,780 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameterspezifikation.probenahmestellenparameter#17], was: [at.co.xss.emcs.model.Parameterspezifikation.probenahmestellenparameter#17] (uninitialized)
2007-02-09 17:55:58,781 [.AbstractFlushingEventListener:DEBUG] Processing unreferenced collections
2007-02-09 17:55:58,782 [.AbstractFlushingEventListener:DEBUG] Scheduling collection removes/(re)creates/updates
2007-02-09 17:55:58,783 [.AbstractFlushingEventListener:DEBUG] Flushed: 0 insertions, 0 updates, 0 deletions to 11 objects
2007-02-09 17:55:58,784 [.AbstractFlushingEventListener:DEBUG] Flushed: 0 (re)creations, 0 updates, 0 removals to 11 collections
2007-02-09 17:55:58,785 [  org.hibernate.pretty.Printer:DEBUG] listing entities:
2007-02-09 17:55:58,786 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Zeitreihentyp{code=ONLINE, kommentar=Online-Messwert, name=Online, id=1}
2007-02-09 17:55:58,787 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Visualisierung{komma=1, logarithmic=false, skalmax=40.0, kommentar=Visualisierungsoptionen f?r Lufttemperatur, einheit=at.co.xss.emcs.model.Einheit#3782, skalmin=-20.0, grenzwerte=null, id=2, publish=true}
2007-02-09 17:55:58,788 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Cardinality{code=mv, label=[Ljava.lang.String;@105f83, position=null, kommentar=Ein einzelner Messwert, count=1, name=Einzelmesswert, id=3}
2007-02-09 17:55:58,789 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Parameterspezifikation{code=std, attributes=<uninitialized>, vis=at.co.xss.emcs.model.Visualisierung#2, probenahmestellenparameter=<uninitialized>, position=6.0, par=at.co.xss.emcs.model.Parameter#8, kommentar=Meteo, name=Standard, id=17}
2007-02-09 17:55:58,790 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Probenahmestellenparameter{attributes=<uninitialized>, vis=at.co.xss.emcs.model.Visualisierung#2, zr=<uninitialized>, pspez=at.co.xss.emcs.model.Parameterspezifikation#17, pns=at.co.xss.emcs.model.Probenahmestelle#20, kommentar=Created by numbis_import, id=3339}
2007-02-09 17:55:58,791 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Visualisierung{komma=0, logarithmic=false, skalmax=300.0, kommentar=Visualisierungsoptionen f?r Ozon, einheit=at.co.xss.emcs.model.Einheit#3780, skalmin=0.0, grenzwerte=at.co.xss.emcs.model.Grenzwertsatz#1, id=3, publish=true}
2007-02-09 17:55:58,792 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Parameterspezifikation{code=std, attributes=<uninitialized>, vis=at.co.xss.emcs.model.Visualisierung#3, probenahmestellenparameter=<uninitialized>, position=3.0, par=at.co.xss.emcs.model.Parameter#4, kommentar=null, name=Standard, id=13}
2007-02-09 17:55:58,794 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Parameter{code=O3, attributes=<uninitialized>, vis=at.co.xss.emcs.model.Visualisierung#3, parameterspezifikationen=<uninitialized>, einheiten=<uninitialized>, position=3.0, kommentar=null, name=Ozon, id=4}
2007-02-09 17:55:58,795 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Probenahmestellenparameter{attributes=<uninitialized>, vis=at.co.xss.emcs.model.Visualisierung#2, zr=<uninitialized>, pspez=at.co.xss.emcs.model.Parameterspezifikation#17, pns=at.co.xss.emcs.model.Probenahmestelle#48, kommentar=Created by numbis_import, id=3583}
2007-02-09 17:55:58,796 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Aggregation{code=1MW, aa=at.co.xss.emcs.model.Aggregationsart#2, position=null, ai=at.co.xss.emcs.model.Aggregationsintervall#2, kommentar=, name=Stundenmittelwert, id=3}
2007-02-09 17:55:58,797 [  org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Einheit{code=?g/m?, label=[?g/m?], position=null, kommentar=null, name=Mikrogramm pro Kubikmeter, id=3780}
2007-02-09 17:55:58,798 [.DefaultAutoFlushEventListener:DEBUG] Dont need to execute flush


The DAO is executing the following HQL query:

Code:
2007-02-09 17:55:58,799 [nate.engine.query.HQLQueryPlan:DEBUG] find: from Messwert mv where mv.id.zr.pnspar.pns=:pns and mv.id.zr.pnspar.pspez=:pspez and mv.id.zr.aggr=:aggr and mv.id.zr.card=:card and mv.id.zr.zrtyp=:zrtyp and (mv.id.ts >= :from and mv.id.ts <= :to or mv.id.ts = (select max(mv2.id.ts) from Messwert mv2 where mv2.id.zr.pnspar.pns=:pns and mv2.id.zr.pnspar.pspez=:pspez and mv2.id.zr.aggr=:aggr and mv2.id.zr.card=:card and mv2.id.zr.zrtyp=:zrtyp and mv2.id.ts<:from) or mv.id.ts = (select min(mv2.id.ts) from Messwert mv2 where mv2.id.zr.pnspar.pns=:pns and mv2.id.zr.pnspar.pspez=:pspez and mv2.id.zr.aggr=:aggr and mv2.id.zr.card=:card and mv2.id.zr.zrtyp=:zrtyp and mv2.id.ts>:to)) order by mv.id.ts
2007-02-09 17:55:58,800 [bernate.engine.QueryParameters:DEBUG] named parameters: {to=2007-02-09 17:00:00, card=3, aggr=3, pspez=17, pns=20, from=2007-02-02 17:00:00, zrtyp=1}
2007-02-09 17:55:58,801 [hibernate.jdbc.AbstractBatcher:DEBUG] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-02-09 17:55:58,802 [hibernate.jdbc.AbstractBatcher:DEBUG] select messwert0_.ts as ts13_, messwert0_.zr as zr13_, messwert0_.pv as pv13_, messwert0_.rv as rv13_, messwert0_.val as val13_, messwert0_.mark as mark13_ from mwdb.t_mv messwert0_, mwdb.vc_zr zeitreihe1_, mwdb.vc_pnspar probenahme2_ left outer join mwdb.v_vis2pnspar probenahme2_1_ on probenahme2_.id=probenahme2_1_.pnspar where messwert0_.zr=zeitreihe1_.id and zeitreihe1_.pnspar=probenahme2_.id and probenahme2_.pns=? and probenahme2_.pspez=? and zeitreihe1_.aggr=? and zeitreihe1_.card=? and zeitreihe1_.typ=? and (messwert0_.ts>=? and messwert0_.ts<=? or messwert0_.ts=(select max(messwert8_.ts) from mwdb.t_mv messwert8_, mwdb.vc_zr zeitreihe9_, mwdb.vc_pnspar probenahme10_ left outer join mwdb.v_vis2pnspar probenahme10_1_ on probenahme10_.id=probenahme10_1_.pnspar where messwert8_.zr=zeitreihe9_.id and zeitreihe9_.pnspar=probenahme10_.id and probenahme10_.pns=? and probenahme10_.pspez=? and zeitreihe9_.aggr=? and zeitreihe9_.card=? and zeitreihe9_.typ=? and messwert8_.ts<?) or messwert0_.ts=(select min(messwert16_.ts) from mwdb.t_mv messwert16_, mwdb.vc_zr zeitreihe17_, mwdb.vc_pnspar probenahme18_ left outer join mwdb.v_vis2pnspar probenahme18_1_ on probenahme18_.id=probenahme18_1_.pnspar where messwert16_.zr=zeitreihe17_.id and zeitreihe17_.pnspar=probenahme18_.id and probenahme18_.pns=? and probenahme18_.pspez=? and zeitreihe17_.aggr=? and zeitreihe17_.card=? and zeitreihe17_.typ=? and messwert16_.ts>?)) order by messwert0_.ts
2007-02-09 17:55:58,803 [hibernate.jdbc.AbstractBatcher:DEBUG] preparing statement
2007-02-09 17:55:58,804 [rg.hibernate.type.NullableType:DEBUG] binding '20' to parameter: 1
2007-02-09 17:55:58,805 [rg.hibernate.type.NullableType:DEBUG] binding '17' to parameter: 2
2007-02-09 17:55:58,806 [rg.hibernate.type.NullableType:DEBUG] binding '3' to parameter: 3
2007-02-09 17:55:58,807 [rg.hibernate.type.NullableType:DEBUG] binding '3' to parameter: 4
2007-02-09 17:55:58,808 [rg.hibernate.type.NullableType:DEBUG] binding '1' to parameter: 5
2007-02-09 17:55:58,810 [rg.hibernate.type.NullableType:DEBUG] binding '2007-02-02 17:00:00' to parameter: 6
2007-02-09 17:55:58,811 [rg.hibernate.type.NullableType:DEBUG] binding '2007-02-09 17:00:00' to parameter: 7
2007-02-09 17:55:58,812 [rg.hibernate.type.NullableType:DEBUG] binding '20' to parameter: 8
2007-02-09 17:55:58,813 [rg.hibernate.type.NullableType:DEBUG] binding '17' to parameter: 9
2007-02-09 17:55:58,814 [rg.hibernate.type.NullableType:DEBUG] binding '3' to parameter: 10
2007-02-09 17:55:58,815 [rg.hibernate.type.NullableType:DEBUG] binding '3' to parameter: 11
2007-02-09 17:55:58,816 [rg.hibernate.type.NullableType:DEBUG] binding '1' to parameter: 12
2007-02-09 17:55:58,818 [rg.hibernate.type.NullableType:DEBUG] binding '2007-02-02 17:00:00' to parameter: 13
2007-02-09 17:55:58,819 [rg.hibernate.type.NullableType:DEBUG] binding '20' to parameter: 14
2007-02-09 17:55:58,820 [rg.hibernate.type.NullableType:DEBUG] binding '17' to parameter: 15
2007-02-09 17:55:58,821 [rg.hibernate.type.NullableType:DEBUG] binding '3' to parameter: 16
2007-02-09 17:55:58,822 [rg.hibernate.type.NullableType:DEBUG] binding '3' to parameter: 17
2007-02-09 17:55:58,823 [rg.hibernate.type.NullableType:DEBUG] binding '1' to parameter: 18
2007-02-09 17:55:58,824 [rg.hibernate.type.NullableType:DEBUG] binding '2007-02-09 17:00:00' to parameter: 19


The query get's executed and Hibernate is processing the results:

Code:
2007-02-09 17:55:58,845 [hibernate.jdbc.AbstractBatcher:DEBUG] about to open ResultSet (open ResultSets: 0, globally: 0)
2007-02-09 17:55:58,846 [   org.hibernate.loader.Loader:DEBUG] processing result set
2007-02-09 17:55:58,847 [   org.hibernate.loader.Loader:DEBUG] result set row: 0
2007-02-09 17:55:58,849 [rg.hibernate.type.NullableType:DEBUG] returning '3340' as column: zr13_
2007-02-09 17:55:58,850 [t.def.DefaultLoadEventListener:DEBUG] loading entity: [at.co.xss.emcs.model.Zeitreihe#3340]
2007-02-09 17:55:58,851 [t.def.DefaultLoadEventListener:DEBUG] creating new proxy for entity
2007-02-09 17:55:58,853 [   org.hibernate.loader.Loader:DEBUG] result row: EntityKey[at.co.xss.emcs.model.Messwert#component[ts,zr]{zr=at.co.xss.emcs.model.Zeitreihe#3340, ts=java.util.GregorianCalendar[time=1170428400000,areFieldsSet=true,areAllFieldsSet=true,lenient=true,zone=sun.util.calendar.ZoneInfo[id="Europe/Vienna",offset=3600000,dstSavings=3600000,useDaylight=true,transitions=139,lastRule=java.util.SimpleTimeZone[id=Europe/Vienna,offset=3600000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=2,startMonth=2,startDay=-1,startDayOfWeek=1,startTime=3600000,startTimeMode=2,endMode=2,endMonth=9,endDay=-1,endDayOfWeek=1,endTime=3600000,endTimeMode=2]],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=1,YEAR=2007,MONTH=1,WEEK_OF_YEAR=5,WEEK_OF_MONTH=1,DAY_OF_MONTH=2,DAY_OF_YEAR=33,DAY_OF_WEEK=6,DAY_OF_WEEK_IN_MONTH=1,AM_PM=1,HOUR=4,HOUR_OF_DAY=16,MINUTE=0,SECOND=0,MILLISECOND=0,ZONE_OFFSET=3600000,DST_OFFSET=0]}]
2007-02-09 17:55:58,854 [   org.hibernate.loader.Loader:DEBUG] Initializing object from ResultSet: [at.co.xss.emcs.model.Messwert#component[ts,zr]{zr=at.co.xss.emcs.model.Zeitreihe#3340, ts=java.util.GregorianCalendar[time=1170428400000,areFieldsSet=true,areAllFieldsSet=true,lenient=true,zone=sun.util.calendar.ZoneInfo[id="Europe/Vienna",offset=3600000,dstSavings=3600000,useDaylight=true,transitions=139,lastRule=java.util.SimpleTimeZone[id=Europe/Vienna,offset=3600000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=2,startMonth=2,startDay=-1,startDayOfWeek=1,startTime=3600000,startTimeMode=2,endMode=2,endMonth=9,endDay=-1,endDayOfWeek=1,endTime=3600000,endTimeMode=2]],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=1,YEAR=2007,MONTH=1,WEEK_OF_YEAR=5,WEEK_OF_MONTH=1,DAY_OF_MONTH=2,DAY_OF_YEAR=33,DAY_OF_WEEK=6,DAY_OF_WEEK_IN_MONTH=1,AM_PM=1,HOUR=4,HOUR_OF_DAY=16,MINUTE=0,SECOND=0,MILLISECOND=0,ZONE_OFFSET=3600000,DST_OFFSET=0]}]
2007-02-09 17:55:58,855 [entity.AbstractEntityPersister:DEBUG] Hydrating entity: [at.co.xss.emcs.model.Messwert#component[ts,zr]{zr=at.co.xss.emcs.model.Zeitreihe#3340, ts=java.util.GregorianCalendar[time=1170428400000,areFieldsSet=true,areAllFieldsSet=true,lenient=true,zone=sun.util.calendar.ZoneInfo[id="Europe/Vienna",offset=3600000,dstSavings=3600000,useDaylight=true,transitions=139,lastRule=java.util.SimpleTimeZone[id=Europe/Vienna,offset=3600000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=2,startMonth=2,startDay=-1,startDayOfWeek=1,startTime=3600000,startTimeMode=2,endMode=2,endMonth=9,endDay=-1,endDayOfWeek=1,endTime=3600000,endTimeMode=2]],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=1,YEAR=2007,MONTH=1,WEEK_OF_YEAR=5,WEEK_OF_MONTH=1,DAY_OF_MONTH=2,DAY_OF_YEAR=33,DAY_OF_WEEK=6,DAY_OF_WEEK_IN_MONTH=1,AM_PM=1,HOUR=4,HOUR_OF_DAY=16,MINUTE=0,SECOND=0,MILLISECOND=0,ZONE_OFFSET=3600000,DST_OFFSET=0]}]
2007-02-09 17:55:58,856 [   org.hibernate.loader.Loader:DEBUG] result set row: 1
2007-02-09 17:55:58,858 [rg.hibernate.type.NullableType:DEBUG] returning '3340' as column: zr13_
2007-02-09 17:55:58,859 [t.def.DefaultLoadEventListener:DEBUG] loading entity: [at.co.xss.emcs.model.Zeitreihe#3340]
2007-02-09 17:55:58,860 [t.def.DefaultLoadEventListener:DEBUG] entity proxy found in session cache
2007-02-09 17:55:58,862 [   org.hibernate.loader.Loader:DEBUG] result row: EntityKey[at.co.xss.emcs.model.Messwert#component[ts,zr]{zr=at.co.xss.emcs.model.Zeitreihe#3340, ts=java.util.GregorianCalendar[time=1170432000000,areFieldsSet=true,areAllFieldsSet=true,lenient=true,zone=sun.util.calendar.ZoneInfo[id="Europe/Vienna",offset=3600000,dstSavings=3600000,useDaylight=true,transitions=139,lastRule=java.util.SimpleTimeZone[id=Europe/Vienna,offset=3600000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=2,startMonth=2,startDay=-1,startDayOfWeek=1,startTime=3600000,startTimeMode=2,endMode=2,endMonth=9,endDay=-1,endDayOfWeek=1,endTime=3600000,endTimeMode=2]],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=1,YEAR=2007,MONTH=1,WEEK_OF_YEAR=5,WEEK_OF_MONTH=1,DAY_OF_MONTH=2,DAY_OF_YEAR=33,DAY_OF_WEEK=6,DAY_OF_WEEK_IN_MONTH=1,AM_PM=1,HOUR=5,HOUR_OF_DAY=17,MINUTE=0,SECOND=0,MILLISECOND=0,ZONE_OFFSET=3600000,DST_OFFSET=0]}]
2007-02-09 17:55:58,863 [   org.hibernate.loader.Loader:DEBUG] Initializing object from ResultSet: [at.co.xss.emcs.model.Messwert#component[ts,zr]{zr=at.co.xss.emcs.model.Zeitreihe#3340, ts=java.util.GregorianCalendar[time=1170432000000,areFieldsSet=true,areAllFieldsSet=true,lenient=true,zone=sun.util.calendar.ZoneInfo[id="Europe/Vienna",offset=3600000,dstSavings=3600000,useDaylight=true,transitions=139,lastRule=java.util.SimpleTimeZone[id=Europe/Vienna,offset=3600000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=2,startMonth=2,startDay=-1,startDayOfWeek=1,startTime=3600000,startTimeMode=2,endMode=2,endMonth=9,endDay=-1,endDayOfWeek=1,endTime=3600000,endTimeMode=2]],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=1,YEAR=2007,MONTH=1,WEEK_OF_YEAR=5,WEEK_OF_MONTH=1,DAY_OF_MONTH=2,DAY_OF_YEAR=33,DAY_OF_WEEK=6,DAY_OF_WEEK_IN_MONTH=1,AM_PM=1,HOUR=5,HOUR_OF_DAY=17,MINUTE=0,SECOND=0,MILLISECOND=0,ZONE_OFFSET=3600000,DST_OFFSET=0]}]
2007-02-09 17:55:58,864 [entity.AbstractEntityPersister:DEBUG] Hydrating entity: [at.co.xss.emcs.model.Messwert#component[ts,zr]{zr=at.co.xss.emcs.model.Zeitreihe#3340, ts=java.util.GregorianCalendar[time=1170432000000,areFieldsSet=true,areAllFieldsSet=true,lenient=true,zone=sun.util.calendar.ZoneInfo[id="Europe/Vienna",offset=3600000,dstSavings=3600000,useDaylight=true,transitions=139,lastRule=java.util.SimpleTimeZone[id=Europe/Vienna,offset=3600000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=2,startMonth=2,startDay=-1,startDayOfWeek=1,startTime=3600000,startTimeMode=2,endMode=2,endMonth=9,endDay=-1,endDayOfWeek=1,endTime=3600000,endTimeMode=2]],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=1,YEAR=2007,MONTH=1,WEEK_OF_YEAR=5,WEEK_OF_MONTH=1,DAY_OF_MONTH=2,DAY_OF_YEAR=33,DAY_OF_WEEK=6,DAY_OF_WEEK_IN_MONTH=1,AM_PM=1,HOUR=5,HOUR_OF_DAY=17,MINUTE=0,SECOND=0,MILLISECOND=0,ZONE_OFFSET=3600000,DST_OFFSET=0]}]


This is going on for exactly 170 rows in the result set (I'm omitting most of the messages here, the session does not get closed inside here, I have checked the messages several times!)

Code:
2007-02-09 17:56:00,672 [   org.hibernate.loader.Loader:DEBUG] done processing result set (170 rows)
2007-02-09 17:56:00,673 [hibernate.jdbc.AbstractBatcher:DEBUG] about to close ResultSet (open ResultSets: 1, globally: 1)
2007-02-09 17:56:00,674 [hibernate.jdbc.AbstractBatcher:DEBUG] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-02-09 17:56:00,675 [hibernate.jdbc.AbstractBatcher:DEBUG] closing statement
2007-02-09 17:56:00,676 [   org.hibernate.loader.Loader:DEBUG] total objects hydrated: 170


It then goes on resolving associations. The first few are working fine, but with entity "Untersuchungsgebiet" id 10 it finds the session closed and throws the exception:

Code:
2007-02-09 17:56:00,677 [.hibernate.engine.TwoPhaseLoad:DEBUG] resolving associations for [at.co.xss.emcs.model.Messwert#component[ts,zr]{zr=at.co.xss.emcs.model.Zeitreihe#3340, ts=java.util.GregorianCalendar[time=1170428400000,areFieldsSet=true,areAllFieldsSet=true,lenient=true,zone=sun.util.calendar.ZoneInfo[id="Europe/Vienna",offset=3600000,dstSavings=3600000,useDaylight=true,transitions=139,lastRule=java.util.SimpleTimeZone[id=Europe/Vienna,offset=3600000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=2,startMonth=2,startDay=-1,startDayOfWeek=1,startTime=3600000,startTimeMode=2,endMode=2,endMonth=9,endDay=-1,endDayOfWeek=1,endTime=3600000,endTimeMode=2]],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=1,YEAR=2007,MONTH=1,WEEK_OF_YEAR=5,WEEK_OF_MONTH=1,DAY_OF_MONTH=2,DAY_OF_YEAR=33,DAY_OF_WEEK=6,DAY_OF_WEEK_IN_MONTH=1,AM_PM=1,HOUR=4,HOUR_OF_DAY=16,MINUTE=0,SECOND=0,MILLISECOND=0,ZONE_OFFSET=3600000,DST_OFFSET=0]}]
2007-02-09 17:56:00,678 [org.hibernate.impl.SessionImpl:DEBUG] initializing proxy: [at.co.xss.emcs.model.Zeitreihe#3340]
2007-02-09 17:56:00,679 [t.def.DefaultLoadEventListener:DEBUG] attempting to resolve: [at.co.xss.emcs.model.Zeitreihe#3340]
2007-02-09 17:56:00,681 [   org.hibernate.cache.EhCache:DEBUG] key: at.co.xss.emcs.model.Zeitreihe#3340
2007-02-09 17:56:00,682 [.hibernate.cache.ReadOnlyCache:DEBUG] Cache hit: at.co.xss.emcs.model.Zeitreihe#3340
2007-02-09 17:56:00,683 [t.def.DefaultLoadEventListener:DEBUG] assembling entity from second-level cache: [at.co.xss.emcs.model.Zeitreihe#3340]
2007-02-09 17:56:00,685 [t.def.DefaultLoadEventListener:DEBUG] loading entity: [at.co.xss.emcs.model.Probenahmestellenparameter#3339]
2007-02-09 17:56:00,686 [t.def.DefaultLoadEventListener:DEBUG] entity found in session cache
2007-02-09 17:56:00,688 [t.def.DefaultLoadEventListener:DEBUG] loading entity: [at.co.xss.emcs.model.Aggregation#3]
2007-02-09 17:56:00,689 [t.def.DefaultLoadEventListener:DEBUG] entity found in session cache
2007-02-09 17:56:00,690 [t.def.DefaultLoadEventListener:DEBUG] loading entity: [at.co.xss.emcs.model.Cardinality#3]
2007-02-09 17:56:00,692 [t.def.DefaultLoadEventListener:DEBUG] entity found in session cache
2007-02-09 17:56:00,693 [t.def.DefaultLoadEventListener:DEBUG] loading entity: [at.co.xss.emcs.model.Zeitreihentyp#1]
2007-02-09 17:56:00,695 [t.def.DefaultLoadEventListener:DEBUG] entity found in session cache
2007-02-09 17:56:00,696 [t.def.DefaultLoadEventListener:DEBUG] Cached Version: null
2007-02-09 17:56:00,697 [t.def.DefaultLoadEventListener:DEBUG] resolved object in second-level cache: [at.co.xss.emcs.model.Zeitreihe#3340]
2007-02-09 17:56:00,699 [.hibernate.engine.TwoPhaseLoad:DEBUG] adding entity to second-level cache: [at.co.xss.emcs.model.Messwert#component[ts,zr]{zr=at.co.xss.emcs.model.Zeitreihe#3340, ts=java.util.GregorianCalendar[time=1170428400000,areFieldsSet=true,areAllFieldsSet=true,lenient=true,zone=sun.util.calendar.ZoneInfo[id="Europe/Vienna",offset=3600000,dstSavings=3600000,useDaylight=true,transitions=139,lastRule=java.util.SimpleTimeZone[id=Europe/Vienna,offset=3600000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=2,startMonth=2,startDay=-1,startDayOfWeek=1,startTime=3600000,startTimeMode=2,endMode=2,endMonth=9,endDay=-1,endDayOfWeek=1,endTime=3600000,endTimeMode=2]],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=1,YEAR=2007,MONTH=1,WEEK_OF_YEAR=5,WEEK_OF_MONTH=1,DAY_OF_MONTH=2,DAY_OF_YEAR=33,DAY_OF_WEEK=6,DAY_OF_WEEK_IN_MONTH=1,AM_PM=1,HOUR=4,HOUR_OF_DAY=16,MINUTE=0,SECOND=0,MILLISECOND=0,ZONE_OFFSET=3600000,DST_OFFSET=0]}]
2007-02-09 17:56:00,700 [hibernate.cache.ReadWriteCache:DEBUG] Caching: at.co.xss.emcs.model.Messwert#zr=3340, ts=Fri Feb 02 16:00:00 CET 2007
2007-02-09 17:56:00,701 [   org.hibernate.cache.EhCache:DEBUG] key: at.co.xss.emcs.model.Messwert#zr=3340, ts=Fri Feb 02 16:00:00 CET 2007
2007-02-09 17:56:00,702 [org.hibernate.impl.SessionImpl:DEBUG] initializing proxy: [at.co.xss.emcs.model.Probenahmestelle#20]
2007-02-09 17:56:00,704 [t.def.DefaultLoadEventListener:DEBUG] attempting to resolve: [at.co.xss.emcs.model.Probenahmestelle#20]
2007-02-09 17:56:00,705 [   org.hibernate.cache.EhCache:DEBUG] key: at.co.xss.emcs.model.Probenahmestelle#20
2007-02-09 17:56:00,706 [.hibernate.cache.ReadOnlyCache:DEBUG] Cache hit: at.co.xss.emcs.model.Probenahmestelle#20
2007-02-09 17:56:00,708 [t.def.DefaultLoadEventListener:DEBUG] assembling entity from second-level cache: [at.co.xss.emcs.model.Probenahmestelle#20]
2007-02-09 17:56:00,709 [e.engine.CollectionLoadContext:DEBUG] creating collection wrapper:[at.co.xss.emcs.model.Probenahmestelle.attributes#20]
2007-02-09 17:56:00,711 [e.engine.CollectionLoadContext:DEBUG] creating collection wrapper:[at.co.xss.emcs.model.Probenahmestelle.probenahmestellenparameter#20]
2007-02-09 17:56:00,712 [t.def.DefaultLoadEventListener:DEBUG] loading entity: [at.co.xss.emcs.model.Untersuchungsgebiet#10]
2007-02-09 17:56:00,714 [t.def.DefaultLoadEventListener:DEBUG] creating new proxy for entity
2007-02-09 17:56:00,716 [t.def.DefaultLoadEventListener:DEBUG] Cached Version: null
2007-02-09 17:56:00,717 [t.def.DefaultLoadEventListener:DEBUG] resolved object in second-level cache: [at.co.xss.emcs.model.Probenahmestelle#20]
2007-02-09 17:56:00,718 [org.hibernate.impl.SessionImpl:DEBUG] initializing proxy: [at.co.xss.emcs.model.Untersuchungsgebiet#10]
2007-02-09 17:56:00,720 [t.def.DefaultLoadEventListener:DEBUG] attempting to resolve: [at.co.xss.emcs.model.Untersuchungsgebiet#10]
2007-02-09 17:56:00,721 [   org.hibernate.cache.EhCache:DEBUG] key: at.co.xss.emcs.model.Untersuchungsgebiet#10
2007-02-09 17:56:00,723 [.hibernate.cache.ReadOnlyCache:DEBUG] Cache hit: at.co.xss.emcs.model.Untersuchungsgebiet#10
2007-02-09 17:56:00,724 [t.def.DefaultLoadEventListener:DEBUG] assembling entity from second-level cache: [at.co.xss.emcs.model.Untersuchungsgebiet#10]
2007-02-09 17:56:00,726 [e.engine.CollectionLoadContext:DEBUG] creating collection wrapper:[at.co.xss.emcs.model.Untersuchungsgebiet.probenahmestellen#10]
2007-02-09 17:56:00,727 [e.engine.CollectionLoadContext:DEBUG] creating collection wrapper:[at.co.xss.emcs.model.Untersuchungsgebiet.attributes#10]
2007-02-09 17:56:00,729 [t.def.DefaultLoadEventListener:DEBUG] Cached Version: null
2007-02-09 17:56:00,731 [t.def.DefaultLoadEventListener:DEBUG] resolved object in second-level cache: [at.co.xss.emcs.model.Untersuchungsgebiet#10]
2007-02-09 17:56:00,744 [te.LazyInitializationException:ERROR] could not initialize proxy - the owning Session was closed
org.hibernate.LazyInitializationException: could not initialize proxy - the owning Session was closed
   at org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:60)
   at org.hibernate.proxy.AbstractLazyInitializer.getImplementation(AbstractLazyInitializer.java:111)
   at org.hibernate.proxy.pojo.cglib.CGLIBLazyInitializer.invoke(CGLIBLazyInitializer.java:140)
   at at.co.xss.emcs.model.Untersuchungsgebiet$$EnhancerByCGLIB$$908cd3f0.getCode(<generated>)
   at at.co.xss.emcs.model.Untersuchungsgebiet.equals(Untersuchungsgebiet.java:165)
   at sun.reflect.GeneratedMethodAccessor217.invoke(Unknown Source)
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
   at java.lang.reflect.Method.invoke(Method.java:585)
   at org.hibernate.proxy.pojo.cglib.CGLIBLazyInitializer.invoke(CGLIBLazyInitializer.java:147)
   at at.co.xss.emcs.model.Untersuchungsgebiet$$EnhancerByCGLIB$$908cd3f0.equals(<generated>)
   at at.co.xss.emcs.model.Probenahmestelle.equals(Probenahmestelle.java:444)
   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
   at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
   at java.lang.reflect.Method.invoke(Method.java:585)
   at org.hibernate.proxy.pojo.cglib.CGLIBLazyInitializer.invoke(CGLIBLazyInitializer.java:147)
   at at.co.xss.emcs.model.Probenahmestelle$$EnhancerByCGLIB$$7a728622.equals(<generated>)
   at at.co.xss.emcs.model.Probenahmestellenparameter.equals(Probenahmestellenparameter.java:447)
   at at.co.xss.emcs.model.Zeitreihe.equals(Zeitreihe.java:256)
   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
   at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
   at java.lang.reflect.Method.invoke(Method.java:585)
   at org.hibernate.proxy.pojo.cglib.CGLIBLazyInitializer.invoke(CGLIBLazyInitializer.java:147)
   at at.co.xss.emcs.model.Zeitreihe$$EnhancerByCGLIB$$9ea987e5.equals(<generated>)
   at org.hibernate.util.EqualsHelper.equals(EqualsHelper.java:10)
   at org.hibernate.type.AbstractType.isEqual(AbstractType.java:108)
   at org.hibernate.type.ComponentType.isEqual(ComponentType.java:125)
   at org.hibernate.cache.CacheKey.equals(CacheKey.java:51)
   at java.util.HashMap.eq(HashMap.java:299)
   at java.util.HashMap.getEntry(HashMap.java:398)
   at java.util.LinkedHashMap.get(LinkedHashMap.java:273)
   at net.sf.ehcache.store.MemoryStore.get(MemoryStore.java:130)
   at net.sf.ehcache.Cache.searchInMemoryStore(Cache.java:819)
   at net.sf.ehcache.Cache.get(Cache.java:654)
   at org.hibernate.cache.EhCache.get(EhCache.java:74)
   at org.hibernate.cache.ReadWriteCache.put(ReadWriteCache.java:153)
   at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:156)
   at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:842)
   at org.hibernate.loader.Loader.doQuery(Loader.java:717)
   at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)
   at org.hibernate.loader.Loader.doList(Loader.java:2211)
   at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2095)
   at org.hibernate.loader.Loader.list(Loader.java:2090)
   at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:375)
   at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:338)
   at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:172)
   at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1121)
   at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)
   at at.co.xss.emcs.dao.hibernate.MesswertDAOHibernate.getList(MesswertDAOHibernate.java:520)
   at at.co.xss.emcs.tg.data.AbstractEmcsXYDataset.readData(AbstractEmcsXYDataset.java:165)
   at at.co.xss.emcs.tg.data.MultilineXYDataset.readSeries(MultilineXYDataset.java:231)
   at at.co.xss.emcs.tg.data.MultilineXYDataset.readData(MultilineXYDataset.java:216)
   at at.co.xss.emcs.tg.dsp.AbstractEmcsDatasetProducer.produceDataset(AbstractEmcsDatasetProducer.java:174)
   at at.co.xss.emcs.tg.dsp.AbstractEmcsDatasetProducer.produceDataset(AbstractEmcsDatasetProducer.java:123)
   at de.laures.cewolf.taglib.DataContainer.getDataset(DataContainer.java:53)
   at de.laures.cewolf.taglib.SimpleChartDefinition.getDataset(SimpleChartDefinition.java:34)
   at de.laures.cewolf.taglib.SimpleChartDefinition.produceChart(SimpleChartDefinition.java:30)
   at de.laures.cewolf.taglib.AbstractChartDefinition.getChart(AbstractChartDefinition.java:121)
   at de.laures.cewolf.taglib.ChartImageDefinition.ensureRendered(ChartImageDefinition.java:137)
   at de.laures.cewolf.taglib.ChartImageDefinition.getBytes(ChartImageDefinition.java:131)
   at de.laures.cewolf.storage.SerializableChartImage.<init>(SerializableChartImage.java:49)
   at de.laures.cewolf.storage.ClusterableSessionStorage.getCacheObject(ClusterableSessionStorage.java:40)
   at de.laures.cewolf.storage.AbstractSessionStorage.storeChartImage(AbstractSessionStorage.java:88)
   at de.laures.cewolf.storage.AbstractSessionStorage.storeChartImage(AbstractSessionStorage.java:60)
   at de.laures.cewolf.taglib.tags.ChartImgTag.doStartTag(ChartImgTag.java:79)
   at org.apache.jsp.jsps.multiline_jsp._jspx_meth_cewolf_img_0(multiline_jsp.java:403)
   at org.apache.jsp.jsps.multiline_jsp._jspService(multiline_jsp.java:257)
   at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:97)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
   at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:334)
   at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:314)
   at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:264)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
   at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:672)
   at org.apache.catalina.core.ApplicationDispatcher.doInclude(ApplicationDispatcher.java:574)
   at org.apache.catalina.core.ApplicationDispatcher.include(ApplicationDispatcher.java:499)
   at org.apache.jasper.runtime.JspRuntimeLibrary.include(JspRuntimeLibrary.java:966)
   at org.apache.jsp.jsps.evaluation_jsp._jspService(evaluation_jsp.java:187)
   at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:97)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
   at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:334)
   at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:314)
   at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:264)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
   at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:672)
   at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:463)
   at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:398)
   at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:301)
   at org.apache.struts.action.RequestProcessor.doForward(RequestProcessor.java:1085)
   at org.apache.struts.action.RequestProcessor.processForwardConfig(RequestProcessor.java:398)
   at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:241)
   at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1196)
   at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:414)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:689)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
   at at.co.xss.emcs.db.HibernateFilter.doFilter(HibernateFilter.java:172)
   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
   at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
   at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
   at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
   at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
   at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
   at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
   at org.apache.coyote.http11.Http11AprProcessor.process(Http11AprProcessor.java:833)
   at org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:639)
   at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1285)
   at java.lang.Thread.run(Thread.java:595)


This exception immediately gets the program flow into the "catch" clause of our HibernateFiler#doFilter() method where we log the error and try to roll back the transaction:

Code:
2007-02-09 17:56:00,803 [co.xss.emcs.db.HibernateFilter:ERROR] request http://tolstoi.intern.xss.co.at:8080/emcs-demo/Multiline.do from host 192.168.162.51 - doFilter failed with exception org.apache.jasper.JasperException: could not initialize proxy - the owning Session was closed


The following lines I do not understand given the exception above: it looks like there is an open session which now gets closed by the rollback.
But if there is an open session, why does Hibernate throw the exception in the first place?

[code]
2007-02-09 17:56:00,805 [t$TransactionProtectionWrapper:DEBUG] allowing proxied method [getTransaction] to proceed to real session
2007-02-09 17:56:00,805 [t$TransactionProtectionWrapper:DEBUG] allowing proxied method [getTransaction] to proceed to real session
2007-02-09 17:56:00,806 [t$TransactionProtectionWrapper:DEBUG] allowing proxied method [hashCode] to proceed to real session
2007-02-09 17:56:00,807 [t$TransactionProtectionWrapper:DEBUG] allowing proxied method [isConnected] to proceed to real session
2007-02-09 17:56:00,807 [t$TransactionProtectionWrapper:DEBUG] allowing proxied method [isDirty] to proceed to real session
2007-02-09 17:56:00,808 [org.hibernate.impl.SessionImpl:DEBUG] checking session dirtiness
2007-02-09 17:56:00,808 [.AbstractFlushingEventListener:DEBUG] flushing session
2007-02-09 17:56:00,809 [.AbstractFlushingEventListener:DEBUG] processing flush-time cascades
2007-02-09 17:56:00,809 [.AbstractFlushingEventListener:DEBUG] dirty checking collections
2007-02-09 17:56:00,810 [.AbstractFlushingEventListener:DEBUG] Flushing entities and processing referenced collections
2007-02-09 17:56:00,811 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Probenahmestellenparameter.attributes#3339], was: [at.co.xss.emcs.model.Probenahmestellenparameter.attributes#3339] (uninitialized)
2007-02-09 17:56:00,812 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Probenahmestellenparameter.zr#3339], was: [at.co.xss.emcs.model.Probenahmestellenparameter.zr#3339] (uninitialized)
2007-02-09 17:56:00,813 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Probenahmestellenparameter.attributes#3583], was: [at.co.xss.emcs.model.Probenahmestellenparameter.attributes#3583] (uninitialized)
2007-02-09 17:56:00,813 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Probenahmestellenparameter.zr#3583], was: [at.co.xss.emcs.model.Probenahmestellenparameter.zr#3583] (uninitialized)
2007-02-09 17:56:00,814 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameterspezifikation.attributes#13], was: [at.co.xss.emcs.model.Parameterspezifikation.attributes#13] (uninitialized)
2007-02-09 17:56:00,815 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameterspezifikation.probenahmestellenparameter#13], was: [at.co.xss.emcs.model.Parameterspezifikation.probenahmestellenparameter#13] (uninitialized)
2007-02-09 17:56:00,816 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameter.parameterspezifikationen#4], was: [at.co.xss.emcs.model.Parameter.parameterspezifikationen#4] (uninitialized)
2007-02-09 17:56:00,816 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameter.einheiten#4], was: [at.co.xss.emcs.model.Parameter.einheiten#4] (uninitialized)
2007-02-09 17:56:00,817 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameter.attributes#4], was: [at.co.xss.emcs.model.Parameter.attributes#4] (uninitialized)
2007-02-09 17:56:00,818 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameterspezifikation.attributes#17], was: [at.co.xss.emcs.model.Parameterspezifikation.attributes#17] (uninitialized)
2007-02-09 17:56:00,818 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Parameterspezifikation.probenahmestellenparameter#17], was: [at.co.xss.emcs.model.Parameterspezifikation.probenahmestellenparameter#17] (uninitialized)
2007-02-09 17:56:00,819 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Probenahmestelle.attributes#20], was: [at.co.xss.emcs.model.Probenahmestelle.attributes#20] (uninitialized)
2007-02-09 17:56:00,820 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Probenahmestelle.probenahmestellenparameter#20], was: [at.co.xss.emcs.model.Probenahmestelle.probenahmestellenparameter#20] (uninitialized)
2007-02-09 17:56:00,821 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Untersuchungsgebiet.probenahmestellen#10], was: [at.co.xss.emcs.model.Untersuchungsgebiet.probenahmestellen#10] (uninitialized)
2007-02-09 17:56:00,822 [g.hibernate.engine.Collections:DEBUG] Collection found: [at.co.xss.emcs.model.Untersuchungsgebiet.attributes#10], was: [at.co.xss.emcs.model.Untersuchungsgebiet.attributes#10] (uninitialized)
2007-02-09 17:56:00,822 [.AbstractFlushingEventListener:DEBUG] Processing unreferenced collections
2007-02-09 17:56:00,823 [.AbstractFlushingEventListener:DEBUG] Scheduling collection removes/(re)creates/updates
2007-02-09 17:56:00,824 [.AbstractFlushingEventListener:DEBUG] Flushed: 0 insertions, 0 updates, 0 deletions to 184 objects
2007-02-09 17:56:00,824 [.AbstractFlushingEventListener:DEBUG] Flushed: 0 (re)creations, 0 updates, 0 removals to 15 collections
2007-02-09 17:56:00,825 [ org.hibernate.pretty.Printer:DEBUG] listing entities:
2007-02-09 17:56:00,825 [ org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Zeitreihentyp{code=ONLINE, kommentar=Online-Messwert, name=Online, id=1}
2007-02-09 17:56:00,826 [ org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Messwert{mark=null, rv=null, valid=null, id=component[ts,zr]{zr=at.co.xss.emcs.model.Zeitreihe#3340, ts=java.util.GregorianCalendar[time=1170662400000,areFieldsSet=true,areAllFieldsSet=true,lenient=true,zone=sun.util.calendar.ZoneInfo[id="Europe/Vienna",offset=3600000,dstSavings=3600000,useDaylight=true,transitions=139,lastRule=java.util.SimpleTimeZone[id=Europe/Vienna,offset=3600000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=2,startMonth=2,startDay=-1,startDayOfWeek=1,startTime=3600000,startTimeMode=2,endMode=2,endMonth=9,endDay=-1,endDayOfWeek=1,endTime=3600000,endTimeMode=2]],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=1,YEAR=2007,MONTH=1,WEEK_OF_YEAR=6,WEEK_OF_MONTH=2,DAY_OF_MONTH=5,DAY_OF_YEAR=36,DAY_OF_WEEK=2,DAY_OF_WEEK_IN_MONTH=1,AM_PM=0,HOUR=9,HOUR_OF_DAY=9,MINUTE=0,SECOND=0,MILLISECOND=0,ZONE_OFFSET=3600000,DST_OFFSET=0]}, pv=null}
2007-02-09 17:56:00,827 [ org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Messwert{mark=null, rv=null, valid=null, id=component[ts,zr]{zr=at.co.xss.emcs.model.Zeitreihe#3340, ts=java.util.GregorianCalendar[time=1170640800000,areFieldsSet=true,areAllFieldsSet=true,lenient=true,zone=sun.util.calendar.ZoneInfo[id="Europe/Vienna",offset=3600000,dstSavings=3600000,useDaylight=true,transitions=139,lastRule=java.util.SimpleTimeZone[id=Europe/Vienna,offset=3600000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=2,startMonth=2,startDay=-1,startDayOfWeek=1,startTime=3600000,startTimeMode=2,endMode=2,endMonth=9,endDay=-1,endDayOfWeek=1,endTime=3600000,endTimeMode=2]],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=1,YEAR=2007,MONTH=1,WEEK_OF_YEAR=6,WEEK_OF_MONTH=2,DAY_OF_MONTH=5,DAY_OF_YEAR=36,DAY_OF_WEEK=2,DAY_OF_WEEK_IN_MONTH=1,AM_PM=0,HOUR=3,HOUR_OF_DAY=3,MINUTE=0,SECOND=0,MILLISECOND=0,ZONE_OFFSET=3600000,DST_OFFSET=0]}, pv=null}
2007-02-09 17:56:00,828 [ org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Messwert{mark=null, rv=null, valid=null, id=component[ts,zr]{zr=at.co.xss.emcs.model.Zeitreihe#3340, ts=java.util.GregorianCalendar[time=1170860400000,areFieldsSet=true,areAllFieldsSet=true,lenient=true,zone=sun.util.calendar.ZoneInfo[id="Europe/Vienna",offset=3600000,dstSavings=3600000,useDaylight=true,transitions=139,lastRule=java.util.SimpleTimeZone[id=Europe/Vienna,offset=3600000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=2,startMonth=2,startDay=-1,startDayOfWeek=1,startTime=3600000,startTimeMode=2,endMode=2,endMonth=9,endDay=-1,endDayOfWeek=1,endTime=3600000,endTimeMode=2]],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=1,YEAR=2007,MONTH=1,WEEK_OF_YEAR=6,WEEK_OF_MONTH=2,DAY_OF_MONTH=7,DAY_OF_YEAR=38,DAY_OF_WEEK=4,DAY_OF_WEEK_IN_MONTH=1,AM_PM=1,HOUR=4,HOUR_OF_DAY=16,MINUTE=0,SECOND=0,MILLISECOND=0,ZONE_OFFSET=3600000,DST_OFFSET=0]}, pv=null}
2007-02-09 17:56:00,828 [ org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Messwert{mark=null, rv=null, valid=null, id=component[ts,zr]{zr=at.co.xss.emcs.model.Zeitreihe#3340, ts=java.util.GregorianCalendar[time=1170723600000,areFieldsSet=true,areAllFieldsSet=true,lenient=true,zone=sun.util.calendar.ZoneInfo[id="Europe/Vienna",offset=3600000,dstSavings=3600000,useDaylight=true,transitions=139,lastRule=java.util.SimpleTimeZone[id=Europe/Vienna,offset=3600000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=2,startMonth=2,startDay=-1,startDayOfWeek=1,startTime=3600000,startTimeMode=2,endMode=2,endMonth=9,endDay=-1,endDayOfWeek=1,endTime=3600000,endTimeMode=2]],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=1,YEAR=2007,MONTH=1,WEEK_OF_YEAR=6,WEEK_OF_MONTH=2,DAY_OF_MONTH=6,DAY_OF_YEAR=37,DAY_OF_WEEK=3,DAY_OF_WEEK_IN_MONTH=1,AM_PM=0,HOUR=2,HOUR_OF_DAY=2,MINUTE=0,SECOND=0,MILLISECOND=0,ZONE_OFFSET=3600000,DST_OFFSET=0]}, pv=null}
2007-02-09 17:56:00,829 [ org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Messwert{mark=null, rv=null, valid=null, id=component[ts,zr]{zr=at.co.xss.emcs.model.Zeitreihe#3340, ts=java.util.GregorianCalendar[time=1170630000000,areFieldsSet=true,areAllFieldsSet=true,lenient=true,zone=sun.util.calendar.ZoneInfo[id="Europe/Vienna",offset=3600000,dstSavings=3600000,useDaylight=true,transitions=139,lastRule=java.util.SimpleTimeZone[id=Europe/Vienna,offset=3600000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=2,startMonth=2,startDay=-1,startDayOfWeek=1,startTime=3600000,startTimeMode=2,endMode=2,endMonth=9,endDay=-1,endDayOfWeek=1,endTime=3600000,endTimeMode=2]],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=1,YEAR=2007,MONTH=1,WEEK_OF_YEAR=6,WEEK_OF_MONTH=2,DAY_OF_MONTH=5,DAY_OF_YEAR=36,DAY_OF_WEEK=2,DAY_OF_WEEK_IN_MONTH=1,AM_PM=0,HOUR=0,HOUR_OF_DAY=0,MINUTE=0,SECOND=0,MILLISECOND=0,ZONE_OFFSET=3600000,DST_OFFSET=0]}, pv=null}
2007-02-09 17:56:00,830 [ org.hibernate.pretty.Printer:DEBUG] at.co.xss.emcs.model.Messwert{mark=null, rv=null, valid=null, id=component[ts,zr]{zr=at.co.xss.emcs.model.Zeitreihe#3340, ts=java.util.GregorianCalendar[time=1170853200000,areFieldsSet=true,areAllFieldsSet=true,lenient=true,zone=sun.util.calendar.ZoneInfo[id="Europe/Vienna",offset=3600000,dstSavings=3600000,useDaylight=true,transitions=139,lastRule=java.util.SimpleTimeZone[id=Europe/Vienna,offset=3600000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=2,startMonth=2,startDay=-1,startDayOfWeek=1,startTime=3600000,startTimeMode=2,endMode=2,endMonth=9,endDay=-1,endDayOfWeek=1,endTime=3600000,endTimeMode=2]],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=1,YEAR=2007,MONTH=1,WEEK_OF_YEAR=6,WEEK_OF_MONTH=2,DAY_OF_MONTH=7,DAY_OF_YEAR=38,DAY_OF_WEEK=4,DAY_OF_WEEK_IN_MONTH=1,AM_PM=1,HOUR=2,HOUR_OF_DAY=14,MINUTE=0,SECOND=0,MILLISECOND=0,ZONE_OFFSET=3600000,DST_OFFSET=0]}, pv=null}
2007-02-09 17:56:00,831 [
Top
 Profile  
 
AndreasH
 Post subject: the last few debug messages...
PostPosted: Fri Feb 09, 2007 1:56 pm 
Newbie

Joined: Fri Jul 14, 2006 7:32 am
Posts: 9
I'm sorry but it seems the last few messages from my previous post got corrupted somehow. :-(

These messages show how the (seemingly already closed?) session gets closed via the transaction rollback.

Here they are again:

Code:
2007-02-09 17:56:00,842 [DefaultDirtyCheckEventListener:DEBUG] session not dirty
2007-02-09 17:56:00,843 [t$TransactionProtectionWrapper:DEBUG] allowing proxied method [isOpen] to proceed to real session
2007-02-09 17:56:00,843 [t.co.xss.emcs.db.HibernateUtil:DEBUG] rollbackTransaction: transaction 8890902 (active=true,commited=false,rolledback=false), Hibernate session 11505600 (connected=true,dirty=false,open=true)
2007-02-09 17:56:00,843 [te.transaction.JDBCTransaction:DEBUG] rollback
2007-02-09 17:56:00,845 [te.transaction.JDBCTransaction:DEBUG] rolled back JDBC Connection
2007-02-09 17:56:00,845 [org.hibernate.jdbc.JDBCContext:DEBUG] after transaction completion
2007-02-09 17:56:00,846 [bernate.jdbc.ConnectionManager:DEBUG] aggressively releasing JDBC connection
2007-02-09 17:56:00,846 [bernate.jdbc.ConnectionManager:DEBUG] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-02-09 17:56:00,847 [org.hibernate.impl.SessionImpl:DEBUG] after transaction completion
2007-02-09 17:56:00,848 [org.hibernate.impl.SessionImpl:DEBUG] automatically closing session
2007-02-09 17:56:00,848 [org.hibernate.impl.SessionImpl:DEBUG] closing session
2007-02-09 17:56:00,849 [bernate.jdbc.ConnectionManager:DEBUG] connection already null in cleanup : no action
Top
 Profile  
 
jwenting
 Post subject:
PostPosted: Fri Feb 09, 2007 6:10 pm 
Regular
Regular

Joined: Tue Jan 03, 2006 9:20 am
Posts: 74
You put an object in the cache that has references to other persistant entities which aren't yet loaded when you put it in the cache.
But the database session that you used to load the object has been closed, so it can't load those objects your main object depends on, causing this exception.

You most likely want to turn off lazy loading.
Top
 Profile  
 
AndreasH
 Post subject:
PostPosted: Sat Feb 10, 2007 5:16 am 
Newbie

Joined: Fri Jul 14, 2006 7:32 am
Posts: 9
Hi!

Thank you for your reply!

I understand what you are saying, but the main question IMHO is: why does the session appear to be closed somewhere in the middle of the transaction when it is open before and then again after the exception?

Looking at the hash code of the session it seems to be the exact same session object! My code does the open and close only in the servlet filter ("open session in view", so the session should still be open when those entities are put into the cache, shouldn't it? If so, then why is it suddenly closed inbetween?

Besides turning off lazy loading or the cache (which both I'd rather not) it seems I can work around the problem by changing the main entity ("Messwert") from "business key equality" to "database identifier equality". The "Untersuchungsgebiet" object which seems to trigger the execption is part of the identifier of the "Messwert" object. If I use only dbid's in the identifier, the exception does not occur, because the equals() method of the Messwert object (which is called when the Messwert object is put into the cache) does not trigger a lazy load of the whole Untersuchungsgebiet object.
This has some drawbacks (I need the dbid of the Untersuchungsgebiet before I can create a Messwert, but this is not a big problem), but it seems to solve the LIE (I already tried it past night and it did work in my first tests)

Any comments?
Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  Page 1 of 1
  [ 5 posts ] 

Board index » Hibernate & Java Persistence » Hibernate Users

All times are UTC - 5 hours [ DST ]

You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.