Hello
Here is the more detailed log of the "eg" application provided with hibernate 3.0.5.
I'm running MySQL but in any case, the log does not show any UPDATE where I believe it should...
the test
Code:
test.changeItemDescription(mainItem.getId(), "new description");
is supposed to change the description of AuctionItem id 3 from "auction item 2" to "new description". This in turn is used in some test
Code:
test.viewAuctionsByDescription("DESC", 8);
Unfortunately, the description is NOT changed.
Code:
id seller description ends condition successfulBid
----- --------- -------------- --------------------- ------------ ----------------
3 1 auction item 2 2005-07-09 10:21:30.0 8 (null)
To me, it looks like the test is failing under hibernate 3.0.5!
Could anyone confirm this, as it is after all the first hibernate application that I run...
The XML for the AuctionItem is the one downloaded with Hibernate 3.0.5, left unmodified:
Code:
<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">
<hibernate-mapping
package="org.hibernate.auction">
<import class="AuctionInfo"/>
<class name="AuctionItem">
<comment>An item that is being auctioned.</comment>
<id name="id">
<generator class="native"/>
</id>
<natural-id>
<many-to-one name="seller"/>
<property name="description"
length="200"/>
</natural-id>
<property name="ends"/>
<property name="condition"/>
<many-to-one name="successfulBid"
outer-join="false"/>
<bag name="bids"
inverse="true"
cascade="all">
<key column="item"/>
<one-to-many class="Bid"/>
</bag>
</class>
</hibernate-mapping>
And the test code, again, unmodified from the hibernate distribution:
Code:
/**
* Demonstrates automatic dirty checking
*/
public void changeItemDescription(Long itemId, String description) throws Exception {
System.out.println("Changing auction item description for: " + itemId );
Session s = factory.openSession();
Transaction tx=null;
try {
tx = s.beginTransaction();
AuctionItem item = (AuctionItem) s.get(AuctionItem.class, itemId);
if (item==null) throw new IllegalArgumentException("No item for the given id: " + itemId);
item.setDescription(description);
tx.commit();
}
catch (Exception e) {
if (tx!=null) tx.rollback();
throw e;
}
finally {
s.close();
}
}
...
test.changeItemDescription(mainItem.getId(), "new description");
...
The log below shows the detailed trace of that particular test, other tests show the SQL select/insert/update but this one has NO update.
Code:
[java] 10:21:32,882 DEBUG SessionImpl:403 - after transaction completion
[java] Changing auction item description for: 3
[java] 10:21:32,882 DEBUG SessionImpl:250 - opened session at timestamp: 4591210057244672
[java] 10:21:32,892 DEBUG JDBCTransaction:46 - begin
[java] 10:21:32,892 DEBUG ConnectionManager:296 - opening JDBC connection
[java] 10:21:32,892 DEBUG DriverManagerConnectionProvider:93 - total checked-out connections: 0
[java] 10:21:32,892 DEBUG DriverManagerConnectionProvider:99 - using pooled JDBC connection, pool size: 0
[java] 10:21:32,892 DEBUG JDBCTransaction:50 - current autocommit status: false
[java] 10:21:32,892 DEBUG DefaultLoadEventListener:143 - loading entity: [org.hibernate.auction.AuctionItem#3]
[java] 10:21:32,892 DEBUG ConnectionManager:369 - running Session.finalize()
[java] 10:21:32,892 DEBUG DefaultLoadEventListener:290 - attempting to resolve: [org.hibernate.auction.AuctionItem#3]
[java] 10:21:32,892 DEBUG DefaultLoadEventListener:326 - object not resolved in any cache: [org.hibernate.auction.AuctionItem#3]
[java] 10:21:32,892 DEBUG BasicEntityPersister:2467 - Materializing entity: [org.hibernate.auction.AuctionItem#3]
[java] 10:21:32,892 DEBUG Loader:1340 - loading entity: [org.hibernate.auction.AuctionItem#3]
[java] 10:21:32,892 DEBUG AbstractBatcher:290 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
[java] 10:21:32,892 DEBUG SQL:324 - select auctionite0_.id as id0_, auctionite0_.seller as seller0_0_, auctionite0_.description as descript3_0_0_, auctionite0_.ends as ends0_0_, auctionite0_.condition as condition0_0_, auctionite0_.successfulBid as successf6_0_0_ from AuctionItem auctionite0_ where auctionite0_.id=?
[java] Hibernate: select auctionite0_.id as id0_, auctionite0_.seller as seller0_0_, auctionite0_.description as descript3_0_0_, auctionite0_.ends as ends0_0_, auctionite0_.condition as condition0_0_, auctionite0_.successfulBid as successf6_0_0_ from AuctionItem auctionite0_ where auctionite0_.id=?
[java] 10:21:32,902 DEBUG AbstractBatcher:378 - preparing statement
[java] 10:21:32,902 DEBUG AbstractBatcher:306 - about to open ResultSet (open ResultSets: 0, globally: 0)
[java] 10:21:32,902 DEBUG Loader:405 - processing result set
[java] 10:21:32,902 DEBUG Loader:410 - result set row: 0
[java] 10:21:32,902 DEBUG Loader:828 - result row: EntityKey[org.hibernate.auction.AuctionItem#3]
[java] 10:21:32,902 DEBUG Loader:978 - Initializing object from ResultSet: [org.hibernate.auction.AuctionItem#3]
[java] 10:21:32,902 DEBUG BasicEntityPersister:1651 - Hydrating entity: [org.hibernate.auction.AuctionItem#3]
[java] 10:21:32,912 DEBUG Loader:429 - done processing result set (1 rows)
[java] 10:21:32,912 DEBUG AbstractBatcher:313 - about to close ResultSet (open ResultSets: 1, globally: 1)
[java] 10:21:32,912 DEBUG AbstractBatcher:298 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
[java] 10:21:32,912 DEBUG AbstractBatcher:416 - closing statement
[java] 10:21:32,912 DEBUG Loader:528 - total objects hydrated: 1
[java] 10:21:32,912 DEBUG TwoPhaseLoad:96 - resolving associations for [org.hibernate.auction.AuctionItem#3]
[java] 10:21:32,912 DEBUG DefaultLoadEventListener:143 - loading entity: [org.hibernate.auction.User#1]
[java] 10:21:32,912 DEBUG DefaultLoadEventListener:216 - creating new proxy for entity
[java] 10:21:32,912 DEBUG CollectionLoadContext:141 - creating collection wrapper:[org.hibernate.auction.AuctionItem.bids#3]
[java] 10:21:32,912 DEBUG TwoPhaseLoad:167 - done materializing entity [org.hibernate.auction.AuctionItem#3]
[java] 10:21:32,922 DEBUG PersistenceContext:789 - initializing non-lazy collections
[java] 10:21:32,922 DEBUG Loader:1368 - done entity load
[java] 10:21:32,922 DEBUG JDBCTransaction:83 - commit
[java] 10:21:32,922 DEBUG SessionImpl:323 - automatically flushing session
[java] 10:21:32,922 DEBUG AbstractFlushingEventListener:52 - flushing session
[java] 10:21:32,922 DEBUG AbstractFlushingEventListener:102 - processing flush-time cascades
[java] 10:21:32,922 DEBUG Cascades:836 - processing cascade ACTION_SAVE_UPDATE for: org.hibernate.auction.AuctionItem
[java] 10:21:32,922 DEBUG Cascades:890 - cascade ACTION_SAVE_UPDATE for collection: org.hibernate.auction.AuctionItem.bids
[java] 10:21:32,922 DEBUG Cascades:908 - done cascade ACTION_SAVE_UPDATE for collection: org.hibernate.auction.AuctionItem.bids
[java] 10:21:32,922 DEBUG Cascades:861 - done processing cascade ACTION_SAVE_UPDATE for: org.hibernate.auction.AuctionItem
[java] 10:21:32,922 DEBUG AbstractFlushingEventListener:150 - dirty checking collections
[java] 10:21:32,922 DEBUG AbstractFlushingEventListener:167 - Flushing entities and processing referenced collections
[java] 10:21:32,932 DEBUG Collections:140 - Collection found: [org.hibernate.auction.AuctionItem.bids#3], was: [org.hibernate.auction.AuctionItem.bids#3] (uninitialized)
[java] 10:21:32,932 DEBUG AbstractFlushingEventListener:203 - Processing unreferenced collections
[java] 10:21:32,932 DEBUG AbstractFlushingEventListener:217 - Scheduling collection removes/(re)creates/updates
[java] 10:21:32,932 DEBUG AbstractFlushingEventListener:79 - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
[java] 10:21:32,932 DEBUG AbstractFlushingEventListener:85 - Flushed: 0 (re)creations, 0 updates, 0 removals to 1 collections
[java] 10:21:32,932 DEBUG Printer:83 - listing entities:
[java] 10:21:32,932 DEBUG Printer:90 - org.hibernate.auction.AuctionItem{successfulBid=null, seller=org.hibernate.auction.User#1, bids=<uninitialized>, description=new description, ends=2005-07-09 10:21:30, condition=8, id=3}
[java] 10:21:32,932 DEBUG AbstractFlushingEventListener:267 - executing flush
[java] 10:21:32,932 DEBUG AbstractFlushingEventListener:294 - post flush
[java] 10:21:32,942 DEBUG JDBCContext:278 - before transaction completion
[java] 10:21:32,942 DEBUG SessionImpl:372 - before transaction completion
[java] 10:21:32,942 DEBUG JDBCTransaction:96 - committed JDBC Connection
[java] 10:21:32,942 DEBUG JDBCContext:283 - after transaction completion
[java] 10:21:32,942 DEBUG SessionImpl:403 - after transaction completion
[java] 10:21:32,942 DEBUG SessionImpl:269 - closing session
[java] 10:21:32,942 DEBUG ConnectionManager:317 - closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
[java] 10:21:32,952 DEBUG DriverManagerConnectionProvider:129 - returning connection to pool, pool size: 1
[java] 10:21:32,952 DEBUG JDBCContext:283 - after transaction completion
[java] 10:21:32,952 DEBUG SessionImpl:403 - after transaction completion
[java] Viewing user and auctions: 1
Any help would be greatly appreciated, I'm a bit surprised to see an issue in the main demo... but it could be me...
Best regards
Benoit