Hibernate

The following comment has been added to this issue:

     Author: Max Rydahl Andersen
    Created: Fri, 26 Dec 2003 4:03 PM
       Body:
oh - sorry, to quick ;)

use the ugly:

addJar(Thread.currentThread().getContextClassLoader().getResource(resourceName).getFile());

instead.
---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-580


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-580
    Summary: Undo deprecation of Configuration.addJar(String)
       Type: Improvement

     Status: Closed
   Priority: Critical
 Resolution: WON'T FIX

    Project: Hibernate2
 Components: 
             core
   Versions:
             2.1.1

   Assignee: 
   Reporter: tom quas

    Created: Fri, 26 Dec 2003 3:51 PM
    Updated: Fri, 26 Dec 2003 4:03 PM
Environment: API

Description:
I just realized that Configuration.addJar( String filename ) has been deprecated. I regularly use it to load mappings from the classpath.
Could you please leave it in for convenience?


---------------------------------------------------------------------
JIRA INFORMATION:
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.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira

The following comment has been added to this issue:

     Author: Max Rydahl Andersen
    Created: Sun, 28 Dec 2003 6:01 AM
       Body:
Yup - but the "weird" thing is that the bug seems to indicate that it worked in previous versions of hibernate ?
---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-582


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-582
    Summary: Extra ' ' when read char type field in SQLServer 2000 
       Type: Bug

     Status: Closed
   Priority: Critical
 Resolution: REJECTED

    Project: Hibernate2
 Components: 
             core
   Versions:
             2.1.1

   Assignee: Gavin King
   Reporter: Shining

    Created: Sat, 27 Dec 2003 7:33 AM
    Updated: Sun, 28 Dec 2003 6:01 AM
Environment: Windows2000 Professional with SP4, JDK 1.4.2_02, Eclipse 2.1.2 Hibernate 2.1.1 SQLServer 2000 Desktop with SP2, Microsoft SQLServer JDBC Driver SP2

Description:
There's a strange phenomenon when using SQLServer2000. When you read a char field through JDBC(ODBC is the same), the result were padded with extra blankspace, the length of blank space is equal to the length of data character subtract from the length of the field. for example:
field type is: char(10), data character is '1', the result of read will be '1         '.  The same reading operator in MySQL is correct. Other Database server have not been tested. 

When I test the sample code(figure 1) with hibernate 2.1.1, I found a bug that course collection lost when load a class with the char type id and a collection field with the same id as the id column.

