-->
These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

All times are UTC - 5 hours [ DST ]



Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 2 posts ] 
Author Message
 Post subject: EntityManger.find() not finding persisted Entity (postgres)
PostPosted: Tue Jul 25, 2006 9:56 am 
Senior
Senior

Joined: Tue Jul 25, 2006 9:05 am
Posts: 163
Location: Stuttgart/Karlsruhe, Germany
Hibernate version: 3 (version that ships with JBoss 4.0.4GA)

Name and version of the database you are using: PostgreSQL 8.1.4

We currently have an JBoss application that receives a byte stream and persists it wit hibernate and then reads it from the db for further parsing before saving it again. When using the default Hypersonic datasource hibernate manages it without any problems, but when trying to use PostgreSQL as the datasource we run into problems, with the reading/retrieval of the initially persisted object for further parsing.

I have turned on all the logging in jboss for hibernate and the output is as so:

Code:
2006-07-25 14:42:40,615 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 11538313605
2006-07-25 14:42:40,616 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
2006-07-25 14:42:40,616 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join
2006-07-25 14:42:40,622 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
2006-07-25 14:42:40,625 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join
2006-07-25 14:42:40,625 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Transaction already joined
2006-07-25 14:42:40,632 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-07-25 14:42:40,632 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2006-07-25 14:42:40,632 DEBUG [org.hibernate.SQL] select nextval ('hibernate_sequence')
2006-07-25 14:42:40,637 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 1
2006-07-25 14:42:40,637 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-07-25 14:42:40,637 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2006-07-25 14:42:40,637 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2006-07-25 14:42:40,637 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 1, using strategy: org.hibernate.id.SequenceGenerator
2006-07-25 14:42:40,663 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades
2006-07-25 14:42:40,664 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] dirty checking collections
2006-07-25 14:42:40,670 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 1 insertions, 0 updates, 0 deletions to 1 objects
2006-07-25 14:42:40,670 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2006-07-25 14:42:40,673 DEBUG [org.hibernate.pretty.Printer] listing entities:
2006-07-25 14:42:40,675 DEBUG [org.hibernate.pretty.Printer] de.comsoft.{mID=1, }
2006-07-25 14:42:40,677 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-07-25 14:42:40,677 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2006-07-25 14:42:40,678 DEBUG [org.hibernate.SQL] /* insert de.comsoft.RawMessage */ insert into TRAFFIC_TBL (TRANSMISSION_CHANNEL, RECEPTION_DATE, BUFFER, TLI, mID) values (?, ?, ?, ?, ?)
2006-07-25 14:42:40,683 DEBUG [org.hibernate.jdbc.AbstractBatcher] Executing batch size: 1
2006-07-25 14:42:40,687 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-07-25 14:42:40,687 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
2006-07-25 14:42:40,688 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2006-07-25 14:42:40,688 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2006-07-25 14:42:40,688 INFO  [STDOUT] written to database with PK = 1
2006-07-25 14:42:40,688 INFO  [STDOUT] waiting for 10 seconds...
2006-07-25 14:42:50,437 DEBUG [de.comsoft.cadas.mep.MEPRequestHandler] Size: 289
2006-07-25 14:42:50,437 DEBUG [de.comsoft] Version: 49
2006-07-25 14:42:50,437 DEBUG [de.comsoft] Type: 49
2006-07-25 14:42:50,437 DEBUG [de.comsoft] Id: 0000010ca5b57e9b0001
2006-07-25 14:42:50,437 DEBUG [de.comsoft] Data Size: 273
2006-07-25 14:42:50,437 DEBUG [de.comsoft] Data received: 0000010ca5b57e9b0001
2006-07-25 14:42:50,437 INFO  [STDOUT] Received message [19309576] @ 1153831370437
2006-07-25 14:42:50,693 INFO  [STDOUT] done
2006-07-25 14:42:50,695 INFO  [STDOUT] JMS message ID = null
2006-07-25 14:42:50,714 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades
2006-07-25 14:42:50,714 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] dirty checking collections
2006-07-25 14:42:50,714 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
2006-07-25 14:42:50,714 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2006-07-25 14:42:50,715 DEBUG [org.hibernate.pretty.Printer] listing entities:
2006-07-25 14:42:50,715 DEBUG [org.hibernate.pretty.Printer] de.comsoft{mID=1, mTli=null, mBuffer=81c4c1c1b0b0b8b3a0b0b5b0b9b4b68d8ac7c7a0ccd1d3c1d9ced9d8a0ccd1cdcfd9ced9d8a0ccd1d4dad9ced9d88d8ab0b5b0b9b4b6a0ccc9c9c1d9ced9d88d8a82a8c2b0b5b7b4afb0b3a0cecfd4c1cdce8d8ad1a9ccc9cdcdafd1cdd2ccc3afc9d6afcec2cfafc1afb0b0b0afb9b9b9afb4b5b4b0ceb0b0b9b4b2c5b0b0b18d8ac1a9ccc9cdc5a0c2a9b0b3b0b2b0b8b0b0b0b0a0c3a9b0b3b0b2b1b6b0b5b5b08d8ac4a9c6c5c2a0b0b8a0b0b0b0b1adb0b5b0b0a0b2b3b1b0adb0b5b5b0a0b1b4a0b2b3b5b0adb0b5b5b0a0c1cec4a0b1b6a0b0b0b5b0adb0b5b5b08d8ac5a9cdd3c7a0b0b1a0a0a0d2d7d9a0b1b1afb2b9a0c3ccd3c4a0c4d5c5a0d4cfa0d7c9d0a98d8a8b83, mChannel=AFTN, mReceptionDate=2006-07-25 14:42:40}
2006-07-25 14:42:50,715 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2006-07-25 14:42:50,719 INFO  [STDOUT]


