Hi,

I'm trying to get naming strategies to work properly and I'm not having much luck.

I'm generating my schema from .hbm.xml files using the Maven hbm2ddl task, with the following line in pom.xml:




This works fine. So for example, I have a Client class with attributes emailAddress and inetAddress, and hbm2ddl generates the following:




So far, so good.

However, I can't get the Hibernate runtime to use this naming strategy. I've tried setting it on my Configuration object, e.g.:




[*See notes below]

I've also tried setting it in hibernate.properties as suggested by one or two web pages I found:




However, neither of these methods make any difference! When I try to create and save a Client, I get errors like this:




Looking in my log file, I see the mappings have been made without paying any heed to the naming strategy:




Am I missing something here? What else do I need to do to make this work at run time?

Many thanks!

Andrew.

*Notes:

ModelConfiguration is just a class of mine that extends Configuration and sets up the mappings, so:




Doing it this way is a symptom of using Guice for dependency injection and thinking in terms of small modular configuration objects.

Also, I'm using Warp-Persist to inject the configuration at the right time, hence why I don't call buildSessionFactory() myself. You just provide it with a Configuration (via Guice) and it produces the factory when it's needed. I know Warp-Persist is calling setNamingStrategy() at the start of my test run, as I can hit a breakpoint on that method. But I can't see why Hibernate's ignoring the strategy...

It occurred to me I didn't include some of the required information when I posted this. So see below. Still grateful for any suggestions.

Thanks,

Andrew.

Hibernate version: 3.2.5.ga

Mapping documents:

Here's Client.hbm.xml since I used this entity in the example.

<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">
<hibernate-mapping>

<class name="info.cathdb.funcnet_0_1.sessiondb.model.Client">

<meta attribute="class-description">Represents a FuncNet user at a specific location.</meta>
<meta attribute="class-code"> public static final long serialVersionUID = 1L; // Suppress Eclipse warning</meta>

<id column="client_id" type="integer">
<meta attribute="scope-set">protected</meta>
<generator class="increment" />
</id>

<property name="emailAddress" type="string" not-null="true">
<meta attribute="use-in-tostring">true</meta>
<meta attribute="use-in-equals">true</meta>
<meta attribute="scope-set">protected</meta>
</property>

<property name="inetAddress" type="string" not-null="true">
<meta attribute="use-in-tostring">true</meta>
<meta attribute="use-in-equals">true</meta>
<meta attribute="scope-set">protected</meta>
</property>

<!--
Taken this out because we never need to do it, and it's an extra manual step
to keep it updated.
<set name="sessions" inverse="true">
<key column="client_id" not-null="true" />
<one-to-many class="info.cathdb.funcnet_0_1.sessiondb.model.Session" />
</set>
-->

</class>

</hibernate-mapping>

Code between sessionFactory.openSession() and session.close():

The method is as follows -- the session and transaction open/close logic is wrapped around it automatically by warp-persist, using AOP method interception, as per the @Transactional annotation.

@Override @Transactional
public String createNewSession( Set<String> predictors, String emailAddress, String inetAddress, boolean enableEmailNotify )
{
if( predictors == null )
throw new IllegalArgumentException( "Predictor set may not be null" );

if( predictors.size() == 0 )
throw new IllegalArgumentException( "Predictor set may not be empty" );

if( emailAddress == null )
throw new IllegalArgumentException( "Email address may not be null" );

if( inetAddress == null )
throw new IllegalArgumentException( "Internet address may not be null" );

// Build client object, or retrieve matching one that already exists
org.hibernate.Session h3 = _h3.get();
inetAddress = inetAddress.trim();
Client client = getOrMakeClientMatching( emailAddress, inetAddress, h3 );

// Build and persist session object
String sessionID = makeSessionID();
Date now = new Date();
String status = PredictorStatus.WORKING.name(); // TODO get this working properly with enums
Session session = new Session( sessionID, now, status, client );
h3.saveOrUpdate( session );

// Build predictor session objects -- one for each predictor requested
for( String predictor : predictors )
{
PredictorSession ps = new PredictorSession( predictor, PredictorStatus.WORKING.name() );
session.getPredictors().add( ps );
}

return sessionID;
}

Full stack trace of any exception that occurs:

org.hibernate.exception.SQLGrammarException: could not execute query
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:67)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
at org.hibernate.loader.Loader.doList(Loader.java:2223)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2104)
at org.hibernate.loader.Loader.list(Loader.java:2099)
at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:94)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1569)
at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:283)
at org.hibernate.impl.CriteriaImpl.uniqueResult(CriteriaImpl.java:305)
at info.cathdb.funcnet_0_1.sessiondb.hib3impl.HibernateRepository.getOrMakeClientMatching(HibernateRepository.java:382)
at info.cathdb.funcnet_0_1.sessiondb.hib3impl.HibernateRepository.createNewSession(HibernateRepository.java:100)
at info.cathdb.funcnet_0_1.sessiondb.hib3impl.HibernateRepository$$EnhancerByGuice$$9cd4ff07.CGLIB$createNewSession$8(<generated>)
at info.cathdb.funcnet_0_1.sessiondb.hib3impl.HibernateRepository$$EnhancerByGuice$$9cd4ff07$$FastClassByGuice$$d9d3bc19.invoke(<generated>)
at com.google.inject.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:187)
at com.google.inject.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:66)
at com.wideplay.warp.hibernate.HibernateLocalTxnInterceptor.invoke(HibernateLocalTxnInterceptor.java:68)
at com.google.inject.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:66)
at com.google.inject.InterceptorStackCallback.intercept(InterceptorStackCallback.java:45)
at info.cathdb.funcnet_0_1.sessiondb.hib3impl.HibernateRepository$$EnhancerByGuice$$9cd4ff07.createNewSession(<generated>)
at info.cathdb.funcnet_0_1.sessiondb.hib3impl.RepositoryTest.createStandardSession(RepositoryTest.java:215)
at info.cathdb.funcnet_0_1.sessiondb.hib3impl.RepositoryTest.testMultipleIdenticalClientsAreUnified(RepositoryTest.java:206)
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:597)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:73)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:46)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:180)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:41)
at org.junit.runners.ParentRunner$1.evaluate(ParentRunner.java:173)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
at org.junit.runners.ParentRunner.run(ParentRunner.java:220)
at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:45)
at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:460)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:673)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:386)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:196)
Caused by: org.postgresql.util.PSQLException: ERROR: column this_.emailaddress does not exist
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:1592)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1327)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:192)
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:451)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:350)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:254)
at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:186)
at org.hibernate.loader.Loader.getResultSet(Loader.java:1787)
at org.hibernate.loader.Loader.doQuery(Loader.java:674)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236)
at org.hibernate.loader.Loader.doList(Loader.java:2220)
... 42 more

Name and version of the database you are using:

PostgreSQL 8.3.3

The generated SQL (show_sql=true):

Schema creation code from hbm2ddl:

create table client (client_id int4 not null, email_address varchar(255) not null, inet_address varchar(255) not null, primary key (client_id));
create table prediction (prediction_id int4 not null, predictor_session int4, protein1 varchar(255) not null, protein2 varchar(255) not null, raw_score float8 not null, p_value float8 not null, predictor_session_id int4 not null, primary key (prediction_id), unique (predictor_session, protein1, protein2));
create table predictor_session (predictor_session_id int4 not null, predictor_name varchar(255) not null, status varchar(255) not null, status_message varchar(255), session_id int4 not null, primary key (predictor_session_id));
create table session (session_id int4 not null, funcnet_jobid varchar(255) not null, start_time timestamp not null, status varchar(255) not null, client_id int4 not null, status_message varchar(255), comments varchar(255), enable_email_notify bool, primary key (session_id));
alter table prediction add constraint FK4537088FCA9B48B0 foreign key (predictor_session_id) references predictor_session;
alter table prediction add constraint FK4537088F5ABCC77C foreign key (predictor_session) references predictor_session;
alter table predictor_session add constraint FKA5BCDDD3406E3DEB foreign key (session_id) references session;
alter table session add constraint FK76508296E6113BC9 foreign key (client_id) references client;

But the actual query code ignores the naming strategy:

select this_.client_id as client1_3_0_, this_.emailAddress as emailAdd2_3_0_, this_.inetAddress as inetAddr3_3_0_ from Client this_ where this_.emailAddress ilike ? and this_.inetAddress ilike ?

Debug level Hibernate log excerpt:

Not sure where the stuff about naming strategies should appear, so here's the whole log for a single test case:

