Hibernate version: 3.1

I trying to create an enviroment that has support for long converations.
I've got a filter that disconnects and reconnects a Hibernate Session for each request. The code is the same as for the example: http://www.hibernate.org/43.html. The only difference is that I run from within a java-application, so I store the session in a static hashMap instead of a userSession.

When first running a Query, it works well and the session is disconnected (but not null or something). When I try to reconnect/bind the session (ThreadLocalSessionContext.bind(hibernateSession)), I've got the exception: only beginTransaction() is valid when transaction not yet started.

What might be wrong here?

In my HibernateUtil class I also set the property:

HibernateUtil.getConfiguration().setProperty(
Environment.CURRENT_SESSION_CONTEXT_CLASS,
ExtendedSessionContext.class.getName());

The ExtendedSessionContext.java is identical with the one in: http://www.hibernate.org/43.html.

Log?

11:32:33,876 INFO Environment:474 - Hibernate 3.1 rc1
log4j:INFO Creating new logger [org.hibernate.util.ConfigHelper] in repository [default].
11:32:33,892 INFO Environment:489 - loaded properties from resource hibernate.properties: {hibernate.order_updates=true, hibernate.default_batch_fetch_size=8, hibernate.connection.driver_class=org.hsqldb.jdbcDriver, hibernate.cglib.use_reflection_optimizer=true, hibernate.cache.provider_class=org.hibernate.cache.HashtableCacheProvider, hibernate.cache.use_query_cache=true, hibernate.max_fetch_depth=1, hibernate.dialect=org.hibernate.dialect.HSQLDialect, hibernate.jdbc.use_streams_for_binary=true, hibernate.query.substitutions=true 1, false 0, yes 'Y', no 'N', hibernate.proxool.pool_alias=pool1, hibernate.connection.username=sa, hibernate.cache.region_prefix=hibernate.test, hibernate.connection.url=jdbc:hsqldb:., hibernate.connection.password=****, hibernate.jdbc.batch_versioned_data=true, hibernate.connection.pool_size=1}
11:32:33,892 INFO Environment:519 - using java.io streams to persist binary types
11:32:33,892 INFO Environment:520 - using CGLIB reflection optimizer
11:32:33,892 INFO Environment:550 - using JDK 1.4 java.sql.Timestamp handling
log4j:INFO Creating new logger [org.hibernate.event.def.AbstractReassociateEventListener] in repository [default].
log4j:INFO Creating new logger [org.hibernate.event.def.AbstractLockUpgradeEventListener] in repository [default].
log4j:INFO Creating new logger [org.hibernate.event.def.DefaultLoadEventListener] in repository [default].
log4j:INFO Creating new logger [org.hibernate.event.def.AbstractSaveEventListener] in repository [default].
log4j:INFO Creating new logger [org.hibernate.event.def.DefaultSaveOrUpdateEventListener] in repository [default].
log4j:INFO Creating new logger [org.hibernate.event.def.DefaultMergeEventListener] in repository [default].
log4j:INFO Creating new logger [org.hibernate.event.def.DefaultPersistEventListener] in repository [default].
log4j:INFO Creating new logger [org.hibernate.event.def.DefaultReplicateEventListener] in repository [default].
log4j:INFO Creating new logger [org.hibernate.event.def.DefaultDeleteEventListener] in repository [default].
log4j:INFO Creating new logger [org.hibernate.event.def.AbstractFlushingEventListener] in repository [default].
log4j:INFO Creating new logger [org.hibernate.event.def.DefaultAutoFlushEventListener] in repository [default].
log4j:INFO Creating new logger [org.hibernate.event.def.DefaultDirtyCheckEventListener] in repository [default].
log4j:INFO Creating new logger [org.hibernate.event.def.DefaultEvictEventListener] in repository [default].
log4j:INFO Creating new logger [org.hibernate.event.def.DefaultRefreshEventListener] in repository [default].
log4j:INFO Creating new logger [org.hibernate.event.def.DefaultFlushEntityEventListener] in repository [default].
log4j:INFO Creating new logger [org.hibernate.event.def.DefaultInitializeCollectionEventListener] in repository [default].
log4j:INFO Creating new logger [com.ericsson.rgv.platform.database.persistence.ImportFromClasspathEntityResolver] in repository [default].
11:32:34,017 INFO Configuration:1291 - configuring from file: hibernate.cfg.xml
11:32:34,454 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/StatisticsBean.hbm.xml
11:32:34,673 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/CsRegisteredBean.hbm.xml
11:32:34,720 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/TestCategoryBean.hbm.xml
11:32:34,751 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/SuiteModelBean.hbm.xml
11:32:34,767 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/FtpThroughPutBean.hbm.xml
11:32:34,798 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/LogDataBean.hbm.xml
11:32:34,813 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/StatisticsTypeBean.hbm.xml
11:32:34,845 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/TestSuiteInvokationBean.hbm.xml
11:32:34,923 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/UePropertiesBean.hbm.xml
11:32:34,954 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/CellBean.hbm.xml
11:32:34,970 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/TestProgressResultBean.hbm.xml
11:32:35,001 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/UeCoverageBean.hbm.xml
11:32:35,001 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/FolderBean.hbm.xml
11:32:35,017 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/CellTrafficBean.hbm.xml
11:32:35,032 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/UeCallSetupBean.hbm.xml
11:32:35,095 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/LogTypeBean.hbm.xml
11:32:35,110 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/PropertyBean.hbm.xml
11:32:35,126 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/CsTypeBean.hbm.xml
11:32:35,173 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/AutotestVersionBean.hbm.xml
11:32:35,188 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/TestBean.hbm.xml
11:32:35,204 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/SocketThroughPutBean.hbm.xml
11:32:35,220 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/HttpThroughPutBean.hbm.xml
11:32:35,298 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/AutotestInvokationBean.hbm.xml
11:32:35,313 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/RasFailMessageBean.hbm.xml
11:32:35,329 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/UeTrafficBean.hbm.xml
11:32:35,345 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/TestSuiteBean.hbm.xml
11:32:35,345 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/ErrorEventBean.hbm.xml
11:32:35,360 INFO Configuration:460 - Reading mappings from resource: com/ericsson/rgv/platform/database/hibernate/UeBean.hbm.xml
11:32:35,376 INFO Configuration:1368 - Configured SessionFactory: null
log4j:INFO Creating new logger [org.hibernate.cfg.Mappings] in repository [default].
log4j:INFO Creating new logger [org.hibernate.cfg.HbmBinder] in repository [default].
11:32:35,532 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.FtpThroughPutBean -> FTP_THROUGHPUT
log4j:INFO Returning existing logger [org.hibernate.type] in repository [default].
log4j:INFO Creating new logger [org.hibernate.type.DbTimestampType] in repository [default].
11:32:35,657 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.TestProgressResultBean -> TEST_PROGRESS_RESULT
log4j:INFO Creating new logger [org.hibernate.cfg.CollectionSecondPass] in repository [default].
11:32:35,673 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.UePropertiesBean -> UE_PROPERTIES
11:32:35,673 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.CsRegisteredBean -> CS_REGISTER
11:32:35,673 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.UeCallSetupBean -> UE_CALL_SETUP
11:32:35,673 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.AutotestVersionBean -> AUTOTEST_VERSION
11:32:35,673 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.LogDataBean -> LOG_DATA
11:32:35,673 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.StatisticsBean -> STATISTICS
log4j:INFO Creating new logger [org.hibernate.persister.entity.AbstractEntityPersister] in repository [default].
11:32:35,720 INFO HbmBinder:825 - Mapping joined-subclass: com.ericsson.rgv.platform.database.hibernate.SmsBean -> SMS
11:32:35,735 INFO HbmBinder:825 - Mapping joined-subclass: com.ericsson.rgv.platform.database.hibernate.CsStatisticsBean -> CS
11:32:35,735 INFO HbmBinder:825 - Mapping joined-subclass: com.ericsson.rgv.platform.database.hibernate.FtpStatisticsBean -> FTP
11:32:35,735 INFO HbmBinder:825 - Mapping joined-subclass: com.ericsson.rgv.platform.database.hibernate.UdpStatisticsBean -> UDP
11:32:35,735 INFO HbmBinder:825 - Mapping joined-subclass: com.ericsson.rgv.platform.database.hibernate.SocketStatisticsBean -> SOCKET
11:32:35,735 INFO HbmBinder:825 - Mapping joined-subclass: com.ericsson.rgv.platform.database.hibernate.HttpStatisticsBean -> HTTP
11:32:35,735 INFO HbmBinder:825 - Mapping joined-subclass: com.ericsson.rgv.platform.database.hibernate.PingStatisticsBean -> PING
11:32:35,735 INFO HbmBinder:825 - Mapping joined-subclass: com.ericsson.rgv.platform.database.hibernate.RasBean -> RAS
11:32:35,735 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.RasFailMessageBean -> RAS_FAIL_MESSAGE
11:32:35,751 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.TestBean -> TEST
11:32:35,751 INFO HbmBinder:1310 - Mapping collection: com.ericsson.rgv.platform.database.hibernate.TestBean.testCategories -> TEST_TEST_CATEGORY
11:32:35,751 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.UeBean -> UE
11:32:35,751 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.SuiteModelBean -> SUITE_MODEL
11:32:35,751 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.PropertyBean -> PROPERTY
11:32:35,751 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.CsTypeBean -> CS_TYPE
11:32:35,751 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.TestSuiteBean -> TESTSUITE
11:32:35,751 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.CellTrafficBean -> CELL_TRAFFIC
11:32:35,751 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.ErrorEventBean -> ERROR_EVENT
11:32:35,751 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.FolderBean -> FOLDER
11:32:35,751 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.CellBean -> CELL
11:32:35,751 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.LogTypeBean -> LOG_TYPE
11:32:35,751 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.HttpThroughPutBean -> HTTP_THROUGHPUT
11:32:35,767 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.SocketThroughPutBean -> SOCKET_THROUGHPUT
11:32:35,767 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.UeTrafficBean -> UE_TRAFFIC
11:32:35,767 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.UeCoverageBean -> UE_COVERAGE
11:32:35,767 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.AutotestInvokationBean -> AUTOTEST_INVOKATION
11:32:35,767 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.StatisticsTypeBean -> STATISTICS_TYPE
11:32:35,767 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.TestCategoryBean -> TEST_CATEGORY
11:32:35,767 INFO HbmBinder:266 - Mapping class: com.ericsson.rgv.platform.database.hibernate.TestSuiteInvokationBean -> TESTSUITE_INVOKATION
11:32:35,767 INFO Configuration:1014 - processing extends queue
11:32:35,767 INFO Configuration:1018 - processing collection mappings
11:32:35,767 INFO HbmBinder:2233 - Mapping collection: com.ericsson.rgv.platform.database.hibernate.TestProgressResultBean.statistics -> STATISTICS
11:32:35,767 INFO HbmBinder:2233 - Mapping collection: com.ericsson.rgv.platform.database.hibernate.UePropertiesBean.ueTraffic -> UE_TRAFFIC
11:32:35,767 INFO HbmBinder:2233 - Mapping collection: com.ericsson.rgv.platform.database.hibernate.StatisticsBean.ueTraffic -> UE_TRAFFIC
11:32:35,782 INFO HbmBinder:2233 - Mapping collection: com.ericsson.rgv.platform.database.hibernate.CsStatisticsBean.csRegister -> CS_REGISTER
11:32:35,782 INFO HbmBinder:2233 - Mapping collection: com.ericsson.rgv.platform.database.hibernate.TestBean.runningTests -> TEST_PROGRESS_RESULT
11:32:35,782 INFO HbmBinder:2233 - Mapping collection: com.ericsson.rgv.platform.database.hibernate.UeBean.ueProperties -> UE_PROPERTIES
11:32:35,782 INFO HbmBinder:2233 - Mapping collection: com.ericsson.rgv.platform.database.hibernate.AutotestInvokationBean.suiteInvokations -> TESTSUITE_INVOKATION
11:32:35,782 INFO HbmBinder:2233 - Mapping collection: com.ericsson.rgv.platform.database.hibernate.TestSuiteInvokationBean.testProgressResultSet -> TEST_PROGRESS_RESULT
11:32:35,782 INFO Configuration:1027 - processing association property references
11:32:35,782 INFO Configuration:1049 - processing foreign key constraints
log4j:INFO Creating new logger [org.hibernate.tuple.EntityMetamodel] in repository [default].
log4j:INFO Creating new logger [org.hibernate.property.BasicPropertyAccessor] in repository [default].
log4j:INFO Creating new logger [org.hibernate.util.ReflectHelper] in repository [default].
log4j:INFO Creating new logger [org.hibernate.tuple.PojoInstantiator] in repository [default].
log4j:INFO Creating new logger [org.hibernate.connection.ConnectionProviderFactory] in repository [default].
log4j:INFO Creating new logger [org.hibernate.connection.DriverManagerConnectionProvider] in repository [default].
11:32:36,126 INFO DriverManagerConnectionProvider:41 - Using Hibernate built-in connection pool (not for production use!)
11:32:36,126 INFO DriverManagerConnectionProvider:42 - Hibernate connection pool size: 1
11:32:36,126 INFO DriverManagerConnectionProvider:45 - autocommit mode: false
11:32:36,126 INFO DriverManagerConnectionProvider:80 - using driver: org.hsqldb.jdbcDriver at URL: jdbc:hsqldb:file:database/autotest2
11:32:36,126 INFO DriverManagerConnectionProvider:86 - connection properties: {user=sa, password=****}
11:32:44,485 INFO SettingsFactory:77 - RDBMS: HSQL Database Engine, version: 1.8.0
11:32:44,485 INFO SettingsFactory:78 - JDBC driver: HSQL Database Engine Driver, version: 1.8.0
log4j:INFO Creating new logger [org.hibernate.dialect.Dialect] in repository [default].
11:32:44,516 INFO Dialect:100 - Using dialect: org.hibernate.dialect.HSQLDialect
log4j:INFO Creating new logger [org.hibernate.transaction.TransactionFactoryFactory] in repository [default].
11:32:44,532 INFO TransactionFactoryFactory:31 - Using default transaction strategy (direct JDBC transactions)
log4j:INFO Creating new logger [org.hibernate.transaction.TransactionManagerLookupFactory] in repository [default].
11:32:44,532 INFO TransactionManagerLookupFactory:33 - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
11:32:44,532 INFO SettingsFactory:125 - Automatic flush during beforeCompletion(): disabled
11:32:44,532 INFO SettingsFactory:129 - Automatic session close at end of transaction: disabled
11:32:44,532 INFO SettingsFactory:136 - JDBC batch size: 15
11:32:44,532 INFO SettingsFactory:139 - JDBC batch updates for versioned data: enabled
11:32:44,532 INFO SettingsFactory:144 - Scrollable result sets: enabled
11:32:44,532 INFO SettingsFactory:152 - JDBC3 getGeneratedKeys(): disabled
11:32:44,548 INFO SettingsFactory:160 - Connection release mode: null
11:32:44,548 INFO SettingsFactory:184 - Maximum outer join fetch depth: 1
11:32:44,548 INFO SettingsFactory:187 - Default batch fetch size: 8
11:32:44,548 INFO SettingsFactory:191 - Generate SQL with comments: disabled
11:32:44,548 INFO SettingsFactory:195 - Order SQL updates by primary key: enabled
11:32:44,548 INFO SettingsFactory:338 - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
log4j:INFO Creating new logger [org.hibernate.hql.ast.ASTQueryTranslatorFactory] in repository [default].
11:32:44,548 INFO ASTQueryTranslatorFactory:21 - Using ASTQueryTranslatorFactory
11:32:44,548 INFO SettingsFactory:203 - Query language substitutions: {no='N', true=1, yes='Y', false=0}
11:32:44,548 INFO SettingsFactory:209 - Second-level cache: enabled
11:32:44,548 INFO SettingsFactory:213 - Query cache: enabled
11:32:44,548 INFO SettingsFactory:325 - Cache provider: org.hibernate.cache.HashtableCacheProvider
11:32:44,548 INFO SettingsFactory:228 - Optimize cache for minimal puts: disabled
11:32:44,548 INFO SettingsFactory:233 - Cache region prefix: hibernate.test
11:32:44,563 INFO SettingsFactory:237 - Structured second-level cache entries: disabled
11:32:44,563 INFO SettingsFactory:312 - Query cache factory: org.hibernate.cache.StandardQueryCacheFactory
log4j:INFO Creating new logger [org.hibernate.exception.SQLExceptionConverterFactory] in repository [default].
11:32:44,563 INFO SettingsFactory:264 - Statistics: disabled
11:32:44,563 INFO SettingsFactory:268 - Deleted entity synthetic identifier rollback: disabled
11:32:44,579 INFO SettingsFactory:283 - Default entity-mode: POJO
log4j:INFO Creating new logger [org.hibernate.impl.SessionFactoryImpl] in repository [default].
log4j:INFO Creating new logger [org.hibernate.stat.StatisticsImpl] in repository [default].
11:32:44,641 INFO SessionFactoryImpl:155 - building session factory
log4j:INFO Creating new logger [org.hibernate.id.IdentifierGeneratorFactory] in repository [default].
log4j:INFO Creating new logger [org.hibernate.engine.TransactionHelper] in repository [default].
log4j:INFO Creating new logger [org.hibernate.id.TableGenerator] in repository [default].
log4j:INFO Creating new logger [org.hibernate.id.TableHiLoGenerator] in repository [default].
log4j:INFO Creating new logger [org.hibernate.id.SequenceGenerator] in repository [default].
log4j:INFO Creating new logger [org.hibernate.id.SequenceHiLoGenerator] in repository [default].
log4j:INFO Creating new logger [org.hibernate.id.IncrementGenerator] in repository [default].
log4j:INFO Creating new logger [org.hibernate.id.GUIDGenerator] in repository [default].
log4j:INFO Creating new logger [org.hibernate.cache.CacheFactory] in repository [default].
log4j:INFO Creating new logger [org.hibernate.engine.IdentifierValue] in repository [default].
log4j:INFO Creating new logger [org.hibernate.tuple.DynamicMapEntityTuplizer] in repository [default].
log4j:INFO Creating new logger [org.hibernate.tuple.PojoEntityTuplizer] in repository [default].
log4j:INFO Creating new logger [org.hibernate.tuple.Dom4jEntityTuplizer] in repository [default].
log4j:INFO Creating new logger [org.hibernate.persister.collection.AbstractCollectionPersister] in repository [default].
log4j:INFO Creating new logger [org.hibernate.loader.Loader] in repository [default].
log4j:INFO Creating new logger [org.hibernate.loader.entity.EntityLoader] in repository [default].
log4j:INFO Creating new logger [org.hibernate.engine.CascadingAction] in repository [default].
log4j:INFO Creating new logger [org.hibernate.loader.collection.OneToManyLoader] in repository [default].
log4j:INFO Creating new logger [org.hibernate.loader.collection.BasicCollectionLoader] in repository [default].
log4j:INFO Creating new logger [org.hibernate.impl.SessionFactoryObjectFactory] in repository [default].
11:32:46,016 INFO SessionFactoryObjectFactory:82 - Not binding factory to JNDI, no JNDI name configured
log4j:INFO Creating new logger [org.hibernate.context.ThreadLocalSessionContext] in repository [default].
log4j:INFO Creating new logger [org.hibernate.cache.UpdateTimestampsCache] in repository [default].
11:32:46,032 INFO UpdateTimestampsCache:43 - starting update timestamps cache at region: hibernate.test.org.hibernate.cache.UpdateTimestampsCache
log4j:INFO Creating new logger [org.hibernate.cache.StandardQueryCache] in repository [default].
11:32:46,032 INFO StandardQueryCache:51 - starting query cache at region: hibernate.test.org.hibernate.cache.StandardQueryCache
11:32:46,032 INFO SessionFactoryImpl:432 - Checking 0 named queries
Begin transaction
log4j:INFO Creating new logger [org.hibernate.impl.SessionImpl] in repository [default].
log4j:INFO Creating new logger [org.hibernate.engine.ActionQueue] in repository [default].
log4j:INFO Creating new logger [org.hibernate.engine.StatefulPersistenceContext] in repository [default].
log4j:INFO Creating new logger [org.hibernate.jdbc.JDBCContext] in repository [default].
log4j:INFO Creating new logger [org.hibernate.jdbc.ConnectionManager] in repository [default].
log4j:INFO Creating new logger [org.hibernate.jdbc.AbstractBatcher] in repository [default].
log4j:INFO Returning existing logger [org.hibernate.SQL] in repository [default].
log4j:INFO Creating new logger [org.hibernate.transaction.JDBCTransaction] in repository [default].
log4j:INFO Creating new logger [org.hibernate.engine.QueryParameters] in repository [default].
Process work
11:32:46,204 DEBUG SQL:344 - select testsuitei0_.TESTSUITE_INVOKATION_ID as TESTSUITE1_36_1_, testsuitei0_.TESTSUITE_FINISHED as TESTSUITE2_36_1_, testsuitei0_.SUITE_FILE_NAME as SUITE3_36_1_, testsuitei0_.TESTSUITE_STARTED as TESTSUITE4_36_1_, testsuitei0_.AUTOTEST_INVOKATION_ID as AUTOTEST5_36_1_, autotestin1_.AUTOTEST_INVOKATION_ID as AUTOTEST1_33_0_, autotestin1_.SIGNUM as SIGNUM33_0_, autotestin1_.AUTOTEST_VERSION_ID as AUTOTEST3_33_0_, autotestin1_.TESTSUITE_ID as TESTSUITE4_33_0_, autotestin1_.START_DATE as START5_33_0_, autotestin1_.STOP_DATE as STOP6_33_0_ from TESTSUITE_INVOKATION testsuitei0_ left outer join AUTOTEST_INVOKATION autotestin1_ on testsuitei0_.AUTOTEST_INVOKATION_ID=autotestin1_.AUTOTEST_INVOKATION_ID where testsuitei0_.TESTSUITE_INVOKATION_ID=?
log4j:INFO Creating new logger [org.hibernate.type.IntegerType] in repository [default].
11:32:46,235 DEBUG IntegerType:79 - binding '1' to parameter: 1
11:32:46,235 DEBUG IntegerType:123 - returning '1' as column: AUTOTEST1_33_0_
log4j:INFO Creating new logger [org.hibernate.engine.TwoPhaseLoad] in repository [default].
log4j:INFO Creating new logger [org.hibernate.type.StringType] in repository [default].
11:32:46,251 DEBUG StringType:116 - returning null as column: SIGNUM33_0_
11:32:46,251 DEBUG IntegerType:123 - returning '1' as column: AUTOTEST3_33_0_
11:32:46,251 DEBUG IntegerType:123 - returning '1' as column: TESTSUITE4_33_0_
log4j:INFO Creating new logger [org.hibernate.type.TimestampType] in repository [default].
11:32:46,251 DEBUG TimestampType:123 - returning '2005-10-18 11:42:13' as column: START5_33_0_
11:32:46,251 DEBUG TimestampType:123 - returning '2005-10-18 11:46:32' as column: STOP6_33_0_
log4j:INFO Creating new logger [org.hibernate.engine.Versioning] in repository [default].
11:32:46,266 DEBUG TimestampType:123 - returning '2005-10-18 11:46:32' as column: TESTSUITE2_36_1_
11:32:46,266 DEBUG StringType:116 - returning null as column: SUITE3_36_1_
11:32:46,266 DEBUG TimestampType:123 - returning '2005-10-18 11:42:13' as column: TESTSUITE4_36_1_
11:32:46,266 DEBUG IntegerType:123 - returning '1' as column: AUTOTEST5_36_1_
11:32:46,266 DEBUG SQL:344 - select autotestve0_.AUTOTEST_VERSION_ID as AUTOTEST1_5_0_, autotestve0_.COMMENT as COMMENT5_0_, autotestve0_.INSTALL_DATE as INSTALL3_5_0_, autotestve0_.VERSION as VERSION5_0_ from AUTOTEST_VERSION autotestve0_ where autotestve0_.AUTOTEST_VERSION_ID=?
11:32:46,266 DEBUG IntegerType:79 - binding '1' to parameter: 1
11:32:46,266 DEBUG StringType:116 - returning null as column: COMMENT5_0_
11:32:46,282 DEBUG TimestampType:123 - returning '2005-10-18 11:42:13' as column: INSTALL3_5_0_
11:32:46,282 DEBUG StringType:123 - returning 'R4D06' as column: VERSION5_0_
11:32:46,282 DEBUG SQL:344 - select testsuiteb0_.TESTSUITE_ID as TESTSUITE1_23_0_, testsuiteb0_.TESTSUITE_NAME as TESTSUITE2_23_0_ from TESTSUITE testsuiteb0_ where testsuiteb0_.TESTSUITE_ID=?
11:32:46,282 DEBUG IntegerType:79 - binding '1' to parameter: 1
11:32:46,282 DEBUG StringType:123 - returning 'Autotest_R1P1_40percent_v1.xml' as column: TESTSUITE2_23_0_
log4j:INFO Creating new logger [org.hibernate.engine.CollectionLoadContext] in repository [default].
log4j:INFO Creating new logger [org.hibernate.engine.CollectionEntry] in repository [default].
Commit work (first tranaction)
log4j:INFO Creating new logger [org.hibernate.util.JDBCExceptionReporter] in repository [default].
Disconnect Context
Store session in HashMap
böna 1: com.ericsson.rgv.platform.database.hibernate.TestSuiteInvokationBean@c9630a
Bind Session stored in HashMap (Connect Context)
org.hibernate.HibernateException: only beginTransaction() is valid when transaction not yet started
at org.hibernate.context.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:263)
at $Proxy0.getSessionFactory(Unknown Source)
at org.hibernate.context.ThreadLocalSessionContext.bind(ThreadLocalSessionContext.java:155)
at com.ericsson.rgv.platform.database.persistence.ExtendedHibernateThreadFilter.reconnectContext(ExtendedHibernateThreadFilter.java:24)
at com.ericsson.rgv.platform.database.persistence.ExtendedHibernateThreadFilter.invoke(ExtendedHibernateThreadFilter.java:33)
at com.ericsson.rgv.platform.database.actions.RequestProcessor.processRequest(RequestProcessor.java:9)
at com.ericsson.rgv.platform.database.actions.ExampleAction$1.run(ExampleAction.java:31)
com.ericsson.rgv.platform.database.actions.ActionException: org.hibernate.HibernateException: only beginTransaction() is valid when transaction not yet started
at com.ericsson.rgv.platform.database.persistence.ExtendedHibernateThreadFilter.invoke(ExtendedHibernateThreadFilter.java:71)
at com.ericsson.rgv.platform.database.actions.RequestProcessor.processRequest(RequestProcessor.java:9)
at com.ericsson.rgv.platform.database.actions.ExampleAction$1.run(ExampleAction.java:31)
Caused by: org.hibernate.HibernateException: only beginTransaction() is valid when transaction not yet started
at org.hibernate.context.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:263)
at $Proxy0.getTransaction(Unknown Source)
at com.ericsson.rgv.platform.database.persistence.ExtendedHibernateThreadFilter.invoke(ExtendedHibernateThreadFilter.java:67)
... 2 more

