This is a very strange problem that I'm having. I've used Hibernate for over a year now, and I've never run into this, and I'm at a loss for how to continue troubleshooting.
I'm unable to load an object from the database by calling 'load()' or 'get()', but I can load a collection of objects. Once that collection has been populated, I can then load the object, but it loads from the cache.
Oh, and here's the kicker: The code works (as it should) when I use an HSQL test database, but not from a MySQL database (error mentioned above).
I'm using hibernate annotations to create my hibernate mappings and create my database. For a DAO I'm extending Spring's HibernateDaoSupport class.
Based upon the log files, I can see that when using MySQL, the object is returned by get()/load(), however, it can't be populated/hydrated when it is checked. But if the object was loaded into a collection, it is properly populated/hydrated.
This isn't the case when using HSQLDB/HSQLDialect. Using HSQL, things are populated correctly.
I've also tried the Spring OpenSessionInViewFilter to keep the session open as long as it is needed... and that doesn't seem to to be the problem.
I'm not sure how to further troubleshoot this... so, any help would be appreciated. Has anyone else ever seen this?
Thanks,
Marcus
Hibernate version: 3.1
Mapping documents: Via Hibernate-Annotations
Code:
<!DOCTYPE hibernate-configuration PUBLIC
"-//Hibernate/Hibernate Configuration DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd">
<hibernate-configuration>
<session-factory>
<!-- HSQL mapping -->
<property name="dialect">org.hibernate.dialect.HSQLDialect</property>
<property name="connection.driver_class">org.hsqldb.jdbcDriver</property>
<property name="connection.url">jdbc:hsqldb:hsql://localhost/</property>
<property name="connection.username">sa</property>
<property name="connection.password"/>
<!-- MySQL mapping -->
<!--
<property name="dialect">org.hibernate.dialect.MySQLDialect</property>
<property name="connection.driver_class">com.mysql.jdbc.Driver</property>
<property name="connection.url">jdbc:mysql://127.0.0.1/mytodo</property>
<property name="connection.username">root</property>
<property name="connection.password"/>
-->
<!-- MODEL -->
<mapping class="model.Todo"/>
</session-factory>
</hibernate-configuration>
Mapped classCode:
package model;
... imports ...
@Entity
@Table(name="todo")
public class Todo implements Serializable {
private static final long serialVersionUID = 1892254546067096800L;
private Integer id;
private String description;
private boolean done=false;
private Date completed;
@Column(nullable=false)
public boolean isDone() {
return done;
}
public void setDone(boolean done) {
this.done = done;
}
@Id(generate=GeneratorType.AUTO)
public Integer getId() {
return id;
}
public void setId(Integer id) {
this.id = id;
}
public String getDescription() {
return description;
}
public void setDescription(String name) {
this.description = name;
}
public Date getCompleted() {
return completed;
}
public void setCompleted(Date completed) {
this.completed = completed;
}
public String toString() { return "Todo #"+id+" - "+description; }
}
Hibernate/Spring access codeCode:
class TodoService extends HibernateDaoSupport {
public Todo get(Integer id) {
if (id==null) { log.debug("id was null");return null; }
Todo obj = (Todo) getHibernateTemplate().get(Todo.class, id);
if (obj==null) {
log.error("Null object found!");
} else {
log.debug("found obj!");
}
return obj;
}
public List<Todo> findAll() {
return (List<Todo>) getHibernateTemplate().execute(new HibernateCallback() {
public Object doInHibernate(Session session) throws HibernateException, SQLException {
Criteria c = session.createCriteria(Todo.class);
return c.list();
}
});
}
public List<Todo> findAllAndTest() {
log.debug("Searching for all Todo items");
List<Todo> list = findAll();
for (Todo t : list) {
log.debug("Looking for Todo#"+t.getId());
Todo t2 = this.find(t.getId());
log.debug("Found?"+(t2!=null));
}
return list;
}
}
Log file - Loading List of Todo objects in HSQL
-- findAllAndTest()
Code:
2005-12-19 18:36:41,616 DEBUG [com.grooveapp.service.impl.TodoService] - <Searching for all Todo items>
2005-12-19 18:36:41,714 DEBUG [com.grooveapp.service.impl.TodoService] - <Model for this:class com.grooveapp.model.Todo>
2005-12-19 18:36:41,765 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <about to open PreparedStatement (open PreparedStatements: 0, globally: 0)>
2005-12-19 18:36:41,765 DEBUG [org.hibernate.jdbc.ConnectionManager] - <opening JDBC connection>
2005-12-19 18:36:41,765 DEBUG [org.hibernate.connection.DriverManagerConnectionProvider] - <total checked-out connections: 0>
2005-12-19 18:36:41,765 DEBUG [org.hibernate.connection.DriverManagerConnectionProvider] - <using pooled JDBC connection, pool size: 0>
2005-12-19 18:36:41,769 DEBUG [org.hibernate.SQL] - <select this_.id as id0_0_, this_.completed as completed0_0_, this_.done as done0_0_, this_.description as descript4_0_0_ from todo this_ order by this_.description asc>
Hibernate: select this_.id as id0_0_, this_.completed as completed0_0_, this_.done as done0_0_, this_.description as descript4_0_0_ from todo this_ order by this_.description asc
2005-12-19 18:36:41,769 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <preparing statement>
2005-12-19 18:36:41,776 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <about to open ResultSet (open ResultSets: 0, globally: 0)>
2005-12-19 18:36:41,776 DEBUG [org.hibernate.loader.Loader] - <processing result set>
2005-12-19 18:36:41,777 DEBUG [org.hibernate.loader.Loader] - <result set row: 0>
2005-12-19 18:36:41,777 DEBUG [org.hibernate.type.IntegerType] - <returning '4' as column: id0_0_>
2005-12-19 18:36:41,777 DEBUG [org.hibernate.loader.Loader] - <result row: EntityKey[com.grooveapp.model.Todo#4]>
2005-12-19 18:36:41,777 DEBUG [org.hibernate.loader.Loader] - <Initializing object from ResultSet: [com.grooveapp.model.Todo#4]>
2005-12-19 18:36:41,777 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] - <Hydrating entity: [com.grooveapp.model.Todo#4]>
2005-12-19 18:36:41,777 DEBUG [org.hibernate.type.DateType] - <returning null as column: completed0_0_>
2005-12-19 18:36:41,778 DEBUG [org.hibernate.type.BooleanType] - <returning 'false' as column: done0_0_>
2005-12-19 18:36:41,778 DEBUG [org.hibernate.type.StringType] - <returning 'bar' as column: descript4_0_0_>
2005-12-19 18:36:41,781 DEBUG [org.hibernate.loader.Loader] - <result set row: 1>
2005-12-19 18:36:41,782 DEBUG [org.hibernate.type.IntegerType] - <returning '3' as column: id0_0_>
2005-12-19 18:36:41,782 DEBUG [org.hibernate.loader.Loader] - <result row: EntityKey[com.grooveapp.model.Todo#3]>
2005-12-19 18:36:41,782 DEBUG [org.hibernate.loader.Loader] - <Initializing object from ResultSet: [com.grooveapp.model.Todo#3]>
2005-12-19 18:36:41,782 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] - <Hydrating entity: [com.grooveapp.model.Todo#3]>
2005-12-19 18:36:41,782 DEBUG [org.hibernate.type.DateType] - <returning null as column: completed0_0_>
2005-12-19 18:36:41,782 DEBUG [org.hibernate.type.BooleanType] - <returning 'false' as column: done0_0_>
2005-12-19 18:36:41,782 DEBUG [org.hibernate.type.StringType] - <returning 'foo' as column: descript4_0_0_>
2005-12-19 18:36:41,783 DEBUG [org.hibernate.loader.Loader] - <done processing result set (2 rows)>
2005-12-19 18:36:41,783 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <about to close ResultSet (open ResultSets: 1, globally: 1)>
2005-12-19 18:36:41,783 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <about to close PreparedStatement (open PreparedStatements: 1, globally: 1)>
2005-12-19 18:36:41,783 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <closing statement>
2005-12-19 18:36:41,790 DEBUG [org.hibernate.loader.Loader] - <total objects hydrated: 2>
2005-12-19 18:36:41,794 DEBUG [org.hibernate.engine.TwoPhaseLoad] - <resolving associations for [com.grooveapp.model.Todo#4]>
2005-12-19 18:36:41,794 DEBUG [org.hibernate.engine.TwoPhaseLoad] - <done materializing entity [com.grooveapp.model.Todo#4]>
2005-12-19 18:36:41,794 DEBUG [org.hibernate.engine.TwoPhaseLoad] - <resolving associations for [com.grooveapp.model.Todo#3]>
2005-12-19 18:36:41,794 DEBUG [org.hibernate.engine.TwoPhaseLoad] - <done materializing entity [com.grooveapp.model.Todo#3]>
2005-12-19 18:36:41,794 DEBUG [org.hibernate.engine.StatefulPersistenceContext] - <initializing non-lazy collections>
2005-12-19 18:36:41,795 DEBUG [org.hibernate.jdbc.JDBCContext] - <after autocommit>
2005-12-19 18:36:41,807 DEBUG [org.hibernate.jdbc.ConnectionManager] - <transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!>
2005-12-19 18:36:41,811 DEBUG [com.grooveapp.service.impl.TodoService] - <Looking for Todo#4>
2005-12-19 18:36:41,811 DEBUG [com.grooveapp.service.impl.TodoService] - <Model for this:class com.grooveapp.model.Todo>
2005-12-19 18:36:41,812 DEBUG [com.grooveapp.service.impl.TodoService] - <Finding object of type:Todo>
2005-12-19 18:36:41,812 DEBUG [com.grooveapp.service.impl.TodoService] - <id:4 of type:Integer>
2005-12-19 18:36:41,814 DEBUG [com.grooveapp.service.impl.TodoService] - <Model for this:class com.grooveapp.model.Todo>
2005-12-19 18:36:41,814 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] - <loading entity: [com.grooveapp.model.Todo#4]>
2005-12-19 18:36:41,814 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] - <entity found in session cache>
2005-12-19 18:36:41,815 DEBUG [org.hibernate.jdbc.JDBCContext] - <after autocommit>
2005-12-19 18:36:41,828 DEBUG [org.hibernate.jdbc.ConnectionManager] - <transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!>
2005-12-19 18:36:41,828 DEBUG [com.grooveapp.service.impl.TodoService] - <found obj!>
2005-12-19 18:36:41,828 DEBUG [com.grooveapp.service.impl.TodoService] - <Found?true>
-- find(Integer(4)
Code:
2005-12-19 18:42:00,699 DEBUG [com.grooveapp.service.impl.TodoService] - <Model for this:class com.grooveapp.model.Todo>
2005-12-19 18:42:00,699 DEBUG [com.grooveapp.service.impl.TodoService] - <Finding object of type:Todo>
2005-12-19 18:42:00,699 DEBUG [com.grooveapp.service.impl.TodoService] - <id:4 of type:Integer>
2005-12-19 18:42:00,699 DEBUG [com.grooveapp.service.impl.TodoService] - <Model for this:class com.grooveapp.model.Todo>
2005-12-19 18:42:00,699 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] - <loading entity: [com.grooveapp.model.Todo#4]>
2005-12-19 18:42:00,699 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] - <creating new proxy for entity>
2005-12-19 18:42:00,700 DEBUG [org.hibernate.jdbc.JDBCContext] - <after autocommit>
2005-12-19 18:42:00,700 DEBUG [org.hibernate.jdbc.ConnectionManager] - <transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!>
2005-12-19 18:42:00,700 DEBUG [org.hibernate.impl.SessionImpl] - <after transaction completion>
2005-12-19 18:42:00,700 DEBUG [com.grooveapp.service.impl.TodoService] - <found obj!>
2005-12-19 18:42:00,700 DEBUG [com.grooveapp.filter.GrooveFilter] - <including : /todo/view.jsp>
2005-12-19 18:42:00,701 DEBUG [org.hibernate.impl.SessionImpl] - <initializing proxy: [com.grooveapp.model.Todo#4]>
2005-12-19 18:42:00,701 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] - <attempting to resolve: [com.grooveapp.model.Todo#4]>
2005-12-19 18:42:00,702 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] - <object not resolved in any cache: [com.grooveapp.model.Todo#4]>
2005-12-19 18:42:00,702 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] - <Fetching entity: [com.grooveapp.model.Todo#4]>
2005-12-19 18:42:00,702 DEBUG [org.hibernate.loader.Loader] - <loading entity: [com.grooveapp.model.Todo#4]>
2005-12-19 18:42:00,702 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <about to open PreparedStatement (open PreparedStatements: 0, globally: 0)>
2005-12-19 18:42:00,702 DEBUG [org.hibernate.jdbc.ConnectionManager] - <opening JDBC connection>
2005-12-19 18:42:00,702 DEBUG [org.hibernate.connection.DriverManagerConnectionProvider] - <total checked-out connections: 0>
2005-12-19 18:42:00,702 DEBUG [org.hibernate.connection.DriverManagerConnectionProvider] - <using pooled JDBC connection, pool size: 0>
2005-12-19 18:42:00,703 DEBUG [org.hibernate.SQL] - <select todo0_.id as id0_0_, todo0_.completed as completed0_0_, todo0_.done as done0_0_, todo0_.description as descript4_0_0_ from todo todo0_ where todo0_.id=?>
Hibernate: select todo0_.id as id0_0_, todo0_.completed as completed0_0_, todo0_.done as done0_0_, todo0_.description as descript4_0_0_ from todo todo0_ where todo0_.id=?
2005-12-19 18:42:00,703 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <preparing statement>
2005-12-19 18:42:00,705 DEBUG [org.hibernate.type.IntegerType] - <binding '4' to parameter: 1>
2005-12-19 18:42:00,708 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <about to open ResultSet (open ResultSets: 0, globally: 0)>
2005-12-19 18:42:00,708 DEBUG [org.hibernate.loader.Loader] - <processing result set>
2005-12-19 18:42:00,708 DEBUG [org.hibernate.loader.Loader] - <result set row: 0>
2005-12-19 18:42:00,708 DEBUG [org.hibernate.loader.Loader] - <result row: EntityKey[com.grooveapp.model.Todo#4]>
2005-12-19 18:42:00,708 DEBUG [org.hibernate.loader.Loader] - <Initializing object from ResultSet: [com.grooveapp.model.Todo#4]>
2005-12-19 18:42:00,708 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] - <Hydrating entity: [com.grooveapp.model.Todo#4]>
2005-12-19 18:42:00,708 DEBUG [org.hibernate.type.DateType] - <returning null as column: completed0_0_>
2005-12-19 18:42:00,709 DEBUG [org.hibernate.type.BooleanType] - <returning 'false' as column: done0_0_>
2005-12-19 18:42:00,709 DEBUG [org.hibernate.type.StringType] - <returning 'bar' as column: descript4_0_0_>
2005-12-19 18:42:00,709 DEBUG [org.hibernate.loader.Loader] - <done processing result set (1 rows)>
2005-12-19 18:42:00,709 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <about to close ResultSet (open ResultSets: 1, globally: 1)>
2005-12-19 18:42:00,709 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <about to close PreparedStatement (open PreparedStatements: 1, globally: 1)>
2005-12-19 18:42:00,709 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <closing statement>
2005-12-19 18:42:00,719 DEBUG [org.hibernate.loader.Loader] - <total objects hydrated: 1>
2005-12-19 18:42:00,719 DEBUG [org.hibernate.engine.TwoPhaseLoad] - <resolving associations for [com.grooveapp.model.Todo#4]>
2005-12-19 18:42:00,719 DEBUG [org.hibernate.engine.TwoPhaseLoad] - <done materializing entity [com.grooveapp.model.Todo#4]>
2005-12-19 18:42:00,719 DEBUG [org.hibernate.engine.StatefulPersistenceContext] - <initializing non-lazy collections>
2005-12-19 18:42:00,719 DEBUG [org.hibernate.loader.Loader] - <done entity load>
2005-12-19 18:42:00,719 DEBUG [com.grooveapp.filter.FlushingViewFilter] - <Closing single Hibernate Session in OpenSessionInViewFilter>
2005-12-19 18:42:00,719 DEBUG [org.hibernate.impl.SessionImpl] - <checking session dirtiness>
2005-12-19 18:42:00,720 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] - <flushing session>
2005-12-19 18:42:00,720 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] - <processing flush-time cascades>
2005-12-19 18:42:00,720 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] - <dirty checking collections>
2005-12-19 18:42:00,720 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] - <Flushing entities and processing referenced collections>
2005-12-19 18:42:00,720 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] - <Processing unreferenced collections>
2005-12-19 18:42:00,720 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] - <Scheduling collection removes/(re)creates/updates>
2005-12-19 18:42:00,720 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] - <Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects>
2005-12-19 18:42:00,724 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] - <Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections>
2005-12-19 18:42:00,724 DEBUG [org.hibernate.pretty.Printer] - <listing entities:>
2005-12-19 18:42:00,724 DEBUG [org.hibernate.pretty.Printer] - <com.grooveapp.model.Todo{description=bar, done=false, completed=null, id=4}>
2005-12-19 18:42:00,724 DEBUG [org.hibernate.event.def.DefaultDirtyCheckEventListener] - <session not dirty>
2005-12-19 18:42:00,724 DEBUG [org.hibernate.impl.SessionImpl] - <closing session>
2005-12-19 18:42:00,724 DEBUG [org.hibernate.jdbc.ConnectionManager] - <performing cleanup>
2005-12-19 18:42:00,725 DEBUG [org.hibernate.jdbc.ConnectionManager] - <closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]>
2005-12-19 18:42:00,725 DEBUG [org.hibernate.connection.DriverManagerConnectionProvider] - <returning connection to pool, pool size: 1>
2005-12-19 18:42:00,725 DEBUG [org.hibernate.jdbc.JDBCContext] - <after transaction completion>
2005-12-19 18:42:00,725 DEBUG [org.hibernate.jdbc.ConnectionManager] - <transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!>
2005-12-19 18:42:00,725 DEBUG [org.hibernate.impl.SessionImpl] - <after transaction completion>
Log file - Loading List of Todo objects in MySQL
-- findAllAndTest()
Code:
2005-12-19 18:45:47,485 DEBUG [com.grooveapp.service.impl.TodoService] - <Searching for all Todo items>
2005-12-19 18:45:47,485 DEBUG [com.grooveapp.service.impl.TodoService] - <Model for this:class com.grooveapp.model.Todo>
2005-12-19 18:45:47,486 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <about to open PreparedStatement (open PreparedStatements: 0, globally: 0)>
2005-12-19 18:45:47,486 DEBUG [org.hibernate.jdbc.ConnectionManager] - <opening JDBC connection>
2005-12-19 18:45:47,486 DEBUG [org.hibernate.connection.DriverManagerConnectionProvider] - <total checked-out connections: 0>
2005-12-19 18:45:47,486 DEBUG [org.hibernate.connection.DriverManagerConnectionProvider] - <using pooled JDBC connection, pool size: 0>
2005-12-19 18:45:47,486 DEBUG [org.hibernate.SQL] - <select this_.id as id0_0_, this_.completed as completed0_0_, this_.done as done0_0_, this_.description as descript4_0_0_ from todo this_ order by this_.description asc>
Hibernate: select this_.id as id0_0_, this_.completed as completed0_0_, this_.done as done0_0_, this_.description as descript4_0_0_ from todo this_ order by this_.description asc
2005-12-19 18:45:47,486 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <preparing statement>
2005-12-19 18:45:47,507 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <about to open ResultSet (open ResultSets: 0, globally: 0)>
2005-12-19 18:45:47,507 DEBUG [org.hibernate.loader.Loader] - <processing result set>
2005-12-19 18:45:47,507 DEBUG [org.hibernate.loader.Loader] - <result set row: 0>
2005-12-19 18:45:47,508 DEBUG [org.hibernate.type.IntegerType] - <returning '2' as column: id0_0_>
2005-12-19 18:45:47,508 DEBUG [org.hibernate.loader.Loader] - <result row: EntityKey[com.grooveapp.model.Todo#2]>
2005-12-19 18:45:47,508 DEBUG [org.hibernate.loader.Loader] - <Initializing object from ResultSet: [com.grooveapp.model.Todo#2]>
2005-12-19 18:45:47,508 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] - <Hydrating entity: [com.grooveapp.model.Todo#2]>
2005-12-19 18:45:47,508 DEBUG [org.hibernate.type.DateType] - <returning null as column: completed0_0_>
2005-12-19 18:45:47,509 DEBUG [org.hibernate.type.BooleanType] - <returning 'false' as column: done0_0_>
2005-12-19 18:45:47,509 DEBUG [org.hibernate.type.StringType] - <returning 'bar' as column: descript4_0_0_>
2005-12-19 18:45:47,509 DEBUG [org.hibernate.loader.Loader] - <result set row: 1>
2005-12-19 18:45:47,509 DEBUG [org.hibernate.type.IntegerType] - <returning '1' as column: id0_0_>
2005-12-19 18:45:47,509 DEBUG [org.hibernate.loader.Loader] - <result row: EntityKey[com.grooveapp.model.Todo#1]>
2005-12-19 18:45:47,509 DEBUG [org.hibernate.loader.Loader] - <Initializing object from ResultSet: [com.grooveapp.model.Todo#1]>
2005-12-19 18:45:47,509 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] - <Hydrating entity: [com.grooveapp.model.Todo#1]>
2005-12-19 18:45:47,509 DEBUG [org.hibernate.type.DateType] - <returning null as column: completed0_0_>
2005-12-19 18:45:47,510 DEBUG [org.hibernate.type.BooleanType] - <returning 'false' as column: done0_0_>
2005-12-19 18:45:47,510 DEBUG [org.hibernate.type.StringType] - <returning 'foo' as column: descript4_0_0_>
2005-12-19 18:45:47,510 DEBUG [org.hibernate.loader.Loader] - <done processing result set (2 rows)>
2005-12-19 18:45:47,510 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <about to close ResultSet (open ResultSets: 1, globally: 1)>
2005-12-19 18:45:47,510 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <about to close PreparedStatement (open PreparedStatements: 1, globally: 1)>
2005-12-19 18:45:47,510 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <closing statement>
2005-12-19 18:45:47,510 DEBUG [org.hibernate.loader.Loader] - <total objects hydrated: 2>
2005-12-19 18:45:47,511 DEBUG [org.hibernate.engine.TwoPhaseLoad] - <resolving associations for [com.grooveapp.model.Todo#2]>
2005-12-19 18:45:47,511 DEBUG [org.hibernate.engine.TwoPhaseLoad] - <done materializing entity [com.grooveapp.model.Todo#2]>
2005-12-19 18:45:47,514 DEBUG [org.hibernate.engine.TwoPhaseLoad] - <resolving associations for [com.grooveapp.model.Todo#1]>
2005-12-19 18:45:47,515 DEBUG [org.hibernate.engine.TwoPhaseLoad] - <done materializing entity [com.grooveapp.model.Todo#1]>
2005-12-19 18:45:47,515 DEBUG [org.hibernate.engine.StatefulPersistenceContext] - <initializing non-lazy collections>
2005-12-19 18:45:47,515 DEBUG [org.hibernate.jdbc.JDBCContext] - <after autocommit>
2005-12-19 18:45:47,515 DEBUG [org.hibernate.jdbc.ConnectionManager] - <transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!>
2005-12-19 18:45:47,515 DEBUG [com.grooveapp.service.impl.TodoService] - <Looking for Todo#2>
2005-12-19 18:45:47,515 DEBUG [com.grooveapp.service.impl.TodoService] - <Model for this:class com.grooveapp.model.Todo>
2005-12-19 18:45:47,515 DEBUG [com.grooveapp.service.impl.TodoService] - <Finding object of type:Todo>
2005-12-19 18:45:47,515 DEBUG [com.grooveapp.service.impl.TodoService] - <id:2 of type:Integer>
2005-12-19 18:45:47,515 DEBUG [com.grooveapp.service.impl.TodoService] - <Model for this:class com.grooveapp.model.Todo>
2005-12-19 18:45:47,516 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] - <loading entity: [com.grooveapp.model.Todo#2]>
2005-12-19 18:45:47,516 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] - <entity found in session cache>
2005-12-19 18:45:47,516 DEBUG [org.hibernate.jdbc.JDBCContext] - <after autocommit>
2005-12-19 18:45:47,516 DEBUG [org.hibernate.jdbc.ConnectionManager] - <transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!>
2005-12-19 18:45:47,516 DEBUG [com.grooveapp.service.impl.TodoService] - <found obj!>
2005-12-19 18:45:47,516 DEBUG [com.grooveapp.service.impl.TodoService] - <Found?true>
2005-12-19 18:45:47,516 DEBUG [com.grooveapp.service.impl.TodoService] - <Looking for Todo#1>
2005-12-19 18:45:47,516 DEBUG [com.grooveapp.service.impl.TodoService] - <Model for this:class com.grooveapp.model.Todo>
2005-12-19 18:45:47,516 DEBUG [com.grooveapp.service.impl.TodoService] - <Finding object of type:Todo>
2005-12-19 18:45:47,516 DEBUG [com.grooveapp.service.impl.TodoService] - <id:1 of type:Integer>
2005-12-19 18:45:47,517 DEBUG [com.grooveapp.service.impl.TodoService] - <Model for this:class com.grooveapp.model.Todo>
2005-12-19 18:45:47,518 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] - <loading entity: [com.grooveapp.model.Todo#1]>
2005-12-19 18:45:47,518 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] - <entity found in session cache>
2005-12-19 18:45:47,518 DEBUG [org.hibernate.jdbc.JDBCContext] - <after autocommit>
2005-12-19 18:45:47,518 DEBUG [org.hibernate.jdbc.ConnectionManager] - <transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!>
2005-12-19 18:45:47,518 DEBUG [com.grooveapp.service.impl.TodoService] - <found obj!>
2005-12-19 18:45:47,518 DEBUG [com.grooveapp.service.impl.TodoService] - <Found?true>
-- find(Integer(1) in MySQL
Code:
2005-12-19 18:47:12,240 DEBUG [com.grooveapp.filter.FlushingViewFilter] - <Using SessionFactory 'sessionFactory' for OpenSessionInViewFilter>
2005-12-19 18:47:12,240 DEBUG [com.grooveapp.filter.FlushingViewFilter] - <Opening single Hibernate Session in OpenSessionInViewFilter>
2005-12-19 18:47:12,240 DEBUG [org.hibernate.impl.SessionImpl] - <opened session at timestamp: 4649107588055040>
2005-12-19 18:47:12,240 DEBUG [org.hibernate.impl.SessionImpl] - <setting flush mode to: NEVER>
2005-12-19 18:47:12,240 DEBUG [org.hibernate.impl.SessionImpl] - <setting flush mode to: AUTO>
[com.grooveapp.service.impl.TodoService] - <Model for this:class com.grooveapp.model.Todo>
2005-12-19 18:47:12,245 DEBUG [com.grooveapp.service.impl.TodoService] - <Finding object of type:Todo>
2005-12-19 18:47:12,245 DEBUG [com.grooveapp.service.impl.TodoService] - <id:1 of type:Integer>
2005-12-19 18:47:12,245 DEBUG [com.grooveapp.service.impl.TodoService] - <Model for this:class com.grooveapp.model.Todo>
2005-12-19 18:47:12,245 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] - <loading entity: [com.grooveapp.model.Todo#1]>
2005-12-19 18:47:12,245 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] - <creating new proxy for entity>
2005-12-19 18:47:12,245 DEBUG [org.hibernate.jdbc.JDBCContext] - <after autocommit>
2005-12-19 18:47:12,245 DEBUG [org.hibernate.jdbc.ConnectionManager] - <transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!>
2005-12-19 18:47:12,246 DEBUG [org.hibernate.impl.SessionImpl] - <after transaction completion>
2005-12-19 18:47:12,246 DEBUG [com.grooveapp.service.impl.TodoService] - <found obj!>
2005-12-19 18:47:12,246 DEBUG [com.grooveapp.filter.GrooveFilter] - <including : /todo/view.jsp>
2005-12-19 18:47:12,247 DEBUG [org.hibernate.impl.SessionImpl] - <initializing proxy: [com.grooveapp.model.Todo#1]>
2005-12-19 18:47:12,247 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] - <attempting to resolve: [com.grooveapp.model.Todo#1]>
2005-12-19 18:47:12,247 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] - <object not resolved in any cache: [com.grooveapp.model.Todo#1]>
2005-12-19 18:47:12,247 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] - <Fetching entity: [com.grooveapp.model.Todo#1]>
2005-12-19 18:47:12,247 DEBUG [org.hibernate.loader.Loader] - <loading entity: [com.grooveapp.model.Todo#1]>
2005-12-19 18:47:12,247 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <about to open PreparedStatement (open PreparedStatements: 0, globally: 0)>
2005-12-19 18:47:12,247 DEBUG [org.hibernate.jdbc.ConnectionManager] - <opening JDBC connection>
2005-12-19 18:47:12,248 DEBUG [org.hibernate.connection.DriverManagerConnectionProvider] - <total checked-out connections: 0>
2005-12-19 18:47:12,248 DEBUG [org.hibernate.connection.DriverManagerConnectionProvider] - <using pooled JDBC connection, pool size: 0>
2005-12-19 18:47:12,248 DEBUG [org.hibernate.SQL] - <select todo0_.id as id0_0_, todo0_.completed as completed0_0_, todo0_.done as done0_0_, todo0_.description as descript4_0_0_ from todo todo0_ where todo0_.id=?>
Hibernate: select todo0_.id as id0_0_, todo0_.completed as completed0_0_, todo0_.done as done0_0_, todo0_.description as descript4_0_0_ from todo todo0_ where todo0_.id=?
2005-12-19 18:47:12,248 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <preparing statement>
2005-12-19 18:47:12,253 DEBUG [org.hibernate.type.IntegerType] - <binding '1' to parameter: 1>
2005-12-19 18:47:12,256 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <about to open ResultSet (open ResultSets: 0, globally: 0)>
2005-12-19 18:47:12,256 DEBUG [org.hibernate.loader.Loader] - <processing result set>
2005-12-19 18:47:12,256 DEBUG [org.hibernate.loader.Loader] - <done processing result set (0 rows)>
2005-12-19 18:47:12,257 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <about to close ResultSet (open ResultSets: 1, globally: 1)>
2005-12-19 18:47:12,257 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <about to close PreparedStatement (open PreparedStatements: 1, globally: 1)>
2005-12-19 18:47:12,257 DEBUG [org.hibernate.jdbc.AbstractBatcher] - <closing statement>
2005-12-19 18:47:12,257 DEBUG [org.hibernate.loader.Loader] - <total objects hydrated: 0>
2005-12-19 18:47:12,257 DEBUG [org.hibernate.engine.StatefulPersistenceContext] - <initializing non-lazy collections>
2005-12-19 18:47:12,257 DEBUG [org.hibernate.loader.Loader] - <done entity load>
2005-12-19 18:47:12,258 ERROR [org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/groove2].[jsp]] - <Servlet.service() for servlet jsp threw exception>org.hibernate.ObjectNotFoundException: No row with the given identifier exists: [com.grooveapp.model.Todo#1]
at org.hibernate.ObjectNotFoundException.throwIfNull(ObjectNotFoundException.java:27)
at org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:65)
at org.hibernate.proxy.AbstractLazyInitializer.getImplementation(AbstractLazyInitializer.java:98)
at org.hibernate.proxy.CGLIBLazyInitializer.intercept(CGLIBLazyInitializer.java:158)
at com.grooveapp.model.Todo$$EnhancerByCGLIB$$ed06346c.getDescription(<generated>)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.apache.taglibs.standard.lang.jstl.ArraySuffix.evaluate(ArraySuffix.java:278)
at org.apache.taglibs.standard.lang.jstl.ComplexValue.evaluate(ComplexValue.java:107)
at org.apache.taglibs.standard.lang.jstl.ELEvaluator.evaluate(ELEvaluator.java:204)
at org.apache.taglibs.standard.lang.jstl.ELEvaluator.evaluate(ELEvaluator.java:163)
at org.apache.taglibs.standard.lang.jstl.Evaluator.evaluate(Evaluator.java:101)
at org.apache.taglibs.standard.lang.jstl.Evaluator.evaluate(Evaluator.java:129)
at org.apache.taglibs.standard.lang.support.ExpressionEvaluatorManager.evaluate(ExpressionEvaluatorManager.java:75)
at org.apache.taglibs.standard.tag.el.core.ExpressionUtil.evalNotNull(ExpressionUtil.java:48)
at org.apache.taglibs.standard.tag.el.core.OutTag.evaluateExpressions(OutTag.java:99)
at org.apache.taglibs.standard.tag.el.core.OutTag.doStartTag(OutTag.java:57)
at org.apache.jsp.todo.view_jsp._jspx_meth_c_out_1(org.apache.jsp.todo.view_jsp:103)
at org.apache.jsp.todo.view_jsp._jspService(org.apache.jsp.todo.view_jsp:59)
at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:97)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:322)
at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:314)
at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:264)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:672)
at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:463)
at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:398)
at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:301)
at com.grooveapp.filter.GrooveFilter.processResult(GrooveFilter.java:147)
at com.grooveapp.filter.GrooveFilter.doFilter(GrooveFilter.java:99)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at org.springframework.orm.hibernate3.support.OpenSessionInViewFilter.doFilterInternal(OpenSessionInViewFilter.java:174)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:868)
at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:663)
at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
at java.lang.Thread.run(Thread.java:595)
2005-12-19 18:47:12,268 ERROR [com.grooveapp.filter.GrooveFilter] - <Exception with action: todo->1>
2005-12-19 18:47:12,268 ERROR [com.grooveapp.filter.GrooveFilter] - <javax.servlet.ServletException: javax.servlet.jsp.JspException: An error occurred while evaluating custom action attribute "value" with value "${todo.description}": An error occurred while getting property "description" from an instance of class com.grooveapp.model.Todo$$EnhancerByCGLIB$$ed06346c (org.hibernate.ObjectNotFoundException: No row with the given identifier exists: [com.grooveapp.model.Todo#1])>
javax.servlet.ServletException: javax.servlet.jsp.JspException: An error occurred while evaluating custom action attribute "value" with value "${todo.description}": An error occurred while getting property "description" from an instance of class com.grooveapp.model.Todo$$EnhancerByCGLIB$$ed06346c (org.hibernate.ObjectNotFoundException: No row with the given identifier exists: [com.grooveapp.model.Todo#1])
at org.apache.jasper.runtime.PageContextImpl.doHandlePageException(PageContextImpl.java:844)
at org.apache.jasper.runtime.PageContextImpl.handlePageException(PageContextImpl.java:781)
at org.apache.jsp.todo.view_jsp._jspService(org.apache.jsp.todo.view_jsp:69)
at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:97)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:322)
at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:314)
at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:264)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:672)
at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:463)
at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:398)
at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:301)
at com.grooveapp.filter.GrooveFilter.processResult(GrooveFilter.java:147)
at com.grooveapp.filter.GrooveFilter.doFilter(GrooveFilter.java:99)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at org.springframework.orm.hibernate3.support.OpenSessionInViewFilter.doFilterInternal(OpenSessionInViewFilter.java:174)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:868)
at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:663)
at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
at java.lang.Thread.run(Thread.java:595)
2005-12-19 18:47:12,273 DEBUG [com.grooveapp.filter.FlushingViewFilter] - <Closing single Hibernate Session in OpenSessionInViewFilter>
2005-12-19 18:47:12,273 DEBUG [org.hibernate.impl.SessionImpl] - <checking session dirtiness>
2005-12-19 18:47:12,273 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] - <flushing session>
2005-12-19 18:47:12,274 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] - <processing flush-time cascades>
2005-12-19 18:47:12,274 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] - <dirty checking collections>
2005-12-19 18:47:12,274 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] - <Flushing entities and processing referenced collections>
2005-12-19 18:47:12,274 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] - <Processing unreferenced collections>
2005-12-19 18:47:12,274 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] - <Scheduling collection removes/(re)creates/updates>
2005-12-19 18:47:12,274 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] - <Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects>
2005-12-19 18:47:12,274 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] - <Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections>
2005-12-19 18:47:12,274 DEBUG [org.hibernate.event.def.DefaultDirtyCheckEventListener] - <session not dirty>
2005-12-19 18:47:12,274 DEBUG [org.hibernate.impl.SessionImpl] - <closing session>
2005-12-19 18:47:12,274 DEBUG [org.hibernate.jdbc.ConnectionManager] - <performing cleanup>
2005-12-19 18:47:12,274 DEBUG [org.hibernate.jdbc.ConnectionManager] - <closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]>
2005-12-19 18:47:12,274 DEBUG [org.hibernate.connection.DriverManagerConnectionProvider] - <returning connection to pool, pool size: 1>
2005-12-19 18:47:12,274 DEBUG [org.hibernate.jdbc.JDBCContext] - <after transaction completion>
2005-12-19 18:47:12,275 DEBUG [org.hibernate.jdbc.ConnectionManager] - <transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!>
2005-12-19 18:47:12,275 DEBUG [org.hibernate.impl.SessionImpl] - <after transaction completion>