16:13:59,891 INFO Environment:514 - Hibernate 3.2.5
16:13:59,896 INFO Environment:532 - loaded properties from resource hibernate.properties: {hibernate.connection.driver_class=org.postgresql.Driver, hibernate.current_session_context_class=thread, hibernate.dialect=org.hibernate.dialect.PostgreSQLDialect, hibernate.jdbc.batch_size=50, hibernate.connection.username=funcnet, hibernate.connection.url=jdbc:postgresql://caffdubya/FuncNet, hibernate.bytecode.use_reflection_optimizer=false, hibernate.connection.password=****, hibernate.transaction.factory_class=org.hibernate.transaction.JDBCTransactionFactory}
16:13:59,896 INFO Environment:681 - Bytecode provider name : cglib
16:13:59,899 INFO Environment:598 - using JDK 1.4 java.sql.Timestamp handling
16:13:59,942 INFO Configuration:553 - Reading mappings from resource : Session.hbm.xml
16:13:59,985 DEBUG DTDEntityResolver:38 - trying to resolve system-id [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd]
16:13:59,986 DEBUG DTDEntityResolver:40 - recognized hibernate namespace; attempting to resolve on classpath under org/hibernate/
16:13:59,992 DEBUG DTDEntityResolver:50 - located [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd] in classpath
16:14:00,117 INFO HbmBinder:300 - Mapping class: info.cathdb.funcnet_0_1.sessiondb.model.Session -> Session
16:14:00,127 DEBUG HbmBinder:1270 - Mapped property: funcnetJobID -> funcnetJobID
16:14:00,128 DEBUG HbmBinder:1270 - Mapped property: startTime -> startTime
16:14:00,128 DEBUG HbmBinder:1270 - Mapped property: status -> status
16:14:00,225 DEBUG HbmBinder:1270 - Mapped property: client -> client_id
16:14:00,226 DEBUG HbmBinder:1270 - Mapped property: statusMessage -> statusMessage
16:14:00,226 DEBUG HbmBinder:1270 - Mapped property: comments -> comments
16:14:00,227 DEBUG HbmBinder:1270 - Mapped property: enableEmailNotify -> enableEmailNotify
16:14:00,230 DEBUG HbmBinder:1270 - Mapped property: predictors
16:14:00,230 DEBUG HbmBinder:2571 - Named query: info.cathdb.funcnet_0_1.sessiondb.model.Session.info.cathdb.funcnet_0_1.sessiondb.model.pairwiseScores ->

select prediction.protein1,
prediction.protein2,
-2 * sum( log( prediction.pValue ) )
from info.cathdb.funcnet_0_1.sessiondb.model.Session session
inner join session.predictors predictorSession
inner join predictorSession.predictions prediction
where session.funcnetJobID = :jobID
group by prediction.protein1,
prediction.protein2


16:14:00,231 INFO Configuration:553 - Reading mappings from resource : PredictorSession.hbm.xml
16:14:00,233 DEBUG DTDEntityResolver:38 - trying to resolve system-id [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd]
16:14:00,234 DEBUG DTDEntityResolver:40 - recognized hibernate namespace; attempting to resolve on classpath under org/hibernate/
16:14:00,235 DEBUG DTDEntityResolver:50 - located [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd] in classpath
16:14:00,272 INFO HbmBinder:300 - Mapping class: info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession -> PredictorSession
16:14:00,272 DEBUG HbmBinder:1270 - Mapped property: predictorName -> predictorName
16:14:00,273 DEBUG HbmBinder:1270 - Mapped property: status -> status
16:14:00,273 DEBUG HbmBinder:1270 - Mapped property: statusMessage -> statusMessage
16:14:00,273 DEBUG HbmBinder:1270 - Mapped property: predictions
16:14:00,274 INFO Configuration:553 - Reading mappings from resource : Prediction.hbm.xml
16:14:00,275 DEBUG DTDEntityResolver:38 - trying to resolve system-id [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd]
16:14:00,275 DEBUG DTDEntityResolver:40 - recognized hibernate namespace; attempting to resolve on classpath under org/hibernate/
16:14:00,279 DEBUG DTDEntityResolver:50 - located [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd] in classpath
16:14:00,317 INFO HbmBinder:300 - Mapping class: info.cathdb.funcnet_0_1.sessiondb.model.Prediction -> Prediction
16:14:00,318 DEBUG HbmBinder:1270 - Mapped property: predictorSession -> predictorSession
16:14:00,319 DEBUG HbmBinder:1270 - Mapped property: protein1 -> protein1
16:14:00,319 DEBUG HbmBinder:1270 - Mapped property: protein2 -> protein2
16:14:00,320 DEBUG HbmBinder:1270 - Mapped property: rawScore -> rawScore
16:14:00,320 DEBUG HbmBinder:1270 - Mapped property: pValue -> pValue
16:14:00,324 INFO Configuration:553 - Reading mappings from resource : Client.hbm.xml
16:14:00,325 DEBUG DTDEntityResolver:38 - trying to resolve system-id [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd]
16:14:00,325 DEBUG DTDEntityResolver:40 - recognized hibernate namespace; attempting to resolve on classpath under org/hibernate/
16:14:00,326 DEBUG DTDEntityResolver:50 - located [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd] in classpath
16:14:00,357 INFO HbmBinder:300 - Mapping class: info.cathdb.funcnet_0_1.sessiondb.model.Client -> Client
16:14:00,357 DEBUG HbmBinder:1270 - Mapped property: emailAddress -> emailAddress
16:14:00,358 DEBUG HbmBinder:1270 - Mapped property: inetAddress -> inetAddress
16:14:00,513 DEBUG Configuration:1285 - Preparing to build session factory with filters : {}
16:14:00,513 DEBUG Configuration:1120 - processing extends queue
16:14:00,513 DEBUG Configuration:1124 - processing collection mappings
16:14:00,514 DEBUG CollectionSecondPass:41 - Second pass for collection: info.cathdb.funcnet_0_1.sessiondb.model.Session.predictors
16:14:00,514 INFO HbmBinder:2385 - Mapping collection: info.cathdb.funcnet_0_1.sessiondb.model.Session.predictors -> PredictorSession
16:14:00,515 DEBUG CollectionSecondPass:57 - Mapped collection key: session_id, one-to-many: info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession
16:14:00,516 DEBUG CollectionSecondPass:41 - Second pass for collection: info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession.predictions
16:14:00,516 INFO HbmBinder:2385 - Mapping collection: info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession.predictions -> Prediction
16:14:00,516 DEBUG CollectionSecondPass:57 - Mapped collection key: predictor_session_id, one-to-many: info.cathdb.funcnet_0_1.sessiondb.model.Prediction
16:14:00,517 DEBUG Configuration:1135 - processing native query and ResultSetMapping mappings
16:14:00,517 DEBUG Configuration:1143 - processing association property references
16:14:00,517 DEBUG Configuration:1165 - processing foreign key constraints
16:14:00,518 DEBUG Configuration:1248 - resolving reference to class: info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession
16:14:00,518 DEBUG Configuration:1248 - resolving reference to class: info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession
16:14:00,518 DEBUG Configuration:1248 - resolving reference to class: info.cathdb.funcnet_0_1.sessiondb.model.Session
16:14:00,519 DEBUG Configuration:1248 - resolving reference to class: info.cathdb.funcnet_0_1.sessiondb.model.Client
16:14:00,523 INFO DriverManagerConnectionProvider:41 - Using Hibernate built-in connection pool (not for production use!)
16:14:00,523 INFO DriverManagerConnectionProvider:42 - Hibernate connection pool size: 20
16:14:00,524 INFO DriverManagerConnectionProvider:45 - autocommit mode: false
16:14:00,544 INFO DriverManagerConnectionProvider:80 - using driver: org.postgresql.Driver at URL: jdbc:postgresql://caffdubya/FuncNet
16:14:00,545 INFO DriverManagerConnectionProvider:83 - connection properties: {user=funcnet, password=4funcnetuse}
16:14:00,545 DEBUG DriverManagerConnectionProvider:93 - total checked-out connections: 0
16:14:00,545 DEBUG DriverManagerConnectionProvider:109 - opening new JDBC connection
16:14:00,599 DEBUG DriverManagerConnectionProvider:115 - created connection to: jdbc:postgresql://caffdubya/FuncNet, Isolation Level: 2
16:14:00,607 INFO SettingsFactory:89 - RDBMS: PostgreSQL, version: 8.3.3
16:14:00,609 INFO SettingsFactory:90 - JDBC driver: PostgreSQL Native Driver, version: PostgreSQL 8.3 JDBC4 with SSL (build 603)
16:14:00,609 DEBUG DriverManagerConnectionProvider:129 - returning connection to pool, pool size: 1
16:14:00,620 INFO Dialect:152 - Using dialect: org.hibernate.dialect.PostgreSQLDialect
16:14:00,624 INFO TransactionFactoryFactory:34 - Transaction strategy: org.hibernate.transaction.JDBCTransactionFactory
16:14:00,626 INFO TransactionManagerLookupFactory:33 - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
16:14:00,626 INFO SettingsFactory:143 - Automatic flush during beforeCompletion(): disabled
16:14:00,626 INFO SettingsFactory:147 - Automatic session close at end of transaction: disabled
16:14:00,627 INFO SettingsFactory:154 - JDBC batch size: 50
16:14:00,627 INFO SettingsFactory:157 - JDBC batch updates for versioned data: disabled
16:14:00,628 INFO SettingsFactory:162 - Scrollable result sets: enabled
16:14:00,628 DEBUG SettingsFactory:166 - Wrap result sets: disabled
16:14:00,628 INFO SettingsFactory:170 - JDBC3 getGeneratedKeys(): disabled
16:14:00,629 INFO SettingsFactory:178 - Connection release mode: auto
16:14:00,630 INFO SettingsFactory:205 - Default batch fetch size: 1
16:14:00,630 INFO SettingsFactory:209 - Generate SQL with comments: disabled
16:14:00,630 INFO SettingsFactory:213 - Order SQL updates by primary key: disabled
16:14:00,631 INFO SettingsFactory:217 - Order SQL inserts for batching: disabled
16:14:00,631 INFO SettingsFactory:386 - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
16:14:00,633 INFO ASTQueryTranslatorFactory:24 - Using ASTQueryTranslatorFactory
16:14:00,633 INFO SettingsFactory:225 - Query language substitutions: {}
16:14:00,633 INFO SettingsFactory:230 - JPA-QL strict compliance: disabled
16:14:00,634 INFO SettingsFactory:235 - Second-level cache: enabled
16:14:00,634 INFO SettingsFactory:239 - Query cache: disabled
16:14:00,635 INFO SettingsFactory:373 - Cache provider: org.hibernate.cache.NoCacheProvider
16:14:00,635 INFO SettingsFactory:254 - Optimize cache for minimal puts: disabled
16:14:00,635 INFO SettingsFactory:263 - Structured second-level cache entries: disabled
16:14:00,636 DEBUG SQLExceptionConverterFactory:52 - Using dialect defined converter
16:14:00,639 INFO SettingsFactory:283 - Echoing all SQL to stdout
16:14:00,639 INFO SettingsFactory:290 - Statistics: disabled
16:14:00,640 INFO SettingsFactory:294 - Deleted entity synthetic identifier rollback: disabled
16:14:00,640 INFO SettingsFactory:309 - Default entity-mode: pojo
16:14:00,640 INFO SettingsFactory:313 - Named query checking : enabled
16:14:00,658 INFO SessionFactoryImpl:161 - building session factory
16:14:00,659 DEBUG SessionFactoryImpl:173 - Session factory constructed with filter configurations : {}
16:14:00,659 DEBUG SessionFactoryImpl:177 - instantiating session factory with properties: {java.runtime.name=Java(TM) SE Runtime Environment, hibernate.connection.password=4funcnetuse, sun.boot.library.path=/export/people/clegg/Java/jdk1.6.0_10/jre/lib/i386, java.vm.version=11.0-b15, hibernate.connection.username=funcnet, java.vm.vendor=Sun Microsystems Inc., java.vendor.url=http://java.sun.com/, path.separator=:, java.vm.name=Java HotSpot(TM) Server VM, file.encoding.pkg=sun.io, user.country=US, sun.java.launcher=SUN_STANDARD, sun.os.patch.level=unknown, java.vm.specification.name=Java Virtual Machine Specification, user.dir=/export/people/clegg/data/EmbraceWorkspace/EMBRACE/FuncNet/sessionDB, java.runtime.version=1.6.0_10-rc2-b32, java.awt.graphicsenv=sun.awt.X11GraphicsEnvironment, hibernate.current_session_context_class=thread, java.endorsed.dirs=/export/people/clegg/Java/jdk1.6.0_10/jre/lib/endorsed, os.arch=i386, java.io.tmpdir=/tmp, line.separator=
, java.vm.specification.vendor=Sun Microsystems Inc., os.name=Linux, sun.jnu.encoding=UTF-8, java.library.path=/export/people/clegg/Java/jdk1.6.0_10/jre/lib/i386/server:/export/people/clegg/Java/jdk1.6.0_10/jre/lib/i386:/export/people/clegg/Java/jdk1.6.0_10/jre/../lib/i386:/export/people/clegg/Java/java_ee_sdk-5_06/jdk/jre/lib/i386/client:/export/people/clegg/Java/java_ee_sdk-5_06/jdk/jre/lib/i386:/usr/lib/firefox-1.5.0.12:/usr/lib/firefox-1.5.0.12:/usr/java/packages/lib/i386:/lib:/usr/lib, java.specification.name=Java Platform API Specification, java.class.version=50.0, sun.management.compiler=HotSpot Tiered Compilers, hibernate.transaction.factory_class=org.hibernate.transaction.JDBCTransactionFactory, os.version=2.6.18-53.1.21.el5, user.home=/home/bsm/clegg, user.timezone=Europe/London, java.awt.printerjob=sun.print.PSPrinterJob, java.specification.version=1.6, file.encoding=UTF-8, hibernate.connection.driver_class=org.postgresql.Driver, user.name=clegg, java.class.path=/export/people/clegg/data/EmbraceWorkspace/EMBRACE/FuncNet/sessionDB/target/test-classes:/export/people/clegg/data/EmbraceWorkspace/EMBRACE/FuncNet/sessionDB/target/classes:/home/bsm/clegg/.m2/repository/antlr/antlr/2.7.6/antlr-2.7.6.jar:/home/bsm/clegg/.m2/repository/asm/asm/1.5.3/asm-1.5.3.jar:/home/bsm/clegg/.m2/repository/asm/asm-attrs/1.5.3/asm-attrs-1.5.3.jar:/home/bsm/clegg/.m2/repository/cglib/cglib/2.1_3/cglib-2.1_3.jar:/home/bsm/clegg/.m2/repository/commons-collections/commons-collections/2.1.1/commons-collections-2.1.1.jar:/home/bsm/clegg/.m2/repository/commons-logging/commons-logging/1.0.4/commons-logging-1.0.4.jar:/home/bsm/clegg/.m2/repository/dom4j/dom4j/1.6.1/dom4j-1.6.1.jar:/home/bsm/clegg/.m2/repository/net/sf/ehcache/ehcache/1.2.3/ehcache-1.2.3.jar:/home/bsm/clegg/.m2/repository/com/google/code/guice/guice/1.0/guice-1.0.jar:/home/bsm/clegg/.m2/repository/org/hibernate/hibernate/3.2.5.ga/hibernate-3.2.5.ga.jar:/home/bsm/clegg/.m2/repository/hsqldb/hsqldb/1.8.0.7/hsqldb-1.8.0.7.jar:/home/bsm/clegg/.m2/repository/javax/transaction/jta/1.1/jta-1.1.jar:/home/bsm/clegg/.m2/repository/junit/junit/4.5/junit-4.5.jar:/home/bsm/clegg/.m2/repository/log4j/log4j/1.2.14/log4j-1.2.14.jar:/home/bsm/clegg/.m2/repository/postgresql/postgresql/8.3-603.jdbc4/postgresql-8.3-603.jdbc4.jar:/home/bsm/clegg/.m2/repository/com/wideplay/warp/warp-persist/1.0.1/warp-persist-1.0.1.jar:/home/bsm/clegg/.m2/repository/postgresql/postgresql/8.3-604.jdbc4/postgresql-8.3-604.jdbc4.jar:/home/bsm/clegg/.m2/repository/aopalliance/aopalliance/1.0/aopalliance-1.0.jar:/export/people/clegg/sw/eclipse/configuration/org.eclipse.osgi/bundles/306/1/.cp/:/export/people/clegg/sw/eclipse/configuration/org.eclipse.osgi/bundles/304/1/.cp/:/export/people/clegg/sw/eclipse/configuration/org.eclipse.osgi/bundles/305/1/.cp/, hibernate.bytecode.use_reflection_optimizer=false, hibernate.show_sql=true, java.vm.specification.version=1.0, sun.arch.data.model=32, java.home=/export/people/clegg/Java/jdk1.6.0_10/jre, hibernate.connection.url=jdbc:postgresql://caffdubya/FuncNet, hibernate.dialect=org.hibernate.dialect.PostgreSQLDialect, java.specification.vendor=Sun Microsystems Inc., user.language=en, java.vm.info=mixed mode, java.version=1.6.0_10-rc2, java.ext.dirs=/export/people/clegg/Java/jdk1.6.0_10/jre/lib/ext:/usr/java/packages/lib/ext, sun.boot.class.path=/export/people/clegg/Java/jdk1.6.0_10/jre/lib/resources.jar:/export/people/clegg/Java/jdk1.6.0_10/jre/lib/rt.jar:/export/people/clegg/Java/jdk1.6.0_10/jre/lib/sunrsasign.jar:/export/people/clegg/Java/jdk1.6.0_10/jre/lib/jsse.jar:/export/people/clegg/Java/jdk1.6.0_10/jre/lib/jce.jar:/export/people/clegg/Java/jdk1.6.0_10/jre/lib/charsets.jar:/export/people/clegg/Java/jdk1.6.0_10/jre/classes, java.vendor=Sun Microsystems Inc., hibernate.jdbc.batch_size=50, file.separator=/, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, sun.cpu.endian=little, sun.io.unicode.encoding=UnicodeLittle, sun.desktop=gnome, sun.cpu.isalist=}
16:14:00,794 DEBUG AbstractEntityPersister:2738 - Static SQL for entity: info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession
16:14:00,794 DEBUG AbstractEntityPersister:2743 - Version select: select predictor_session_id from PredictorSession where predictor_session_id =?
16:14:00,794 DEBUG AbstractEntityPersister:2746 - Snapshot select: select predictors_.predictor_session_id, predictors_.predictorName as predicto2_1_, predictors_.status as status1_, predictors_.statusMessage as statusMe4_1_ from PredictorSession predictors_ where predictors_.predictor_session_id=?
16:14:00,795 DEBUG AbstractEntityPersister:2749 - Insert 0: insert into PredictorSession (predictorName, status, statusMessage, session_id, predictor_session_id) values (?, ?, ?, ?, ?)
16:14:00,795 DEBUG AbstractEntityPersister:2750 - Update 0: update PredictorSession set predictorName=?, status=?, statusMessage=? where predictor_session_id=?
16:14:00,795 DEBUG AbstractEntityPersister:2751 - Delete 0: delete from PredictorSession where predictor_session_id=?
16:14:00,812 DEBUG AbstractEntityPersister:2738 - Static SQL for entity: info.cathdb.funcnet_0_1.sessiondb.model.Client
16:14:00,812 DEBUG AbstractEntityPersister:2743 - Version select: select client_id from Client where client_id =?
16:14:00,813 DEBUG AbstractEntityPersister:2746 - Snapshot select: select client_.client_id, client_.emailAddress as emailAdd2_3_, client_.inetAddress as inetAddr3_3_ from Client client_ where client_.client_id=?
16:14:00,813 DEBUG AbstractEntityPersister:2749 - Insert 0: insert into Client (emailAddress, inetAddress, client_id) values (?, ?, ?)
16:14:00,813 DEBUG AbstractEntityPersister:2750 - Update 0: update Client set emailAddress=?, inetAddress=? where client_id=?
16:14:00,814 DEBUG AbstractEntityPersister:2751 - Delete 0: delete from Client where client_id=?
16:14:00,822 DEBUG AbstractEntityPersister:2738 - Static SQL for entity: info.cathdb.funcnet_0_1.sessiondb.model.Prediction
16:14:00,823 DEBUG AbstractEntityPersister:2743 - Version select: select prediction_id from Prediction where prediction_id =?
16:14:00,823 DEBUG AbstractEntityPersister:2746 - Snapshot select: select prediction_.prediction_id, prediction_.predictorSession as predicto2_2_, prediction_.protein1 as protein3_2_, prediction_.protein2 as protein4_2_, prediction_.rawScore as rawScore2_, prediction_.pValue as pValue2_ from Prediction prediction_ where prediction_.prediction_id=?
16:14:00,823 DEBUG AbstractEntityPersister:2749 - Insert 0: insert into Prediction (predictorSession, protein1, protein2, rawScore, pValue, predictor_session_id, prediction_id) values (?, ?, ?, ?, ?, ?, ?)
16:14:00,824 DEBUG AbstractEntityPersister:2750 - Update 0: update Prediction set predictorSession=?, protein1=?, protein2=?, rawScore=?, pValue=? where prediction_id=?
16:14:00,824 DEBUG AbstractEntityPersister:2751 - Delete 0: delete from Prediction where prediction_id=?
16:14:00,833 DEBUG AbstractEntityPersister:2738 - Static SQL for entity: info.cathdb.funcnet_0_1.sessiondb.model.Session
16:14:00,833 DEBUG AbstractEntityPersister:2743 - Version select: select session_id from Session where session_id =?
16:14:00,833 DEBUG AbstractEntityPersister:2746 - Snapshot select: select session_.session_id, session_.funcnetJobID as funcnetJ2_0_, session_.startTime as startTime0_, session_.status as status0_, session_.client_id as client5_0_, session_.statusMessage as statusMe6_0_, session_.comments as comments0_, session_.enableEmailNotify as enableEm8_0_ from Session session_ where session_.session_id=?
16:14:00,834 DEBUG AbstractEntityPersister:2749 - Insert 0: insert into Session (funcnetJobID, startTime, status, client_id, statusMessage, comments, enableEmailNotify, session_id) values (?, ?, ?, ?, ?, ?, ?, ?)
16:14:00,834 DEBUG AbstractEntityPersister:2750 - Update 0: update Session set funcnetJobID=?, startTime=?, status=?, client_id=?, statusMessage=?, comments=?, enableEmailNotify=? where session_id=?
16:14:00,834 DEBUG AbstractEntityPersister:2751 - Delete 0: delete from Session where session_id=?
16:14:00,840 DEBUG AbstractCollectionPersister:548 - Static SQL for collection: info.cathdb.funcnet_0_1.sessiondb.model.Session.predictors
16:14:00,840 DEBUG AbstractCollectionPersister:550 - Row insert: update PredictorSession set session_id=? where predictor_session_id=?
16:14:00,841 DEBUG AbstractCollectionPersister:556 - Row delete: update PredictorSession set session_id=null where session_id=? and predictor_session_id=?
16:14:00,841 DEBUG AbstractCollectionPersister:559 - One-shot delete: update PredictorSession set session_id=null where session_id=?
16:14:00,842 DEBUG AbstractCollectionPersister:548 - Static SQL for collection: info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession.predictions
16:14:00,842 DEBUG AbstractCollectionPersister:550 - Row insert: update Prediction set predictor_session_id=? where prediction_id=?
16:14:00,842 DEBUG AbstractCollectionPersister:556 - Row delete: update Prediction set predictor_session_id=null where predictor_session_id=? and prediction_id=?
16:14:00,843 DEBUG AbstractCollectionPersister:559 - One-shot delete: update Prediction set predictor_session_id=null where predictor_session_id=?
16:14:00,857 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession: select predictors0_.predictor_session_id as predictor1_1_0_, predictors0_.predictorName as predicto2_1_0_, predictors0_.status as status1_0_, predictors0_.statusMessage as statusMe4_1_0_ from PredictorSession predictors0_ where predictors0_.predictor_session_id=?
16:14:00,857 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession: select predictors0_.predictor_session_id as predictor1_1_0_, predictors0_.predictorName as predicto2_1_0_, predictors0_.status as status1_0_, predictors0_.statusMessage as statusMe4_1_0_ from PredictorSession predictors0_ where predictors0_.predictor_session_id=?
16:14:00,858 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession: select predictors0_.predictor_session_id as predictor1_1_0_, predictors0_.predictorName as predicto2_1_0_, predictors0_.status as status1_0_, predictors0_.statusMessage as statusMe4_1_0_ from PredictorSession predictors0_ where predictors0_.predictor_session_id=? for update
16:14:00,858 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession: select predictors0_.predictor_session_id as predictor1_1_0_, predictors0_.predictorName as predicto2_1_0_, predictors0_.status as status1_0_, predictors0_.statusMessage as statusMe4_1_0_ from PredictorSession predictors0_ where predictors0_.predictor_session_id=? for update
16:14:00,859 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession: select predictors0_.predictor_session_id as predictor1_1_0_, predictors0_.predictorName as predicto2_1_0_, predictors0_.status as status1_0_, predictors0_.statusMessage as statusMe4_1_0_ from PredictorSession predictors0_ where predictors0_.predictor_session_id=? for update
16:14:00,866 DEBUG EntityLoader:34 - Static select for action ACTION_MERGE on entity info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession: select predictors0_.predictor_session_id as predictor1_1_1_, predictors0_.predictorName as predicto2_1_1_, predictors0_.status as status1_1_, predictors0_.statusMessage as statusMe4_1_1_, prediction1_.predictor_session_id as predictor7_3_, prediction1_.prediction_id as prediction1_3_, prediction1_.prediction_id as prediction1_2_0_, prediction1_.predictorSession as predicto2_2_0_, prediction1_.protein1 as protein3_2_0_, prediction1_.protein2 as protein4_2_0_, prediction1_.rawScore as rawScore2_0_, prediction1_.pValue as pValue2_0_ from PredictorSession predictors0_ left outer join Prediction prediction1_ on predictors0_.predictor_session_id=prediction1_.predictor_session_id where predictors0_.predictor_session_id=?
16:14:00,867 DEBUG EntityLoader:34 - Static select for action ACTION_REFRESH on entity info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession: select predictors0_.predictor_session_id as predictor1_1_1_, predictors0_.predictorName as predicto2_1_1_, predictors0_.status as status1_1_, predictors0_.statusMessage as statusMe4_1_1_, prediction1_.predictor_session_id as predictor7_3_, prediction1_.prediction_id as prediction1_3_, prediction1_.prediction_id as prediction1_2_0_, prediction1_.predictorSession as predicto2_2_0_, prediction1_.protein1 as protein3_2_0_, prediction1_.protein2 as protein4_2_0_, prediction1_.rawScore as rawScore2_0_, prediction1_.pValue as pValue2_0_ from PredictorSession predictors0_ left outer join Prediction prediction1_ on predictors0_.predictor_session_id=prediction1_.predictor_session_id where predictors0_.predictor_session_id=?
16:14:00,868 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.Client: select client0_.client_id as client1_3_0_, client0_.emailAddress as emailAdd2_3_0_, client0_.inetAddress as inetAddr3_3_0_ from Client client0_ where client0_.client_id=?
16:14:00,868 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.Client: select client0_.client_id as client1_3_0_, client0_.emailAddress as emailAdd2_3_0_, client0_.inetAddress as inetAddr3_3_0_ from Client client0_ where client0_.client_id=?
16:14:00,869 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.Client: select client0_.client_id as client1_3_0_, client0_.emailAddress as emailAdd2_3_0_, client0_.inetAddress as inetAddr3_3_0_ from Client client0_ where client0_.client_id=? for update
16:14:00,869 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.Client: select client0_.client_id as client1_3_0_, client0_.emailAddress as emailAdd2_3_0_, client0_.inetAddress as inetAddr3_3_0_ from Client client0_ where client0_.client_id=? for update
16:14:00,869 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.Client: select client0_.client_id as client1_3_0_, client0_.emailAddress as emailAdd2_3_0_, client0_.inetAddress as inetAddr3_3_0_ from Client client0_ where client0_.client_id=? for update
16:14:00,870 DEBUG EntityLoader:34 - Static select for action ACTION_MERGE on entity info.cathdb.funcnet_0_1.sessiondb.model.Client: select client0_.client_id as client1_3_0_, client0_.emailAddress as emailAdd2_3_0_, client0_.inetAddress as inetAddr3_3_0_ from Client client0_ where client0_.client_id=?
16:14:00,870 DEBUG EntityLoader:34 - Static select for action ACTION_REFRESH on entity info.cathdb.funcnet_0_1.sessiondb.model.Client: select client0_.client_id as client1_3_0_, client0_.emailAddress as emailAdd2_3_0_, client0_.inetAddress as inetAddr3_3_0_ from Client client0_ where client0_.client_id=?
16:14:00,871 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.Prediction: select prediction0_.prediction_id as prediction1_2_0_, prediction0_.predictorSession as predicto2_2_0_, prediction0_.protein1 as protein3_2_0_, prediction0_.protein2 as protein4_2_0_, prediction0_.rawScore as rawScore2_0_, prediction0_.pValue as pValue2_0_ from Prediction prediction0_ where prediction0_.prediction_id=?
16:14:00,871 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.Prediction: select prediction0_.prediction_id as prediction1_2_0_, prediction0_.predictorSession as predicto2_2_0_, prediction0_.protein1 as protein3_2_0_, prediction0_.protein2 as protein4_2_0_, prediction0_.rawScore as rawScore2_0_, prediction0_.pValue as pValue2_0_ from Prediction prediction0_ where prediction0_.prediction_id=?
16:14:00,872 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.Prediction: select prediction0_.prediction_id as prediction1_2_0_, prediction0_.predictorSession as predicto2_2_0_, prediction0_.protein1 as protein3_2_0_, prediction0_.protein2 as protein4_2_0_, prediction0_.rawScore as rawScore2_0_, prediction0_.pValue as pValue2_0_ from Prediction prediction0_ where prediction0_.prediction_id=? for update
16:14:00,872 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.Prediction: select prediction0_.prediction_id as prediction1_2_0_, prediction0_.predictorSession as predicto2_2_0_, prediction0_.protein1 as protein3_2_0_, prediction0_.protein2 as protein4_2_0_, prediction0_.rawScore as rawScore2_0_, prediction0_.pValue as pValue2_0_ from Prediction prediction0_ where prediction0_.prediction_id=? for update
16:14:00,873 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.Prediction: select prediction0_.prediction_id as prediction1_2_0_, prediction0_.predictorSession as predicto2_2_0_, prediction0_.protein1 as protein3_2_0_, prediction0_.protein2 as protein4_2_0_, prediction0_.rawScore as rawScore2_0_, prediction0_.pValue as pValue2_0_ from Prediction prediction0_ where prediction0_.prediction_id=? for update
16:14:00,873 DEBUG EntityLoader:34 - Static select for action ACTION_MERGE on entity info.cathdb.funcnet_0_1.sessiondb.model.Prediction: select prediction0_.prediction_id as prediction1_2_0_, prediction0_.predictorSession as predicto2_2_0_, prediction0_.protein1 as protein3_2_0_, prediction0_.protein2 as protein4_2_0_, prediction0_.rawScore as rawScore2_0_, prediction0_.pValue as pValue2_0_ from Prediction prediction0_ where prediction0_.prediction_id=?
16:14:00,874 DEBUG EntityLoader:34 - Static select for action ACTION_REFRESH on entity info.cathdb.funcnet_0_1.sessiondb.model.Prediction: select prediction0_.prediction_id as prediction1_2_0_, prediction0_.predictorSession as predicto2_2_0_, prediction0_.protein1 as protein3_2_0_, prediction0_.protein2 as protein4_2_0_, prediction0_.rawScore as rawScore2_0_, prediction0_.pValue as pValue2_0_ from Prediction prediction0_ where prediction0_.prediction_id=?
16:14:00,874 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.Session: select session0_.session_id as session1_0_0_, session0_.funcnetJobID as funcnetJ2_0_0_, session0_.startTime as startTime0_0_, session0_.status as status0_0_, session0_.client_id as client5_0_0_, session0_.statusMessage as statusMe6_0_0_, session0_.comments as comments0_0_, session0_.enableEmailNotify as enableEm8_0_0_ from Session session0_ where session0_.session_id=?
16:14:00,875 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.Session: select session0_.session_id as session1_0_0_, session0_.funcnetJobID as funcnetJ2_0_0_, session0_.startTime as startTime0_0_, session0_.status as status0_0_, session0_.client_id as client5_0_0_, session0_.statusMessage as statusMe6_0_0_, session0_.comments as comments0_0_, session0_.enableEmailNotify as enableEm8_0_0_ from Session session0_ where session0_.session_id=?
16:14:00,875 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.Session: select session0_.session_id as session1_0_0_, session0_.funcnetJobID as funcnetJ2_0_0_, session0_.startTime as startTime0_0_, session0_.status as status0_0_, session0_.client_id as client5_0_0_, session0_.statusMessage as statusMe6_0_0_, session0_.comments as comments0_0_, session0_.enableEmailNotify as enableEm8_0_0_ from Session session0_ where session0_.session_id=? for update
16:14:00,876 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.Session: select session0_.session_id as session1_0_0_, session0_.funcnetJobID as funcnetJ2_0_0_, session0_.startTime as startTime0_0_, session0_.status as status0_0_, session0_.client_id as client5_0_0_, session0_.statusMessage as statusMe6_0_0_, session0_.comments as comments0_0_, session0_.enableEmailNotify as enableEm8_0_0_ from Session session0_ where session0_.session_id=? for update
16:14:00,876 DEBUG EntityLoader:79 - Static select for entity info.cathdb.funcnet_0_1.sessiondb.model.Session: select session0_.session_id as session1_0_0_, session0_.funcnetJobID as funcnetJ2_0_0_, session0_.startTime as startTime0_0_, session0_.status as status0_0_, session0_.client_id as client5_0_0_, session0_.statusMessage as statusMe6_0_0_, session0_.comments as comments0_0_, session0_.enableEmailNotify as enableEm8_0_0_ from Session session0_ where session0_.session_id=? for update
16:14:00,877 DEBUG EntityLoader:34 - Static select for action ACTION_MERGE on entity info.cathdb.funcnet_0_1.sessiondb.model.Session: select session0_.session_id as session1_0_1_, session0_.funcnetJobID as funcnetJ2_0_1_, session0_.startTime as startTime0_1_, session0_.status as status0_1_, session0_.client_id as client5_0_1_, session0_.statusMessage as statusMe6_0_1_, session0_.comments as comments0_1_, session0_.enableEmailNotify as enableEm8_0_1_, predictors1_.session_id as session5_3_, predictors1_.predictor_session_id as predictor1_3_, predictors1_.predictor_session_id as predictor1_1_0_, predictors1_.predictorName as predicto2_1_0_, predictors1_.status as status1_0_, predictors1_.statusMessage as statusMe4_1_0_ from Session session0_ left outer join PredictorSession predictors1_ on session0_.session_id=predictors1_.session_id where session0_.session_id=?
16:14:00,877 DEBUG EntityLoader:34 - Static select for action ACTION_REFRESH on entity info.cathdb.funcnet_0_1.sessiondb.model.Session: select session0_.session_id as session1_0_1_, session0_.funcnetJobID as funcnetJ2_0_1_, session0_.startTime as startTime0_1_, session0_.status as status0_1_, session0_.client_id as client5_0_1_, session0_.statusMessage as statusMe6_0_1_, session0_.comments as comments0_1_, session0_.enableEmailNotify as enableEm8_0_1_, predictors1_.session_id as session5_3_, predictors1_.predictor_session_id as predictor1_3_, predictors1_.predictor_session_id as predictor1_1_0_, predictors1_.predictorName as predicto2_1_0_, predictors1_.status as status1_0_, predictors1_.statusMessage as statusMe4_1_0_ from Session session0_ left outer join PredictorSession predictors1_ on session0_.session_id=predictors1_.session_id where session0_.session_id=?
16:14:00,883 DEBUG OneToManyLoader:64 - Static select for one-to-many info.cathdb.funcnet_0_1.sessiondb.model.Session.predictors: select predictors0_.session_id as session5_1_, predictors0_.predictor_session_id as predictor1_1_, predictors0_.predictor_session_id as predictor1_1_0_, predictors0_.predictorName as predicto2_1_0_, predictors0_.status as status1_0_, predictors0_.statusMessage as statusMe4_1_0_ from PredictorSession predictors0_ where predictors0_.session_id=?
16:14:00,884 DEBUG OneToManyLoader:64 - Static select for one-to-many info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession.predictions: select prediction0_.predictor_session_id as predictor7_1_, prediction0_.prediction_id as prediction1_1_, prediction0_.prediction_id as prediction1_2_0_, prediction0_.predictorSession as predicto2_2_0_, prediction0_.protein1 as protein3_2_0_, prediction0_.protein2 as protein4_2_0_, prediction0_.rawScore as rawScore2_0_, prediction0_.pValue as pValue2_0_ from Prediction prediction0_ where prediction0_.predictor_session_id=?
16:14:00,885 DEBUG SessionFactoryObjectFactory:39 - initializing class SessionFactoryObjectFactory
16:14:00,887 DEBUG SessionFactoryObjectFactory:76 - registered: ff8080811e3b6ceb011e3b6cecb40000 (unnamed)
16:14:00,887 INFO SessionFactoryObjectFactory:82 - Not binding factory to JNDI, no JNDI name configured
16:14:00,888 DEBUG SessionFactoryImpl:308 - instantiated session factory
16:14:00,890 DEBUG SessionFactoryImpl:392 - Checking 1 named HQL queries
16:14:00,891 DEBUG SessionFactoryImpl:400 - Checking named query: info.cathdb.funcnet_0_1.sessiondb.model.Session.info.cathdb.funcnet_0_1.sessiondb.model.pairwiseScores
16:14:00,892 DEBUG QueryPlanCache:70 - unable to locate HQL query plan in cache; generating (

select prediction.protein1,
prediction.protein2,
-2 * sum( log( prediction.pValue ) )
from info.cathdb.funcnet_0_1.sessiondb.model.Session session
inner join session.predictors predictorSession
inner join predictorSession.predictions prediction
where session.funcnetJobID = :jobID
group by prediction.protein1,
prediction.protein2

)
16:14:00,928 DEBUG QueryTranslatorImpl:246 - parse() - HQL:

select prediction.protein1,
prediction.protein2,
-2 * sum( log( prediction.pValue ) )
from info.cathdb.funcnet_0_1.sessiondb.model.Session session
inner join session.predictors predictorSession
inner join predictorSession.predictions prediction
where session.funcnetJobID = :jobID
group by prediction.protein1,
prediction.protein2


16:14:00,944 DEBUG AST:266 - --- HQL AST ---
\-[QUERY] 'query'
+-[SELECT_FROM] 'SELECT_FROM'
| +-[FROM] 'from'
| | +-[RANGE] 'RANGE'
| | | +-[DOT] '.'
| | | | +-[DOT] '.'
| | | | | +-[DOT] '.'
| | | | | | +-[DOT] '.'
| | | | | | | +-[DOT] '.'
| | | | | | | | +-[IDENT] 'info'
| | | | | | | | \-[IDENT] 'cathdb'
| | | | | | | \-[IDENT] 'funcnet_0_1'
| | | | | | \-[IDENT] 'sessiondb'
| | | | | \-[IDENT] 'model'
| | | | \-[IDENT] 'Session'
| | | \-[ALIAS] 'session'
| | +-[JOIN] 'join'
| | | +-[INNER] 'inner'
| | | +-[DOT] '.'
| | | | +-[IDENT] 'session'
| | | | \-[IDENT] 'predictors'
| | | \-[ALIAS] 'predictorSession'
| | \-[JOIN] 'join'
| | +-[INNER] 'inner'
| | +-[DOT] '.'
| | | +-[IDENT] 'predictorSession'
| | | \-[IDENT] 'predictions'
| | \-[ALIAS] 'prediction'
| \-[SELECT] 'select'
| +-[DOT] '.'
| | +-[IDENT] 'prediction'
| | \-[IDENT] 'protein1'
| +-[DOT] '.'
| | +-[IDENT] 'prediction'
| | \-[IDENT] 'protein2'
| \-[STAR] '*'
| +-[UNARY_MINUS] '-'
| | \-[NUM_INT] '2'
| \-[AGGREGATE] 'sum'
| \-[METHOD_CALL] '('
| +-[IDENT] 'log'
| \-[EXPR_LIST] 'exprList'
| \-[DOT] '.'
| +-[IDENT] 'prediction'
| \-[IDENT] 'pValue'
+-[WHERE] 'where'
| \-[EQ] '='
| +-[DOT] '.'
| | +-[IDENT] 'session'
| | \-[IDENT] 'funcnetJobID'
| \-[COLON] ':'
| \-[IDENT] 'jobID'
\-[GROUP] 'group'
+-[DOT] '.'
| +-[IDENT] 'prediction'
| \-[IDENT] 'protein1'
\-[DOT] '.'
+-[IDENT] 'prediction'
\-[IDENT] 'protein2'

16:14:00,944 DEBUG ErrorCounter:68 - throwQueryException() : no errors
16:14:00,971 DEBUG HqlSqlBaseWalker:111 - select << begin [level=1, statement=select]
16:14:00,982 DEBUG FromElement:108 - FromClause{level=1} : info.cathdb.funcnet_0_1.sessiondb.model.Session (session) -> session0_
16:14:00,984 DEBUG FromReferenceNode:51 - Resolved : session -> session0_.session_id
16:14:00,985 DEBUG FromElement:525 - handling property dereference [info.cathdb.funcnet_0_1.sessiondb.model.Session (session) -> predictors (class)]
16:14:00,985 DEBUG DotNode:568 - getDataType() : predictors -> org.hibernate.type.SetType(info.cathdb.funcnet_0_1.sessiondb.model.Session.predictors)
16:14:00,986 DEBUG FromElementFactory:360 - createEntityAssociation() : One to many - path = session.predictors role = info.cathdb.funcnet_0_1.sessiondb.model.Session.predictors associatedEntityName = info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession
16:14:00,988 DEBUG FromElement:108 - FromClause{level=1} : info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession (predictorSession) -> predictors1_
16:14:00,988 DEBUG FromClause:233 - addJoinByPathMap() : session.predictors -> PredictorSession predictors1_
16:14:00,988 DEBUG DotNode:284 - dereferenceCollection() : Created new FROM element for session.predictors : PredictorSession predictors1_
16:14:00,989 DEBUG FromReferenceNode:51 - Resolved : session.predictors -> .
16:14:00,990 DEBUG HqlSqlWalker:320 - createFromJoinElement() : -- join tree --
\-[JOIN_FRAGMENT] FromElement: 'PredictorSession predictors1_' FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=predictorSession,role=info.cathdb.funcnet_0_1.sessiondb.model.Session.predictors,tableName=PredictorSession,tableAlias=predictors1_,origin=Session session0_,colums={session0_.session_id ,className=info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession}}

16:14:00,991 DEBUG FromReferenceNode:51 - Resolved : predictorSession -> predictors1_.predictor_session_id
16:14:00,991 DEBUG FromElement:525 - handling property dereference [info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession (predictorSession) -> predictions (class)]
16:14:00,991 DEBUG DotNode:568 - getDataType() : predictions -> org.hibernate.type.SetType(info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession.predictions)
16:14:00,992 DEBUG FromElementFactory:360 - createEntityAssociation() : One to many - path = predictorSession.predictions role = info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession.predictions associatedEntityName = info.cathdb.funcnet_0_1.sessiondb.model.Prediction
16:14:00,992 DEBUG FromElement:108 - FromClause{level=1} : info.cathdb.funcnet_0_1.sessiondb.model.Prediction (prediction) -> prediction2_
16:14:00,992 DEBUG FromClause:233 - addJoinByPathMap() : predictorSession.predictions -> Prediction prediction2_
16:14:00,992 DEBUG DotNode:284 - dereferenceCollection() : Created new FROM element for predictorSession.predictions : Prediction prediction2_
16:14:00,993 DEBUG FromReferenceNode:51 - Resolved : predictorSession.predictions -> .
16:14:00,993 DEBUG HqlSqlWalker:320 - createFromJoinElement() : -- join tree --
\-[JOIN_FRAGMENT] FromElement: 'Prediction prediction2_' FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=prediction,role=info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession.predictions,tableName=Prediction,tableAlias=prediction2_,origin=PredictorSession predictors1_,colums={predictors1_.predictor_session_id ,className=info.cathdb.funcnet_0_1.sessiondb.model.Prediction}}

