CLONE -merge() with one-to-one throws ClassCastException -------------------------------------------------------- Key: HHH-2000 URL: http://opensource.atlassian.com/projects/hibernate/browse/HHH-2000 Project: Hibernate3 Type: Bug Components: core Versions: 3.1 beta 2 Reporter: Marco Rothe Hibernate tries to bind a persistent object to a long variable in a SQL statement during a call to merge() on an object with a one-to-one relation. I originally posted about this problem here: http://forum.hibernate.org/viewtopic.php?t=948272&highlight= I have created and attached a junit test to reproduce the problem. When running against 3.0 or 3.1beta2 the ClassCastException is thrown all the way out, as shown in the forum post. The latest code from cvs catches the exception and logs it. org.hibernate.type.NullableType.java rev 1.10 is where the exception is caught. It seems like it should be logged and then re-thrown, but it's not. The debug log from the start of the merge() call to where it logs that it failed to bind the value is: [junit] 11:12:32,461 DEBUG SessionImpl:271 - opened session at timestamp: 11283595524 [junit] 11:12:32,461 DEBUG JDBCTransaction:54 - begin [junit] 11:12:32,461 DEBUG ConnectionManager:309 - opening JDBC connection [junit] 11:12:32,461 DEBUG DriverManagerConnectionProvider:93 - total checked-out connections: 0 [junit] 11:12:32,461 DEBUG DriverManagerConnectionProvider:99 - using pooled JDBC connection, pool size: 0 [junit] 11:12:32,461 DEBUG JDBCTransaction:59 - current autocommit status: false [junit] 11:12:32,461 DEBUG JDBCContext:207 - before transaction completion [junit] 11:12:32,477 DEBUG IdentifierValue:207 - id unsaved-value: null [junit] 11:12:32,477 DEBUG AbstractSaveEventListener:470 - detached instance of: org.hibernate.test.onetoone.merge.Person [junit] 11:12:32,477 DEBUG DefaultMergeEventListener:185 - merging detached instance [junit] 11:12:32,477 DEBUG DefaultLoadEventListener:153 - loading entity: [org.hibernate.test.onetoone.merge.Person#1] [junit] 11:12:32,477 DEBUG DefaultLoadEventListener:304 - attempting to resolve: [org.hibernate.test.onetoone.merge.Person#1] [junit] 11:12:32,477 DEBUG DefaultLoadEventListener:340 - object not resolved in any cache: [org.hibernate.test.onetoone.merge.Person#1] [junit] 11:12:32,477 DEBUG ConnectionManager:389 - running Session.finalize() [junit] 11:12:32,477 DEBUG AbstractEntityPersister:2722 - Fetching entity: [org.hibernate.test.onetoone.merge.Person#1] [junit] 11:12:32,493 DEBUG Loader:1774 - loading entity: [org.hibernate.test.onetoone.merge.Person#1] [junit] 11:12:32,493 DEBUG AbstractBatcher:309 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0) [junit] 11:12:32,493 DEBUG SQL:344 - [junit] select [junit] person0_.person_id as person1_0_0_ [junit] from [junit] person person0_ [junit] where [junit] person0_.person_id=? [junit] 11:12:32,493 DEBUG AbstractBatcher:413 - preparing statement [junit] 11:12:32,493 DEBUG AbstractBatcher:325 - about to open ResultSet (open ResultSets: 0, globally: 0) [junit] 11:12:32,508 DEBUG Loader:682 - processing result set [junit] 11:12:32,508 DEBUG Loader:687 - result set row: 0 [junit] 11:12:32,508 DEBUG Loader:1164 - result row: EntityKey[org.hibernate.test.onetoone.merge.Person#1] [junit] 11:12:32,508 DEBUG Loader:1347 - Initializing object from ResultSet: [org.hibernate.test.onetoone.merge.Person#1] [junit] 11:12:32,508 DEBUG AbstractEntityPersister:1859 - Hydrating entity: [org.hibernate.test.onetoone.merge.Person#1] [junit] 11:12:32,508 DEBUG Loader:709 - done processing result set (1 rows) [junit] 11:12:32,524 DEBUG AbstractBatcher:332 - about to close ResultSet (open ResultSets: 1, globally: 1) [junit] 11:12:32,524 DEBUG AbstractBatcher:317 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1) [junit] 11:12:32,524 DEBUG AbstractBatcher:459 - closing statement [junit] 11:12:32,524 DEBUG Loader:839 - total objects hydrated: 1 [junit] 11:12:32,524 DEBUG TwoPhaseLoad:104 - resolving associations for [org.hibernate.test.onetoone.merge.Person#1] [junit] 11:12:32,524 DEBUG Loader:1774 - loading entity: [org.hibernate.test.onetoone.merge.Address#1] [junit] 11:12:32,539 DEBUG AbstractBatcher:309 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0) [junit] 11:12:32,539 DEBUG SQL:344 - [junit] select [junit] address0_.address_id as address1_1_0_, [junit] address0_.person_id as person2_1_0_ [junit] from [junit] address address0_ [junit] where [junit] address0_.person_id=? [junit] 11:12:32,555 DEBUG AbstractBatcher:413 - preparing statement [junit] 11:12:32,555 DEBUG AbstractBatcher:325 - about to open ResultSet (open ResultSets: 0, globally: 0) [junit] 11:12:32,555 DEBUG Loader:682 - processing result set [junit] 11:12:32,571 DEBUG Loader:687 - result set row: 0 [junit] 11:12:32,571 DEBUG Loader:1164 - result row: EntityKey[org.hibernate.test.onetoone.merge.Address#2] [junit] 11:12:32,571 DEBUG Loader:1347 - Initializing object from ResultSet: [org.hibernate.test.onetoone.merge.Address#2] [junit] 11:12:32,571 DEBUG AbstractEntityPersister:1859 - Hydrating entity: [org.hibernate.test.onetoone.merge.Address#2] [junit] 11:12:32,571 DEBUG Loader:709 - done processing result set (1 rows) [junit] 11:12:32,571 DEBUG AbstractBatcher:332 - about to close ResultSet (open ResultSets: 1, globally: 1) [junit] 11:12:32,571 DEBUG AbstractBatcher:317 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1) [junit] 11:12:32,571 DEBUG AbstractBatcher:459 - closing statement [junit] 11:12:32,586 DEBUG Loader:839 - total objects hydrated: 1 [junit] 11:12:32,586 DEBUG TwoPhaseLoad:104 - resolving associations for [org.hibernate.test.onetoone.merge.Address#2] [junit] 11:12:32,586 DEBUG DefaultLoadEventListener:153 - loading entity: [org.hibernate.test.onetoone.merge.Person#1] [junit] 11:12:32,586 DEBUG DefaultLoadEventListener:222 - entity found in session cache [junit] 11:12:32,602 DEBUG TwoPhaseLoad:203 - done materializing entity [org.hibernate.test.onetoone.merge.Address#2] [junit] 11:12:32,602 DEBUG Loader:1805 - done entity load [junit] 11:12:32,602 DEBUG TwoPhaseLoad:203 - done materializing entity [org.hibernate.test.onetoone.merge.Person#1] [junit] 11:12:32,602 DEBUG StatefulPersistenceContext:784 - initializing non-lazy collections [junit] 11:12:32,602 DEBUG Loader:1805 - done entity load [junit] 11:12:32,602 DEBUG Loader:1774 - loading entity: [org.hibernate.test.onetoone.merge.Address#org.hibernate.test.onetoone.merge.Person@153f67e] [junit] 11:12:32,602 DEBUG AbstractBatcher:309 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0) [junit] 11:12:32,602 DEBUG SQL:344 - [junit] select [junit] address0_.address_id as address1_1_0_, [junit] address0_.person_id as person2_1_0_ [junit] from [junit] address address0_ [junit] where [junit] address0_.person_id=? [junit] 11:12:32,618 DEBUG AbstractBatcher:413 - preparing statement [junit] 11:12:32,618 INFO LongType:89 - could not bind value 'org.hibernate.test.onetoone.merge.Person@153f67e' to parameter: 1 Running the test on HSQLDB with the latest from cvs hides the problem (logs it as INFO, but doesn't complain that nothing is bound to the variable), but if you run on PostgreSQL, for example, it complains (SQLException) that nothing is bound to the variable when the statement is executed ( org.postgresql.util.PSQLException: No value specified for parameter 1.): [junit] 11:12:32,633 DEBUG AbstractBatcher:317 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1) [junit] 11:12:32,633 DEBUG AbstractBatcher:459 - closing statement [junit] 11:12:32,649 DEBUG JDBCExceptionReporter:63 - could not load an entity: [org.hibernate.test.onetoone.merge.Address#org.hibernate.test.onetoone.merge.Person@153f67e] [select address0_.address_id as address1_1_0_, address0_.person_id as person2_1_0_ from address address0_ where address0_.person_id=?] [junit] org.postgresql.util.PSQLException: No value specified for parameter 1. [junit] at org.postgresql.core.v3.SimpleParameterList.checkAllParametersSet(SimpleParameterList.java:102) [junit] at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:166) [junit] at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:389) [junit] at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:330) [junit] at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:240) [junit] at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:137) [junit] at org.hibernate.loader.Loader.getResultSet(Loader.java:1676) [junit] at org.hibernate.loader.Loader.doQuery(Loader.java:662) [junit] at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:223) [junit] at org.hibernate.loader.Loader.loadEntity(Loader.java:1782) [junit] at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:93) [junit] at org.hibernate.loader.entity.EntityLoader.loadByUniqueKey(EntityLoader.java:85) [junit] at org.hibernate.persister.entity.AbstractEntityPersister.loadByUniqueKey(AbstractEntityPersister.java:1522) [junit] at org.hibernate.type.EntityType.loadByUniqueKey(EntityType.java:365) [junit] at org.hibernate.type.EntityType.resolve(EntityType.java:306) [junit] at org.hibernate.type.EntityType.replace(EntityType.java:207) [junit] at org.hibernate.type.TypeFactory.replace(TypeFactory.java:431) [junit] at org.hibernate.event.def.DefaultMergeEventListener.copyValues(DefaultMergeEventListener.java:279) [junit] at org.hibernate.event.def.DefaultMergeEventListener.entityIsDetached(DefaultMergeEventListener.java:245) [junit] at org.hibernate.event.def.DefaultMergeEventListener.onMerge(DefaultMergeEventListener.java:102) [junit] at org.hibernate.event.def.DefaultMergeEventListener.onMerge(DefaultMergeEventListener.java:53) [junit] at org.hibernate.impl.SessionImpl.fireMerge(SessionImpl.java:609) [junit] at org.hibernate.impl.SessionImpl.merge(SessionImpl.java:595) [junit] at org.hibernate.impl.SessionImpl.merge(SessionImpl.java:599) [junit] at org.hibernate.test.onetoone.merge.OneToOneTest.testOne(OneToOneTest.java:52) [junit] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [junit] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [junit] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [junit] at java.lang.reflect.Method.invoke(Method.java:585) [junit] at junit.framework.TestCase.runTest(TestCase.java:154) [junit] at org.hibernate.test.TestCase.runTest(TestCase.java:140) [junit] at junit.framework.TestCase.runBare(TestCase.java:127) [junit] at junit.framework.TestResult$1.protect(TestResult.java:106) [junit] at junit.framework.TestResult.runProtected(TestResult.java:124) [junit] at junit.framework.TestResult.run(TestResult.java:109) [junit] at junit.framework.TestCase.run(TestCase.java:118) [junit] at junit.framework.TestSuite.runTest(TestSuite.java:208) [junit] at junit.framework.TestSuite.run(TestSuite.java:203) [junit] at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:297) [junit] at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:672) [junit] at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:567) [junit] 11:12:32,664 WARN JDBCExceptionReporter:71 - SQL Error: 0, SQLState: 22023 [junit] 11:12:32,664 ERROR JDBCExceptionReporter:72 - No value specified for parameter 1. [junit] 11:12:32,680 DEBUG SessionImpl:290 - closing session [junit] 11:12:32,680 DEBUG ConnectionManager:330 - closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] [junit] 11:12:32,680 DEBUG DriverManagerConnectionProvider:129 - returning connection to pool, pool size: 1 [junit] 11:12:32,680 INFO SessionFactoryImpl:865 - closing [junit] 11:12:32,680 INFO DriverManagerConnectionProvider:147 - cleaning up connection pool: jdbc:postgresql://localhost:5432/hibtest [junit] 11:12:32,680 INFO SchemaExport:153 - Running hbm2ddl schema export [junit] 11:12:32,696 DEBUG SchemaExport:171 - import file not found: /import.sql [junit] 11:12:32,696 INFO SchemaExport:180 - exporting generated schema to database [junit] 11:12:32,696 DEBUG DriverManagerConnectionProvider:93 - total checked-out connections: 0 [junit] 11:12:32,696 DEBUG DriverManagerConnectionProvider:109 - opening new JDBC connection [junit] 11:12:32,774 DEBUG DriverManagerConnectionProvider:115 - created connection to: jdbc:postgresql://localhost:5432/hibtest, Isolation Level: 2 [junit] 11:12:32,789 DEBUG SchemaExport:283 - [junit] alter table address [junit] drop constraint FKBB979BF4986F6BA3 [junit] 11:12:32,805 DEBUG SchemaExport:283 - [junit] drop table address [junit] 11:12:32,836 DEBUG SchemaExport:283 - [junit] drop table person [junit] 11:12:32,867 DEBUG SchemaExport:283 - [junit] drop sequence hibernate_sequence [junit] 11:12:32,883 INFO SchemaExport:200 - schema export complete [junit] 11:12:32,883 DEBUG DriverManagerConnectionProvider:129 - returning connection to pool, pool size: 1 [junit] Tests run: 1, Failures: 0, Errors: 1, Time elapsed: 5.233 sec [junit] Test org.hibernate.test.onetoone.merge.OneToOneTest FAILED -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://opensource.atlassian.com/projects/hibernate/secure/Administrators.... - For more information on JIRA, see: http://www.atlassian.com/software/jira