2006-07-25 14:42:50,720 INFO  [STDOUT] MessageHandler::onMessage begin @ 1153831370720 for message with ID ID:3-11538313706951
2006-07-25 14:42:50,720 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 11538313707
2006-07-25 14:42:50,720 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
2006-07-25 14:42:50,720 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join
2006-07-25 14:42:50,720 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
2006-07-25 14:42:50,720 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join
2006-07-25 14:42:50,720 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Transaction already joined
2006-07-25 14:42:50,724 DEBUG [org.hibernate.loader.Loader] loading entity: [de.comsoft#1]
2006-07-25 14:42:50,728 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-07-25 14:42:50,728 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2006-07-25 14:42:50,734 DEBUG [org.hibernate.SQL] /* load de.comsoft/ select rawmessage0_.mID as mID0_0_, rawmessage0_.TRANSMISSION_CHANNEL as TRANSMIS2_0_0_, rawmessage0_.RECEPTION_DATE as RECEPTION3_0_0_, rawmessage0_.BUFFER as BUFFER0_0_, rawmessage0_.TLI as TLI0_0_ from TRAFFIC_TBL rawmessage0_ where rawmessage0_.mID=?
2006-07-25 14:42:50,737 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2006-07-25 14:42:50,737 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
2006-07-25 14:42:50,737 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-07-25 14:42:50,737 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2006-07-25 14:42:50,737 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2006-07-25 14:42:50,740 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
2006-07-25 14:42:50,740 DEBUG [org.hibernate.loader.Loader] done entity load
2006-07-25 14:42:50,740 INFO  [STDOUT]

rm is null, pKey is 1

2006-07-25 14:42:50,747 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
2006-07-25 14:42:50,748 DEBUG [org.jboss.ejb3.entity.ManagedEntityManagerFactory] ************** closing entity managersession **************
2006-07-25 14:42:50,748 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
2006-07-25 14:42:50,784 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
2006-07-25 14:42:50,784 DEBUG [org.jboss.ejb3.entity.ManagedEntityManagerFactory] ************** closing entity managersession **************
2006-07-25 14:42:50,784 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered


The line "rm is null, pKey is 1" is a debug line. rm is the result of EntityManager.find() passing it the primary key (1 is the above case) of the already persisted object. I have a quick question about the hibernate logging, how do i display what the ? are in the perparedStatements ?

Currently the application is behaving like it is trying to read (SELECT) the data after it has been persisted, but it is not there, I have veryfied it is with the pgAdmin application, I also enabled full trace logging on PostgreSQL itself, and i can't see where the problems is, as commits take place at the correct time.

My gut feeling is that this might have something to do with the fact that we are using the bytea datatype in postgres, and i know from personal experience that large objects are a bit tricky in postgres.

Can anyone offer my any adive on how to over come this problem ??

Thanks in advance,

Andy


Last edited by andydale on Thu Jul 27, 2006 11:35 am, edited 3 times in total.

Top
 Profile  
 
 Post subject:
PostPosted: Wed Jul 26, 2006 10:21 am 
Senior
Senior

Joined: Tue Jul 25, 2006 9:05 am
Posts: 163
Location: Stuttgart/Karlsruhe, Germany
I am still having this problem, but have been investigating it further. What i have found out is that if you call the EntityManager.find() method directly after you have just persisted the object in the same class then it manages to find the Entity in the database.

The problem starts to happen when the you call the EntityManager.find() from within another class with the same persistence context (using the same persistence unit), it seems to return null 99.99% of the time. I have no idea if this due to the database being used as it works with a Hypersonic data source but not with postgres.

Andy


Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 2 posts ] 

All times are UTC - 5 hours [ DST ]


You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.