16:14:00,994 DEBUG FromReferenceNode:51 - Resolved : prediction -> prediction2_.prediction_id
16:14:00,994 DEBUG FromElement:525 - handling property dereference [info.cathdb.funcnet_0_1.sessiondb.model.Prediction (prediction) -> protein1 (class)]
16:14:00,994 DEBUG DotNode:568 - getDataType() : protein1 -> org.hibernate.type.StringType@1de0b5e
16:14:00,995 DEBUG FromReferenceNode:51 - Resolved : prediction.protein1 -> prediction2_.protein1
16:14:00,995 DEBUG FromElement:525 - handling property dereference [info.cathdb.funcnet_0_1.sessiondb.model.Prediction (prediction) -> protein1 (class)]
16:14:00,995 DEBUG FromReferenceNode:51 - Resolved : prediction -> prediction2_.prediction_id
16:14:00,996 DEBUG FromElement:525 - handling property dereference [info.cathdb.funcnet_0_1.sessiondb.model.Prediction (prediction) -> protein2 (class)]
16:14:00,996 DEBUG DotNode:568 - getDataType() : protein2 -> org.hibernate.type.StringType@1de0b5e
16:14:00,996 DEBUG FromReferenceNode:51 - Resolved : prediction.protein2 -> prediction2_.protein2
16:14:00,996 DEBUG FromElement:525 - handling property dereference [info.cathdb.funcnet_0_1.sessiondb.model.Prediction (prediction) -> protein2 (class)]
16:14:01,005 DEBUG FromReferenceNode:51 - Resolved : prediction -> prediction2_.prediction_id
16:14:01,005 DEBUG FromElement:525 - handling property dereference [info.cathdb.funcnet_0_1.sessiondb.model.Prediction (prediction) -> pValue (class)]
16:14:01,007 DEBUG DotNode:568 - getDataType() : pValue -> org.hibernate.type.DoubleType@96212a
16:14:01,007 DEBUG FromElement:525 - handling property dereference [info.cathdb.funcnet_0_1.sessiondb.model.Prediction (prediction) -> pValue (class)]
16:14:01,007 DEBUG FromReferenceNode:51 - Resolved : prediction.pValue -> prediction2_.pValue
16:14:01,012 DEBUG FromReferenceNode:51 - Resolved : session -> session0_.session_id
16:14:01,013 DEBUG FromElement:525 - handling property dereference [info.cathdb.funcnet_0_1.sessiondb.model.Session (session) -> funcnetJobID (class)]
16:14:01,013 DEBUG DotNode:568 - getDataType() : funcnetJobID -> org.hibernate.type.StringType@1de0b5e
16:14:01,013 DEBUG FromReferenceNode:51 - Resolved : session.funcnetJobID -> session0_.funcnetJobID
16:14:01,014 DEBUG FromReferenceNode:51 - Resolved : prediction -> prediction2_.prediction_id
16:14:01,015 DEBUG FromElement:525 - handling property dereference [info.cathdb.funcnet_0_1.sessiondb.model.Prediction (prediction) -> protein1 (class)]
16:14:01,015 DEBUG DotNode:568 - getDataType() : protein1 -> org.hibernate.type.StringType@1de0b5e
16:14:01,015 DEBUG FromReferenceNode:51 - Resolved : prediction.protein1 -> prediction2_.protein1
16:14:01,016 DEBUG FromReferenceNode:51 - Resolved : prediction -> prediction2_.prediction_id
16:14:01,016 DEBUG FromElement:525 - handling property dereference [info.cathdb.funcnet_0_1.sessiondb.model.Prediction (prediction) -> protein2 (class)]
16:14:01,016 DEBUG DotNode:568 - getDataType() : protein2 -> org.hibernate.type.StringType@1de0b5e
16:14:01,016 DEBUG FromReferenceNode:51 - Resolved : prediction.protein2 -> prediction2_.protein2
16:14:01,017 DEBUG HqlSqlBaseWalker:117 - select : finishing up [level=1, statement=select]
16:14:01,017 DEBUG HqlSqlWalker:509 - processQuery() : ( SELECT ( {select clause} ( prediction2_.protein1 prediction2_.prediction_id protein1 ) ( prediction2_.protein2 prediction2_.prediction_id protein2 ) ( * ( - 2 ) ( sum ( ( log ( exprList ( prediction2_.pValue prediction2_.prediction_id pValue ) ) ) ) ) ) ( FromClause{level=1} ( Session session0_ ( PredictorSession predictors1_ Prediction prediction2_ ) ) ) ( where ( = ( session0_.funcnetJobID session0_.session_id funcnetJobID ) ? ) ) ( group ( prediction2_.protein1 prediction2_.prediction_id protein1 ) ( prediction2_.protein2 prediction2_.prediction_id protein2 ) ) )
16:14:01,023 DEBUG JoinProcessor:148 - Using FROM fragment [Session session0_]
16:14:01,023 DEBUG JoinProcessor:148 - Using FROM fragment [inner join PredictorSession predictors1_ on session0_.session_id=predictors1_.session_id]
16:14:01,023 DEBUG JoinProcessor:148 - Using FROM fragment [inner join Prediction prediction2_ on predictors1_.predictor_session_id=prediction2_.predictor_session_id]
16:14:01,023 DEBUG HqlSqlBaseWalker:123 - select >> end [level=1, statement=select]
16:14:01,025 DEBUG AST:232 - --- SQL AST ---
\-[SELECT] QueryNode: 'SELECT' querySpaces (Prediction,PredictorSession,Session)
+-[SELECT_CLAUSE] SelectClause: '{select clause}'
| +-[DOT] DotNode: 'prediction2_.protein1' {propertyName=protein1,dereferenceType=4,propertyPath=protein1,path=prediction.protein1,tableAlias=prediction2_,className=info.cathdb.funcnet_0_1.sessiondb.model.Prediction,classAlias=prediction}
| | +-[ALIAS_REF] IdentNode: 'prediction2_.prediction_id' {alias=prediction, className=info.cathdb.funcnet_0_1.sessiondb.model.Prediction, tableAlias=prediction2_}
| | \-[IDENT] IdentNode: 'protein1' {originalText=protein1}
| +-[SELECT_COLUMNS] SqlNode: ' as col_0_0_'
| +-[DOT] DotNode: 'prediction2_.protein2' {propertyName=protein2,dereferenceType=4,propertyPath=protein2,path=prediction.protein2,tableAlias=prediction2_,className=info.cathdb.funcnet_0_1.sessiondb.model.Prediction,classAlias=prediction}
| | +-[ALIAS_REF] IdentNode: 'prediction2_.prediction_id' {alias=prediction, className=info.cathdb.funcnet_0_1.sessiondb.model.Prediction, tableAlias=prediction2_}
| | \-[IDENT] IdentNode: 'protein2' {originalText=protein2}
| +-[SELECT_COLUMNS] SqlNode: ' as col_1_0_'
| +-[STAR] BinaryArithmeticOperatorNode: '*' {dataType=org.hibernate.type.DoubleType@96212a}
| | +-[UNARY_MINUS] UnaryArithmeticNode: '-'
| | | \-[NUM_INT] LiteralNode: '2'
| | \-[AGGREGATE] AggregateNode: 'sum'
| | \-[METHOD_CALL] MethodNode: '('
| | +-[METHOD_NAME] IdentNode: 'log' {originalText=log}
| | \-[EXPR_LIST] SqlNode: 'exprList'
| | \-[DOT] DotNode: 'prediction2_.pValue' {propertyName=pValue,dereferenceType=4,propertyPath=pValue,path=prediction.pValue,tableAlias=prediction2_,className=info.cathdb.funcnet_0_1.sessiondb.model.Prediction,classAlias=prediction}
| | +-[ALIAS_REF] IdentNode: 'prediction2_.prediction_id' {alias=prediction, className=info.cathdb.funcnet_0_1.sessiondb.model.Prediction, tableAlias=prediction2_}
| | \-[IDENT] IdentNode: 'pValue' {originalText=pValue}
| \-[SELECT_COLUMNS] SqlNode: ' as col_2_0_'
+-[FROM] FromClause: 'from' FromClause{level=1, fromElementCounter=3, fromElements=3, fromElementByClassAlias=[predictorSession, session, prediction], fromElementByTableAlias=[prediction2_, predictors1_, session0_], fromElementsByPath=[session.predictors, predictorSession.predictions], collectionJoinFromElementsByPath=[], impliedElements=[]}
| \-[FROM_FRAGMENT] FromElement: 'Session session0_' FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=session,role=null,tableName=Session,tableAlias=session0_,origin=null,colums={,className=info.cathdb.funcnet_0_1.sessiondb.model.Session}}
| \-[JOIN_FRAGMENT] FromElement: 'inner join PredictorSession predictors1_ on session0_.session_id=predictors1_.session_id' FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=predictorSession,role=info.cathdb.funcnet_0_1.sessiondb.model.Session.predictors,tableName=PredictorSession,tableAlias=predictors1_,origin=Session session0_,colums={session0_.session_id ,className=info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession}}
| \-[JOIN_FRAGMENT] FromElement: 'inner join Prediction prediction2_ on predictors1_.predictor_session_id=prediction2_.predictor_session_id' FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=prediction,role=info.cathdb.funcnet_0_1.sessiondb.model.PredictorSession.predictions,tableName=Prediction,tableAlias=prediction2_,origin=inner join PredictorSession predictors1_ on session0_.session_id=predictors1_.session_id,colums={predictors1_.predictor_session_id ,className=info.cathdb.funcnet_0_1.sessiondb.model.Prediction}}
+-[WHERE] SqlNode: 'where'
| \-[EQ] BinaryLogicOperatorNode: '='
| +-[DOT] DotNode: 'session0_.funcnetJobID' {propertyName=funcnetJobID,dereferenceType=4,propertyPath=funcnetJobID,path=session.funcnetJobID,tableAlias=session0_,className=info.cathdb.funcnet_0_1.sessiondb.model.Session,classAlias=session}
| | +-[ALIAS_REF] IdentNode: 'session0_.session_id' {alias=session, className=info.cathdb.funcnet_0_1.sessiondb.model.Session, tableAlias=session0_}
| | \-[IDENT] IdentNode: 'funcnetJobID' {originalText=funcnetJobID}
| \-[NAMED_PARAM] ParameterNode: '?' {name=jobID, expectedType=org.hibernate.type.StringType@1de0b5e}
\-[GROUP] SqlNode: 'group'
+-[DOT] DotNode: 'prediction2_.protein1' {propertyName=protein1,dereferenceType=4,propertyPath=protein1,path=prediction.protein1,tableAlias=prediction2_,className=info.cathdb.funcnet_0_1.sessiondb.model.Prediction,classAlias=prediction}
| +-[ALIAS_REF] IdentNode: 'prediction2_.prediction_id' {alias=prediction, className=info.cathdb.funcnet_0_1.sessiondb.model.Prediction, tableAlias=prediction2_}
| \-[IDENT] IdentNode: 'protein1' {originalText=protein1}
\-[DOT] DotNode: 'prediction2_.protein2' {propertyName=protein2,dereferenceType=4,propertyPath=protein2,path=prediction.protein2,tableAlias=prediction2_,className=info.cathdb.funcnet_0_1.sessiondb.model.Prediction,classAlias=prediction}
+-[ALIAS_REF] IdentNode: 'prediction2_.prediction_id' {alias=prediction, className=info.cathdb.funcnet_0_1.sessiondb.model.Prediction, tableAlias=prediction2_}
\-[IDENT] IdentNode: 'protein2' {originalText=protein2}

16:14:01,026 DEBUG ErrorCounter:68 - throwQueryException() : no errors
16:14:01,034 DEBUG QueryTranslatorImpl:216 - HQL:

select prediction.protein1,
prediction.protein2,
-2 * sum( log( prediction.pValue ) )
from info.cathdb.funcnet_0_1.sessiondb.model.Session session
inner join session.predictors predictorSession
inner join predictorSession.predictions prediction
where session.funcnetJobID = :jobID
group by prediction.protein1,
prediction.protein2


16:14:01,034 DEBUG QueryTranslatorImpl:217 - SQL: select prediction2_.protein1 as col_0_0_, prediction2_.protein2 as col_1_0_, -2*sum(log(prediction2_.pValue)) as col_2_0_ from Session session0_ inner join PredictorSession predictors1_ on session0_.session_id=predictors1_.session_id inner join Prediction prediction2_ on predictors1_.predictor_session_id=prediction2_.predictor_session_id where session0_.funcnetJobID=? group by prediction2_.protein1 , prediction2_.protein2
16:14:01,035 DEBUG ErrorCounter:68 - throwQueryException() : no errors
16:14:01,040 DEBUG HQLQueryPlan:269 - HQL param location recognition took 1 mills (

select prediction.protein1,
prediction.protein2,
-2 * sum( log( prediction.pValue ) )
from info.cathdb.funcnet_0_1.sessiondb.model.Session session
inner join session.predictors predictorSession
inner join predictorSession.predictions prediction
where session.funcnetJobID = :jobID
group by prediction.protein1,
prediction.protein2

)
16:14:01,042 DEBUG SessionFactoryImpl:412 - Checking 0 named SQL queries
16:14:01,066 DEBUG SessionImpl:220 - opened session at timestamp: 12293576410
16:14:01,105 DEBUG ThreadLocalSessi

Whoops, that log entry got truncated. Continues as follows:

16:14:01,105 DEBUG ThreadLocalSessionContext:290 - allowing method [getTransaction] in non-transacted context
16:14:01,105 DEBUG ThreadLocalSessionContext:300 - allowing proxied method [getTransaction] to proceed to real session
16:14:01,105 DEBUG ThreadLocalSessionContext:290 - allowing method [beginTransaction] in non-transacted context
16:14:01,105 DEBUG ThreadLocalSessionContext:300 - allowing proxied method [beginTransaction] to proceed to real session
16:14:01,106 DEBUG JDBCTransaction:54 - begin
16:14:01,106 DEBUG ConnectionManager:421 - opening JDBC connection
16:14:01,106 DEBUG DriverManagerConnectionProvider:93 - total checked-out connections: 0
16:14:01,106 DEBUG DriverManagerConnectionProvider:99 - using pooled JDBC connection, pool size: 0
16:14:01,107 DEBUG JDBCTransaction:59 - current autocommit status: false
16:14:01,107 DEBUG JDBCContext:210 - after transaction begin
16:14:01,113 DEBUG ThreadLocalSessionContext:300 - allowing proxied method [createCriteria] to proceed to real session
16:14:01,121 DEBUG AbstractBatcher:366 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
16:14:01,121 DEBUG SQL:401 - select this_.client_id as client1_3_0_, this_.emailAddress as emailAdd2_3_0_, this_.inetAddress as inetAddr3_3_0_ from Client this_ where this_.emailAddress ilike ? and this_.inetAddress ilike ?
16:14:01,122 DEBUG AbstractBatcher:484 - preparing statement
16:14:01,124 DEBUG StringType:133 - binding 'example1@cathdb.info' to parameter: 1
16:14:01,124 DEBUG StringType:133 - binding 'example1.cathdb.info' to parameter: 2
16:14:01,128 DEBUG AbstractBatcher:374 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
16:14:01,128 DEBUG AbstractBatcher:533 - closing statement
16:14:01,131 DEBUG JDBCExceptionReporter:69 - could not execute query [select this_.client_id as client1_3_0_, this_.emailAddress as emailAdd2_3_0_, this_.inetAddress as inetAddr3_3_0_ from Client this_ where this_.emailAddress ilike ? and this_.inetAddress ilike ?]
org.postgresql.util.PSQLException: ERROR: column this_.emailaddress does not exist
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:1592)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1327)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:192)
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:451)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:350)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:254)
at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:186)
at org.hibernate.loader.Loader.getResultSet(Loader.java:1787)
at org.hibernate.loader.Loader.doQuery(Loader.java:674)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236)
at org.hibernate.loader.Loader.doList(Loader.java:2220)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2104)
at org.hibernate.loader.Loader.list(Loader.java:2099)
at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:94)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1569)
at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:283)
at org.hibernate.impl.CriteriaImpl.uniqueResult(CriteriaImpl.java:305)
at info.cathdb.funcnet_0_1.sessiondb.hib3impl.HibernateRepository.getOrMakeClientMatching(HibernateRepository.java:382)
at info.cathdb.funcnet_0_1.sessiondb.hib3impl.HibernateRepository.createNewSession(HibernateRepository.java:100)
at info.cathdb.funcnet_0_1.sessiondb.hib3impl.HibernateRepository$$EnhancerByGuice$$6baa54d9.CGLIB$createNewSession$8(<generated>)
at info.cathdb.funcnet_0_1.sessiondb.hib3impl.HibernateRepository$$EnhancerByGuice$$6baa54d9$$FastClassByGuice$$6a8e9678.invoke(<generated>)
at com.google.inject.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:187)
at com.google.inject.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:66)
at com.wideplay.warp.hibernate.HibernateLocalTxnInterceptor.invoke(HibernateLocalTxnInterceptor.java:68)
at com.google.inject.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:66)
at com.google.inject.InterceptorStackCallback.intercept(InterceptorStackCallback.java:45)
at info.cathdb.funcnet_0_1.sessiondb.hib3impl.HibernateRepository$$EnhancerByGuice$$6baa54d9.createNewSession(<generated>)
at info.cathdb.funcnet_0_1.sessiondb.hib3impl.RepositoryTest.createStandardSession(RepositoryTest.java:215)
at info.cathdb.funcnet_0_1.sessiondb.hib3impl.RepositoryTest.testMultipleIdenticalClientsAreUnified(RepositoryTest.java:206)
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:597)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:73)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:46)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:180)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:41)
at org.junit.runners.ParentRunner$1.evaluate(ParentRunner.java:173)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
at org.junit.runners.ParentRunner.run(ParentRunner.java:220)
at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:45)
at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:460)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:673)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:386)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:196)
16:14:01,132 WARN JDBCExceptionReporter:77 - SQL Error: 0, SQLState: 42703
16:14:01,132 ERROR JDBCExceptionReporter:78 - ERROR: column this_.emailaddress does not exist
16:14:01,133 DEBUG JDBCTransaction:152 - rollback
16:14:01,134 DEBUG JDBCTransaction:163 - rolled back JDBC Connection
16:14:01,134 DEBUG JDBCContext:215 - after transaction completion
16:14:01,135 DEBUG ConnectionManager:404 - aggressively releasing JDBC connection
16:14:01,135 DEBUG ConnectionManager:441 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
16:14:01,135 DEBUG DriverManagerConnectionProvider:129 - returning connection to pool, pool size: 1
16:14:01,136 DEBUG SessionImpl:422 - after transaction completion
16:14:01,136 DEBUG SessionImpl:353 - automatically closing session
16:14:01,136 DEBUG SessionImpl:273 - closing session
16:14:01,137 DEBUG ConnectionManager:375 - connection already null in cleanup : no action