Spring OpenSessionInViewFilter; why are other Sessions still being opened and closed?

Question

Hi,

I'm trying to use OpenSessionInViewFilter to avoid the infamous lazy loading errors that crop up from time to time. I've spent about a day solid on this, though, but apparently I'm doing something wrong. According to what I can tell from my log files, Spring does indeed report that it's opening a transaction from within the filter. Yet it also seems to open and close other Sessions as well (mostly in conjunction with Transactions, as I'd expect to be the case if I [B]didn't[/B] have the filter configured).

Here are what I believe to be some relevant logs, that indicate that Spring is trying--but failing--to open a single session to span a single HTTP request:

(this is the very first line, when I make my HTTP request)

DEBUG 2010-10-29 14:29:41,218 - Using SessionFactory 'sessionFactory' for OpenSessionInViewFilter
DEBUG 2010-10-29 14:29:41,218 - Returning cached instance of singleton bean 'sessionFactory'
DEBUG 2010-10-29 14:29:41,218 - Opening single Hibernate Session in OpenSessionInViewFilter
DEBUG 2010-10-29 14:29:41,218 - Opening Hibernate Session
DEBUG 2010-10-29 14:29:41,218 - opened session at timestamp: 12883877812
TRACE 2010-10-29 14:29:41,218 - setting flush mode to: MANUAL
TRACE 2010-10-29 14:29:41,218 - Bound value [org.springframework.orm.hibernate3.SessionHolder@7cd25883] for key [org.hibernate.impl.SessionFactoryImpl@349955ab] to thread [http-8443-exec-6]
DEBUG 2010-10-29 14:29:41,219 - Creating new transaction with name [com.xxx.dao.IssueDAO.getIssue]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly
DEBUG 2010-10-29 14:29:41,219 - opened session at timestamp: 12883877812
DEBUG 2010-10-29 14:29:41,219 - Opened new Session [org.hibernate.impl.SessionImpl@65baeab6] for Hibernate transaction
DEBUG 2010-10-29 14:29:41,219 - Preparing JDBC Connection of Hibernate Session [org.hibernate.impl.SessionImpl@65baeab6]
DEBUG 2010-10-29 14:29:41,219 - opening JDBC connection
DEBUG 2010-10-29 14:29:41,219 - Creating new JDBC DriverManager Connection to [jdbc:postgresql://localhost:5432/spdb]
DEBUG 2010-10-29 14:29:41,228 - Setting JDBC Connection [org.postgresql.jdbc3.Jdbc3Connection@528786e7] read-only
TRACE 2010-10-29 14:29:41,232 - setting flush mode to: MANUAL
DEBUG 2010-10-29 14:29:41,232 - begin
DEBUG 2010-10-29 14:29:41,233 - current autocommit status: true
DEBUG 2010-10-29 14:29:41,233 - disabling autocommit
TRACE 2010-10-29 14:29:41,233 - after transaction begin
DEBUG 2010-10-29 14:29:41,233 - Exposing Hibernate transaction as JDBC transaction [org.postgresql.jdbc3.Jdbc3Connection@528786e7]
TRACE 2010-10-29 14:29:41,233 - Bound value [org.springframework.jdbc.datasource.ConnectionHolder@41bc1a83] for key [org.springframework.jdbc.datasource.DriverManagerDataSource@173ceeb6] to thread [http-8443-exec-6]
TRACE 2010-10-29 14:29:41,233 - Bound value [org.springframework.orm.hibernate3.SessionHolder@2470b02c] for key [org.hibernate.impl.SessionFactoryImpl@22e5b6b0] to thread [http-8443-exec-6]
TRACE 2010-10-29 14:29:41,233 - Initializing transaction synchronization
TRACE 2010-10-29 14:29:41,233 - Getting transaction for [com.xxx.dao.IssueDAO.getIssue]
TRACE 2010-10-29 14:29:41,233 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@2470b02c] for key [org.hibernate.impl.SessionFactoryImpl@22e5b6b0] bound to thread [http-8443-exec-6]

... lotta stuff happens loading the entity

DEBUG 2010-10-29 14:29:41,241 - done entity load
TRACE 2010-10-29 14:29:41,241 - Completing transaction for [com.xxx.dao.IssueDAO.getIssue]
TRACE 2010-10-29 14:29:41,241 - Triggering beforeCommit synchronization
TRACE 2010-10-29 14:29:41,241 - Triggering beforeCompletion synchronization
DEBUG 2010-10-29 14:29:41,241 - Initiating transaction commit
DEBUG 2010-10-29 14:29:41,241 - Committing Hibernate transaction on Session [org.hibernate.impl.SessionImpl@65baeab6]
DEBUG 2010-10-29 14:29:41,241 - commit
TRACE 2010-10-29 14:29:41,241 - before transaction completion
TRACE 2010-10-29 14:29:41,241 - before transaction completion
DEBUG 2010-10-29 14:29:41,242 - re-enabling autocommit
DEBUG 2010-10-29 14:29:41,242 - committed JDBC Connection
TRACE 2010-10-29 14:29:41,242 - after transaction completion
DEBUG 2010-10-29 14:29:41,242 - transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!
TRACE 2010-10-29 14:29:41,242 - after transaction completion
TRACE 2010-10-29 14:29:41,242 - Triggering afterCommit synchronization
TRACE 2010-10-29 14:29:41,242 - Triggering afterCompletion synchronization
TRACE 2010-10-29 14:29:41,242 - Clearing transaction synchronization
TRACE 2010-10-29 14:29:41,242 - Removed value [org.springframework.orm.hibernate3.SessionHolder@2470b02c] for key [org.hibernate.impl.SessionFactoryImpl@22e5b6b0] from thread [http-8443-exec-6]
TRACE 2010-10-29 14:29:41,242 - Removed value [org.springframework.jdbc.datasource.ConnectionHolder@41bc1a83] for key [org.springframework.jdbc.datasource.DriverManagerDataSource@173ceeb6] from thread [http-8443-exec-6]
DEBUG 2010-10-29 14:29:41,242 - Resetting read-only flag of JDBC Connection [org.postgresql.jdbc3.Jdbc3Connection@528786e7]
DEBUG 2010-10-29 14:29:41,243 - Closing Hibernate Session [org.hibernate.impl.SessionImpl@65baeab6] after transaction
DEBUG 2010-10-29 14:29:41,243 - Closing Hibernate Session
TRACE 2010-10-29 14:29:41,243 - closing session
TRACE 2010-10-29 14:29:41,243 - performing cleanup
DEBUG 2010-10-29 14:29:41,243 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
TRACE 2010-10-29 14:29:41,243 - after transaction completion
DEBUG 2010-10-29 14:29:41,243 - transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!
TRACE 2010-10-29 14:29:41,243 - after transaction completion
DEBUG 2010-10-29 14:29:41,243 - Creating new transaction with name [com.xxx.dao.SPProjectDAO.getAvailableActiveProjects]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly
DEBUG 2010-10-29 14:29:41,244 - opened session at timestamp: 12883877812

(see how yet another Session is opened at the start of the next DAO call)

I've configured my web.xml thusly (just showing the filter stuff):

  <filter>
   <filter-name>hibernateFilter</filter-name>
   <filter-class>org.springframework.orm.hibernate3.support.OpenSessionInViewFilter</filter-class>
   <init-param>
             <param-name>sessionFactoryBeanName</param-name>
             <param-value>sessionFactory</param-value>
   </init-param>

  </filter>
  <filter-mapping>
   <filter-name>hibernateFilter</filter-name>
    <url-pattern>/*</url-pattern>
  </filter-mapping>

  <listener>
   <listener-class>org.springframework.web.context.ContextLoaderListener</listener-class>
  </listener>
  <context-param>
         <param-name>contextConfigLocation</param-name>
         <param-value>/WEB-INF/classes/com/xxx/biz/config/spring-biz-context.xml</param-value>
     </context-param>

and my spring-biz-context.xml:

 <bean id="sessionFactory" class="org.springframework.orm.hibernate3.LocalSessionFactoryBean">
  <property name="dataSource" ref="dataSource" />
  <property name="mappingResources">
   <list>
    ... hbm files here...
   </list>
  </property>
  <property name="hibernateProperties">
   <props>
     <prop key="hibernate.dialect">org.hibernate.dialect.PostgreSQLDialect</prop>
     <prop key="hibernate.show.sql">true</prop>
     <prop key="hibernate.show_sql">true</prop>
     <!-- prop key="current_session_context_class">thread</prop-->
     <!--prop key="hibernate.current_session_context_class">org.hibernate.context.ThreadLocalSessionContext</prop-->
     <!--prop key="hibernate.current_session_context_class">org.hibernate.context.ManagedSessionContext</prop--> 
     <prop key="hibernate.connection.release_mode">auto</prop>
     <prop key="hibernate.transaction.auto_close_session">false</prop>
   </props>
  </property>
 </bean>

 <bean id="hibernateTemplate"
  class="org.springframework.orm.hibernate3.HibernateTemplate">
  <property name="sessionFactory" ref="sessionFactory" />
 </bean>

 <bean id="txManager" class="org.springframework.orm.hibernate3.HibernateTransactionManager">
  <property name="dataSource" ref="dataSource" />
  <property name="sessionFactory" ref="sessionFactory" />
 </bean>

Note that I'd tried (and commented out) several session context class settings. (Also, for some reason some spaces appeared in those XML snippits in this post; they aren't present in the actual files).

Anyway, can someone more knowledgeable than I possibly provide some insight as to what Spring is/isn't doing? Thanks in advance!

Answer 1

Are you getting any errors?

My setup is very similar to yours. I don't have the release mode and auto close session in my hibernate session factory. I don't notice loads of sessions getting opened/closed. You might want to try setting the single session parameter on the hibernateFilter.

On the hibernate filter, I have:

<filter>
    <filter-name>hibernateFilter</filter-name>
    <filter-class>org.springframework.orm.hibernate3.support.OpenSessionInViewFilter</filter-class>
    <init-param>
      <param-name>sessionFactoryBeanName</param-name>
      <param-value>hibernateSessionFactory</param-value>
    </init-param>
    <init-param>
      <param-name>singleSession</param-name>
      <param-value>true</param-value>
    </init-param>
  </filter>

Are you doing the annotation based transactions or are you managing that yourself?

In the web.xml I also use the request context listener, but I'm pretty sure that had to do with getting dwr to use session scoped beans.

Hope that helps, sorry I'm not able to be more insightful. If the singleSession param doesn't do what you want, I can try upping my log level. It might be that for each lazy fetch it opens a new session, which would make sense for what you are seeing.