Hibernate 2.1.1 DEBUG&OUTPUT Information
----------------------------------------------------------------------------------------------------------------------------------------
19:49:19,902  INFO Environment:432 - Hibernate 2.1.1
19:49:19,952  INFO Environment:461 - hibernate.properties not found
19:49:20,042  INFO Environment:481 - using CGLIB reflection optimizer
19:49:20,102  INFO Configuration:843 - configuring from resource: /hibernate.cfg.xml
19:49:20,112  INFO Configuration:815 - Configuration resource: /hibernate.cfg.xml
......
19:49:37,428 DEBUG SessionFactoryImpl:196 - instantiated session factory
19:49:37,729 DEBUG SessionImpl:528 - opened session
19:49:37,739 DEBUG SessionImpl:1913 - loading [test.Group#1]
19:49:37,739 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1]
19:49:37,759 DEBUG SessionImpl:2043 - object not resolved in any cache [test.Group#1]
19:49:37,759 DEBUG EntityPersister:417 - Materializing entity: [test.Group#1]
19:49:37,779 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:49:37,779 DEBUG DriverManagerConnectionProvider:78 - total checked-out connections: 0
19:49:37,789 DEBUG DriverManagerConnectionProvider:84 - using pooled JDBC connection, pool size: 0
19:49:37,789 DEBUG SQL:223 - select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
19:49:37,789 DEBUG BatcherImpl:227 - preparing statement
19:49:38,239 DEBUG StringType:46 - binding '1' to parameter: 1
19:49:38,590 DEBUG Loader:196 - processing result set
19:49:38,590 DEBUG Loader:404 - result row: 1
19:49:38,610 DEBUG Loader:535 - Initializing object from ResultSet: 1
19:49:38,630 DEBUG Loader:604 - Hydrating entity: test.Group#1
19:49:38,650 DEBUG StringType:68 - returning 'group1              ' as column: group_name0_
19:49:38,660 DEBUG Loader:225 - done processing result set (1 rows)
19:49:38,680 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:49:38,680 DEBUG BatcherImpl:240 - closing statement
19:49:38,690 DEBUG Loader:238 - total objects hydrated: 1
19:49:38,700 DEBUG SessionImpl:2129 - resolving associations for [test.Group#1]
19:49:38,720 DEBUG SessionImpl:3746 - collection not cached
19:49:38,760 DEBUG SessionImpl:2153 - done materializing entity [test.Group#1]
19:49:38,760 DEBUG SessionImpl:3000 - initializing non-lazy collections
19:49:38,760 DEBUG SessionImpl:3132 - initializing collection [test.Group.persons#1]
19:49:38,770 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:49:38,770 DEBUG SQL:223 - select persons0_.person_id as person_id__, persons0_.group_id as group_id__, persons0_.person_id as person_id0_, persons0_.person_name as person_n2_0_, persons0_.group_id as group_id0_ from tbl_person persons0_ where persons0_.group_id=?
Hibernate: select persons0_.person_id as person_id__, persons0_.group_id as group_id__, persons0_.person_id as person_id0_, persons0_.person_name as person_n2_0_, persons0_.group_id as group_id0_ from tbl_person persons0_ where persons0_.group_id=?
19:49:38,790 DEBUG BatcherImpl:227 - preparing statement
19:49:38,790 DEBUG StringType:46 - binding '1' to parameter: 1
19:49:38,810 DEBUG Loader:326 - result set contains (possibly empty) collection: [test.Group.persons#1]
19:49:38,810 DEBUG SessionImpl:2902 - uninitialized collection: initializing
19:49:38,830 DEBUG Loader:196 - processing result set
19:49:38,840 DEBUG StringType:68 - returning '11        ' as column: person_id0_
19:49:38,840 DEBUG Loader:404 - result row: 11        
19:49:38,850 DEBUG Loader:535 - Initializing object from ResultSet: 11        
19:49:38,850 DEBUG Loader:604 - Hydrating entity: test.Person#11        
19:49:38,860 DEBUG StringType:68 - returning 'person11            ' as column: person_n2_0_
19:49:38,860 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:38,860 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:38,870 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:38,870 DEBUG SessionImpl:2914 - new collection: instantiating
19:49:38,870 DEBUG StringType:68 - returning '11        ' as column: person_id__
19:49:38,880 DEBUG SessionImpl:1913 - loading [test.Person#11        ]
19:49:38,890 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#11        ]
19:49:38,910 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#11        ]
19:49:38,910 DEBUG StringType:68 - returning '12        ' as column: person_id0_
19:49:38,910 DEBUG Loader:404 - result row: 12        
19:49:38,920 DEBUG Loader:535 - Initializing object from ResultSet: 12        
19:49:38,920 DEBUG Loader:604 - Hydrating entity: test.Person#12        
19:49:38,930 DEBUG StringType:68 - returning 'person12            ' as column: person_n2_0_
19:49:38,930 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:38,960 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:38,960 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:38,960 DEBUG SessionImpl:2925 - reading row
19:49:38,960 DEBUG StringType:68 - returning '12        ' as column: person_id__
19:49:39,001 DEBUG SessionImpl:1913 - loading [test.Person#12        ]
19:49:39,001 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#12        ]
19:49:39,011 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#12        ]
19:49:39,011 DEBUG StringType:68 - returning '13        ' as column: person_id0_
19:49:39,011 DEBUG Loader:404 - result row: 13        
19:49:39,021 DEBUG Loader:535 - Initializing object from ResultSet: 13        
19:49:39,021 DEBUG Loader:604 - Hydrating entity: test.Person#13        
19:49:39,021 DEBUG StringType:68 - returning 'person13            ' as column: person_n2_0_
19:49:39,021 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:39,031 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:39,031 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:39,041 DEBUG SessionImpl:2925 - reading row
19:49:39,041 DEBUG StringType:68 - returning '13        ' as column: person_id__
19:49:39,051 DEBUG SessionImpl:1913 - loading [test.Person#13        ]
19:49:39,071 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#13        ]
19:49:39,071 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#13        ]
19:49:39,081 DEBUG StringType:68 - returning '14        ' as column: person_id0_
19:49:39,091 DEBUG Loader:404 - result row: 14        
19:49:39,091 DEBUG Loader:535 - Initializing object from ResultSet: 14        
19:49:39,091 DEBUG Loader:604 - Hydrating entity: test.Person#14        
19:49:39,091 DEBUG StringType:68 - returning 'person14            ' as column: person_n2_0_
19:49:39,101 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:39,101 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:39,111 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:39,111 DEBUG SessionImpl:2925 - reading row
19:49:39,111 DEBUG StringType:68 - returning '14        ' as column: person_id__
19:49:39,131 DEBUG SessionImpl:1913 - loading [test.Person#14        ]
19:49:39,131 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#14        ]
19:49:39,131 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#14        ]
19:49:39,131 DEBUG StringType:68 - returning '15        ' as column: person_id0_
19:49:39,141 DEBUG Loader:404 - result row: 15        
19:49:39,141 DEBUG Loader:535 - Initializing object from ResultSet: 15        
19:49:39,151 DEBUG Loader:604 - Hydrating entity: test.Person#15        
19:49:39,151 DEBUG StringType:68 - returning 'person15            ' as column: person_n2_0_
19:49:39,161 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:39,161 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:39,161 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:39,171 DEBUG SessionImpl:2925 - reading row
19:49:39,201 DEBUG StringType:68 - returning '15        ' as column: person_id__
19:49:39,201 DEBUG SessionImpl:1913 - loading [test.Person#15        ]
19:49:39,211 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#15        ]
19:49:39,211 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#15        ]
19:49:39,221 DEBUG Loader:225 - done processing result set (5 rows)
19:49:39,221 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:49:39,221 DEBUG BatcherImpl:240 - closing statement
19:49:39,231 DEBUG Loader:238 - total objects hydrated: 5
19:49:39,231 DEBUG SessionImpl:2129 - resolving associations for [test.Person#11        ]
{****
19:49:39,241 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,241 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,241 DEBUG SessionImpl:2043 - object not resolved in any cache [test.Group#1         ]
***}
19:49:39,241 DEBUG EntityPersister:417 - Materializing entity: [test.Group#1         ]
19:49:39,251 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:49:39,251 DEBUG SQL:223 - select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
19:49:39,261 DEBUG BatcherImpl:227 - preparing statement
19:49:39,261 DEBUG StringType:46 - binding '1         ' to parameter: 1
19:49:39,281 DEBUG Loader:196 - processing result set
19:49:39,281 DEBUG Loader:404 - result row: 1         
19:49:39,281 DEBUG Loader:535 - Initializing object from ResultSet: 1         
19:49:39,291 DEBUG Loader:604 - Hydrating entity: test.Group#1         
19:49:39,321 DEBUG StringType:68 - returning 'group1              ' as column: group_name0_
19:49:39,321 DEBUG Loader:225 - done processing result set (1 rows)
19:49:39,331 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:49:39,331 DEBUG BatcherImpl:240 - closing statement
19:49:39,331 DEBUG Loader:238 - total objects hydrated: 1
19:49:39,341 DEBUG SessionImpl:2129 - resolving associations for [test.Group#1         ]
19:49:39,341 DEBUG SessionImpl:2153 - done materializing entity [test.Group#1         ]
19:49:39,351 DEBUG SessionImpl:2153 - done materializing entity [test.Person#11        ]
19:49:39,351 DEBUG SessionImpl:2129 - resolving associations for [test.Person#12        ]
19:49:39,351 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,361 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,361 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,371 DEBUG SessionImpl:2153 - done materializing entity [test.Person#12        ]
19:49:39,371 DEBUG SessionImpl:2129 - resolving associations for [test.Person#13        ]
19:49:39,381 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,381 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,381 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,381 DEBUG SessionImpl:2153 - done materializing entity [test.Person#13        ]
19:49:39,391 DEBUG SessionImpl:2129 - resolving associations for [test.Person#14        ]
19:49:39,391 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,401 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,401 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,411 DEBUG SessionImpl:2153 - done materializing entity [test.Person#14        ]
19:49:39,411 DEBUG SessionImpl:2129 - resolving associations for [test.Person#15        ]
19:49:39,441 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,441 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,441 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,451 DEBUG SessionImpl:2153 - done materializing entity [test.Person#15        ]
19:49:39,451 DEBUG SessionImpl:2961 - 2 collections were found in result set
19:49:39,461 DEBUG SessionImpl:2979 - collection fully initialized: [test.Group.persons#1         ]
19:49:39,461 DEBUG SessionImpl:2979 - collection fully initialized: [test.Group.persons#1]
19:49:39,461 DEBUG SessionImpl:2982 - 2 collections initialized
----------------------------------------------------------------------------------------------------------------------------------------
The message in {**** ***} show the problem reson. Because of the strange behavior of the jdbc driver of SQLServer, the object id in the cache is "1"(load(group.class, "1")), the id read through jdbc is "1        ", hibernate can not got the group object from the cache. 

I have test the same code with the hibernate version 2.0.3, the result is correct, the debug information is:
Hibernate 2.0.3 DEBUG&OUTPUT Information
----------------------------------------------------------------------------------------------------------------------------------------
19:40:48,701  INFO Environment:403 - Hibernate 2.0.3
19:40:48,721  INFO Environment:432 - hibernate.properties not found
19:40:48,751  INFO Environment:452 - using CGLIB reflection optimizer
19:40:48,761  INFO Environment:462 - JVM proxy support: true
19:40:48,791  INFO Configuration:703 - Configuration resource: /hibernate.cfg.xml
19:41:00,579  INFO SessionFactoryImpl:269 - Query language substitutions: {}
......
19:41:00,589 DEBUG SessionFactoryImpl:281 - instantiated session factory
19:41:00,749 DEBUG SessionImpl:413 - opened session
19:41:00,769 DEBUG SessionImpl:1752 - loading [test.Group#1]
19:41:00,769 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1]
19:41:00,789 DEBUG SessionImpl:1887 - object not resolved in any cache [test.Group#1]
19:41:00,789 DEBUG EntityPersister:394 - Materializing entity: test.Group#1
19:41:00,799 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:00,799 DEBUG DriverManagerConnectionProvider:77 - total checked-out connections: 0
19:41:00,799 DEBUG DriverManagerConnectionProvider:83 - using pooled JDBC connection, pool size: 0
19:41:00,809 DEBUG SessionFactoryImpl:526 - prepared statement get: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
19:41:00,809 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,160 DEBUG StringType:44 - binding '1' to parameter: 1
19:41:01,300 DEBUG Loader:148 - processing result set
19:41:01,310 DEBUG Loader:260 - result row: 1
19:41:01,310 DEBUG Loader:357 - Initializing object from ResultSet: 1
19:41:01,320 DEBUG Loader:413 - Hydrating entity: test.Group#1
19:41:01,320 DEBUG StringType:65 - returning 'group1              ' as column: group_name
19:41:01,330 DEBUG Loader:182 - done processing result set (1 rows)
19:41:01,340 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,350 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,350 DEBUG Loader:195 - total objects hydrated: 1
19:41:01,350 DEBUG SessionImpl:1954 - resolving associations for [test.Group#1]
19:41:01,390 DEBUG SessionImpl:2888 - initializing collection [test.Group.persons#1]
19:41:01,390 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:01,400 DEBUG SessionFactoryImpl:526 - prepared statement get: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
Hibernate: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
19:41:01,400 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,400 DEBUG StringType:44 - binding '1' to parameter: 1
19:41:01,430 DEBUG Loader:148 - processing result set
19:41:01,440 DEBUG StringType:65 - returning '11        ' as column: person_id
19:41:01,440 DEBUG Loader:260 - result row: 11        
19:41:01,440 DEBUG Loader:357 - Initializing object from ResultSet: 11        
19:41:01,440 DEBUG Loader:413 - Hydrating entity: test.Person#11        
19:41:01,450 DEBUG StringType:65 - returning 'person11            ' as column: person_n2_
19:41:01,450 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,450 DEBUG StringType:65 - returning '11        ' as column: person_id__
19:41:01,460 DEBUG SessionImpl:1752 - loading [test.Person#11        ]
19:41:01,460 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#11        ]
19:41:01,470 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#11        ]
19:41:01,470 DEBUG StringType:65 - returning '12        ' as column: person_id
19:41:01,470 DEBUG Loader:260 - result row: 12        
19:41:01,480 DEBUG Loader:357 - Initializing object from ResultSet: 12        
19:41:01,480 DEBUG Loader:413 - Hydrating entity: test.Person#12        
19:41:01,480 DEBUG StringType:65 - returning 'person12            ' as column: person_n2_
19:41:01,480 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,490 DEBUG StringType:65 - returning '12        ' as column: person_id__
19:41:01,500 DEBUG SessionImpl:1752 - loading [test.Person#12        ]
19:41:01,500 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#12        ]
19:41:01,500 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#12        ]
19:41:01,510 DEBUG StringType:65 - returning '13        ' as column: person_id
19:41:01,510 DEBUG Loader:260 - result row: 13        
19:41:01,510 DEBUG Loader:357 - Initializing object from ResultSet: 13        
19:41:01,530 DEBUG Loader:413 - Hydrating entity: test.Person#13        
19:41:01,540 DEBUG StringType:65 - returning 'person13            ' as column: person_n2_
19:41:01,540 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,540 DEBUG StringType:65 - returning '13        ' as column: person_id__
19:41:01,550 DEBUG SessionImpl:1752 - loading [test.Person#13        ]
19:41:01,550 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#13        ]
19:41:01,550 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#13        ]
19:41:01,560 DEBUG StringType:65 - returning '14        ' as column: person_id
19:41:01,560 DEBUG Loader:260 - result row: 14        
19:41:01,560 DEBUG Loader:357 - Initializing object from ResultSet: 14        
19:41:01,570 DEBUG Loader:413 - Hydrating entity: test.Person#14        
19:41:01,570 DEBUG StringType:65 - returning 'person14            ' as column: person_n2_
19:41:01,570 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,580 DEBUG StringType:65 - returning '14        ' as column: person_id__
19:41:01,580 DEBUG SessionImpl:1752 - loading [test.Person#14        ]
19:41:01,580 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#14        ]
19:41:01,590 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#14        ]
19:41:01,590 DEBUG StringType:65 - returning '15        ' as column: person_id
19:41:01,600 DEBUG Loader:260 - result row: 15        
19:41:01,600 DEBUG Loader:357 - Initializing object from ResultSet: 15        
19:41:01,600 DEBUG Loader:413 - Hydrating entity: test.Person#15        
19:41:01,600 DEBUG StringType:65 - returning 'person15            ' as column: person_n2_
19:41:01,610 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,610 DEBUG StringType:65 - returning '15        ' as column: person_id__
19:41:01,620 DEBUG SessionImpl:1752 - loading [test.Person#15        ]
19:41:01,620 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#15        ]
19:41:01,630 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#15        ]
19:41:01,650 DEBUG Loader:182 - done processing result set (5 rows)
19:41:01,650 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,650 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,650 DEBUG Loader:195 - total objects hydrated: 5
19:41:01,660 DEBUG SessionImpl:1954 - resolving associations for [test.Person#11        ]
19:41:01,660 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:01,660 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:01,671 DEBUG SessionImpl:1887 - object not resolved in any cache [test.Group#1         ]
19:41:01,671 DEBUG EntityPersister:394 - Materializing entity: test.Group#1         
19:41:01,681 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:01,681 DEBUG SessionFactoryImpl:526 - prepared statement get: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
19:41:01,681 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,691 DEBUG StringType:44 - binding '1         ' to parameter: 1
19:41:01,691 DEBUG Loader:148 - processing result set
19:41:01,711 DEBUG Loader:260 - result row: 1         
19:41:01,711 DEBUG Loader:357 - Initializing object from ResultSet: 1         
19:41:01,711 DEBUG Loader:413 - Hydrating entity: test.Group#1         
19:41:01,721 DEBUG StringType:65 - returning 'group1              ' as column: group_name
19:41:01,721 DEBUG Loader:182 - done processing result set (1 rows)
19:41:01,721 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,731 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,731 DEBUG Loader:195 - total objects hydrated: 1
19:41:01,741 DEBUG SessionImpl:1954 - resolving associations for [test.Group#1         ]
19:41:01,741 DEBUG SessionImpl:2888 - initializing collection [test.Group.persons#1         ]
19:41:01,741 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:01,771 DEBUG SessionFactoryImpl:526 - prepared statement get: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
Hibernate: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
19:41:01,791 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,791 DEBUG StringType:44 - binding '1         ' to parameter: 1
19:41:01,811 DEBUG Loader:148 - processing result set
19:41:01,811 DEBUG StringType:65 - returning '11        ' as column: person_id
19:41:01,821 DEBUG Loader:260 - result row: 11        
19:41:01,821 DEBUG StringType:65 - returning '11        ' as column: person_id__
19:41:01,821 DEBUG SessionImpl:1752 - loading [test.Person#11        ]
19:41:01,831 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#11        ]
19:41:01,831 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#11        ]
19:41:01,841 DEBUG StringType:65 - returning '12        ' as column: person_id
19:41:01,841 DEBUG Loader:260 - result row: 12        
19:41:01,841 DEBUG StringType:65 - returning '12        ' as column: person_id__
19:41:01,841 DEBUG SessionImpl:1752 - loading [test.Person#12        ]
19:41:01,851 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#12        ]
19:41:01,851 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#12        ]
19:41:01,861 DEBUG StringType:65 - returning '13        ' as column: person_id
19:41:01,871 DEBUG Loader:260 - result row: 13        
19:41:01,881 DEBUG StringType:65 - returning '13        ' as column: person_id__
19:41:01,881 DEBUG SessionImpl:1752 - loading [test.Person#13        ]
19:41:01,881 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#13        ]
19:41:01,901 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#13        ]
19:41:01,901 DEBUG StringType:65 - returning '14        ' as column: person_id
19:41:01,911 DEBUG Loader:260 - result row: 14        
19:41:01,911 DEBUG StringType:65 - returning '14        ' as column: person_id__
19:41:01,911 DEBUG SessionImpl:1752 - loading [test.Person#14        ]
19:41:01,921 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#14        ]
19:41:01,921 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#14        ]
19:41:01,931 DEBUG StringType:65 - returning '15        ' as column: person_id
19:41:01,931 DEBUG Loader:260 - result row: 15        
19:41:01,931 DEBUG StringType:65 - returning '15        ' as column: person_id__
19:41:01,941 DEBUG SessionImpl:1752 - loading [test.Person#15        ]
19:41:01,941 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#15        ]
19:41:01,951 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#15        ]
19:41:01,951 DEBUG Loader:182 - done processing result set (5 rows)
19:41:01,951 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,961 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,961 DEBUG Loader:195 - total objects hydrated: 0
19:41:01,961 DEBUG SessionImpl:1975 - done materializing entity [test.Group#1         ]
19:41:01,971 DEBUG SessionImpl:1975 - done materializing entity [test.Person#11        ]
19:41:01,991 DEBUG SessionImpl:1954 - resolving associations for [test.Person#12        ]
19:41:01,991 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:01,991 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:01,991 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,001 DEBUG SessionImpl:1975 - done materializing entity [test.Person#12        ]
19:41:02,001 DEBUG SessionImpl:1954 - resolving associations for [test.Person#13        ]
19:41:02,001 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:02,011 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:02,011 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,011 DEBUG SessionImpl:1975 - done materializing entity [test.Person#13        ]
19:41:02,021 DEBUG SessionImpl:1954 - resolving associations for [test.Person#14        ]
19:41:02,021 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:02,021 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:02,021 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,031 DEBUG SessionImpl:1975 - done materializing entity [test.Person#14        ]
19:41:02,031 DEBUG SessionImpl:1954 - resolving associations for [test.Person#15        ]
19:41:02,041 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:02,041 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:02,041 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,051 DEBUG SessionImpl:1975 - done materializing entity [test.Person#15        ]
19:41:02,051 DEBUG SessionImpl:1975 - done materializing entity [test.Group#1]
----------------------------------------------------------------------------------------------------------------------------------------

If hibernate have a trim() operator when dealing with SQLServerDialect, the problem will be corrected perfectly.


---------------------------------------------------------------------
JIRA INFORMATION:
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.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira

The following comment has been added to this issue:

     Author: Eric Pugh
    Created: Sun, 28 Dec 2003 4:53 PM
       Body:
Benoit, Can you share the result set proxy that you have?  I have the same problem, and am getting around it by not loading all my data in one sql statement.   While debugging this problem, I found quite a few posts on the net about it.  It sounds like something we should update in the wiki (http://www.hibernate.org/80.html).  MS SQL's JDBC driver may be buggy, but it is very popular because it is free and from Microsoft...
---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-484


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-484
    Summary: ResultSet can not re-read row data for column 2
       Type: Bug

     Status: Closed
   Priority: Major
 Resolution: WON'T FIX

    Project: Hibernate2

   Assignee: 
   Reporter: Benoit Menendez

    Created: Thu, 20 Nov 2003 12:24 PM
    Updated: Sun, 28 Dec 2003 4:53 PM

Description:



---------------------------------------------------------------------
JIRA INFORMATION:
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.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira

The following issue has been updated:

    Updater: Nick Heudecker (mailto:nick@...)
       Date: Sun, 28 Dec 2003 2:47 PM
    Comment:
Here is the patch file for AbstractQueryImpl.java.  Generated with: diff -C 5 from-file to-file
    Changes:
             Attachment changed to AbstractQueryImpl.patch
    ---------------------------------------------------------------------
For a full history of the issue, see:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-579&page=history

---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-579


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-579
    Summary: Patch AbstractQuery so that it supports parameter lists
       Type: Improvement

     Status: Unassigned
   Priority: Minor

    Project: Hibernate2
 Components: 
             core
   Versions:
             2.1
             2.0 final
             2.1.1

   Assignee: 
   Reporter: Nick Heudecker

    Created: Fri, 26 Dec 2003 11:42 AM
    Updated: Sun, 28 Dec 2003 2:47 PM
Environment: Any

Description:
Currently, the AbstractQuery class doesn't take into account setting parameter lists when using the 'setProperties(Object)' method.  This would be extremely helpful to me.  A patch is below.

public Query setProperties(Object bean) throws HibernateException {
  Class clazz = bean.getClass();
  String[] params = getNamedParameters();
  for (int i = 0; i < params.length; i++) {
    String namedParam = params[i];
    try {
      Getter getter = ReflectHelper.getter(clazz, namedParam);
      Class retType = getter.getReturnType();
      if (retType.isArray() || 
          retType instanceof java.util.Collection) {
        setParameterList( namedParam, getter.get(bean) );
      }                                                                                                             
      else {
        setParameter( namedParam, getter.get(bean), 
                      guessType( getter.getReturnType() ) );
      }                                                                                                                 
    }                                                                                                                                  
    catch (PropertyNotFoundException pnfe) {
      // shouldn't something be logged here....?
    }                                                                                                                      
  }                                                                                                                                  
  return this;
}                    




---------------------------------------------------------------------
JIRA INFORMATION:
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.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira

The following comment has been added to this issue:

     Author: Gavin King
    Created: Sun, 28 Dec 2003 5:17 AM
       Body:
In fact, the tests I have done show that the "overhead" of using column names is nonexistent in most drivers (at least in JDK 1.3+).
---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-583


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-583
    Summary: Subclass.java and MSSQL JDBC driver cause a reread exception.
       Type: Bug

     Status: Closed
   Priority: Minor
 Resolution: WON'T FIX

    Project: Hibernate2
 Components: 
             core
   Versions:
             2.1.1

   Assignee: 
   Reporter: Eric Pugh

    Created: Sat, 27 Dec 2003 11:25 AM
    Updated: Sun, 28 Dec 2003 5:17 AM
Environment: Hibernate 2.1.1 and also the nightly build.  Using MS JDBC driver, both the  Service Pack 1 and Service Pack 2 versions.

Description:
Per my forum posting about MSSQL Throwing "ResultSet can not re-read row data for column 51.".

The MSSQL JDBC Driver throws an exception if you don't read left to right if you are quering columns that contain types IMAGE, NTEXT, or TEXT.  According to the JDBC API this actually okay:

For maximum portability, columns within a row should be read 
in left-to-right order, and each column should only be read once. This reflects implementation limitations in some underlying database protocols

The way around this is to use proxies and lazy loading to not load all the objects at once.  However, for joined-subclasses you have to.  The fix is to swap the order of the propertys are read  in Subclass.java:
public Iterator getPropertyClosureIterator() { 
return new JoinedIterator( new Iterator[] { 
getSuperclass().getPropertyClosureIterator(), 
getPropertyIterator()} 
); 
} 

However, I think that a better approch (but beyond me) is to use indexes instead of columns names.  Which I also believe is supposed to be faster for most JDBC drivers.

Eric Pugh



---------------------------------------------------------------------
JIRA INFORMATION:
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.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira

Message:

   The following issue has been closed.

   Resolver: Gavin King
       Date: Sun, 28 Dec 2003 5:07 AM

So don't map them with not-null="true".
---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-584


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-584
    Summary: Update and create schema and "not-null" properties for subclass
       Type: Bug

     Status: Closed
   Priority: Minor
 Resolution: REJECTED

    Project: Hibernate2
 Components: 
             core
   Versions:
             2.1 final

   Assignee: 
   Reporter: Robson Miranda

    Created: Sat, 27 Dec 2003 4:04 PM
    Updated: Sun, 28 Dec 2003 5:07 AM
Environment: Hibernate 2.1final, MaxDB 7.5.00.05

Description:
When using a mapping of one table per class hierarchy, the columns of the subclasses should not be created as "not-null", since not always all the columns of the table will be filled.

Thanks,
   Robson


---------------------------------------------------------------------
JIRA INFORMATION:
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.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira

Message:

   The following issue has been closed.

   Resolver: Gavin King
       Date: Sun, 28 Dec 2003 5:02 AM

You should, of course, use VARCHAR. This is obviously not a bug in Hibernate.
---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-582


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-582
    Summary: Extra ' ' when read char type field in SQLServer 2000 
       Type: Bug

     Status: Closed
   Priority: Critical
 Resolution: REJECTED

    Project: Hibernate2
 Components: 
             core
   Versions:
             2.1.1

   Assignee: Gavin King
   Reporter: Shining

    Created: Sat, 27 Dec 2003 7:33 AM
    Updated: Sun, 28 Dec 2003 5:02 AM
Environment: Windows2000 Professional with SP4, JDK 1.4.2_02, Eclipse 2.1.2 Hibernate 2.1.1 SQLServer 2000 Desktop with SP2, Microsoft SQLServer JDBC Driver SP2

Description:
There's a strange phenomenon when using SQLServer2000. When you read a char field through JDBC(ODBC is the same), the result were padded with extra blankspace, the length of blank space is equal to the length of data character subtract from the length of the field. for example:
field type is: char(10), data character is '1', the result of read will be '1         '.  The same reading operator in MySQL is correct. Other Database server have not been tested. 

When I test the sample code(figure 1) with hibernate 2.1.1, I found a bug that course collection lost when load a class with the char type id and a collection field with the same id as the id column.

Hibernate 2.1.1 DEBUG&OUTPUT Information
----------------------------------------------------------------------------------------------------------------------------------------
19:49:19,902  INFO Environment:432 - Hibernate 2.1.1
19:49:19,952  INFO Environment:461 - hibernate.properties not found
19:49:20,042  INFO Environment:481 - using CGLIB reflection optimizer
19:49:20,102  INFO Configuration:843 - configuring from resource: /hibernate.cfg.xml
19:49:20,112  INFO Configuration:815 - Configuration resource: /hibernate.cfg.xml
......
19:49:37,428 DEBUG SessionFactoryImpl:196 - instantiated session factory
19:49:37,729 DEBUG SessionImpl:528 - opened session
19:49:37,739 DEBUG SessionImpl:1913 - loading [test.Group#1]
19:49:37,739 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1]
19:49:37,759 DEBUG SessionImpl:2043 - object not resolved in any cache [test.Group#1]
19:49:37,759 DEBUG EntityPersister:417 - Materializing entity: [test.Group#1]
19:49:37,779 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:49:37,779 DEBUG DriverManagerConnectionProvider:78 - total checked-out connections: 0
19:49:37,789 DEBUG DriverManagerConnectionProvider:84 - using pooled JDBC connection, pool size: 0
19:49:37,789 DEBUG SQL:223 - select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
19:49:37,789 DEBUG BatcherImpl:227 - preparing statement
19:49:38,239 DEBUG StringType:46 - binding '1' to parameter: 1
19:49:38,590 DEBUG Loader:196 - processing result set
19:49:38,590 DEBUG Loader:404 - result row: 1
19:49:38,610 DEBUG Loader:535 - Initializing object from ResultSet: 1
19:49:38,630 DEBUG Loader:604 - Hydrating entity: test.Group#1
19:49:38,650 DEBUG StringType:68 - returning 'group1              ' as column: group_name0_
19:49:38,660 DEBUG Loader:225 - done processing result set (1 rows)
19:49:38,680 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:49:38,680 DEBUG BatcherImpl:240 - closing statement
19:49:38,690 DEBUG Loader:238 - total objects hydrated: 1
19:49:38,700 DEBUG SessionImpl:2129 - resolving associations for [test.Group#1]
19:49:38,720 DEBUG SessionImpl:3746 - collection not cached
19:49:38,760 DEBUG SessionImpl:2153 - done materializing entity [test.Group#1]
19:49:38,760 DEBUG SessionImpl:3000 - initializing non-lazy collections
19:49:38,760 DEBUG SessionImpl:3132 - initializing collection [test.Group.persons#1]
19:49:38,770 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:49:38,770 DEBUG SQL:223 - select persons0_.person_id as person_id__, persons0_.group_id as group_id__, persons0_.person_id as person_id0_, persons0_.person_name as person_n2_0_, persons0_.group_id as group_id0_ from tbl_person persons0_ where persons0_.group_id=?
Hibernate: select persons0_.person_id as person_id__, persons0_.group_id as group_id__, persons0_.person_id as person_id0_, persons0_.person_name as person_n2_0_, persons0_.group_id as group_id0_ from tbl_person persons0_ where persons0_.group_id=?
19:49:38,790 DEBUG BatcherImpl:227 - preparing statement
19:49:38,790 DEBUG StringType:46 - binding '1' to parameter: 1
19:49:38,810 DEBUG Loader:326 - result set contains (possibly empty) collection: [test.Group.persons#1]
19:49:38,810 DEBUG SessionImpl:2902 - uninitialized collection: initializing
19:49:38,830 DEBUG Loader:196 - processing result set
19:49:38,840 DEBUG StringType:68 - returning '11        ' as column: person_id0_
19:49:38,840 DEBUG Loader:404 - result row: 11        
19:49:38,850 DEBUG Loader:535 - Initializing object from ResultSet: 11        
19:49:38,850 DEBUG Loader:604 - Hydrating entity: test.Person#11        
19:49:38,860 DEBUG StringType:68 - returning 'person11            ' as column: person_n2_0_
19:49:38,860 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:38,860 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:38,870 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:38,870 DEBUG SessionImpl:2914 - new collection: instantiating
19:49:38,870 DEBUG StringType:68 - returning '11        ' as column: person_id__
19:49:38,880 DEBUG SessionImpl:1913 - loading [test.Person#11        ]
19:49:38,890 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#11        ]
19:49:38,910 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#11        ]
19:49:38,910 DEBUG StringType:68 - returning '12        ' as column: person_id0_
19:49:38,910 DEBUG Loader:404 - result row: 12        
19:49:38,920 DEBUG Loader:535 - Initializing object from ResultSet: 12        
19:49:38,920 DEBUG Loader:604 - Hydrating entity: test.Person#12        
19:49:38,930 DEBUG StringType:68 - returning 'person12            ' as column: person_n2_0_
19:49:38,930 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:38,960 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:38,960 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:38,960 DEBUG SessionImpl:2925 - reading row
19:49:38,960 DEBUG StringType:68 - returning '12        ' as column: person_id__
19:49:39,001 DEBUG SessionImpl:1913 - loading [test.Person#12        ]
19:49:39,001 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#12        ]
19:49:39,011 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#12        ]
19:49:39,011 DEBUG StringType:68 - returning '13        ' as column: person_id0_
19:49:39,011 DEBUG Loader:404 - result row: 13        
19:49:39,021 DEBUG Loader:535 - Initializing object from ResultSet: 13        
19:49:39,021 DEBUG Loader:604 - Hydrating entity: test.Person#13        
19:49:39,021 DEBUG StringType:68 - returning 'person13            ' as column: person_n2_0_
19:49:39,021 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:39,031 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:39,031 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:39,041 DEBUG SessionImpl:2925 - reading row
19:49:39,041 DEBUG StringType:68 - returning '13        ' as column: person_id__
19:49:39,051 DEBUG SessionImpl:1913 - loading [test.Person#13        ]
19:49:39,071 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#13        ]
19:49:39,071 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#13        ]
19:49:39,081 DEBUG StringType:68 - returning '14        ' as column: person_id0_
19:49:39,091 DEBUG Loader:404 - result row: 14        
19:49:39,091 DEBUG Loader:535 - Initializing object from ResultSet: 14        
19:49:39,091 DEBUG Loader:604 - Hydrating entity: test.Person#14        
19:49:39,091 DEBUG StringType:68 - returning 'person14            ' as column: person_n2_0_
19:49:39,101 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:39,101 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:39,111 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:39,111 DEBUG SessionImpl:2925 - reading row
19:49:39,111 DEBUG StringType:68 - returning '14        ' as column: person_id__
19:49:39,131 DEBUG SessionImpl:1913 - loading [test.Person#14        ]
19:49:39,131 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#14        ]
19:49:39,131 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#14        ]
19:49:39,131 DEBUG StringType:68 - returning '15        ' as column: person_id0_
19:49:39,141 DEBUG Loader:404 - result row: 15        
19:49:39,141 DEBUG Loader:535 - Initializing object from ResultSet: 15        
19:49:39,151 DEBUG Loader:604 - Hydrating entity: test.Person#15        
19:49:39,151 DEBUG StringType:68 - returning 'person15            ' as column: person_n2_0_
19:49:39,161 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:39,161 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:39,161 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:39,171 DEBUG SessionImpl:2925 - reading row
19:49:39,201 DEBUG StringType:68 - returning '15        ' as column: person_id__
19:49:39,201 DEBUG SessionImpl:1913 - loading [test.Person#15        ]
19:49:39,211 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#15        ]
19:49:39,211 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#15        ]
19:49:39,221 DEBUG Loader:225 - done processing result set (5 rows)
19:49:39,221 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:49:39,221 DEBUG BatcherImpl:240 - closing statement
19:49:39,231 DEBUG Loader:238 - total objects hydrated: 5
19:49:39,231 DEBUG SessionImpl:2129 - resolving associations for [test.Person#11        ]
{****
19:49:39,241 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,241 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,241 DEBUG SessionImpl:2043 - object not resolved in any cache [test.Group#1         ]
***}
19:49:39,241 DEBUG EntityPersister:417 - Materializing entity: [test.Group#1         ]
19:49:39,251 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:49:39,251 DEBUG SQL:223 - select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
19:49:39,261 DEBUG BatcherImpl:227 - preparing statement
19:49:39,261 DEBUG StringType:46 - binding '1         ' to parameter: 1
19:49:39,281 DEBUG Loader:196 - processing result set
19:49:39,281 DEBUG Loader:404 - result row: 1         
19:49:39,281 DEBUG Loader:535 - Initializing object from ResultSet: 1         
19:49:39,291 DEBUG Loader:604 - Hydrating entity: test.Group#1         
19:49:39,321 DEBUG StringType:68 - returning 'group1              ' as column: group_name0_
19:49:39,321 DEBUG Loader:225 - done processing result set (1 rows)
19:49:39,331 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:49:39,331 DEBUG BatcherImpl:240 - closing statement
19:49:39,331 DEBUG Loader:238 - total objects hydrated: 1
19:49:39,341 DEBUG SessionImpl:2129 - resolving associations for [test.Group#1         ]
19:49:39,341 DEBUG SessionImpl:2153 - done materializing entity [test.Group#1         ]
19:49:39,351 DEBUG SessionImpl:2153 - done materializing entity [test.Person#11        ]
19:49:39,351 DEBUG SessionImpl:2129 - resolving associations for [test.Person#12        ]
19:49:39,351 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,361 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,361 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,371 DEBUG SessionImpl:2153 - done materializing entity [test.Person#12        ]
19:49:39,371 DEBUG SessionImpl:2129 - resolving associations for [test.Person#13        ]
19:49:39,381 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,381 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,381 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,381 DEBUG SessionImpl:2153 - done materializing entity [test.Person#13        ]
19:49:39,391 DEBUG SessionImpl:2129 - resolving associations for [test.Person#14        ]
19:49:39,391 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,401 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,401 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,411 DEBUG SessionImpl:2153 - done materializing entity [test.Person#14        ]
19:49:39,411 DEBUG SessionImpl:2129 - resolving associations for [test.Person#15        ]
19:49:39,441 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,441 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,441 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,451 DEBUG SessionImpl:2153 - done materializing entity [test.Person#15        ]
19:49:39,451 DEBUG SessionImpl:2961 - 2 collections were found in result set
19:49:39,461 DEBUG SessionImpl:2979 - collection fully initialized: [test.Group.persons#1         ]
19:49:39,461 DEBUG SessionImpl:2979 - collection fully initialized: [test.Group.persons#1]
19:49:39,461 DEBUG SessionImpl:2982 - 2 collections initialized
----------------------------------------------------------------------------------------------------------------------------------------
The message in {**** ***} show the problem reson. Because of the strange behavior of the jdbc driver of SQLServer, the object id in the cache is "1"(load(group.class, "1")), the id read through jdbc is "1        ", hibernate can not got the group object from the cache. 

I have test the same code with the hibernate version 2.0.3, the result is correct, the debug information is:
Hibernate 2.0.3 DEBUG&OUTPUT Information
----------------------------------------------------------------------------------------------------------------------------------------
19:40:48,701  INFO Environment:403 - Hibernate 2.0.3
19:40:48,721  INFO Environment:432 - hibernate.properties not found
19:40:48,751  INFO Environment:452 - using CGLIB reflection optimizer
19:40:48,761  INFO Environment:462 - JVM proxy support: true
19:40:48,791  INFO Configuration:703 - Configuration resource: /hibernate.cfg.xml
19:41:00,579  INFO SessionFactoryImpl:269 - Query language substitutions: {}
......
19:41:00,589 DEBUG SessionFactoryImpl:281 - instantiated session factory
19:41:00,749 DEBUG SessionImpl:413 - opened session
19:41:00,769 DEBUG SessionImpl:1752 - loading [test.Group#1]
19:41:00,769 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1]
19:41:00,789 DEBUG SessionImpl:1887 - object not resolved in any cache [test.Group#1]
19:41:00,789 DEBUG EntityPersister:394 - Materializing entity: test.Group#1
19:41:00,799 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:00,799 DEBUG DriverManagerConnectionProvider:77 - total checked-out connections: 0
19:41:00,799 DEBUG DriverManagerConnectionProvider:83 - using pooled JDBC connection, pool size: 0
19:41:00,809 DEBUG SessionFactoryImpl:526 - prepared statement get: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
19:41:00,809 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,160 DEBUG StringType:44 - binding '1' to parameter: 1
19:41:01,300 DEBUG Loader:148 - processing result set
19:41:01,310 DEBUG Loader:260 - result row: 1
19:41:01,310 DEBUG Loader:357 - Initializing object from ResultSet: 1
19:41:01,320 DEBUG Loader:413 - Hydrating entity: test.Group#1
19:41:01,320 DEBUG StringType:65 - returning 'group1              ' as column: group_name
19:41:01,330 DEBUG Loader:182 - done processing result set (1 rows)
19:41:01,340 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,350 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,350 DEBUG Loader:195 - total objects hydrated: 1
19:41:01,350 DEBUG SessionImpl:1954 - resolving associations for [test.Group#1]
19:41:01,390 DEBUG SessionImpl:2888 - initializing collection [test.Group.persons#1]
19:41:01,390 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:01,400 DEBUG SessionFactoryImpl:526 - prepared statement get: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
Hibernate: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
19:41:01,400 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,400 DEBUG StringType:44 - binding '1' to parameter: 1
19:41:01,430 DEBUG Loader:148 - processing result set
19:41:01,440 DEBUG StringType:65 - returning '11        ' as column: person_id
19:41:01,440 DEBUG Loader:260 - result row: 11        
19:41:01,440 DEBUG Loader:357 - Initializing object from ResultSet: 11        
19:41:01,440 DEBUG Loader:413 - Hydrating entity: test.Person#11        
19:41:01,450 DEBUG StringType:65 - returning 'person11            ' as column: person_n2_
19:41:01,450 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,450 DEBUG StringType:65 - returning '11        ' as column: person_id__
19:41:01,460 DEBUG SessionImpl:1752 - loading [test.Person#11        ]
19:41:01,460 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#11        ]
19:41:01,470 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#11        ]
19:41:01,470 DEBUG StringType:65 - returning '12        ' as column: person_id
19:41:01,470 DEBUG Loader:260 - result row: 12        
19:41:01,480 DEBUG Loader:357 - Initializing object from ResultSet: 12        
19:41:01,480 DEBUG Loader:413 - Hydrating entity: test.Person#12        
19:41:01,480 DEBUG StringType:65 - returning 'person12            ' as column: person_n2_
19:41:01,480 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,490 DEBUG StringType:65 - returning '12        ' as column: person_id__
19:41:01,500 DEBUG SessionImpl:1752 - loading [test.Person#12        ]
19:41:01,500 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#12        ]
19:41:01,500 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#12        ]
19:41:01,510 DEBUG StringType:65 - returning '13        ' as column: person_id
19:41:01,510 DEBUG Loader:260 - result row: 13        
19:41:01,510 DEBUG Loader:357 - Initializing object from ResultSet: 13        
19:41:01,530 DEBUG Loader:413 - Hydrating entity: test.Person#13        
19:41:01,540 DEBUG StringType:65 - returning 'person13            ' as column: person_n2_
19:41:01,540 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,540 DEBUG StringType:65 - returning '13        ' as column: person_id__
19:41:01,550 DEBUG SessionImpl:1752 - loading [test.Person#13        ]
19:41:01,550 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#13        ]
19:41:01,550 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#13        ]
19:41:01,560 DEBUG StringType:65 - returning '14        ' as column: person_id
19:41:01,560 DEBUG Loader:260 - result row: 14        
19:41:01,560 DEBUG Loader:357 - Initializing object from ResultSet: 14        
19:41:01,570 DEBUG Loader:413 - Hydrating entity: test.Person#14        
19:41:01,570 DEBUG StringType:65 - returning 'person14            ' as column: person_n2_
19:41:01,570 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,580 DEBUG StringType:65 - returning '14        ' as column: person_id__
19:41:01,580 DEBUG SessionImpl:1752 - loading [test.Person#14        ]
19:41:01,580 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#14        ]
19:41:01,590 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#14        ]
19:41:01,590 DEBUG StringType:65 - returning '15        ' as column: person_id
19:41:01,600 DEBUG Loader:260 - result row: 15        
19:41:01,600 DEBUG Loader:357 - Initializing object from ResultSet: 15        
19:41:01,600 DEBUG Loader:413 - Hydrating entity: test.Person#15        
19:41:01,600 DEBUG StringType:65 - returning 'person15            ' as column: person_n2_
19:41:01,610 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,610 DEBUG StringType:65 - returning '15        ' as column: person_id__
19:41:01,620 DEBUG SessionImpl:1752 - loading [test.Person#15        ]
19:41:01,620 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#15        ]
19:41:01,630 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#15        ]
19:41:01,650 DEBUG Loader:182 - done processing result set (5 rows)
19:41:01,650 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,650 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,650 DEBUG Loader:195 - total objects hydrated: 5
19:41:01,660 DEBUG SessionImpl:1954 - resolving associations for [test.Person#11        ]
19:41:01,660 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:01,660 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:01,671 DEBUG SessionImpl:1887 - object not resolved in any cache [test.Group#1         ]
19:41:01,671 DEBUG EntityPersister:394 - Materializing entity: test.Group#1         
19:41:01,681 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:01,681 DEBUG SessionFactoryImpl:526 - prepared statement get: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
19:41:01,681 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,691 DEBUG StringType:44 - binding '1         ' to parameter: 1
19:41:01,691 DEBUG Loader:148 - processing result set
19:41:01,711 DEBUG Loader:260 - result row: 1         
19:41:01,711 DEBUG Loader:357 - Initializing object from ResultSet: 1         
19:41:01,711 DEBUG Loader:413 - Hydrating entity: test.Group#1         
19:41:01,721 DEBUG StringType:65 - returning 'group1              ' as column: group_name
19:41:01,721 DEBUG Loader:182 - done processing result set (1 rows)
19:41:01,721 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,731 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,731 DEBUG Loader:195 - total objects hydrated: 1
19:41:01,741 DEBUG SessionImpl:1954 - resolving associations for [test.Group#1         ]
19:41:01,741 DEBUG SessionImpl:2888 - initializing collection [test.Group.persons#1         ]
19:41:01,741 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:01,771 DEBUG SessionFactoryImpl:526 - prepared statement get: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
Hibernate: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
19:41:01,791 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,791 DEBUG StringType:44 - binding '1         ' to parameter: 1
19:41:01,811 DEBUG Loader:148 - processing result set
19:41:01,811 DEBUG StringType:65 - returning '11        ' as column: person_id
19:41:01,821 DEBUG Loader:260 - result row: 11        
19:41:01,821 DEBUG StringType:65 - returning '11        ' as column: person_id__
19:41:01,821 DEBUG SessionImpl:1752 - loading [test.Person#11        ]
19:41:01,831 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#11        ]
19:41:01,831 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#11        ]
19:41:01,841 DEBUG StringType:65 - returning '12        ' as column: person_id
19:41:01,841 DEBUG Loader:260 - result row: 12        
19:41:01,841 DEBUG StringType:65 - returning '12        ' as column: person_id__
19:41:01,841 DEBUG SessionImpl:1752 - loading [test.Person#12        ]
19:41:01,851 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#12        ]
19:41:01,851 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#12        ]
19:41:01,861 DEBUG StringType:65 - returning '13        ' as column: person_id
19:41:01,871 DEBUG Loader:260 - result row: 13        
19:41:01,881 DEBUG StringType:65 - returning '13        ' as column: person_id__
19:41:01,881 DEBUG SessionImpl:1752 - loading [test.Person#13        ]
19:41:01,881 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#13        ]
19:41:01,901 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#13        ]
19:41:01,901 DEBUG StringType:65 - returning '14        ' as column: person_id
19:41:01,911 DEBUG Loader:260 - result row: 14        
19:41:01,911 DEBUG StringType:65 - returning '14        ' as column: person_id__
19:41:01,911 DEBUG SessionImpl:1752 - loading [test.Person#14        ]
19:41:01,921 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#14        ]
19:41:01,921 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#14        ]
19:41:01,931 DEBUG StringType:65 - returning '15        ' as column: person_id
19:41:01,931 DEBUG Loader:260 - result row: 15        
19:41:01,931 DEBUG StringType:65 - returning '15        ' as column: person_id__
19:41:01,941 DEBUG SessionImpl:1752 - loading [test.Person#15        ]
19:41:01,941 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#15        ]
19:41:01,951 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#15        ]
19:41:01,951 DEBUG Loader:182 - done processing result set (5 rows)
19:41:01,951 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,961 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,961 DEBUG Loader:195 - total objects hydrated: 0
19:41:01,961 DEBUG SessionImpl:1975 - done materializing entity [test.Group#1         ]
19:41:01,971 DEBUG SessionImpl:1975 - done materializing entity [test.Person#11        ]
19:41:01,991 DEBUG SessionImpl:1954 - resolving associations for [test.Person#12        ]
19:41:01,991 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:01,991 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:01,991 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,001 DEBUG SessionImpl:1975 - done materializing entity [test.Person#12        ]
19:41:02,001 DEBUG SessionImpl:1954 - resolving associations for [test.Person#13        ]
19:41:02,001 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:02,011 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:02,011 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,011 DEBUG SessionImpl:1975 - done materializing entity [test.Person#13        ]
19:41:02,021 DEBUG SessionImpl:1954 - resolving associations for [test.Person#14        ]
19:41:02,021 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:02,021 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:02,021 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,031 DEBUG SessionImpl:1975 - done materializing entity [test.Person#14        ]
19:41:02,031 DEBUG SessionImpl:1954 - resolving associations for [test.Person#15        ]
19:41:02,041 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:02,041 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:02,041 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,051 DEBUG SessionImpl:1975 - done materializing entity [test.Person#15        ]
19:41:02,051 DEBUG SessionImpl:1975 - done materializing entity [test.Group#1]
----------------------------------------------------------------------------------------------------------------------------------------

If hibernate have a trim() operator when dealing with SQLServerDialect, the problem will be corrected perfectly.


---------------------------------------------------------------------
JIRA INFORMATION:
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.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira

Message:

  A new issue has been created in JIRA.

---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-584


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-584
    Summary: Update and create schema and "not-null" properties for subclass
       Type: Bug

     Status: Unassigned
   Priority: Minor

    Project: Hibernate2
 Components: 
             core
   Versions:
             2.1 final

   Assignee: 
   Reporter: Robson Miranda

    Created: Sat, 27 Dec 2003 4:04 PM
    Updated: Sat, 27 Dec 2003 4:04 PM
Environment: Hibernate 2.1final, MaxDB 7.5.00.05

Description:
When using a mapping of one table per class hierarchy, the columns of the subclasses should not be created as "not-null", since not always all the columns of the table will be filled.

Thanks,
   Robson


---------------------------------------------------------------------
JIRA INFORMATION:
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.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira

Message:

  A new issue has been created in JIRA.

---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-585


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-585
    Summary: Queries with Session.createSQLQuery() require hard-coded table names
       Type: Improvement

     Status: Unassigned
   Priority: Minor

    Project: Hibernate2
 Components: 
             core
   Versions:
             2.1.1

   Assignee: 
   Reporter: Will Gayther

    Created: Sat, 27 Dec 2003 10:51 PM
    Updated: Sat, 27 Dec 2003 10:51 PM

Description:
The new sql queries run by calling Session.createSQLQuery() allow you to write an sql statement that refers to the properties of your objects, rather than having to remember or look up column names. Oddly though, they do require you to remember and hard-code the name of the table that stores the object(s) you're interested in, rather than letting you refer directly to the object you're interested in querying. For example:
"SELECT {cat.*} FROM CAT AS {cat} WHERE ROWNUM<10"
Notice that the table name "CAT" is hard-coded into the query. It would be much easier and abstract if I could refer to the name of the class rather than the name of the table. For example, like this:
"SELECT {cat.*} FROM {cat} AS {cat} WHERE ROWNUM<10"
Or, if that would add to much complication to the parser, than like this:
"SELECT {cat.*} FROM {table:cat} AS {cat} WHERE ROWNUM<10"

I've also discussed this issue somewhat on the forum:
http://forum.hibernate.org/viewtopic.php?p=2183641#2183641

What do you think?


---------------------------------------------------------------------
JIRA INFORMATION:
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.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira

The following comment has been added to this issue:

     Author: Max Rydahl Andersen
    Created: Sat, 27 Dec 2003 4:33 AM
       Body:
posted in the thread also:
The sql update thingy is MESSY since what you are actually asking for is "bulk-update", which Hibernate (as it is an ORM) have a hard time fullfilling because it respect the lifecycle of objects - and thus need to reload objects etc. 

IF this should be provided currently, it would be a small helper-class that exposes the sql alias replacement stuff....but that ain't nice ;)
---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-581


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-581
    Summary: Add ability to use hibernate syntax to do an "update"
       Type: Improvement

     Status: Unassigned
   Priority: Minor

    Project: Hibernate2
 Components: 
             core
   Versions:
             2.1.1

   Assignee: 
   Reporter: Will Gayther

    Created: Sat, 27 Dec 2003 12:03 AM
    Updated: Sat, 27 Dec 2003 4:33 AM

Description:
Hibernate has several ways of writing abstract queries in a query language - native sql, the new psuedo-sql query through session.createSQLQuery(), and hql. Changes to the database are typically made by loading the object(s) to change, changing them, and resaving them to the database.

However, there are a few cases where this is incredibly inefficient. For example, I have a large number of "Link" objects in the database. Each link has a "displayIndex" - a long value that is used to determine which Links are displayed first. Naturally, I allow the user to change this ordering themselves. However, if there are a large number of links, and the user wants to move a link from the bottom of the ordering to the top, it would be extremely inefficient to load all of the links in-between the two spots, change all of their displayIndex's, then resave them, when sql like:
"update linkTable set displayIndex = displayIndex - 1 where displayIndex <= ? and displayIndex > ?"
would do the job much more efficiently with much less database traffic.

Of course, you can do this with straight sql. But that requires you to look up table names, column names, etc which breaks the abstraction which is the reason for using Hibernate in the first place.

What I propose is that you add a method, Session.createSQLUpdate(), that allows you to create and execute an sql update using the same syntax you that is used for Session.createSQLQuery(), so that the above statement could be written as:
"update linkTable set {link.displayIndex} = {link.displayIndex} - 1 where {link.displayIndex} <= ? and {link.displayIndex} > ?"
I know that in this example, since the property names and the column names are identical, it doesn't seem to do much good. But they can be different, and to write the query as sql requires you to stop thinking about objects, and start thinking "Are the property names the same as the column names?". This, together with my post on abstracting the table name rather than hard coding it (http://forum.hibernate.org/viewtopic.php?p=2183636#2183636) I think this would help keep the hibernate abstraction from being broken.

I would think that you could reuse the exact same parser used for Session.createSQLQuery(), so it wouldn't require any significant extra work for you guys (otherwise I wouldn't bring it up because it probably wouldn't be worth the time to do). Perhaps I'm wrong, or there's already a better way - what do you think?


---------------------------------------------------------------------
JIRA INFORMATION:
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.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira

The following comment has been added to this issue:

     Author: Nick Heudecker
    Created: Sat, 27 Dec 2003 11:36 AM
       Body:
You're right of course, but I can never remember how to generate a patch file.  I'll look into it and try to attach it.
---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-579


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-579
    Summary: Patch AbstractQuery so that it supports parameter lists
       Type: Improvement

     Status: Unassigned
   Priority: Minor

    Project: Hibernate2
 Components: 
             core
   Versions:
             2.1
             2.0 final
             2.1.1

   Assignee: 
   Reporter: Nick Heudecker

    Created: Fri, 26 Dec 2003 11:42 AM
    Updated: Sat, 27 Dec 2003 11:36 AM
Environment: Any

Description:
Currently, the AbstractQuery class doesn't take into account setting parameter lists when using the 'setProperties(Object)' method.  This would be extremely helpful to me.  A patch is below.

public Query setProperties(Object bean) throws HibernateException {
  Class clazz = bean.getClass();
  String[] params = getNamedParameters();
  for (int i = 0; i < params.length; i++) {
    String namedParam = params[i];
    try {
      Getter getter = ReflectHelper.getter(clazz, namedParam);
      Class retType = getter.getReturnType();
      if (retType.isArray() || 
          retType instanceof java.util.Collection) {
        setParameterList( namedParam, getter.get(bean) );
      }                                                                                                             
      else {
        setParameter( namedParam, getter.get(bean), 
                      guessType( getter.getReturnType() ) );
      }                                                                                                                 
    }                                                                                                                                  
    catch (PropertyNotFoundException pnfe) {
      // shouldn't something be logged here....?
    }                                                                                                                      
  }                                                                                                                                  
  return this;
}                    




---------------------------------------------------------------------
JIRA INFORMATION:
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.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira

Message:

   The following issue has been closed.

   Resolver: Max Rydahl Andersen
       Date: Sat, 27 Dec 2003 11:42 AM

duplicate af HB-484
---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-583


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-583
    Summary: Subclass.java and MSSQL JDBC driver cause a reread exception.
       Type: Bug

     Status: Closed
   Priority: Minor
 Resolution: WON'T FIX

    Project: Hibernate2
 Components: 
             core
   Versions:
             2.1.1

   Assignee: 
   Reporter: Eric Pugh

    Created: Sat, 27 Dec 2003 11:25 AM
    Updated: Sat, 27 Dec 2003 11:42 AM
Environment: Hibernate 2.1.1 and also the nightly build.  Using MS JDBC driver, both the  Service Pack 1 and Service Pack 2 versions.

Description:
Per my forum posting about MSSQL Throwing "ResultSet can not re-read row data for column 51.".

The MSSQL JDBC Driver throws an exception if you don't read left to right if you are quering columns that contain types IMAGE, NTEXT, or TEXT.  According to the JDBC API this actually okay:

For maximum portability, columns within a row should be read 
in left-to-right order, and each column should only be read once. This reflects implementation limitations in some underlying database protocols

The way around this is to use proxies and lazy loading to not load all the objects at once.  However, for joined-subclasses you have to.  The fix is to swap the order of the propertys are read  in Subclass.java:
public Iterator getPropertyClosureIterator() { 
return new JoinedIterator( new Iterator[] { 
getSuperclass().getPropertyClosureIterator(), 
getPropertyIterator()} 
); 
} 

However, I think that a better approch (but beyond me) is to use indexes instead of columns names.  Which I also believe is supposed to be faster for most JDBC drivers.

Eric Pugh



---------------------------------------------------------------------
JIRA INFORMATION:
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.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira

Message:

  A new issue has been created in JIRA.

---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-583


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-583
    Summary: Subclass.java and MSSQL JDBC driver cause a reread exception.
       Type: Bug

     Status: Unassigned
   Priority: Minor

    Project: Hibernate2
 Components: 
             core
   Versions:
             2.1.1

   Assignee: 
   Reporter: Eric Pugh

    Created: Sat, 27 Dec 2003 11:25 AM
    Updated: Sat, 27 Dec 2003 11:25 AM
Environment: Hibernate 2.1.1 and also the nightly build.  Using MS JDBC driver, both the  Service Pack 1 and Service Pack 2 versions.

Description:
Per my forum posting about MSSQL Throwing "ResultSet can not re-read row data for column 51.".

The MSSQL JDBC Driver throws an exception if you don't read left to right if you are quering columns that contain types IMAGE, NTEXT, or TEXT.  According to the JDBC API this actually okay:

For maximum portability, columns within a row should be read 
in left-to-right order, and each column should only be read once. This reflects implementation limitations in some underlying database protocols

The way around this is to use proxies and lazy loading to not load all the objects at once.  However, for joined-subclasses you have to.  The fix is to swap the order of the propertys are read  in Subclass.java:
public Iterator getPropertyClosureIterator() { 
return new JoinedIterator( new Iterator[] { 
getSuperclass().getPropertyClosureIterator(), 
getPropertyIterator()} 
); 
} 

However, I think that a better approch (but beyond me) is to use indexes instead of columns names.  Which I also believe is supposed to be faster for most JDBC drivers.

Eric Pugh



---------------------------------------------------------------------
JIRA INFORMATION:
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.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira

Message:

   The following issue has been re-assigned.

   Assignee: Gavin King (mailto:gavin@...)
   Assigner: Max Rydahl Andersen (mailto:xampub@...)
       Date: Sat, 27 Dec 2003 7:50 AM
    Comment:
The solution is probably not to trim() since we really do not like to change the scalars returned via JDBC - some people might EXPECT the padded stuff to be there!

I guess the issue relates to the new caching stuff, maybe one of our cache providers does the trim or something ? Throwing it to gavin ;)


---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-582


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-582
    Summary: Extra ' ' when read char type field in SQLServer 2000 
       Type: Bug

     Status: Open
   Priority: Critical

    Project: Hibernate2
 Components: 
             core
   Versions:
             2.1.1

   Assignee: Gavin King
   Reporter: Shining

    Created: Sat, 27 Dec 2003 7:33 AM
    Updated: Sat, 27 Dec 2003 7:50 AM
Environment: Windows2000 Professional with SP4, JDK 1.4.2_02, Eclipse 2.1.2 Hibernate 2.1.1 SQLServer 2000 Desktop with SP2, Microsoft SQLServer JDBC Driver SP2

Description:
There's a strange phenomenon when using SQLServer2000. When you read a char field through JDBC(ODBC is the same), the result were padded with extra blankspace, the length of blank space is equal to the length of data character subtract from the length of the field. for example:
field type is: char(10), data character is '1', the result of read will be '1         '.  The same reading operator in MySQL is correct. Other Database server have not been tested. 

When I test the sample code(figure 1) with hibernate 2.1.1, I found a bug that course collection lost when load a class with the char type id and a collection field with the same id as the id column.

Hibernate 2.1.1 DEBUG&OUTPUT Information
----------------------------------------------------------------------------------------------------------------------------------------
19:49:19,902  INFO Environment:432 - Hibernate 2.1.1
19:49:19,952  INFO Environment:461 - hibernate.properties not found
19:49:20,042  INFO Environment:481 - using CGLIB reflection optimizer
19:49:20,102  INFO Configuration:843 - configuring from resource: /hibernate.cfg.xml
19:49:20,112  INFO Configuration:815 - Configuration resource: /hibernate.cfg.xml
......
19:49:37,428 DEBUG SessionFactoryImpl:196 - instantiated session factory
19:49:37,729 DEBUG SessionImpl:528 - opened session
19:49:37,739 DEBUG SessionImpl:1913 - loading [test.Group#1]
19:49:37,739 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1]
19:49:37,759 DEBUG SessionImpl:2043 - object not resolved in any cache [test.Group#1]
19:49:37,759 DEBUG EntityPersister:417 - Materializing entity: [test.Group#1]
19:49:37,779 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:49:37,779 DEBUG DriverManagerConnectionProvider:78 - total checked-out connections: 0
19:49:37,789 DEBUG DriverManagerConnectionProvider:84 - using pooled JDBC connection, pool size: 0
19:49:37,789 DEBUG SQL:223 - select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
19:49:37,789 DEBUG BatcherImpl:227 - preparing statement
19:49:38,239 DEBUG StringType:46 - binding '1' to parameter: 1
19:49:38,590 DEBUG Loader:196 - processing result set
19:49:38,590 DEBUG Loader:404 - result row: 1
19:49:38,610 DEBUG Loader:535 - Initializing object from ResultSet: 1
19:49:38,630 DEBUG Loader:604 - Hydrating entity: test.Group#1
19:49:38,650 DEBUG StringType:68 - returning 'group1              ' as column: group_name0_
19:49:38,660 DEBUG Loader:225 - done processing result set (1 rows)
19:49:38,680 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:49:38,680 DEBUG BatcherImpl:240 - closing statement
19:49:38,690 DEBUG Loader:238 - total objects hydrated: 1
19:49:38,700 DEBUG SessionImpl:2129 - resolving associations for [test.Group#1]
19:49:38,720 DEBUG SessionImpl:3746 - collection not cached
19:49:38,760 DEBUG SessionImpl:2153 - done materializing entity [test.Group#1]
19:49:38,760 DEBUG SessionImpl:3000 - initializing non-lazy collections
19:49:38,760 DEBUG SessionImpl:3132 - initializing collection [test.Group.persons#1]
19:49:38,770 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:49:38,770 DEBUG SQL:223 - select persons0_.person_id as person_id__, persons0_.group_id as group_id__, persons0_.person_id as person_id0_, persons0_.person_name as person_n2_0_, persons0_.group_id as group_id0_ from tbl_person persons0_ where persons0_.group_id=?
Hibernate: select persons0_.person_id as person_id__, persons0_.group_id as group_id__, persons0_.person_id as person_id0_, persons0_.person_name as person_n2_0_, persons0_.group_id as group_id0_ from tbl_person persons0_ where persons0_.group_id=?
19:49:38,790 DEBUG BatcherImpl:227 - preparing statement
19:49:38,790 DEBUG StringType:46 - binding '1' to parameter: 1
19:49:38,810 DEBUG Loader:326 - result set contains (possibly empty) collection: [test.Group.persons#1]
19:49:38,810 DEBUG SessionImpl:2902 - uninitialized collection: initializing
19:49:38,830 DEBUG Loader:196 - processing result set
19:49:38,840 DEBUG StringType:68 - returning '11        ' as column: person_id0_
19:49:38,840 DEBUG Loader:404 - result row: 11        
19:49:38,850 DEBUG Loader:535 - Initializing object from ResultSet: 11        
19:49:38,850 DEBUG Loader:604 - Hydrating entity: test.Person#11        
19:49:38,860 DEBUG StringType:68 - returning 'person11            ' as column: person_n2_0_
19:49:38,860 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:38,860 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:38,870 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:38,870 DEBUG SessionImpl:2914 - new collection: instantiating
19:49:38,870 DEBUG StringType:68 - returning '11        ' as column: person_id__
19:49:38,880 DEBUG SessionImpl:1913 - loading [test.Person#11        ]
19:49:38,890 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#11        ]
19:49:38,910 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#11        ]
19:49:38,910 DEBUG StringType:68 - returning '12        ' as column: person_id0_
19:49:38,910 DEBUG Loader:404 - result row: 12        
19:49:38,920 DEBUG Loader:535 - Initializing object from ResultSet: 12        
19:49:38,920 DEBUG Loader:604 - Hydrating entity: test.Person#12        
19:49:38,930 DEBUG StringType:68 - returning 'person12            ' as column: person_n2_0_
19:49:38,930 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:38,960 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:38,960 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:38,960 DEBUG SessionImpl:2925 - reading row
19:49:38,960 DEBUG StringType:68 - returning '12        ' as column: person_id__
19:49:39,001 DEBUG SessionImpl:1913 - loading [test.Person#12        ]
19:49:39,001 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#12        ]
19:49:39,011 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#12        ]
19:49:39,011 DEBUG StringType:68 - returning '13        ' as column: person_id0_
19:49:39,011 DEBUG Loader:404 - result row: 13        
19:49:39,021 DEBUG Loader:535 - Initializing object from ResultSet: 13        
19:49:39,021 DEBUG Loader:604 - Hydrating entity: test.Person#13        
19:49:39,021 DEBUG StringType:68 - returning 'person13            ' as column: person_n2_0_
19:49:39,021 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:39,031 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:39,031 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:39,041 DEBUG SessionImpl:2925 - reading row
19:49:39,041 DEBUG StringType:68 - returning '13        ' as column: person_id__
19:49:39,051 DEBUG SessionImpl:1913 - loading [test.Person#13        ]
19:49:39,071 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#13        ]
19:49:39,071 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#13        ]
19:49:39,081 DEBUG StringType:68 - returning '14        ' as column: person_id0_
19:49:39,091 DEBUG Loader:404 - result row: 14        
19:49:39,091 DEBUG Loader:535 - Initializing object from ResultSet: 14        
19:49:39,091 DEBUG Loader:604 - Hydrating entity: test.Person#14        
19:49:39,091 DEBUG StringType:68 - returning 'person14            ' as column: person_n2_0_
19:49:39,101 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:39,101 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:39,111 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:39,111 DEBUG SessionImpl:2925 - reading row
19:49:39,111 DEBUG StringType:68 - returning '14        ' as column: person_id__
19:49:39,131 DEBUG SessionImpl:1913 - loading [test.Person#14        ]
19:49:39,131 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#14        ]
19:49:39,131 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#14        ]
19:49:39,131 DEBUG StringType:68 - returning '15        ' as column: person_id0_
19:49:39,141 DEBUG Loader:404 - result row: 15        
19:49:39,141 DEBUG Loader:535 - Initializing object from ResultSet: 15        
19:49:39,151 DEBUG Loader:604 - Hydrating entity: test.Person#15        
19:49:39,151 DEBUG StringType:68 - returning 'person15            ' as column: person_n2_0_
19:49:39,161 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:39,161 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:39,161 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:39,171 DEBUG SessionImpl:2925 - reading row
19:49:39,201 DEBUG StringType:68 - returning '15        ' as column: person_id__
19:49:39,201 DEBUG SessionImpl:1913 - loading [test.Person#15        ]
19:49:39,211 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#15        ]
19:49:39,211 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#15        ]
19:49:39,221 DEBUG Loader:225 - done processing result set (5 rows)
19:49:39,221 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:49:39,221 DEBUG BatcherImpl:240 - closing statement
19:49:39,231 DEBUG Loader:238 - total objects hydrated: 5
19:49:39,231 DEBUG SessionImpl:2129 - resolving associations for [test.Person#11        ]
{****
19:49:39,241 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,241 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,241 DEBUG SessionImpl:2043 - object not resolved in any cache [test.Group#1         ]
***}
19:49:39,241 DEBUG EntityPersister:417 - Materializing entity: [test.Group#1         ]
19:49:39,251 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:49:39,251 DEBUG SQL:223 - select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
19:49:39,261 DEBUG BatcherImpl:227 - preparing statement
19:49:39,261 DEBUG StringType:46 - binding '1         ' to parameter: 1
19:49:39,281 DEBUG Loader:196 - processing result set
19:49:39,281 DEBUG Loader:404 - result row: 1         
19:49:39,281 DEBUG Loader:535 - Initializing object from ResultSet: 1         
19:49:39,291 DEBUG Loader:604 - Hydrating entity: test.Group#1         
19:49:39,321 DEBUG StringType:68 - returning 'group1              ' as column: group_name0_
19:49:39,321 DEBUG Loader:225 - done processing result set (1 rows)
19:49:39,331 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:49:39,331 DEBUG BatcherImpl:240 - closing statement
19:49:39,331 DEBUG Loader:238 - total objects hydrated: 1
19:49:39,341 DEBUG SessionImpl:2129 - resolving associations for [test.Group#1         ]
19:49:39,341 DEBUG SessionImpl:2153 - done materializing entity [test.Group#1         ]
19:49:39,351 DEBUG SessionImpl:2153 - done materializing entity [test.Person#11        ]
19:49:39,351 DEBUG SessionImpl:2129 - resolving associations for [test.Person#12        ]
19:49:39,351 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,361 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,361 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,371 DEBUG SessionImpl:2153 - done materializing entity [test.Person#12        ]
19:49:39,371 DEBUG SessionImpl:2129 - resolving associations for [test.Person#13        ]
19:49:39,381 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,381 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,381 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,381 DEBUG SessionImpl:2153 - done materializing entity [test.Person#13        ]
19:49:39,391 DEBUG SessionImpl:2129 - resolving associations for [test.Person#14        ]
19:49:39,391 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,401 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,401 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,411 DEBUG SessionImpl:2153 - done materializing entity [test.Person#14        ]
19:49:39,411 DEBUG SessionImpl:2129 - resolving associations for [test.Person#15        ]
19:49:39,441 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,441 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,441 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,451 DEBUG SessionImpl:2153 - done materializing entity [test.Person#15        ]
19:49:39,451 DEBUG SessionImpl:2961 - 2 collections were found in result set
19:49:39,461 DEBUG SessionImpl:2979 - collection fully initialized: [test.Group.persons#1         ]
19:49:39,461 DEBUG SessionImpl:2979 - collection fully initialized: [test.Group.persons#1]
19:49:39,461 DEBUG SessionImpl:2982 - 2 collections initialized
----------------------------------------------------------------------------------------------------------------------------------------
The message in {**** ***} show the problem reson. Because of the strange behavior of the jdbc driver of SQLServer, the object id in the cache is "1"(load(group.class, "1")), the id read through jdbc is "1        ", hibernate can not got the group object from the cache. 

I have test the same code with the hibernate version 2.0.3, the result is correct, the debug information is:
Hibernate 2.0.3 DEBUG&OUTPUT Information
----------------------------------------------------------------------------------------------------------------------------------------
19:40:48,701  INFO Environment:403 - Hibernate 2.0.3
19:40:48,721  INFO Environment:432 - hibernate.properties not found
19:40:48,751  INFO Environment:452 - using CGLIB reflection optimizer
19:40:48,761  INFO Environment:462 - JVM proxy support: true
19:40:48,791  INFO Configuration:703 - Configuration resource: /hibernate.cfg.xml
19:41:00,579  INFO SessionFactoryImpl:269 - Query language substitutions: {}
......
19:41:00,589 DEBUG SessionFactoryImpl:281 - instantiated session factory
19:41:00,749 DEBUG SessionImpl:413 - opened session
19:41:00,769 DEBUG SessionImpl:1752 - loading [test.Group#1]
19:41:00,769 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1]
19:41:00,789 DEBUG SessionImpl:1887 - object not resolved in any cache [test.Group#1]
19:41:00,789 DEBUG EntityPersister:394 - Materializing entity: test.Group#1
19:41:00,799 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:00,799 DEBUG DriverManagerConnectionProvider:77 - total checked-out connections: 0
19:41:00,799 DEBUG DriverManagerConnectionProvider:83 - using pooled JDBC connection, pool size: 0
19:41:00,809 DEBUG SessionFactoryImpl:526 - prepared statement get: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
19:41:00,809 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,160 DEBUG StringType:44 - binding '1' to parameter: 1
19:41:01,300 DEBUG Loader:148 - processing result set
19:41:01,310 DEBUG Loader:260 - result row: 1
19:41:01,310 DEBUG Loader:357 - Initializing object from ResultSet: 1
19:41:01,320 DEBUG Loader:413 - Hydrating entity: test.Group#1
19:41:01,320 DEBUG StringType:65 - returning 'group1              ' as column: group_name
19:41:01,330 DEBUG Loader:182 - done processing result set (1 rows)
19:41:01,340 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,350 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,350 DEBUG Loader:195 - total objects hydrated: 1
19:41:01,350 DEBUG SessionImpl:1954 - resolving associations for [test.Group#1]
19:41:01,390 DEBUG SessionImpl:2888 - initializing collection [test.Group.persons#1]
19:41:01,390 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:01,400 DEBUG SessionFactoryImpl:526 - prepared statement get: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
Hibernate: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
19:41:01,400 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,400 DEBUG StringType:44 - binding '1' to parameter: 1
19:41:01,430 DEBUG Loader:148 - processing result set
19:41:01,440 DEBUG StringType:65 - returning '11        ' as column: person_id
19:41:01,440 DEBUG Loader:260 - result row: 11        
19:41:01,440 DEBUG Loader:357 - Initializing object from ResultSet: 11        
19:41:01,440 DEBUG Loader:413 - Hydrating entity: test.Person#11        
19:41:01,450 DEBUG StringType:65 - returning 'person11            ' as column: person_n2_
19:41:01,450 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,450 DEBUG StringType:65 - returning '11        ' as column: person_id__
19:41:01,460 DEBUG SessionImpl:1752 - loading [test.Person#11        ]
19:41:01,460 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#11        ]
19:41:01,470 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#11        ]
19:41:01,470 DEBUG StringType:65 - returning '12        ' as column: person_id
19:41:01,470 DEBUG Loader:260 - result row: 12        
19:41:01,480 DEBUG Loader:357 - Initializing object from ResultSet: 12        
19:41:01,480 DEBUG Loader:413 - Hydrating entity: test.Person#12        
19:41:01,480 DEBUG StringType:65 - returning 'person12            ' as column: person_n2_
19:41:01,480 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,490 DEBUG StringType:65 - returning '12        ' as column: person_id__
19:41:01,500 DEBUG SessionImpl:1752 - loading [test.Person#12        ]
19:41:01,500 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#12        ]
19:41:01,500 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#12        ]
19:41:01,510 DEBUG StringType:65 - returning '13        ' as column: person_id
19:41:01,510 DEBUG Loader:260 - result row: 13        
19:41:01,510 DEBUG Loader:357 - Initializing object from ResultSet: 13        
19:41:01,530 DEBUG Loader:413 - Hydrating entity: test.Person#13        
19:41:01,540 DEBUG StringType:65 - returning 'person13            ' as column: person_n2_
19:41:01,540 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,540 DEBUG StringType:65 - returning '13        ' as column: person_id__
19:41:01,550 DEBUG SessionImpl:1752 - loading [test.Person#13        ]
19:41:01,550 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#13        ]
19:41:01,550 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#13        ]
19:41:01,560 DEBUG StringType:65 - returning '14        ' as column: person_id
19:41:01,560 DEBUG Loader:260 - result row: 14        
19:41:01,560 DEBUG Loader:357 - Initializing object from ResultSet: 14        
19:41:01,570 DEBUG Loader:413 - Hydrating entity: test.Person#14        
19:41:01,570 DEBUG StringType:65 - returning 'person14            ' as column: person_n2_
19:41:01,570 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,580 DEBUG StringType:65 - returning '14        ' as column: person_id__
19:41:01,580 DEBUG SessionImpl:1752 - loading [test.Person#14        ]
19:41:01,580 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#14        ]
19:41:01,590 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#14        ]
19:41:01,590 DEBUG StringType:65 - returning '15        ' as column: person_id
19:41:01,600 DEBUG Loader:260 - result row: 15        
19:41:01,600 DEBUG Loader:357 - Initializing object from ResultSet: 15        
19:41:01,600 DEBUG Loader:413 - Hydrating entity: test.Person#15        
19:41:01,600 DEBUG StringType:65 - returning 'person15            ' as column: person_n2_
19:41:01,610 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,610 DEBUG StringType:65 - returning '15        ' as column: person_id__
19:41:01,620 DEBUG SessionImpl:1752 - loading [test.Person#15        ]
19:41:01,620 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#15        ]
19:41:01,630 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#15        ]
19:41:01,650 DEBUG Loader:182 - done processing result set (5 rows)
19:41:01,650 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,650 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,650 DEBUG Loader:195 - total objects hydrated: 5
19:41:01,660 DEBUG SessionImpl:1954 - resolving associations for [test.Person#11        ]
19:41:01,660 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:01,660 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:01,671 DEBUG SessionImpl:1887 - object not resolved in any cache [test.Group#1         ]
19:41:01,671 DEBUG EntityPersister:394 - Materializing entity: test.Group#1         
19:41:01,681 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:01,681 DEBUG SessionFactoryImpl:526 - prepared statement get: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
19:41:01,681 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,691 DEBUG StringType:44 - binding '1         ' to parameter: 1
19:41:01,691 DEBUG Loader:148 - processing result set
19:41:01,711 DEBUG Loader:260 - result row: 1         
19:41:01,711 DEBUG Loader:357 - Initializing object from ResultSet: 1         
19:41:01,711 DEBUG Loader:413 - Hydrating entity: test.Group#1         
19:41:01,721 DEBUG StringType:65 - returning 'group1              ' as column: group_name
19:41:01,721 DEBUG Loader:182 - done processing result set (1 rows)
19:41:01,721 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,731 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,731 DEBUG Loader:195 - total objects hydrated: 1
19:41:01,741 DEBUG SessionImpl:1954 - resolving associations for [test.Group#1         ]
19:41:01,741 DEBUG SessionImpl:2888 - initializing collection [test.Group.persons#1         ]
19:41:01,741 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:01,771 DEBUG SessionFactoryImpl:526 - prepared statement get: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
Hibernate: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
19:41:01,791 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,791 DEBUG StringType:44 - binding '1         ' to parameter: 1
19:41:01,811 DEBUG Loader:148 - processing result set
19:41:01,811 DEBUG StringType:65 - returning '11        ' as column: person_id
19:41:01,821 DEBUG Loader:260 - result row: 11        
19:41:01,821 DEBUG StringType:65 - returning '11        ' as column: person_id__
19:41:01,821 DEBUG SessionImpl:1752 - loading [test.Person#11        ]
19:41:01,831 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#11        ]
19:41:01,831 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#11        ]
19:41:01,841 DEBUG StringType:65 - returning '12        ' as column: person_id
19:41:01,841 DEBUG Loader:260 - result row: 12        
19:41:01,841 DEBUG StringType:65 - returning '12        ' as column: person_id__
19:41:01,841 DEBUG SessionImpl:1752 - loading [test.Person#12        ]
19:41:01,851 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#12        ]
19:41:01,851 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#12        ]
19:41:01,861 DEBUG StringType:65 - returning '13        ' as column: person_id
19:41:01,871 DEBUG Loader:260 - result row: 13        
19:41:01,881 DEBUG StringType:65 - returning '13        ' as column: person_id__
19:41:01,881 DEBUG SessionImpl:1752 - loading [test.Person#13        ]
19:41:01,881 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#13        ]
19:41:01,901 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#13        ]
19:41:01,901 DEBUG StringType:65 - returning '14        ' as column: person_id
19:41:01,911 DEBUG Loader:260 - result row: 14        
19:41:01,911 DEBUG StringType:65 - returning '14        ' as column: person_id__
19:41:01,911 DEBUG SessionImpl:1752 - loading [test.Person#14        ]
19:41:01,921 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#14        ]
19:41:01,921 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#14        ]
19:41:01,931 DEBUG StringType:65 - returning '15        ' as column: person_id
19:41:01,931 DEBUG Loader:260 - result row: 15        
19:41:01,931 DEBUG StringType:65 - returning '15        ' as column: person_id__
19:41:01,941 DEBUG SessionImpl:1752 - loading [test.Person#15        ]
19:41:01,941 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#15        ]
19:41:01,951 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#15        ]
19:41:01,951 DEBUG Loader:182 - done processing result set (5 rows)
19:41:01,951 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,961 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,961 DEBUG Loader:195 - total objects hydrated: 0
19:41:01,961 DEBUG SessionImpl:1975 - done materializing entity [test.Group#1         ]
19:41:01,971 DEBUG SessionImpl:1975 - done materializing entity [test.Person#11        ]
19:41:01,991 DEBUG SessionImpl:1954 - resolving associations for [test.Person#12        ]
19:41:01,991 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:01,991 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:01,991 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,001 DEBUG SessionImpl:1975 - done materializing entity [test.Person#12        ]
19:41:02,001 DEBUG SessionImpl:1954 - resolving associations for [test.Person#13        ]
19:41:02,001 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:02,011 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:02,011 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,011 DEBUG SessionImpl:1975 - done materializing entity [test.Person#13        ]
19:41:02,021 DEBUG SessionImpl:1954 - resolving associations for [test.Person#14        ]
19:41:02,021 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:02,021 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:02,021 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,031 DEBUG SessionImpl:1975 - done materializing entity [test.Person#14        ]
19:41:02,031 DEBUG SessionImpl:1954 - resolving associations for [test.Person#15        ]
19:41:02,041 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:02,041 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:02,041 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,051 DEBUG SessionImpl:1975 - done materializing entity [test.Person#15        ]
19:41:02,051 DEBUG SessionImpl:1975 - done materializing entity [test.Group#1]
----------------------------------------------------------------------------------------------------------------------------------------

If hibernate have a trim() operator when dealing with SQLServerDialect, the problem will be corrected perfectly.


---------------------------------------------------------------------
JIRA INFORMATION:
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.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira

The following issue has been updated:

    Updater: Shining (mailto:nshi@...)
       Date: Sat, 27 Dec 2003 7:39 AM
    Changes:
             Attachment changed to HibernateTest.zip
    ---------------------------------------------------------------------
For a full history of the issue, see:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-582&page=history

---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-582


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-582
    Summary: Extra ' ' when read char type field in SQLServer 2000 
       Type: Bug

     Status: Unassigned
   Priority: Critical

    Project: Hibernate2
 Components: 
             core
   Versions:
             2.1.1

   Assignee: 
   Reporter: Shining

    Created: Sat, 27 Dec 2003 7:33 AM
    Updated: Sat, 27 Dec 2003 7:39 AM
Environment: Windows2000 Professional with SP4, JDK 1.4.2_02, Eclipse 2.1.2 Hibernate 2.1.1 SQLServer 2000 Desktop with SP2, Microsoft SQLServer JDBC Driver SP2

Description:
There's a strange phenomenon when using SQLServer2000. When you read a char field through JDBC(ODBC is the same), the result were padded with extra blankspace, the length of blank space is equal to the length of data character subtract from the length of the field. for example:
field type is: char(10), data character is '1', the result of read will be '1         '.  The same reading operator in MySQL is correct. Other Database server have not been tested. 

When I test the sample code(figure 1) with hibernate 2.1.1, I found a bug that course collection lost when load a class with the char type id and a collection field with the same id as the id column.

Hibernate 2.1.1 DEBUG&OUTPUT Information
----------------------------------------------------------------------------------------------------------------------------------------
19:49:19,902  INFO Environment:432 - Hibernate 2.1.1
19:49:19,952  INFO Environment:461 - hibernate.properties not found
19:49:20,042  INFO Environment:481 - using CGLIB reflection optimizer
19:49:20,102  INFO Configuration:843 - configuring from resource: /hibernate.cfg.xml
19:49:20,112  INFO Configuration:815 - Configuration resource: /hibernate.cfg.xml
......
19:49:37,428 DEBUG SessionFactoryImpl:196 - instantiated session factory
19:49:37,729 DEBUG SessionImpl:528 - opened session
19:49:37,739 DEBUG SessionImpl:1913 - loading [test.Group#1]
19:49:37,739 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1]
19:49:37,759 DEBUG SessionImpl:2043 - object not resolved in any cache [test.Group#1]
19:49:37,759 DEBUG EntityPersister:417 - Materializing entity: [test.Group#1]
19:49:37,779 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:49:37,779 DEBUG DriverManagerConnectionProvider:78 - total checked-out connections: 0
19:49:37,789 DEBUG DriverManagerConnectionProvider:84 - using pooled JDBC connection, pool size: 0
19:49:37,789 DEBUG SQL:223 - select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
19:49:37,789 DEBUG BatcherImpl:227 - preparing statement
19:49:38,239 DEBUG StringType:46 - binding '1' to parameter: 1
19:49:38,590 DEBUG Loader:196 - processing result set
19:49:38,590 DEBUG Loader:404 - result row: 1
19:49:38,610 DEBUG Loader:535 - Initializing object from ResultSet: 1
19:49:38,630 DEBUG Loader:604 - Hydrating entity: test.Group#1
19:49:38,650 DEBUG StringType:68 - returning 'group1              ' as column: group_name0_
19:49:38,660 DEBUG Loader:225 - done processing result set (1 rows)
19:49:38,680 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:49:38,680 DEBUG BatcherImpl:240 - closing statement
19:49:38,690 DEBUG Loader:238 - total objects hydrated: 1
19:49:38,700 DEBUG SessionImpl:2129 - resolving associations for [test.Group#1]
19:49:38,720 DEBUG SessionImpl:3746 - collection not cached
19:49:38,760 DEBUG SessionImpl:2153 - done materializing entity [test.Group#1]
19:49:38,760 DEBUG SessionImpl:3000 - initializing non-lazy collections
19:49:38,760 DEBUG SessionImpl:3132 - initializing collection [test.Group.persons#1]
19:49:38,770 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:49:38,770 DEBUG SQL:223 - select persons0_.person_id as person_id__, persons0_.group_id as group_id__, persons0_.person_id as person_id0_, persons0_.person_name as person_n2_0_, persons0_.group_id as group_id0_ from tbl_person persons0_ where persons0_.group_id=?
Hibernate: select persons0_.person_id as person_id__, persons0_.group_id as group_id__, persons0_.person_id as person_id0_, persons0_.person_name as person_n2_0_, persons0_.group_id as group_id0_ from tbl_person persons0_ where persons0_.group_id=?
19:49:38,790 DEBUG BatcherImpl:227 - preparing statement
19:49:38,790 DEBUG StringType:46 - binding '1' to parameter: 1
19:49:38,810 DEBUG Loader:326 - result set contains (possibly empty) collection: [test.Group.persons#1]
19:49:38,810 DEBUG SessionImpl:2902 - uninitialized collection: initializing
19:49:38,830 DEBUG Loader:196 - processing result set
19:49:38,840 DEBUG StringType:68 - returning '11        ' as column: person_id0_
19:49:38,840 DEBUG Loader:404 - result row: 11        
19:49:38,850 DEBUG Loader:535 - Initializing object from ResultSet: 11        
19:49:38,850 DEBUG Loader:604 - Hydrating entity: test.Person#11        
19:49:38,860 DEBUG StringType:68 - returning 'person11            ' as column: person_n2_0_
19:49:38,860 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:38,860 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:38,870 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:38,870 DEBUG SessionImpl:2914 - new collection: instantiating
19:49:38,870 DEBUG StringType:68 - returning '11        ' as column: person_id__
19:49:38,880 DEBUG SessionImpl:1913 - loading [test.Person#11        ]
19:49:38,890 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#11        ]
19:49:38,910 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#11        ]
19:49:38,910 DEBUG StringType:68 - returning '12        ' as column: person_id0_
19:49:38,910 DEBUG Loader:404 - result row: 12        
19:49:38,920 DEBUG Loader:535 - Initializing object from ResultSet: 12        
19:49:38,920 DEBUG Loader:604 - Hydrating entity: test.Person#12        
19:49:38,930 DEBUG StringType:68 - returning 'person12            ' as column: person_n2_0_
19:49:38,930 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:38,960 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:38,960 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:38,960 DEBUG SessionImpl:2925 - reading row
19:49:38,960 DEBUG StringType:68 - returning '12        ' as column: person_id__
19:49:39,001 DEBUG SessionImpl:1913 - loading [test.Person#12        ]
19:49:39,001 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#12        ]
19:49:39,011 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#12        ]
19:49:39,011 DEBUG StringType:68 - returning '13        ' as column: person_id0_
19:49:39,011 DEBUG Loader:404 - result row: 13        
19:49:39,021 DEBUG Loader:535 - Initializing object from ResultSet: 13        
19:49:39,021 DEBUG Loader:604 - Hydrating entity: test.Person#13        
19:49:39,021 DEBUG StringType:68 - returning 'person13            ' as column: person_n2_0_
19:49:39,021 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:39,031 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:39,031 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:39,041 DEBUG SessionImpl:2925 - reading row
19:49:39,041 DEBUG StringType:68 - returning '13        ' as column: person_id__
19:49:39,051 DEBUG SessionImpl:1913 - loading [test.Person#13        ]
19:49:39,071 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#13        ]
19:49:39,071 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#13        ]
19:49:39,081 DEBUG StringType:68 - returning '14        ' as column: person_id0_
19:49:39,091 DEBUG Loader:404 - result row: 14        
19:49:39,091 DEBUG Loader:535 - Initializing object from ResultSet: 14        
19:49:39,091 DEBUG Loader:604 - Hydrating entity: test.Person#14        
19:49:39,091 DEBUG StringType:68 - returning 'person14            ' as column: person_n2_0_
19:49:39,101 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:39,101 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:39,111 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:39,111 DEBUG SessionImpl:2925 - reading row
19:49:39,111 DEBUG StringType:68 - returning '14        ' as column: person_id__
19:49:39,131 DEBUG SessionImpl:1913 - loading [test.Person#14        ]
19:49:39,131 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#14        ]
19:49:39,131 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#14        ]
19:49:39,131 DEBUG StringType:68 - returning '15        ' as column: person_id0_
19:49:39,141 DEBUG Loader:404 - result row: 15        
19:49:39,141 DEBUG Loader:535 - Initializing object from ResultSet: 15        
19:49:39,151 DEBUG Loader:604 - Hydrating entity: test.Person#15        
19:49:39,151 DEBUG StringType:68 - returning 'person15            ' as column: person_n2_0_
19:49:39,161 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:39,161 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:39,161 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:39,171 DEBUG SessionImpl:2925 - reading row
19:49:39,201 DEBUG StringType:68 - returning '15        ' as column: person_id__
19:49:39,201 DEBUG SessionImpl:1913 - loading [test.Person#15        ]
19:49:39,211 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#15        ]
19:49:39,211 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#15        ]
19:49:39,221 DEBUG Loader:225 - done processing result set (5 rows)
19:49:39,221 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:49:39,221 DEBUG BatcherImpl:240 - closing statement
19:49:39,231 DEBUG Loader:238 - total objects hydrated: 5
19:49:39,231 DEBUG SessionImpl:2129 - resolving associations for [test.Person#11        ]
{****
19:49:39,241 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,241 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,241 DEBUG SessionImpl:2043 - object not resolved in any cache [test.Group#1         ]
***}
19:49:39,241 DEBUG EntityPersister:417 - Materializing entity: [test.Group#1         ]
19:49:39,251 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:49:39,251 DEBUG SQL:223 - select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
19:49:39,261 DEBUG BatcherImpl:227 - preparing statement
19:49:39,261 DEBUG StringType:46 - binding '1         ' to parameter: 1
19:49:39,281 DEBUG Loader:196 - processing result set
19:49:39,281 DEBUG Loader:404 - result row: 1         
19:49:39,281 DEBUG Loader:535 - Initializing object from ResultSet: 1         
19:49:39,291 DEBUG Loader:604 - Hydrating entity: test.Group#1         
19:49:39,321 DEBUG StringType:68 - returning 'group1              ' as column: group_name0_
19:49:39,321 DEBUG Loader:225 - done processing result set (1 rows)
19:49:39,331 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:49:39,331 DEBUG BatcherImpl:240 - closing statement
19:49:39,331 DEBUG Loader:238 - total objects hydrated: 1
19:49:39,341 DEBUG SessionImpl:2129 - resolving associations for [test.Group#1         ]
19:49:39,341 DEBUG SessionImpl:2153 - done materializing entity [test.Group#1         ]
19:49:39,351 DEBUG SessionImpl:2153 - done materializing entity [test.Person#11        ]
19:49:39,351 DEBUG SessionImpl:2129 - resolving associations for [test.Person#12        ]
19:49:39,351 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,361 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,361 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,371 DEBUG SessionImpl:2153 - done materializing entity [test.Person#12        ]
19:49:39,371 DEBUG SessionImpl:2129 - resolving associations for [test.Person#13        ]
19:49:39,381 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,381 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,381 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,381 DEBUG SessionImpl:2153 - done materializing entity [test.Person#13        ]
19:49:39,391 DEBUG SessionImpl:2129 - resolving associations for [test.Person#14        ]
19:49:39,391 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,401 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,401 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,411 DEBUG SessionImpl:2153 - done materializing entity [test.Person#14        ]
19:49:39,411 DEBUG SessionImpl:2129 - resolving associations for [test.Person#15        ]
19:49:39,441 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,441 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,441 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,451 DEBUG SessionImpl:2153 - done materializing entity [test.Person#15        ]
19:49:39,451 DEBUG SessionImpl:2961 - 2 collections were found in result set
19:49:39,461 DEBUG SessionImpl:2979 - collection fully initialized: [test.Group.persons#1         ]
19:49:39,461 DEBUG SessionImpl:2979 - collection fully initialized: [test.Group.persons#1]
19:49:39,461 DEBUG SessionImpl:2982 - 2 collections initialized
----------------------------------------------------------------------------------------------------------------------------------------
The message in {**** ***} show the problem reson. Because of the strange behavior of the jdbc driver of SQLServer, the object id in the cache is "1"(load(group.class, "1")), the id read through jdbc is "1        ", hibernate can not got the group object from the cache. 

I have test the same code with the hibernate version 2.0.3, the result is correct, the debug information is:
Hibernate 2.0.3 DEBUG&OUTPUT Information
----------------------------------------------------------------------------------------------------------------------------------------
19:40:48,701  INFO Environment:403 - Hibernate 2.0.3
19:40:48,721  INFO Environment:432 - hibernate.properties not found
19:40:48,751  INFO Environment:452 - using CGLIB reflection optimizer
19:40:48,761  INFO Environment:462 - JVM proxy support: true
19:40:48,791  INFO Configuration:703 - Configuration resource: /hibernate.cfg.xml
19:41:00,579  INFO SessionFactoryImpl:269 - Query language substitutions: {}
......
19:41:00,589 DEBUG SessionFactoryImpl:281 - instantiated session factory
19:41:00,749 DEBUG SessionImpl:413 - opened session
19:41:00,769 DEBUG SessionImpl:1752 - loading [test.Group#1]
19:41:00,769 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1]
19:41:00,789 DEBUG SessionImpl:1887 - object not resolved in any cache [test.Group#1]
19:41:00,789 DEBUG EntityPersister:394 - Materializing entity: test.Group#1
19:41:00,799 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:00,799 DEBUG DriverManagerConnectionProvider:77 - total checked-out connections: 0
19:41:00,799 DEBUG DriverManagerConnectionProvider:83 - using pooled JDBC connection, pool size: 0
19:41:00,809 DEBUG SessionFactoryImpl:526 - prepared statement get: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
19:41:00,809 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,160 DEBUG StringType:44 - binding '1' to parameter: 1
19:41:01,300 DEBUG Loader:148 - processing result set
19:41:01,310 DEBUG Loader:260 - result row: 1
19:41:01,310 DEBUG Loader:357 - Initializing object from ResultSet: 1
19:41:01,320 DEBUG Loader:413 - Hydrating entity: test.Group#1
19:41:01,320 DEBUG StringType:65 - returning 'group1              ' as column: group_name
19:41:01,330 DEBUG Loader:182 - done processing result set (1 rows)
19:41:01,340 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,350 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,350 DEBUG Loader:195 - total objects hydrated: 1
19:41:01,350 DEBUG SessionImpl:1954 - resolving associations for [test.Group#1]
19:41:01,390 DEBUG SessionImpl:2888 - initializing collection [test.Group.persons#1]
19:41:01,390 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:01,400 DEBUG SessionFactoryImpl:526 - prepared statement get: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
Hibernate: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
19:41:01,400 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,400 DEBUG StringType:44 - binding '1' to parameter: 1
19:41:01,430 DEBUG Loader:148 - processing result set
19:41:01,440 DEBUG StringType:65 - returning '11        ' as column: person_id
19:41:01,440 DEBUG Loader:260 - result row: 11        
19:41:01,440 DEBUG Loader:357 - Initializing object from ResultSet: 11        
19:41:01,440 DEBUG Loader:413 - Hydrating entity: test.Person#11        
19:41:01,450 DEBUG StringType:65 - returning 'person11            ' as column: person_n2_
19:41:01,450 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,450 DEBUG StringType:65 - returning '11        ' as column: person_id__
19:41:01,460 DEBUG SessionImpl:1752 - loading [test.Person#11        ]
19:41:01,460 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#11        ]
19:41:01,470 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#11        ]
19:41:01,470 DEBUG StringType:65 - returning '12        ' as column: person_id
19:41:01,470 DEBUG Loader:260 - result row: 12        
19:41:01,480 DEBUG Loader:357 - Initializing object from ResultSet: 12        
19:41:01,480 DEBUG Loader:413 - Hydrating entity: test.Person#12        
19:41:01,480 DEBUG StringType:65 - returning 'person12            ' as column: person_n2_
19:41:01,480 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,490 DEBUG StringType:65 - returning '12        ' as column: person_id__
19:41:01,500 DEBUG SessionImpl:1752 - loading [test.Person#12        ]
19:41:01,500 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#12        ]
19:41:01,500 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#12        ]
19:41:01,510 DEBUG StringType:65 - returning '13        ' as column: person_id
19:41:01,510 DEBUG Loader:260 - result row: 13        
19:41:01,510 DEBUG Loader:357 - Initializing object from ResultSet: 13        
19:41:01,530 DEBUG Loader:413 - Hydrating entity: test.Person#13        
19:41:01,540 DEBUG StringType:65 - returning 'person13            ' as column: person_n2_
19:41:01,540 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,540 DEBUG StringType:65 - returning '13        ' as column: person_id__
19:41:01,550 DEBUG SessionImpl:1752 - loading [test.Person#13        ]
19:41:01,550 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#13        ]
19:41:01,550 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#13        ]
19:41:01,560 DEBUG StringType:65 - returning '14        ' as column: person_id
19:41:01,560 DEBUG Loader:260 - result row: 14        
19:41:01,560 DEBUG Loader:357 - Initializing object from ResultSet: 14        
19:41:01,570 DEBUG Loader:413 - Hydrating entity: test.Person#14        
19:41:01,570 DEBUG StringType:65 - returning 'person14            ' as column: person_n2_
19:41:01,570 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,580 DEBUG StringType:65 - returning '14        ' as column: person_id__
19:41:01,580 DEBUG SessionImpl:1752 - loading [test.Person#14        ]
19:41:01,580 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#14        ]
19:41:01,590 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#14        ]
19:41:01,590 DEBUG StringType:65 - returning '15        ' as column: person_id
19:41:01,600 DEBUG Loader:260 - result row: 15        
19:41:01,600 DEBUG Loader:357 - Initializing object from ResultSet: 15        
19:41:01,600 DEBUG Loader:413 - Hydrating entity: test.Person#15        
19:41:01,600 DEBUG StringType:65 - returning 'person15            ' as column: person_n2_
19:41:01,610 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,610 DEBUG StringType:65 - returning '15        ' as column: person_id__
19:41:01,620 DEBUG SessionImpl:1752 - loading [test.Person#15        ]
19:41:01,620 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#15        ]
19:41:01,630 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#15        ]
19:41:01,650 DEBUG Loader:182 - done processing result set (5 rows)
19:41:01,650 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,650 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,650 DEBUG Loader:195 - total objects hydrated: 5
19:41:01,660 DEBUG SessionImpl:1954 - resolving associations for [test.Person#11        ]
19:41:01,660 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:01,660 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:01,671 DEBUG SessionImpl:1887 - object not resolved in any cache [test.Group#1         ]
19:41:01,671 DEBUG EntityPersister:394 - Materializing entity: test.Group#1         
19:41:01,681 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:01,681 DEBUG SessionFactoryImpl:526 - prepared statement get: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
19:41:01,681 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,691 DEBUG StringType:44 - binding '1         ' to parameter: 1
19:41:01,691 DEBUG Loader:148 - processing result set
19:41:01,711 DEBUG Loader:260 - result row: 1         
19:41:01,711 DEBUG Loader:357 - Initializing object from ResultSet: 1         
19:41:01,711 DEBUG Loader:413 - Hydrating entity: test.Group#1         
19:41:01,721 DEBUG StringType:65 - returning 'group1              ' as column: group_name
19:41:01,721 DEBUG Loader:182 - done processing result set (1 rows)
19:41:01,721 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,731 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,731 DEBUG Loader:195 - total objects hydrated: 1
19:41:01,741 DEBUG SessionImpl:1954 - resolving associations for [test.Group#1         ]
19:41:01,741 DEBUG SessionImpl:2888 - initializing collection [test.Group.persons#1         ]
19:41:01,741 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:01,771 DEBUG SessionFactoryImpl:526 - prepared statement get: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
Hibernate: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
19:41:01,791 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,791 DEBUG StringType:44 - binding '1         ' to parameter: 1
19:41:01,811 DEBUG Loader:148 - processing result set
19:41:01,811 DEBUG StringType:65 - returning '11        ' as column: person_id
19:41:01,821 DEBUG Loader:260 - result row: 11        
19:41:01,821 DEBUG StringType:65 - returning '11        ' as column: person_id__
19:41:01,821 DEBUG SessionImpl:1752 - loading [test.Person#11        ]
19:41:01,831 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#11        ]
19:41:01,831 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#11        ]
19:41:01,841 DEBUG StringType:65 - returning '12        ' as column: person_id
19:41:01,841 DEBUG Loader:260 - result row: 12        
19:41:01,841 DEBUG StringType:65 - returning '12        ' as column: person_id__
19:41:01,841 DEBUG SessionImpl:1752 - loading [test.Person#12        ]
19:41:01,851 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#12        ]
19:41:01,851 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#12        ]
19:41:01,861 DEBUG StringType:65 - returning '13        ' as column: person_id
19:41:01,871 DEBUG Loader:260 - result row: 13        
19:41:01,881 DEBUG StringType:65 - returning '13        ' as column: person_id__
19:41:01,881 DEBUG SessionImpl:1752 - loading [test.Person#13        ]
19:41:01,881 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#13        ]
19:41:01,901 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#13        ]
19:41:01,901 DEBUG StringType:65 - returning '14        ' as column: person_id
19:41:01,911 DEBUG Loader:260 - result row: 14        
19:41:01,911 DEBUG StringType:65 - returning '14        ' as column: person_id__
19:41:01,911 DEBUG SessionImpl:1752 - loading [test.Person#14        ]
19:41:01,921 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#14        ]
19:41:01,921 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#14        ]
19:41:01,931 DEBUG StringType:65 - returning '15        ' as column: person_id
19:41:01,931 DEBUG Loader:260 - result row: 15        
19:41:01,931 DEBUG StringType:65 - returning '15        ' as column: person_id__
19:41:01,941 DEBUG SessionImpl:1752 - loading [test.Person#15        ]
19:41:01,941 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#15        ]
19:41:01,951 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#15        ]
19:41:01,951 DEBUG Loader:182 - done processing result set (5 rows)
19:41:01,951 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,961 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,961 DEBUG Loader:195 - total objects hydrated: 0
19:41:01,961 DEBUG SessionImpl:1975 - done materializing entity [test.Group#1         ]
19:41:01,971 DEBUG SessionImpl:1975 - done materializing entity [test.Person#11        ]
19:41:01,991 DEBUG SessionImpl:1954 - resolving associations for [test.Person#12        ]
19:41:01,991 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:01,991 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:01,991 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,001 DEBUG SessionImpl:1975 - done materializing entity [test.Person#12        ]
19:41:02,001 DEBUG SessionImpl:1954 - resolving associations for [test.Person#13        ]
19:41:02,001 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:02,011 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:02,011 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,011 DEBUG SessionImpl:1975 - done materializing entity [test.Person#13        ]
19:41:02,021 DEBUG SessionImpl:1954 - resolving associations for [test.Person#14        ]
19:41:02,021 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:02,021 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:02,021 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,031 DEBUG SessionImpl:1975 - done materializing entity [test.Person#14        ]
19:41:02,031 DEBUG SessionImpl:1954 - resolving associations for [test.Person#15        ]
19:41:02,041 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:02,041 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:02,041 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,051 DEBUG SessionImpl:1975 - done materializing entity [test.Person#15        ]
19:41:02,051 DEBUG SessionImpl:1975 - done materializing entity [test.Group#1]
----------------------------------------------------------------------------------------------------------------------------------------

If hibernate have a trim() operator when dealing with SQLServerDialect, the problem will be corrected perfectly.


---------------------------------------------------------------------
JIRA INFORMATION:
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.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira

Message:

  A new issue has been created in JIRA.

---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-582


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-582
    Summary: Extra ' ' when read char type field in SQLServer 2000 
       Type: Bug

     Status: Unassigned
   Priority: Critical

    Project: Hibernate2
 Components: 
             core
   Versions:
             2.1.1

   Assignee: 
   Reporter: Shining

    Created: Sat, 27 Dec 2003 7:33 AM
    Updated: Sat, 27 Dec 2003 7:33 AM
Environment: Windows2000 Professional with SP4, JDK 1.4.2_02, Eclipse 2.1.2 Hibernate 2.1.1 SQLServer 2000 Desktop with SP2, Microsoft SQLServer JDBC Driver SP2

Description:
There's a strange phenomenon when using SQLServer2000. When you read a char field through JDBC(ODBC is the same), the result were padded with extra blankspace, the length of blank space is equal to the length of data character subtract from the length of the field. for example:
field type is: char(10), data character is '1', the result of read will be '1         '.  The same reading operator in MySQL is correct. Other Database server have not been tested. 

When I test the sample code(figure 1) with hibernate 2.1.1, I found a bug that course collection lost when load a class with the char type id and a collection field with the same id as the id column.

Hibernate 2.1.1 DEBUG&OUTPUT Information
----------------------------------------------------------------------------------------------------------------------------------------
19:49:19,902  INFO Environment:432 - Hibernate 2.1.1
19:49:19,952  INFO Environment:461 - hibernate.properties not found
19:49:20,042  INFO Environment:481 - using CGLIB reflection optimizer
19:49:20,102  INFO Configuration:843 - configuring from resource: /hibernate.cfg.xml
19:49:20,112  INFO Configuration:815 - Configuration resource: /hibernate.cfg.xml
......
19:49:37,428 DEBUG SessionFactoryImpl:196 - instantiated session factory
19:49:37,729 DEBUG SessionImpl:528 - opened session
19:49:37,739 DEBUG SessionImpl:1913 - loading [test.Group#1]
19:49:37,739 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1]
19:49:37,759 DEBUG SessionImpl:2043 - object not resolved in any cache [test.Group#1]
19:49:37,759 DEBUG EntityPersister:417 - Materializing entity: [test.Group#1]
19:49:37,779 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:49:37,779 DEBUG DriverManagerConnectionProvider:78 - total checked-out connections: 0
19:49:37,789 DEBUG DriverManagerConnectionProvider:84 - using pooled JDBC connection, pool size: 0
19:49:37,789 DEBUG SQL:223 - select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
19:49:37,789 DEBUG BatcherImpl:227 - preparing statement
19:49:38,239 DEBUG StringType:46 - binding '1' to parameter: 1
19:49:38,590 DEBUG Loader:196 - processing result set
19:49:38,590 DEBUG Loader:404 - result row: 1
19:49:38,610 DEBUG Loader:535 - Initializing object from ResultSet: 1
19:49:38,630 DEBUG Loader:604 - Hydrating entity: test.Group#1
19:49:38,650 DEBUG StringType:68 - returning 'group1              ' as column: group_name0_
19:49:38,660 DEBUG Loader:225 - done processing result set (1 rows)
19:49:38,680 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:49:38,680 DEBUG BatcherImpl:240 - closing statement
19:49:38,690 DEBUG Loader:238 - total objects hydrated: 1
19:49:38,700 DEBUG SessionImpl:2129 - resolving associations for [test.Group#1]
19:49:38,720 DEBUG SessionImpl:3746 - collection not cached
19:49:38,760 DEBUG SessionImpl:2153 - done materializing entity [test.Group#1]
19:49:38,760 DEBUG SessionImpl:3000 - initializing non-lazy collections
19:49:38,760 DEBUG SessionImpl:3132 - initializing collection [test.Group.persons#1]
19:49:38,770 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:49:38,770 DEBUG SQL:223 - select persons0_.person_id as person_id__, persons0_.group_id as group_id__, persons0_.person_id as person_id0_, persons0_.person_name as person_n2_0_, persons0_.group_id as group_id0_ from tbl_person persons0_ where persons0_.group_id=?
Hibernate: select persons0_.person_id as person_id__, persons0_.group_id as group_id__, persons0_.person_id as person_id0_, persons0_.person_name as person_n2_0_, persons0_.group_id as group_id0_ from tbl_person persons0_ where persons0_.group_id=?
19:49:38,790 DEBUG BatcherImpl:227 - preparing statement
19:49:38,790 DEBUG StringType:46 - binding '1' to parameter: 1
19:49:38,810 DEBUG Loader:326 - result set contains (possibly empty) collection: [test.Group.persons#1]
19:49:38,810 DEBUG SessionImpl:2902 - uninitialized collection: initializing
19:49:38,830 DEBUG Loader:196 - processing result set
19:49:38,840 DEBUG StringType:68 - returning '11        ' as column: person_id0_
19:49:38,840 DEBUG Loader:404 - result row: 11        
19:49:38,850 DEBUG Loader:535 - Initializing object from ResultSet: 11        
19:49:38,850 DEBUG Loader:604 - Hydrating entity: test.Person#11        
19:49:38,860 DEBUG StringType:68 - returning 'person11            ' as column: person_n2_0_
19:49:38,860 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:38,860 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:38,870 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:38,870 DEBUG SessionImpl:2914 - new collection: instantiating
19:49:38,870 DEBUG StringType:68 - returning '11        ' as column: person_id__
19:49:38,880 DEBUG SessionImpl:1913 - loading [test.Person#11        ]
19:49:38,890 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#11        ]
19:49:38,910 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#11        ]
19:49:38,910 DEBUG StringType:68 - returning '12        ' as column: person_id0_
19:49:38,910 DEBUG Loader:404 - result row: 12        
19:49:38,920 DEBUG Loader:535 - Initializing object from ResultSet: 12        
19:49:38,920 DEBUG Loader:604 - Hydrating entity: test.Person#12        
19:49:38,930 DEBUG StringType:68 - returning 'person12            ' as column: person_n2_0_
19:49:38,930 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:38,960 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:38,960 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:38,960 DEBUG SessionImpl:2925 - reading row
19:49:38,960 DEBUG StringType:68 - returning '12        ' as column: person_id__
19:49:39,001 DEBUG SessionImpl:1913 - loading [test.Person#12        ]
19:49:39,001 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#12        ]
19:49:39,011 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#12        ]
19:49:39,011 DEBUG StringType:68 - returning '13        ' as column: person_id0_
19:49:39,011 DEBUG Loader:404 - result row: 13        
19:49:39,021 DEBUG Loader:535 - Initializing object from ResultSet: 13        
19:49:39,021 DEBUG Loader:604 - Hydrating entity: test.Person#13        
19:49:39,021 DEBUG StringType:68 - returning 'person13            ' as column: person_n2_0_
19:49:39,021 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:39,031 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:39,031 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:39,041 DEBUG SessionImpl:2925 - reading row
19:49:39,041 DEBUG StringType:68 - returning '13        ' as column: person_id__
19:49:39,051 DEBUG SessionImpl:1913 - loading [test.Person#13        ]
19:49:39,071 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#13        ]
19:49:39,071 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#13        ]
19:49:39,081 DEBUG StringType:68 - returning '14        ' as column: person_id0_
19:49:39,091 DEBUG Loader:404 - result row: 14        
19:49:39,091 DEBUG Loader:535 - Initializing object from ResultSet: 14        
19:49:39,091 DEBUG Loader:604 - Hydrating entity: test.Person#14        
19:49:39,091 DEBUG StringType:68 - returning 'person14            ' as column: person_n2_0_
19:49:39,101 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:39,101 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:39,111 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:39,111 DEBUG SessionImpl:2925 - reading row
19:49:39,111 DEBUG StringType:68 - returning '14        ' as column: person_id__
19:49:39,131 DEBUG SessionImpl:1913 - loading [test.Person#14        ]
19:49:39,131 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#14        ]
19:49:39,131 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#14        ]
19:49:39,131 DEBUG StringType:68 - returning '15        ' as column: person_id0_
19:49:39,141 DEBUG Loader:404 - result row: 15        
19:49:39,141 DEBUG Loader:535 - Initializing object from ResultSet: 15        
19:49:39,151 DEBUG Loader:604 - Hydrating entity: test.Person#15        
19:49:39,151 DEBUG StringType:68 - returning 'person15            ' as column: person_n2_0_
19:49:39,161 DEBUG StringType:68 - returning '1         ' as column: group_id0_
19:49:39,161 DEBUG StringType:68 - returning '1         ' as column: group_id__
19:49:39,161 DEBUG Loader:288 - found row of collection: [test.Group.persons#1         ]
19:49:39,171 DEBUG SessionImpl:2925 - reading row
19:49:39,201 DEBUG StringType:68 - returning '15        ' as column: person_id__
19:49:39,201 DEBUG SessionImpl:1913 - loading [test.Person#15        ]
19:49:39,211 DEBUG SessionImpl:2010 - attempting to resolve [test.Person#15        ]
19:49:39,211 DEBUG SessionImpl:2026 - resolved object in session cache [test.Person#15        ]
19:49:39,221 DEBUG Loader:225 - done processing result set (5 rows)
19:49:39,221 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:49:39,221 DEBUG BatcherImpl:240 - closing statement
19:49:39,231 DEBUG Loader:238 - total objects hydrated: 5
19:49:39,231 DEBUG SessionImpl:2129 - resolving associations for [test.Person#11        ]
{****
19:49:39,241 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,241 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,241 DEBUG SessionImpl:2043 - object not resolved in any cache [test.Group#1         ]
***}
19:49:39,241 DEBUG EntityPersister:417 - Materializing entity: [test.Group#1         ]
19:49:39,251 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:49:39,251 DEBUG SQL:223 - select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id0_, group0_.group_name as group_name0_ from tbl_group group0_ where group0_.group_id=?
19:49:39,261 DEBUG BatcherImpl:227 - preparing statement
19:49:39,261 DEBUG StringType:46 - binding '1         ' to parameter: 1
19:49:39,281 DEBUG Loader:196 - processing result set
19:49:39,281 DEBUG Loader:404 - result row: 1         
19:49:39,281 DEBUG Loader:535 - Initializing object from ResultSet: 1         
19:49:39,291 DEBUG Loader:604 - Hydrating entity: test.Group#1         
19:49:39,321 DEBUG StringType:68 - returning 'group1              ' as column: group_name0_
19:49:39,321 DEBUG Loader:225 - done processing result set (1 rows)
19:49:39,331 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:49:39,331 DEBUG BatcherImpl:240 - closing statement
19:49:39,331 DEBUG Loader:238 - total objects hydrated: 1
19:49:39,341 DEBUG SessionImpl:2129 - resolving associations for [test.Group#1         ]
19:49:39,341 DEBUG SessionImpl:2153 - done materializing entity [test.Group#1         ]
19:49:39,351 DEBUG SessionImpl:2153 - done materializing entity [test.Person#11        ]
19:49:39,351 DEBUG SessionImpl:2129 - resolving associations for [test.Person#12        ]
19:49:39,351 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,361 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,361 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,371 DEBUG SessionImpl:2153 - done materializing entity [test.Person#12        ]
19:49:39,371 DEBUG SessionImpl:2129 - resolving associations for [test.Person#13        ]
19:49:39,381 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,381 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,381 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,381 DEBUG SessionImpl:2153 - done materializing entity [test.Person#13        ]
19:49:39,391 DEBUG SessionImpl:2129 - resolving associations for [test.Person#14        ]
19:49:39,391 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,401 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,401 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,411 DEBUG SessionImpl:2153 - done materializing entity [test.Person#14        ]
19:49:39,411 DEBUG SessionImpl:2129 - resolving associations for [test.Person#15        ]
19:49:39,441 DEBUG SessionImpl:1913 - loading [test.Group#1         ]
19:49:39,441 DEBUG SessionImpl:2010 - attempting to resolve [test.Group#1         ]
19:49:39,441 DEBUG SessionImpl:2026 - resolved object in session cache [test.Group#1         ]
19:49:39,451 DEBUG SessionImpl:2153 - done materializing entity [test.Person#15        ]
19:49:39,451 DEBUG SessionImpl:2961 - 2 collections were found in result set
19:49:39,461 DEBUG SessionImpl:2979 - collection fully initialized: [test.Group.persons#1         ]
19:49:39,461 DEBUG SessionImpl:2979 - collection fully initialized: [test.Group.persons#1]
19:49:39,461 DEBUG SessionImpl:2982 - 2 collections initialized
----------------------------------------------------------------------------------------------------------------------------------------
The message in {**** ***} show the problem reson. Because of the strange behavior of the jdbc driver of SQLServer, the object id in the cache is "1"(load(group.class, "1")), the id read through jdbc is "1        ", hibernate can not got the group object from the cache. 

I have test the same code with the hibernate version 2.0.3, the result is correct, the debug information is:
Hibernate 2.0.3 DEBUG&OUTPUT Information
----------------------------------------------------------------------------------------------------------------------------------------
19:40:48,701  INFO Environment:403 - Hibernate 2.0.3
19:40:48,721  INFO Environment:432 - hibernate.properties not found
19:40:48,751  INFO Environment:452 - using CGLIB reflection optimizer
19:40:48,761  INFO Environment:462 - JVM proxy support: true
19:40:48,791  INFO Configuration:703 - Configuration resource: /hibernate.cfg.xml
19:41:00,579  INFO SessionFactoryImpl:269 - Query language substitutions: {}
......
19:41:00,589 DEBUG SessionFactoryImpl:281 - instantiated session factory
19:41:00,749 DEBUG SessionImpl:413 - opened session
19:41:00,769 DEBUG SessionImpl:1752 - loading [test.Group#1]
19:41:00,769 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1]
19:41:00,789 DEBUG SessionImpl:1887 - object not resolved in any cache [test.Group#1]
19:41:00,789 DEBUG EntityPersister:394 - Materializing entity: test.Group#1
19:41:00,799 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:00,799 DEBUG DriverManagerConnectionProvider:77 - total checked-out connections: 0
19:41:00,799 DEBUG DriverManagerConnectionProvider:83 - using pooled JDBC connection, pool size: 0
19:41:00,809 DEBUG SessionFactoryImpl:526 - prepared statement get: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
19:41:00,809 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,160 DEBUG StringType:44 - binding '1' to parameter: 1
19:41:01,300 DEBUG Loader:148 - processing result set
19:41:01,310 DEBUG Loader:260 - result row: 1
19:41:01,310 DEBUG Loader:357 - Initializing object from ResultSet: 1
19:41:01,320 DEBUG Loader:413 - Hydrating entity: test.Group#1
19:41:01,320 DEBUG StringType:65 - returning 'group1              ' as column: group_name
19:41:01,330 DEBUG Loader:182 - done processing result set (1 rows)
19:41:01,340 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,350 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,350 DEBUG Loader:195 - total objects hydrated: 1
19:41:01,350 DEBUG SessionImpl:1954 - resolving associations for [test.Group#1]
19:41:01,390 DEBUG SessionImpl:2888 - initializing collection [test.Group.persons#1]
19:41:01,390 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:01,400 DEBUG SessionFactoryImpl:526 - prepared statement get: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
Hibernate: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
19:41:01,400 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,400 DEBUG StringType:44 - binding '1' to parameter: 1
19:41:01,430 DEBUG Loader:148 - processing result set
19:41:01,440 DEBUG StringType:65 - returning '11        ' as column: person_id
19:41:01,440 DEBUG Loader:260 - result row: 11        
19:41:01,440 DEBUG Loader:357 - Initializing object from ResultSet: 11        
19:41:01,440 DEBUG Loader:413 - Hydrating entity: test.Person#11        
19:41:01,450 DEBUG StringType:65 - returning 'person11            ' as column: person_n2_
19:41:01,450 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,450 DEBUG StringType:65 - returning '11        ' as column: person_id__
19:41:01,460 DEBUG SessionImpl:1752 - loading [test.Person#11        ]
19:41:01,460 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#11        ]
19:41:01,470 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#11        ]
19:41:01,470 DEBUG StringType:65 - returning '12        ' as column: person_id
19:41:01,470 DEBUG Loader:260 - result row: 12        
19:41:01,480 DEBUG Loader:357 - Initializing object from ResultSet: 12        
19:41:01,480 DEBUG Loader:413 - Hydrating entity: test.Person#12        
19:41:01,480 DEBUG StringType:65 - returning 'person12            ' as column: person_n2_
19:41:01,480 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,490 DEBUG StringType:65 - returning '12        ' as column: person_id__
19:41:01,500 DEBUG SessionImpl:1752 - loading [test.Person#12        ]
19:41:01,500 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#12        ]
19:41:01,500 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#12        ]
19:41:01,510 DEBUG StringType:65 - returning '13        ' as column: person_id
19:41:01,510 DEBUG Loader:260 - result row: 13        
19:41:01,510 DEBUG Loader:357 - Initializing object from ResultSet: 13        
19:41:01,530 DEBUG Loader:413 - Hydrating entity: test.Person#13        
19:41:01,540 DEBUG StringType:65 - returning 'person13            ' as column: person_n2_
19:41:01,540 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,540 DEBUG StringType:65 - returning '13        ' as column: person_id__
19:41:01,550 DEBUG SessionImpl:1752 - loading [test.Person#13        ]
19:41:01,550 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#13        ]
19:41:01,550 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#13        ]
19:41:01,560 DEBUG StringType:65 - returning '14        ' as column: person_id
19:41:01,560 DEBUG Loader:260 - result row: 14        
19:41:01,560 DEBUG Loader:357 - Initializing object from ResultSet: 14        
19:41:01,570 DEBUG Loader:413 - Hydrating entity: test.Person#14        
19:41:01,570 DEBUG StringType:65 - returning 'person14            ' as column: person_n2_
19:41:01,570 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,580 DEBUG StringType:65 - returning '14        ' as column: person_id__
19:41:01,580 DEBUG SessionImpl:1752 - loading [test.Person#14        ]
19:41:01,580 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#14        ]
19:41:01,590 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#14        ]
19:41:01,590 DEBUG StringType:65 - returning '15        ' as column: person_id
19:41:01,600 DEBUG Loader:260 - result row: 15        
19:41:01,600 DEBUG Loader:357 - Initializing object from ResultSet: 15        
19:41:01,600 DEBUG Loader:413 - Hydrating entity: test.Person#15        
19:41:01,600 DEBUG StringType:65 - returning 'person15            ' as column: person_n2_
19:41:01,610 DEBUG StringType:65 - returning '1         ' as column: group_id
19:41:01,610 DEBUG StringType:65 - returning '15        ' as column: person_id__
19:41:01,620 DEBUG SessionImpl:1752 - loading [test.Person#15        ]
19:41:01,620 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#15        ]
19:41:01,630 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#15        ]
19:41:01,650 DEBUG Loader:182 - done processing result set (5 rows)
19:41:01,650 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,650 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,650 DEBUG Loader:195 - total objects hydrated: 5
19:41:01,660 DEBUG SessionImpl:1954 - resolving associations for [test.Person#11        ]
19:41:01,660 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:01,660 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:01,671 DEBUG SessionImpl:1887 - object not resolved in any cache [test.Group#1         ]
19:41:01,671 DEBUG EntityPersister:394 - Materializing entity: test.Group#1         
19:41:01,681 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:01,681 DEBUG SessionFactoryImpl:526 - prepared statement get: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
Hibernate: select group0_.group_id as group_id, group0_.group_name as group_name from tbl_group group0_ where group0_.group_id=?
19:41:01,681 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,691 DEBUG StringType:44 - binding '1         ' to parameter: 1
19:41:01,691 DEBUG Loader:148 - processing result set
19:41:01,711 DEBUG Loader:260 - result row: 1         
19:41:01,711 DEBUG Loader:357 - Initializing object from ResultSet: 1         
19:41:01,711 DEBUG Loader:413 - Hydrating entity: test.Group#1         
19:41:01,721 DEBUG StringType:65 - returning 'group1              ' as column: group_name
19:41:01,721 DEBUG Loader:182 - done processing result set (1 rows)
19:41:01,721 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,731 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,731 DEBUG Loader:195 - total objects hydrated: 1
19:41:01,741 DEBUG SessionImpl:1954 - resolving associations for [test.Group#1         ]
19:41:01,741 DEBUG SessionImpl:2888 - initializing collection [test.Group.persons#1         ]
19:41:01,741 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
19:41:01,771 DEBUG SessionFactoryImpl:526 - prepared statement get: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
Hibernate: select tbl_pers0_.person_id as person_id__, tbl_pers0_.person_id as person_id, tbl_pers0_.person_name as person_n2_, tbl_pers0_.group_id as group_id from tbl_person tbl_pers0_ where tbl_pers0_.group_id=?
19:41:01,791 DEBUG SessionFactoryImpl:536 - preparing statement
19:41:01,791 DEBUG StringType:44 - binding '1         ' to parameter: 1
19:41:01,811 DEBUG Loader:148 - processing result set
19:41:01,811 DEBUG StringType:65 - returning '11        ' as column: person_id
19:41:01,821 DEBUG Loader:260 - result row: 11        
19:41:01,821 DEBUG StringType:65 - returning '11        ' as column: person_id__
19:41:01,821 DEBUG SessionImpl:1752 - loading [test.Person#11        ]
19:41:01,831 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#11        ]
19:41:01,831 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#11        ]
19:41:01,841 DEBUG StringType:65 - returning '12        ' as column: person_id
19:41:01,841 DEBUG Loader:260 - result row: 12        
19:41:01,841 DEBUG StringType:65 - returning '12        ' as column: person_id__
19:41:01,841 DEBUG SessionImpl:1752 - loading [test.Person#12        ]
19:41:01,851 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#12        ]
19:41:01,851 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#12        ]
19:41:01,861 DEBUG StringType:65 - returning '13        ' as column: person_id
19:41:01,871 DEBUG Loader:260 - result row: 13        
19:41:01,881 DEBUG StringType:65 - returning '13        ' as column: person_id__
19:41:01,881 DEBUG SessionImpl:1752 - loading [test.Person#13        ]
19:41:01,881 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#13        ]
19:41:01,901 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#13        ]
19:41:01,901 DEBUG StringType:65 - returning '14        ' as column: person_id
19:41:01,911 DEBUG Loader:260 - result row: 14        
19:41:01,911 DEBUG StringType:65 - returning '14        ' as column: person_id__
19:41:01,911 DEBUG SessionImpl:1752 - loading [test.Person#14        ]
19:41:01,921 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#14        ]
19:41:01,921 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#14        ]
19:41:01,931 DEBUG StringType:65 - returning '15        ' as column: person_id
19:41:01,931 DEBUG Loader:260 - result row: 15        
19:41:01,931 DEBUG StringType:65 - returning '15        ' as column: person_id__
19:41:01,941 DEBUG SessionImpl:1752 - loading [test.Person#15        ]
19:41:01,941 DEBUG SessionImpl:1843 - attempting to resolve [test.Person#15        ]
19:41:01,951 DEBUG SessionImpl:1858 - resolved object in session cache [test.Person#15        ]
19:41:01,951 DEBUG Loader:182 - done processing result set (5 rows)
19:41:01,951 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
19:41:01,961 DEBUG SessionFactoryImpl:554 - closing statement
19:41:01,961 DEBUG Loader:195 - total objects hydrated: 0
19:41:01,961 DEBUG SessionImpl:1975 - done materializing entity [test.Group#1         ]
19:41:01,971 DEBUG SessionImpl:1975 - done materializing entity [test.Person#11        ]
19:41:01,991 DEBUG SessionImpl:1954 - resolving associations for [test.Person#12        ]
19:41:01,991 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:01,991 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:01,991 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,001 DEBUG SessionImpl:1975 - done materializing entity [test.Person#12        ]
19:41:02,001 DEBUG SessionImpl:1954 - resolving associations for [test.Person#13        ]
19:41:02,001 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:02,011 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:02,011 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,011 DEBUG SessionImpl:1975 - done materializing entity [test.Person#13        ]
19:41:02,021 DEBUG SessionImpl:1954 - resolving associations for [test.Person#14        ]
19:41:02,021 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:02,021 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:02,021 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,031 DEBUG SessionImpl:1975 - done materializing entity [test.Person#14        ]
19:41:02,031 DEBUG SessionImpl:1954 - resolving associations for [test.Person#15        ]
19:41:02,041 DEBUG SessionImpl:1752 - loading [test.Group#1         ]
19:41:02,041 DEBUG SessionImpl:1843 - attempting to resolve [test.Group#1         ]
19:41:02,041 DEBUG SessionImpl:1858 - resolved object in session cache [test.Group#1         ]
19:41:02,051 DEBUG SessionImpl:1975 - done materializing entity [test.Person#15        ]
19:41:02,051 DEBUG SessionImpl:1975 - done materializing entity [test.Group#1]
----------------------------------------------------------------------------------------------------------------------------------------

If hibernate have a trim() operator when dealing with SQLServerDialect, the problem will be corrected perfectly.


---------------------------------------------------------------------
JIRA INFORMATION:
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.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira

Message:

  A new issue has been created in JIRA.

---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-581


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-581
    Summary: Add ability to use hibernate syntax to do an "update"
       Type: Improvement

     Status: Unassigned
   Priority: Minor

    Project: Hibernate2
 Components: 
             core
   Versions:
             2.1.1

   Assignee: 
   Reporter: Will Gayther

    Created: Sat, 27 Dec 2003 12:03 AM
    Updated: Sat, 27 Dec 2003 12:03 AM

Description:
Hibernate has several ways of writing abstract queries in a query language - native sql, the new psuedo-sql query through session.createSQLQuery(), and hql. Changes to the database are typically made by loading the object(s) to change, changing them, and resaving them to the database.

However, there are a few cases where this is incredibly inefficient. For example, I have a large number of "Link" objects in the database. Each link has a "displayIndex" - a long value that is used to determine which Links are displayed first. Naturally, I allow the user to change this ordering themselves. However, if there are a large number of links, and the user wants to move a link from the bottom of the ordering to the top, it would be extremely inefficient to load all of the links in-between the two spots, change all of their displayIndex's, then resave them, when sql like:
"update linkTable set displayIndex = displayIndex - 1 where displayIndex <= ? and displayIndex > ?"
would do the job much more efficiently with much less database traffic.

Of course, you can do this with straight sql. But that requires you to look up table names, column names, etc which breaks the abstraction which is the reason for using Hibernate in the first place.

What I propose is that you add a method, Session.createSQLUpdate(), that allows you to create and execute an sql update using the same syntax you that is used for Session.createSQLQuery(), so that the above statement could be written as:
"update linkTable set {link.displayIndex} = {link.displayIndex} - 1 where {link.displayIndex} <= ? and {link.displayIndex} > ?"
I know that in this example, since the property names and the column names are identical, it doesn't seem to do much good. But they can be different, and to write the query as sql requires you to stop thinking about objects, and start thinking "Are the property names the same as the column names?". This, together with my post on abstracting the table name rather than hard coding it (http://forum.hibernate.org/viewtopic.php?p=2183636#2183636) I think this would help keep the hibernate abstraction from being broken.

I would think that you could reuse the exact same parser used for Session.createSQLQuery(), so it wouldn't require any significant extra work for you guys (otherwise I wouldn't bring it up because it probably wouldn't be worth the time to do). Perhaps I'm wrong, or there's already a better way - what do you think?


---------------------------------------------------------------------
JIRA INFORMATION:
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.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira