Well, this only happens when I'm mappping properties as Serializable. For the simple example it doesn't make much sense, but in the big app, there are collections that themselves contain collections. Without a redesign I have to use this kind of mapping.
I set the log level to DEBUG and ran the app once again:
Code:
[java] 15:45:03,374 DEBUG SessionImpl:555 - opened session
[java] 15:45:03,384 DEBUG JDBCTransaction:37 - begin
[java] 15:45:03,384 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
[java] 15:45:03,384 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 0
[java] 15:45:03,384 DEBUG JDBCTransaction:41 - current autocommit status:false
[java] before save
[java] 15:45:03,394 DEBUG SessionImpl:825 - saving [hibtest.KlasseE#<null>]
[java] 15:45:03,394 DEBUG SessionImpl:2305 - executing insertions
[java] 15:45:03,394 DEBUG Cascades:497 - processing cascades for: hibtest.KlasseE
[java] 15:45:03,404 DEBUG Cascades:506 - done processing cascades for: hibtest.KlasseE
[java] 15:45:03,444 DEBUG EntityPersister:490 - Inserting entity: hibtest.KlasseE (native id)
[java] 15:45:03,444 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
[java] 15:45:03,444 DEBUG SQL:237 - insert into KLASSEE (DREF) values (?)
[java] Hibernate: insert into KLASSEE (DREF) values (?)
[java] 15:45:03,444 DEBUG BatcherImpl:241 - preparing statement
[java] 15:45:03,474 DEBUG EntityPersister:388 - Dehydrating entity: [hibtest.KlasseE#<null>]
[java] 15:45:03,474 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
[java] 15:45:03,474 DEBUG BatcherImpl:261 - closing statement
[java] 15:45:03,474 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
[java] 15:45:03,484 DEBUG SQL:237 - SELECT LAST_INSERT_ID()
[java] Hibernate: SELECT LAST_INSERT_ID()
[java] 15:45:03,484 DEBUG BatcherImpl:241 - preparing statement
[java] 15:45:03,484 DEBUG AbstractEntityPersister:1229 - Natively generated identity: 13
[java] 15:45:03,494 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
[java] 15:45:03,494 DEBUG BatcherImpl:261 - closing statement
[java] 15:45:03,494 DEBUG Cascades:497 - processing cascades for: hibtest.KlasseE
[java] 15:45:03,494 DEBUG Cascades:506 - done processing cascades for: hibtest.KlasseE
[java] after save, before commit
[java] 15:45:03,504 DEBUG JDBCTransaction:59 - commit
[java] 15:45:03,504 DEBUG SessionImpl:2242 - flushing session
[java] 15:45:03,504 DEBUG Cascades:497 - processing cascades for: hibtest.KlasseE
[java] 15:45:03,504 DEBUG Cascades:506 - done processing cascades for: hibtest.KlasseE
[java] 15:45:03,514 DEBUG SessionImpl:2435 - Flushing entities and processing referenced collections
[java] 15:45:03,514 DEBUG AbstractEntityPersister:274 - hibtest.KlasseE.myDRef is dirty
[java] 15:45:03,514 DEBUG SessionImpl:2529 - Updating entity: [hibtest.KlasseE#13]
[java] 15:45:03,524 DEBUG SessionImpl:2776 - Processing unreferenced collections
[java] 15:45:03,524 DEBUG SessionImpl:2790 - Scheduling collection removes/(re)creates/updates
[java] 15:45:03,534 DEBUG SessionImpl:2266 - Flushed: 0 insertions, 1 updates, 0 deletions to 1 objects
[java] 15:45:03,534 DEBUG SessionImpl:2271 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
[java] 15:45:03,534 DEBUG Printer:75 - listing entities:
[java] 15:45:03,544 DEBUG Printer:82 - hibtest.KlasseE{myDRef=...} //omitted to keep this readable
[java] 15:45:03,544 DEBUG SessionImpl:2355 - executing flush
[java] 15:45:03,554 DEBUG EntityPersister:648 - Updating entity: [hibtest.KlasseE#13]
[java] 15:45:03,554 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
[java] 15:45:03,554 DEBUG SQL:237 - update KLASSEE set DREF=? where ID=?
[java] Hibernate: update KLASSEE set DREF=? where ID=?
[java] 15:45:03,554 DEBUG BatcherImpl:241 - preparing statement
[java] 15:45:03,554 DEBUG EntityPersister:388 - Dehydrating entity: [hibtest.KlasseE#13]
[java] 15:45:03,564 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
[java] 15:45:03,564 DEBUG BatcherImpl:261 - closing statement
[java] 15:45:03,564 DEBUG SessionImpl:2820 - post flush
[java] 15:45:03,584 DEBUG SessionImpl:585 - transaction completion
[java] after commit
[java] 15:45:03,584 DEBUG JDBCTransaction:37 - begin
[java] 15:45:03,584 DEBUG JDBCTransaction:41 - current autocommit status:false
[java] before find
[java] 15:45:03,594 DEBUG SessionImpl:1526 - find: from hibtest.KlasseE
[java] 15:45:03,614 DEBUG QueryTranslator:147 - compiling query
[java] 15:45:03,634 DEBUG SessionImpl:2242 - flushing session
[java] 15:45:03,644 DEBUG Cascades:497 - processing cascades for: hibtest.KlasseE
[java] 15:45:03,644 DEBUG Cascades:506 - done processing cascades for: hibtest.KlasseE
[java] 15:45:03,644 DEBUG SessionImpl:2435 - Flushing entities and processing referenced collections
[java] 15:45:03,644 DEBUG SessionImpl:2776 - Processing unreferenced collections
[java] 15:45:03,644 DEBUG SessionImpl:2790 - Scheduling collection removes/(re)creates/updates
[java] 15:45:03,644 DEBUG SessionImpl:2266 - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
[java] 15:45:03,644 DEBUG SessionImpl:2271 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
[java] 15:45:03,644 DEBUG Printer:75 - listing entities:
[java] 15:45:03,644 DEBUG Printer:82 - hibtest.KlasseE{myDRef=...} //omitted to keep this readable
[java] 15:45:03,654 DEBUG SessionImpl:1814 - Dont need to execute flush
[java] 15:45:03,654 DEBUG QueryTranslator:199 - HQL: from hibtest.KlasseE
[java] 15:45:03,654 DEBUG QueryTranslator:200 - SQL: select klassee0_.ID as ID, klassee0_.DREF as DREF from KLASSEE klassee0_
[java] 15:45:03,654 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
[java] 15:45:03,654 DEBUG SQL:237 - select klassee0_.ID as ID, klassee0_.DREF as DREF from KLASSEE klassee0_
[java] Hibernate: select klassee0_.ID as ID, klassee0_.DREF as DREF from KLASSEE klassee0_
[java] 15:45:03,654 DEBUG BatcherImpl:241 - preparing statement
[java] 15:45:03,925 DEBUG Loader:197 - processing result set
[java] 15:45:03,925 DEBUG Loader:405 - result row: 13
[java] 15:45:03,925 DEBUG Loader:226 - done processing result set (1 rows)
[java] 15:45:03,925 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
[java] 15:45:03,925 DEBUG BatcherImpl:261 - closing statement
[java] 15:45:03,925 DEBUG Loader:239 - total objects hydrated: 0
[java] 15:45:03,925 DEBUG SessionImpl:3112 - initializing non-lazy collections
[java] after find
[java] 15:45:03,925 DEBUG SessionImpl:2310 - checking session dirtiness
[java] 15:45:03,925 DEBUG SessionImpl:2242 - flushing session
[java] 15:45:03,925 DEBUG Cascades:497 - processing cascades for: hibtest.KlasseE
[java] 15:45:03,925 DEBUG Cascades:506 - done processing cascades for: hibtest.KlasseE
[java] 15:45:03,965 DEBUG SessionImpl:2435 - Flushing entities and processing referenced collections
[java] 15:45:03,975 DEBUG SessionImpl:2776 - Processing unreferenced collections
[java] 15:45:03,975 DEBUG SessionImpl:2790 - Scheduling collection removes/(re)creates/updates
[java] 15:45:03,975 DEBUG SessionImpl:2266 - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
[java] 15:45:03,975 DEBUG SessionImpl:2271 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
[java] 15:45:04,005 DEBUG Printer:75 - listing entities:
[java] 15:45:04,005 DEBUG Printer:82 - hibtest.KlasseE{myDRef=...} //omitted to keep this readable
[java] 15:45:04,045 DEBUG SessionImpl:2325 - session not dirty
[java] false
[java] before commit
[java] 15:45:04,045 DEBUG JDBCTransaction:59 - commit
[java] 15:45:04,045 DEBUG SessionImpl:2242 - flushing session
[java] 15:45:04,045 DEBUG Cascades:497 - processing cascades for: hibtest.KlasseE
[java] 15:45:04,045 DEBUG Cascades:506 - done processing cascades for: hibtest.KlasseE
[java] 15:45:04,115 DEBUG SessionImpl:2435 - Flushing entities and processing referenced collections
[java] 15:45:04,115 DEBUG SessionImpl:2776 - Processing unreferenced collections
[java] 15:45:04,115 DEBUG SessionImpl:2790 - Scheduling collection removes/(re)creates/updates
[java] 15:45:04,115 DEBUG SessionImpl:2266 - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
[java] 15:45:04,115 DEBUG SessionImpl:2271 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
[java] 15:45:04,145 DEBUG Printer:75 - listing entities:
[java] 15:45:04,145 DEBUG Printer:82 - hibtest.KlasseE{myDRef=...} //omitted to keep this readable
[java] 15:45:04,195 DEBUG SessionImpl:2355 - executing flush
[java] 15:45:04,195 DEBUG SessionImpl:2820 - post flush
[java] 15:45:04,195 DEBUG SessionImpl:585 - transaction completion
[java] after commit
[java] 15:45:04,195 DEBUG SessionImpl:573 - closing session
[java] 15:45:04,195 DEBUG SessionImpl:3332 - disconnecting session
[java] 15:45:04,195 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 1
[java] 15:45:04,215 DEBUG SessionImpl:585 - transaction completion
Now I think I'm crazy: the debug output doesn't print out any updates. It's AN OTHER output - I swear, I didn't change anything except the log level (I changed it back again and the output shown in the first post appeared). Something's going the wrong way in my app, but where???