No, you should use the DEBUG log to figure out what the sequence of sessions and transactions is. That's why there are so many log.debug() statements in the two classes you copied. You have to enable logging for them if you want to see anything...

12:12:19,720 DEBUG ExtendedHibernateThreadFilter:44 - >>> New conversation
2005-11-25 12:12:19,720 DEBUG [persistence.ExtendedHibernateThreadFilter]: >>> New conversation
12:12:19,720 DEBUG ExtendedHibernateThreadFilter:48 - Starting a database transaction
2005-11-25 12:12:19,720 DEBUG [persistence.ExtendedHibernateThreadFilter]: Starting a database transaction
12:12:19,720 DEBUG ExtendedSessionContext:27 - Opening a new Session
2005-11-25 12:12:19,720 DEBUG [persistence.ExtendedSessionContext]: Opening a new Session
12:12:19,783 DEBUG ExtendedSessionContext:30 - Disabling automatic flushing of the Session
2005-11-25 12:12:19,783 DEBUG [persistence.ExtendedSessionContext]: Disabling automatic flushing of the Session
12:12:19,924 DEBUG IntegerType:79 - binding '1' to parameter: 1
2005-11-25 12:12:19,924 DEBUG [type.IntegerType]: binding '1' to parameter: 1
12:12:19,924 DEBUG IntegerType:123 - returning '1' as column: AUTOTEST1_20_0_
2005-11-25 12:12:19,924 DEBUG [type.IntegerType]: returning '1' as column: AUTOTEST1_20_0_
12:12:19,939 DEBUG StringType:116 - returning null as column: SIGNUM20_0_
2005-11-25 12:12:19,939 DEBUG [type.StringType]: returning null as column: SIGNUM20_0_
12:12:19,939 DEBUG IntegerType:123 - returning '1' as column: AUTOTEST3_20_0_
2005-11-25 12:12:19,939 DEBUG [type.IntegerType]: returning '1' as column: AUTOTEST3_20_0_
12:12:19,939 DEBUG IntegerType:123 - returning '1' as column: TESTSUITE4_20_0_
2005-11-25 12:12:19,939 DEBUG [type.IntegerType]: returning '1' as column: TESTSUITE4_20_0_
12:12:19,939 DEBUG TimestampType:123 - returning '2005-10-18 11:42:13' as column: START5_20_0_
2005-11-25 12:12:19,939 DEBUG [type.TimestampType]: returning '2005-10-18 11:42:13' as column: START5_20_0_
12:12:19,939 DEBUG TimestampType:123 - returning '2005-10-18 11:46:32' as column: STOP6_20_0_
2005-11-25 12:12:19,939 DEBUG [type.TimestampType]: returning '2005-10-18 11:46:32' as column: STOP6_20_0_
12:12:19,939 DEBUG TimestampType:123 - returning '2005-10-18 11:46:32' as column: TESTSUITE2_21_1_
2005-11-25 12:12:19,939 DEBUG [type.TimestampType]: returning '2005-10-18 11:46:32' as column: TESTSUITE2_21_1_
12:12:19,939 DEBUG StringType:116 - returning null as column: SUITE3_21_1_
2005-11-25 12:12:19,939 DEBUG [type.StringType]: returning null as column: SUITE3_21_1_
12:12:19,939 DEBUG TimestampType:123 - returning '2005-10-18 11:42:13' as column: TESTSUITE4_21_1_
2005-11-25 12:12:19,939 DEBUG [type.TimestampType]: returning '2005-10-18 11:42:13' as column: TESTSUITE4_21_1_
12:12:19,939 DEBUG IntegerType:123 - returning '1' as column: AUTOTEST5_21_1_
2005-11-25 12:12:19,939 DEBUG [type.IntegerType]: returning '1' as column: AUTOTEST5_21_1_
12:12:19,955 DEBUG IntegerType:79 - binding '1' to parameter: 1
2005-11-25 12:12:19,955 DEBUG [type.IntegerType]: binding '1' to parameter: 1
12:12:19,955 DEBUG StringType:116 - returning null as column: COMMENT34_0_
2005-11-25 12:12:19,955 DEBUG [type.StringType]: returning null as column: COMMENT34_0_
12:12:19,955 DEBUG TimestampType:123 - returning '2005-10-18 11:42:13' as column: INSTALL3_34_0_
2005-11-25 12:12:19,955 DEBUG [type.TimestampType]: returning '2005-10-18 11:42:13' as column: INSTALL3_34_0_
12:12:19,955 DEBUG StringType:123 - returning 'R4D06' as column: VERSION34_0_
2005-11-25 12:12:19,955 DEBUG [type.StringType]: returning 'R4D06' as column: VERSION34_0_
12:12:19,955 DEBUG IntegerType:79 - binding '1' to parameter: 1
2005-11-25 12:12:19,955 DEBUG [type.IntegerType]: binding '1' to parameter: 1
12:12:19,970 DEBUG StringType:123 - returning 'Autotest_R1P1_40percent_v1.xml' as column: TESTSUITE2_12_0_
2005-11-25 12:12:19,970 DEBUG [type.StringType]: returning 'Autotest_R1P1_40percent_v1.xml' as column: TESTSUITE2_12_0_
12:12:19,986 DEBUG ExtendedHibernateThreadFilter:67 - Committing database transaction.
2005-11-25 12:12:19,986 DEBUG [persistence.ExtendedHibernateThreadFilter]: Committing database transaction.
12:12:19,986 DEBUG ExtendedHibernateThreadFilter:71 - Unbinding Session from thread
2005-11-25 12:12:19,986 DEBUG [persistence.ExtendedHibernateThreadFilter]: Unbinding Session from thread
12:12:19,986 DEBUG ExtendedHibernateThreadFilter:74 - Storing Session in static Hashmap
2005-11-25 12:12:19,986 DEBUG [persistence.ExtendedHibernateThreadFilter]: Storing Session in static Hashmap
12:12:19,986 DEBUG ExtendedHibernateThreadFilter:78 - > Returning to user in conversation
2005-11-25 12:12:19,986 DEBUG [persistence.ExtendedHibernateThreadFilter]: > Returning to user in conversation
böna 1: com.ericsson.rgv.platform.database.hibernate.TestSuiteInvokationBean@166bfd8
12:12:19,986 DEBUG ExtendedHibernateThreadFilter:41 - < Continuing conversation
2005-11-25 12:12:19,986 DEBUG [persistence.ExtendedHibernateThreadFilter]: < Continuing conversation
org.hibernate.HibernateException: only beginTransaction() is valid when transaction not yet started
at org.hibernate.context.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:263)
at $Proxy0.getSessionFactory(Unknown Source)
at org.hibernate.context.ThreadLocalSessionContext.bind(ThreadLocalSessionContext.java:155)
at com.ericsson.rgv.platform.database.persistence.ExtendedHibernateThreadFilter.reconnectContext(ExtendedHibernateThreadFilter.java:30)
at com.ericsson.rgv.platform.database.persistence.ExtendedHibernateThreadFilter.invoke(ExtendedHibernateThreadFilter.java:42)
at com.ericsson.rgv.platform.database.actions.RequestProcessor.processRequest(RequestProcessor.java:9)
at com.ericsson.rgv.platform.database.actions.ExampleAction$1.run(ExampleAction.java:31)
12:12:20,002 DEBUG ExtendedHibernateThreadFilter:88 - Trying to rollback database transaction after exception
2005-11-25 12:12:20,002 DEBUG [persistence.ExtendedHibernateThreadFilter]: Trying to rollback database transaction after exception
12:12:20,002 DEBUG ExtendedSessionContext:27 - Opening a new Session
2005-11-25 12:12:20,002 DEBUG [persistence.ExtendedSessionContext]: Opening a new Session
12:12:20,002 DEBUG ExtendedSessionContext:30 - Disabling automatic flushing of the Session
2005-11-25 12:12:20,002 DEBUG [persistence.ExtendedSessionContext]: Disabling automatic flushing of the Session
12:12:20,002 ERROR ExtendedHibernateThreadFilter:93 - Could not rollback transaction after exception!
org.hibernate.HibernateException: only beginTransaction() is valid when transaction not yet started
at org.hibernate.context.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:263)
at $Proxy0.getTransaction(Unknown Source)
at com.ericsson.rgv.platform.database.persistence.ExtendedHibernateThreadFilter.invoke(ExtendedHibernateThreadFilter.java:89)
at com.ericsson.rgv.platform.database.actions.RequestProcessor.processRequest(RequestProcessor.java:9)
at com.ericsson.rgv.platform.database.actions.ExampleAction$1.run(ExampleAction.java:31)
2005-11-25 12:12:20,002 ERROR [persistence.ExtendedHibernateThreadFilter]: Could not rollback transaction after exception!
org.hibernate.HibernateException: only beginTransaction() is valid when transaction not yet started
at org.hibernate.context.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:263)
at $Proxy0.getTransaction(Unknown Source)
at com.ericsson.rgv.platform.database.persistence.ExtendedHibernateThreadFilter.invoke(ExtendedHibernateThreadFilter.java:89)
at com.ericsson.rgv.platform.database.actions.RequestProcessor.processRequest(RequestProcessor.java:9)
at com.ericsson.rgv.platform.database.actions.ExampleAction$1.run(ExampleAction.java:31)
12:12:20,752 DEBUG ExtendedHibernateThreadFilter:96 - Closing and unbinding Session from thread
2005-11-25 12:12:20,752 DEBUG [persistence.ExtendedHibernateThreadFilter]: Closing and unbinding Session from thread
12:12:20,752 DEBUG ExtendedHibernateThreadFilter:99 - Removing Session from HttpSession.
2005-11-25 12:12:20,752 DEBUG [persistence.ExtendedHibernateThreadFilter]: Removing Session from HttpSession.
com.ericsson.rgv.platform.database.actions.ActionException: org.hibernate.HibernateException: only beginTransaction() is valid when transaction not yet started
at com.ericsson.rgv.platform.database.persistence.ExtendedHibernateThreadFilter.invoke(ExtendedHibernateThreadFilter.java:94)
at com.ericsson.rgv.platform.database.actions.RequestProcessor.processRequest(RequestProcessor.java:9)
at com.ericsson.rgv.platform.database.actions.ExampleAction$1.run(ExampleAction.java:31)
Caused by: org.hibernate.HibernateException: only beginTransaction() is valid when transaction not yet started
at org.hibernate.context.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:263)
at $Proxy0.getTransaction(Unknown Source)
at com.ericsson.rgv.platform.database.persistence.ExtendedHibernateThreadFilter.invoke(ExtendedHibernateThreadFilter.java:89)
... 2 more

And what is the problem? Nobody knows what "ExtendedHibernateThreadFilter" is and how you modified the code in that class. There is no such class on the webpage you mentioned.

My recommendation: Download CaveatEmptor. Use the source. Use Hibernate 3.1 rc3.

I remember that this is definitely a problem with RC2. Use RC3.

Yes it worked with RC3. Thanks