Changes on domain obj are committed without calling update

[bullgod]

Hi All,

i'm new to Spring but I like it very much. I started to use the DAO Support with Hibernate a while back and now converting from WebWork to Spring MVC since the Spring MVC offers a bit more flexibility - especially the FormWizard stuff. Now a very strange problems occurs while using OpenSessionInView Filter.
If an error occurs in my form (which uses a FormCommand and a nestest domain object), the changes are commited to the database when errors occur (which leads to re-display the form with error messages)!!! But an Hibernate update query is fired and it updates the database with the (in this case) empty form field value.
But in the error/redisplay case i do not call a save or update method of my service object (or underlying dao).

If i deactivate OpenSessionInView filter the error case behaviour is fine, but if i call the save-method of my DAO i get LazyInitException (no open session). Which is a very strange error, i can't find the cause. When i'm calling the save method of the dao the session is still open.
I'd prefer not having an open session in my view, but i don't know hot to do it properly. Init all those relations by manually calling getters seems to be kludgy to me.
Anyway, I can't get it work properly without OpenSessInViewFilter. I guess it would work if i would use the FormCommand object to update the domain object. but that's double work.

It would be very cool if you guys could give me a hint what's going wrong (why are updates to the database made when dao.update(obj) is NOT called. The DAOs/Service beans worked perfectly with WebWork btw!

Is there a "better" documentaion of the MVC implementation? I found it very hard to learn by the examples. I could use WebWork efficiently after 1 day - and after 3 days still trying to find out how the Spring MVC works.

Here's the code of the FormController:

public class UserFormController extends SimpleFormController {

    private static final Log log = LogFactory.getLog(UserFormController.class);
    
    private UserService userService = null;
    
    protected Object formBackingObject(HttpServletRequest request) throws ServletException {
        log.error("formBackingObject called");
        User user = userService.getUser(RequestUtils.getRequiredStringParameter(request, "username"));
        return new UserForm(user);
    }

    public ModelAndView onSubmit(Object command) throws ServletException {
        log.error("onSubmit called");
        User user = ((UserForm) command).getUser();

        userService.saveUser(user);
        return new ModelAndView(new RedirectView("/admin/user/view"), "username", user.getHandle());
    }

    public void setUserService(UserService userService) {
        log.error("setUserService called called");
        this.userService = userService;
    }
}

FormBackingObject:

public class UserForm {
    
    private User user;
    private String repeatedPassword;
    private boolean newUser;
    
	public UserForm(User user) {
		this.user = user;
		this.newUser = false;
	}

	public UserForm() {
		this.user = new User();
		this.newUser = true;
	}

    public User getUser() {
        return this.user;
    }

    public boolean isNewUser() {
		return newUser;
	}

    
    public void setRepeatedPassword(String repeatedPassword) {
		this.repeatedPassword = repeatedPassword;
	}

	public String getRepeatedPassword() {
		return repeatedPassword;
	}    
    
}

UserFormValidator:

public class UserFormValidator implements Validator {

    public boolean supports(Class clazz) {
		return UserForm.class.isAssignableFrom(clazz);
	}

    public void validate(Object obj, Errors errors) {
	    ValidationUtils.rejectIfEmpty(errors, "user.fullname", "FIRST_NAME_REQUIRED", "First name is required.");
	    ValidationUtils.rejectIfEmpty(errors, "user.email", "FIRST_NAME_REQUIRED", "Email is required.");
	}
}

UserServiceImpl:

public class UserServiceImpl implements UserService {

        private UserDao userDao;
        private RoleDao roleDao;

        public void setUserDao(UserDao userDao) {
            this.userDao = userDao;
        }

        public void setRoleDao(RoleDao roleDao) {
            this.roleDao = roleDao;
        }


        
        // TODO: throw exception
        public boolean authenticate(String username, String password) {
            User user = getUser(username);
            if (user == null || !user.getPassword().equals(password))
                return false;
            return true;
        }

        
        public User getUser(Long id) {
            return userDao.loadUserById(id);
        }

        public List getUsers() {
            return userDao.loadAllUsers();
        }
        
        public User getUser(String username) {
            return userDao.loadUserByName(username);
        }
        
        public void saveUser(User user) {
            userDao.saveOrUpdateUser(user);
        }

        public void deactivateUser(User user) {
            //TODO: implement deactivate
        }
        public void reactivateUser(User user) {
            //TODO: implement reactivate
        }
        
        public List getRoles() {
            return roleDao.loadAllRoles();
        }
        
        public Role getRole(String name) {
            return roleDao.loadRoleByName(name);
        }
        
        public Role getRole(Long id) {
            return roleDao.loadRoleById(id);
        }
        
        public List getUnassignedRoles(User user) {
            return userDao.loadUnassignedRolesForUser(user);
        }
  
}

UserDaoImpl:

 public class UserDaoImpl extends HibernateDaoSupport implements UserDao {

     
     public List loadUnassignedRolesForUser(User user) throws DataAccessException {
         List uaRoles = new ArrayList();
         List roles = getHibernateTemplate().loadAll(Role.class);
         for (Iterator i = roles.iterator(); i.hasNext();) {
             Role current = (Role) i.next();
             // TODO: using contains could be dangerous, try to use named query
             // but don't know how to obtain the hibernate dialect!?
             if (!user.getRoles().contains(current)) {
                 uaRoles.add(current);
             }
         }
         return uaRoles;
    }
 
         
     public User loadUserById(Long id) throws DataAccessException {
        return (User) getHibernateTemplate().load(User.class, id);
    }

    public User loadUserByName(String username) throws DataAccessException {
        return (User) getHibernateTemplate().find("select u from User u where u.handle = ?", username).get(0);
    }

    public List loadAllUsers() throws DataAccessException {
        return (List) getHibernateTemplate().loadAll(User.class);
    }
    
    public void saveOrUpdateUser(User user) throws DataAccessException {
        getHibernateTemplate().saveOrUpdate(user);
    }
    
}

Formbean defininition:

	<bean id="userValidator" class="com.thyrell.pm.user.web.UserFormValidator"/>
	<bean id="editUserForm"  class="com.thyrell.pm.user.web.UserFormController">
		<property name="userService"><ref bean="userService"/></property>
		<property name="validator"><ref local="userValidator"/></property>
		<property name="commandClass"><value>com.thyrell.pm.user.web.UserForm</value></property>
		<property name="commandName"><value>userForm</value></property>
		<property name="formView"><value>EditUserForm</value></property>
		<property name="successView"><value>EditUserFormRedirect</value></property>
	</bean>

Dao/Service Definitions:

	<bean id="pmHibernateInterceptor" class="org.springframework.orm.hibernate.HibernateInterceptor">
		<property name="sessionFactory"><ref local="sessionFactory"/></property>
	</bean> 

	<bean id="pmTransactionManager" class="org.springframework.transaction.jta.JtaTransactionManager"/>

<!--	<bean id="pmTransactionManager" class="org.springframework.orm.hibernate.HibernateTransactionManager">-->
<!--		<property name="sessionFactory"><ref local="sessionFactory"/></property>-->
<!--	</bean>-->

	<bean id="pmTransactionInterceptor" class="org.springframework.transaction.interceptor.TransactionInterceptor">
		<property name="transactionManager"><ref bean="pmTransactionManager" /></property>
		<property name="transactionAttributeSource">
			<value>
				com.thyrell.pm.user.UserServiceImpl.*=PROPAGATION_REQUIRED,-DataAccessException
				com.thyrell.pm.user.UserServiceImpl.get*=PROPAGATION_REQUIRED,readOnly
			</value>
		</property>
	</bean>


	<bean id="userDaoTarget" class="com.thyrell.pm.user.dao.UserDaoImpl">
		<property name="sessionFactory"><ref local="sessionFactory" /></property>
	</bean>
	<bean id="userDao" class="org.springframework.aop.framework.ProxyFactoryBean">
		<property name="proxyInterfaces"><value>com.thyrell.pm.user.dao.UserDao</value></property>
		<property name="interceptorNames">
		    <list>
    		  <value>pmHibernateInterceptor</value>
    		  <value>userDaoTarget</value>
    		</list>
		</property>
	</bean>

	<bean id="roleDaoTarget" class="com.thyrell.pm.user.dao.RoleDaoImpl">
		<property name="sessionFactory"><ref local="sessionFactory" /></property>
	</bean>
	<bean id="roleDao" class="org.springframework.aop.framework.ProxyFactoryBean">
		<property name="proxyInterfaces"><value>com.thyrell.pm.user.dao.RoleDao</value></property>
		<property name="interceptorNames">
		    <list>
    		  <value>pmHibernateInterceptor</value>
    		  <value>roleDaoTarget</value>
    		</list>
		</property>
	</bean>



	<bean id="userServiceTarget" class="com.thyrell.pm.user.UserServiceImpl">
		<property name="userDao"><ref bean="userDao" /></property>
		<property name="roleDao"><ref bean="roleDao" /></property>
	</bean>
	<bean id="userService" class="org.springframework.aop.framework.ProxyFactoryBean">
		<property name="proxyInterfaces"><value>com.thyrell.pm.user.UserService</value></property>
		<property name="interceptorNames">
			<value>pmTransactionInterceptor,userServiceTarget</value>
		</property>
	</bean>

Ah, yeah, the OpenSessionInViewFilter overridden (caus of the auto-flush thing):

public class FlushingSpringSessionInViewFilter extends OpenSessionInViewFilter {

    public FlushingSpringSessionInViewFilter() {
    }

    protected Session getSession(SessionFactory sessionFactory) throws DataAccessResourceFailureException {
	    Session session = SessionFactoryUtils.getSession(sessionFactory, true);
	    session.setFlushMode(FlushMode.AUTO);
	    return session;
	}
    
    protected void closeSession(Session session, SessionFactory sessionFactory) throws CleanupFailureDataAccessException {
        if (session != null && session.isOpen() && session.isConnected()) {
            try {
                session.flush();
            } catch (HibernateException e) {
                throw new CleanupFailureDataAccessException("Failed to flush session before close: " + e.getMessage(), e);
            }
        }
        super.closeSession(session, sessionFactory);
    }
}

Hope the long code listings help you nailing down the problem.

Thanks a lot,
Andi

[irbouho]

Andi,
The long listing is very helpfull

You are applying HibernateInterceptor (which is responsable for handling Hibernate Sessions) to DAOs but the Transactions are applied to the Service Methods. That means:

a. when OpenSessionInView is not configured:
When a service method S1 is called, a new transaction will be started, if S1 calls userDAO method D1 to retrieve a user, a new hibernate Session will be opened before the call is done and closed after the call. Now if S1 tries to touch some user's data that are lazily loaded, an Exception will be thrown since there is no session opened!!!

To solve this problem, you should apply the HibernateInterceptor to Service methods.

[bullgod]

Hey Omar,

thanks for the fast and helpful reply. This nailed it. I thought that the HibernateInterceptor is not closing the session (but OpenSessionInViewFilter is) and just opening one session per request. I'd looked at the config in the last instance before madness, caus it worked with WebWork Anyway it works fine now. I also switchted to OpenSessionInViewInterceptor which seems to be a more natural choice with Spring MVC.

Btw: What would you use in case of the OpenSessionInViewInterceptor: single session mode or deferred close mode?
http://www.springframework.org/docs/...terceptor.html

I tend to singlesession=false but it's slower

Thanks for your help. It works )
-andi

[bullgod]

Damn, premature happiness ...

it does not work properly. when i use singel session in the viewinterceptor, and transactioninterceptor and hibernate interceptor wired up as proposed. i get a read only exception when i try to persist the changes.

if i set AUTO_FLUSH and singleSession=true the changes get persisted even if i don't call a service method (in case of form errors). that's very odd.

if i use singelsession = false i get: can't associate collection with two sessions exception.

argh, i'm really getting lost now. tried all combinations of the openSessioninviewInterceptor settings and with and w/o hibernate interceptor, with hibernate transactionmanager with JTA.... no cure.

-andi

[bullgod]

OK, first I thought it could be a dirty hibernate session, but it was not (since update-dynamic/insert-dynamic = false).

It seems that I found the problem, but i don't understand it. I changed the BO definitions to use the TransactionFactoryBean instead of ProxyFactoryBean with a transaction interceptor:

	<bean id="userServiceTarget" class="com.thyrell.pm.user.UserServiceImpl">
		<property name="userDao"><ref bean="userDao" /></property>
		<property name="roleDao"><ref bean="roleDao" /></property>
	</bean>

	<bean id="userService" class="org.springframework.transaction.interceptor.TransactionProxyFactoryBean">
		<property name="target"><ref bean="userServiceTarget"/></property>
		<property name="transactionManager"><ref bean="pmTransactionManager"/></property>
		<property name="transactionAttributes">
		    <props>
		      <prop key="*">PROPAGATION_REQUIRED</prop>
		    </props>
		</property>
	</bean>

Open SessionInViewInterceptor ist now standard:

	<bean name="openSessionInViewInterceptor"  class="org.springframework.orm.hibernate.support.OpenSessionInViewInterceptor">
       <property name="sessionFactory"><ref bean="sessionFactory"/></property>
	</bean>

This works as expected... so far. At least for the "change-user-details" usecase of my app.

But i do not understand why using the transactionInterceptor (like in the very first post) does not work properly It would rock if you could explain this to me, i really don't get it....

Thanks,
Andi

[irbouho]

Andi,
Could you please try the following configuration:

   <bean id="pmHibernateInterceptor" class="org.springframework.orm.hibernate.HibernateInterceptor">
     <property name="sessionFactory"><ref bean="sessionFactory"/></property>
   </bean>

   <bean id="pmTransactionManager" class="org.springframework.orm.hibernate.HibernateTransactionManager">
     <property name="sessionFactory"><ref bean="sessionFactory"/></property>
   </bean>

   <bean id="pmTransactionInterceptor" class="org.springframework.transaction.interceptor.TransactionInterceptor">
     <property name="transactionManager"><ref bean="pmTransactionManager"/></property>
     <property name="transactionAttributeSource">
       <value>
         com.thyrell.pm.user.UserServiceImpl.*=PROPAGATION_REQUIRED
       </value>
     </property>
   </bean>

   <bean id="userDao" class="com.thyrell.pm.user.dao.UserDaoImpl"> 
      <property name="sessionFactory"><ref local="sessionFactory" /></property> 
   </bean>

   <bean id="roleDaoTarget" class="com.thyrell.pm.user.dao.RoleDaoImpl"> 
      <property name="sessionFactory"><ref local="sessionFactory" /></property> 
   </bean> 

   <bean id="userServiceTarget" class="com.thyrell.pm.user.UserServiceImpl"> 
      <property name="userDao"><ref bean="userDao" /></property> 
      <property name="roleDao"><ref bean="roleDao" /></property> 
   </bean> 

  <bean id="userService" class="org.springframework.aop.framework.ProxyFactoryBean">
    <property name="proxyInterfaces">
     <value>com.thyrell.pm.user.UserService</value>
    </property>
    <property name="interceptorNames">
     <list>
      <value>pmTransactionInterceptor</value>
      <value>pmHibernateInterceptor</value>
      <value>userServiceTarget</value>
     </list>
    </property>
  </bean>

I am too, very interested to know why using configuration TransactionInterceptor did not work.

[bullgod]

Hi Omar,

thanks for your patience and help. i tried your changes. I get correct behaviour in case of an input error (i.e. empty field). Form is displayed with error messages and there is no UPDATE query sent to the database. Eveything fine. But then if it comes to persist the changes (onSubmit), i get the unloved "Write Operations not allowed in read only-mode exception" (see log1). Strange caus i did not set a readonly flag in the transaction interceptor.

According to the API docs of OSIVInterceptor i should set FLUSH_AUTO in the OSIVInterceptor, which is, concerning the API docs, is not a good practice. Anyway... but now i'm back at the beginning. In case of a validation error (in the form) hibernate persists changes without calling a save/saveOrUpdate method (second log). That's really wired.

Either I'm blind and i misunderstand something essential, or there is a bug somewhere.

2004-09-17 11:41:41,896 DEBUG [org.springframework.web.servlet.DispatcherServlet] - DispatcherServlet with name 'perfectmind' received request for [/admin/user/edit.jspa]
2004-09-17 11:41:41,916 DEBUG [org.springframework.web.servlet.DispatcherServlet] - Testing handler map [org.springframework.web.servlet.handler.SimpleUrlHandlerMapping@36d047] in DispatcherServlet with name 'perfectmind'
2004-09-17 11:41:41,916 DEBUG [org.springframework.web.servlet.handler.SimpleUrlHandlerMapping] - Looking up handler for [/admin/user/edit.jspa]
2004-09-17 11:41:41,916 DEBUG [org.springframework.orm.hibernate.support.OpenSessionInViewInterceptor] - Opening single Hibernate session in OpenSessionInViewInterceptor
2004-09-17 11:41:41,916 DEBUG [org.springframework.orm.hibernate.SessionFactoryUtils] - Opening Hibernate session
2004-09-17 11:41:41,916 DEBUG [net.sf.hibernate.impl.SessionImpl] - opened session
2004-09-17 11:41:41,916 DEBUG [org.springframework.transaction.support.TransactionSynchronizationManager] - Bound value [org.springframework.orm.hibernate.SessionHolder@1b59919] for key [net.sf.hibernate.impl.SessionFactoryImpl@1ce663c] to thread [thread-pool-34]
2004-09-17 11:41:41,916 DEBUG [org.springframework.web.servlet.DispatcherServlet] - Testing handler adapter [org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter@18b1f8f]
2004-09-17 11:41:41,926 WARN [com.thyrell.pm.user.web.UserFormController] - formBackingObject called
2004-09-17 11:41:41,926 DEBUG [org.springframework.transaction.interceptor.TransactionInterceptor] - Don't need to create transaction for method 'getUser' in class [com.thyrell.pm.user.UserService]: this method isn't transactional
2004-09-17 11:41:41,926 DEBUG [org.springframework.transaction.support.TransactionSynchronizationManager] - Retrieved value [org.springframework.orm.hibernate.SessionHolder@1b59919] for key [net.sf.hibernate.impl.SessionFactoryImpl@1ce663c] bound to thread [thread-pool-34]
2004-09-17 11:41:41,926 DEBUG [org.springframework.orm.hibernate.HibernateInterceptor] - Found thread-bound session for Hibernate interceptor
2004-09-17 11:41:41,926 DEBUG [org.springframework.transaction.support.TransactionSynchronizationManager] - Retrieved value [org.springframework.orm.hibernate.SessionHolder@1b59919] for key [net.sf.hibernate.impl.SessionFactoryImpl@1ce663c] bound to thread [thread-pool-34]
2004-09-17 11:41:41,926 DEBUG [org.springframework.transaction.support.TransactionSynchronizationManager] - Retrieved value [org.springframework.orm.hibernate.SessionHolder@1b59919] for key [net.sf.hibernate.impl.SessionFactoryImpl@1ce663c] bound to thread [thread-pool-34]
2004-09-17 11:41:41,926 DEBUG [net.sf.hibernate.impl.SessionImpl] - find: select u from User u where u.handle = ?
2004-09-17 11:41:41,926 DEBUG [net.sf.hibernate.engine.QueryParameters] - parameters: [bullgod]
2004-09-17 11:41:41,926 DEBUG [net.sf.hibernate.engine.QueryParameters] - named parameters: {}
2004-09-17 11:41:41,926 DEBUG [net.sf.hibernate.hql.QueryTranslator] - HQL: select u from com.thyrell.pm.model.User u where u.handle = ?
2004-09-17 11:41:41,926 DEBUG [net.sf.hibernate.hql.QueryTranslator] - SQL: select user0_.USER_UID as USER_UID, user0_.TIMEOFLASTUPDATE as TIMEOFLA2_, user0_.TIMEOFCREATION as TIMEOFCR3_, user0_.USERNAME as USERNAME, user0_.`PASSWORD` as y5_, user0_.EMAIL as EMAIL, user0_.FULLNAME as FULLNAME, user0_.DEFAULT_CONTACT_UID as DEFAULT_8_ from USERS user0_ where (user0_.USERNAME=? )
2004-09-17 11:41:41,936 DEBUG [net.sf.hibernate.impl.BatcherImpl] - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-09-17 11:41:41,936 DEBUG [net.sf.hibernate.SQL] - select user0_.USER_UID as USER_UID, user0_.TIMEOFLASTUPDATE as TIMEOFLA2_, user0_.TIMEOFCREATION as TIMEOFCR3_, user0_.USERNAME as USERNAME, user0_.`PASSWORD` as y5_, user0_.EMAIL as EMAIL, user0_.FULLNAME as FULLNAME, user0_.DEFAULT_CONTACT_UID as DEFAULT_8_ from USERS user0_ where (user0_.USERNAME=? )
Hibernate: select user0_.USER_UID as USER_UID, user0_.TIMEOFLASTUPDATE as TIMEOFLA2_, user0_.TIMEOFCREATION as TIMEOFCR3_, user0_.USERNAME as USERNAME, user0_.`PASSWORD` as y5_, user0_.EMAIL as EMAIL, user0_.FULLNAME as FULLNAME, user0_.DEFAULT_CONTACT_UID as DEFAULT_8_ from USERS user0_ where (user0_.USERNAME=? )
2004-09-17 11:41:41,936 DEBUG [net.sf.hibernate.impl.BatcherImpl] - preparing statement
2004-09-17 11:41:41,936 DEBUG [net.sf.hibernate.type.StringType] - binding 'bullgod' to parameter: 1
2004-09-17 11:41:41,936 DEBUG [net.sf.hibernate.loader.Loader] - processing result set
2004-09-17 11:41:41,936 DEBUG [net.sf.hibernate.type.LongType] - returning '3' as column: USER_UID
2004-09-17 11:41:41,936 DEBUG [net.sf.hibernate.loader.Loader] - result row: 3
2004-09-17 11:41:41,936 DEBUG [net.sf.hibernate.loader.Loader] - Initializing object from ResultSet: 3
2004-09-17 11:41:41,936 DEBUG [net.sf.hibernate.loader.Loader] - Hydrating entity: com.thyrell.pm.model.User#3
2004-09-17 11:41:41,936 DEBUG [net.sf.hibernate.type.TimestampType] - returning '2004-09-16 22:59:36' as column: TIMEOFLA2_
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.type.TimestampType] - returning '2004-08-30 17:13:17' as column: TIMEOFCR3_
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.type.StringType] - returning 'bullgod' as column: USERNAME
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.type.StringType] - returning 'bullgod' as column: y5_
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.type.StringType] - returning 'andi@bullgod.de' as column: EMAIL
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.type.StringType] - returning 'Andreas Aderhold' as column: FULLNAME
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.type.LongType] - returning '1' as column: DEFAULT_8_
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.impl.SessionImpl] - Version: 2004-09-16 22:59:36.0
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.loader.Loader] - done processing result set (1 rows)
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.impl.BatcherImpl] - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.impl.BatcherImpl] - closing statement
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.loader.Loader] - total objects hydrated: 1
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.impl.SessionImpl] - resolving associations for [com.thyrell.pm.model.User#3]
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.impl.SessionImpl] - loading [com.thyrell.pm.model.Contact#1]
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.thyrell.pm.model.Contact#1]
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.impl.SessionImpl] - object not resolved in any cache [com.thyrell.pm.model.Contact#1]
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.persister.EntityPersister] - Materializing entity: [com.thyrell.pm.model.Contact#1]
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.impl.BatcherImpl] - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-09-17 11:41:41,946 DEBUG [net.sf.hibernate.SQL] - select contact0_.CONTACT_UID as CONTACT_1_0_, contact0_.TIMEOFLASTUPDATE as TIMEOFLA2_0_, contact0_.TIMEOFCREATION as TIMEOFCR3_0_, contact0_.CONTACTTYPE as CONTACTT4_0_, contact0_.DESCRIPTION as DESCRIPT5_0_, contact0_.HIDDEN as HIDDEN0_, contact0_.FIRSTNAME as FIRSTNAME0_, contact0_.TITLE as TITLE0_, contact0_.LASTNAME as LASTNAME0_, contact0_.STREET as STREET0_, contact0_.ZIPCODE as ZIPCODE0_, contact0_.CITY as CITY0_, contact0_.STATE as STATE0_, contact0_.COUTNTRY as COUTNTRY0_, contact0_.ICQ as ICQ0_, contact0_.AIM as AIM0_, contact0_.MSN as MSN0_, contact0_.YAHOO as YAHOO0_, contact0_.JABBER as JABBER0_, contact0_.PHONE as PHONE0_, contact0_.FAX as FAX0_, contact0_.CELL as CELL0_, contact0_.EMAIL as EMAIL0_, contact0_.USER_UID as USER_UID0_ from CONTACTS contact0_ where contact0_.CONTACT_UID=?
Hibernate: select contact0_.CONTACT_UID as CONTACT_1_0_, contact0_.TIMEOFLASTUPDATE as TIMEOFLA2_0_, contact0_.TIMEOFCREATION as TIMEOFCR3_0_, contact0_.CONTACTTYPE as CONTACTT4_0_, contact0_.DESCRIPTION as DESCRIPT5_0_, contact0_.HIDDEN as HIDDEN0_, contact0_.FIRSTNAME as FIRSTNAME0_, contact0_.TITLE as TITLE0_, contact0_.LASTNAME as LASTNAME0_, contact0_.STREET as STREET0_, contact0_.ZIPCODE as ZIPCODE0_, contact0_.CITY as CITY0_, contact0_.STATE as STATE0_, contact0_.COUTNTRY as COUTNTRY0_, contact0_.ICQ as ICQ0_, contact0_.AIM as AIM0_, contact0_.MSN as MSN0_, contact0_.YAHOO as YAHOO0_, contact0_.JABBER as JABBER0_, contact0_.PHONE as PHONE0_, contact0_.FAX as FAX0_, contact0_.CELL as CELL0_, contact0_.EMAIL as EMAIL0_, contact0_.USER_UID as USER_UID0_ from CONTACTS contact0_ where contact0_.CONTACT_UID=?
2004-09-17 11:41:41,956 DEBUG [net.sf.hibernate.impl.BatcherImpl] - preparing statement
2004-09-17 11:41:41,956 DEBUG [net.sf.hibernate.type.LongType] - binding '1' to parameter: 1
2004-09-17 11:41:41,956 DEBUG [net.sf.hibernate.loader.Loader] - processing result set
2004-09-17 11:41:41,956 DEBUG [net.sf.hibernate.loader.Loader] - result row: 1
2004-09-17 11:41:41,956 DEBUG [net.sf.hibernate.loader.Loader] - Initializing object from ResultSet: 1
2004-09-17 11:41:41,956 DEBUG [net.sf.hibernate.loader.Loader] - Hydrating entity: com.thyrell.pm.model.Contact#1
2004-09-17 11:41:41,956 DEBUG [net.sf.hibernate.type.TimestampType] - returning '2004-09-03 12:40:52' as column: TIMEOFLA2_0_
2004-09-17 11:41:41,956 DEBUG [net.sf.hibernate.type.TimestampType] - returning '2004-08-30 17:13:17' as column: TIMEOFCR3_0_
2004-09-17 11:41:42,136 DEBUG [net.sf.hibernate.type.StringType] - returning 'Meine privaten Kontaktdaten' as column: DESCRIPT5_0_
2004-09-17 11:41:42,146 DEBUG [net.sf.hibernate.type.BooleanType] - returning 'false' as column: HIDDEN0_
2004-09-17 11:41:42,146 DEBUG [net.sf.hibernate.type.StringType] - returning 'Andreas' as column: FIRSTNAME0_
2004-09-17 11:41:42,146 DEBUG [net.sf.hibernate.type.StringType] - returning 'Herr' as column: TITLE0_
2004-09-17 11:41:42,146 DEBUG [net.sf.hibernate.type.StringType] - returning 'Aderhold' as column: LASTNAME0_
2004-09-17 11:41:42,146 DEBUG [net.sf.hibernate.type.StringType] - returning 'Rheinstraße 38' as column: STREET0_
2004-09-17 11:41:42,146 DEBUG [net.sf.hibernate.type.StringType] - returning '68642' as column: ZIPCODE0_
2004-09-17 11:41:42,146 DEBUG [net.sf.hibernate.type.StringType] - returning 'Bürstadt' as column: CITY0_
2004-09-17 11:41:42,146 DEBUG [net.sf.hibernate.type.StringType] - returning 'HE' as column: STATE0_
2004-09-17 11:41:42,146 DEBUG [net.sf.hibernate.type.LocaleType] - returning 'de_DE' as column: COUTNTRY0_
2004-09-17 11:41:42,146 DEBUG [net.sf.hibernate.type.StringType] - returning '76660606' as column: ICQ0_
2004-09-17 11:41:42,146 DEBUG [net.sf.hibernate.type.StringType] - returning 'herineth' as column: AIM0_
2004-09-17 11:41:42,146 DEBUG [net.sf.hibernate.type.StringType] - returning '' as column: MSN0_
2004-09-17 11:41:42,156 DEBUG [net.sf.hibernate.type.StringType] - returning 'herineth' as column: YAHOO0_
2004-09-17 11:41:42,156 DEBUG [net.sf.hibernate.type.StringType] - returning '' as column: JABBER0_
2004-09-17 11:41:42,156 DEBUG [net.sf.hibernate.type.StringType] - returning '06245-905296' as column: PHONE0_
2004-09-17 11:41:42,156 DEBUG [net.sf.hibernate.type.StringType] - returning '06245-905246' as column: FAX0_
2004-09-17 11:41:42,156 DEBUG [net.sf.hibernate.type.StringType] - returning '0174-2026787' as column: CELL0_
2004-09-17 11:41:42,156 DEBUG [net.sf.hibernate.type.StringType] - returning 'privat@bullgod.de' as column: EMAIL0_
2004-09-17 11:41:42,166 DEBUG [net.sf.hibernate.type.LongType] - returning '3' as column: USER_UID0_
2004-09-17 11:41:42,166 DEBUG [net.sf.hibernate.impl.SessionImpl] - Version: 2004-09-03 12:40:52.0
2004-09-17 11:41:42,166 DEBUG [net.sf.hibernate.loader.Loader] - done processing result set (1 rows)
2004-09-17 11:41:42,176 DEBUG [net.sf.hibernate.impl.BatcherImpl] - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-09-17 11:41:42,176 DEBUG [net.sf.hibernate.impl.BatcherImpl] - closing statement
2004-09-17 11:41:42,176 DEBUG [net.sf.hibernate.loader.Loader] - total objects hydrated: 1
2004-09-17 11:41:42,176 DEBUG [net.sf.hibernate.impl.SessionImpl] - resolving associations for [com.thyrell.pm.model.Contact#1]
2004-09-17 11:41:42,176 DEBUG [net.sf.hibernate.impl.SessionImpl] - loading [com.thyrell.pm.model.User#3]
2004-09-17 11:41:42,176 DEBUG [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.thyrell.pm.model.User#3]
2004-09-17 11:41:42,176 DEBUG [net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.thyrell.pm.model.User#3]
2004-09-17 11:41:42,176 DEBUG [net.sf.hibernate.impl.SessionImpl] - done materializing entity [com.thyrell.pm.model.Contact#1]
2004-09-17 11:41:42,176 DEBUG [net.sf.hibernate.impl.SessionImpl] - creating collection wrapper:[com.thyrell.pm.model.User.contacts#3]
2004-09-17 11:41:42,176 DEBUG [net.sf.hibernate.impl.SessionImpl] - creating collection wrapper:[com.thyrell.pm.model.User.userRoles#3]
2004-09-17 11:41:42,196 DEBUG [net.sf.hibernate.impl.SessionImpl] - creating collection wrapper:[com.thyrell.pm.model.User.roles#3]
2004-09-17 11:41:42,196 DEBUG [net.sf.hibernate.impl.SessionImpl] - creating collection wrapper:[com.thyrell.pm.model.User.previousPasswords#3]
2004-09-17 11:41:42,196 DEBUG [net.sf.hibernate.impl.SessionImpl] - adding entity to second-level cache [com.thyrell.pm.model.User#3]
2004-09-17 11:41:42,236 DEBUG [net.sf.hibernate.cache.ReadWriteCache] - Caching: 3
2004-09-17 11:41:42,236 DEBUG [net.sf.hibernate.cache.EhCache] - key: 3
2004-09-17 11:41:42,236 DEBUG [net.sf.ehcache.store.MemoryStore] - com.thyrell.pm.model.UserCache: MemoryStore hit for 3
2004-09-17 11:41:42,236 DEBUG [net.sf.ehcache.Cache] - 3 now: 1095414102236
2004-09-17 11:41:42,236 DEBUG [net.sf.ehcache.Cache] - 3 Creation Time: 1095413910951 Next To Last Access Time: 1095414083459
2004-09-17 11:41:42,236 DEBUG [net.sf.ehcache.Cache] - 3 mostRecentTime: 1095414083459
2004-09-17 11:41:42,236 DEBUG [net.sf.ehcache.Cache] - 3 Age to Idle: 120000 Age Idled: 18777
2004-09-17 11:41:42,236 DEBUG [net.sf.ehcache.Cache] - com.thyrell.pm.model.User: Is element with key 3 expired?: false
2004-09-17 11:41:42,236 DEBUG [net.sf.hibernate.cache.ReadWriteCache] - Item was already cached: 3
2004-09-17 11:41:42,236 DEBUG [net.sf.hibernate.impl.SessionImpl] - done materializing entity [com.thyrell.pm.model.User#3]
2004-09-17 11:41:42,236 DEBUG [net.sf.hibernate.impl.SessionImpl] - initializing non-lazy collections
2004-09-17 11:41:42,236 DEBUG [org.springframework.transaction.support.TransactionSynchronizationManager] - Retrieved value [org.springframework.orm.hibernate.SessionHolder@1b59919] for key [net.sf.hibernate.impl.SessionFactoryImpl@1ce663c] bound to thread [thread-pool-34]
2004-09-17 11:41:42,236 DEBUG [org.springframework.orm.hibernate.HibernateInterceptor] - Not closing pre-bound Hibernate session after interceptor
2004-09-17 11:41:42,236 DEBUG [org.springframework.beans.CachedIntrospectionResults] - Using cached introspection results for class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:41:42,236 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:41:42,236 DEBUG [org.springframework.beans.BeanWrapperImpl] - Creating new nested BeanWrapper for property 'user'
2004-09-17 11:41:42,236 DEBUG [org.springframework.beans.CachedIntrospectionResults] - Using cached introspection results for class [com.thyrell.pm.model.User]
2004-09-17 11:41:42,236 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke write method [public void com.thyrell.pm.model.User.setEmail(java.lang.String)] on object of class [com.thyrell.pm.model.User]
2004-09-17 11:41:42,276 DEBUG [org.springframework.beans.BeanWrapperImpl] - Invoked write method [public void com.thyrell.pm.model.User.setEmail(java.lang.String)] with value [andi@bullgod.de]
2004-09-17 11:41:42,276 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:41:42,276 DEBUG [org.springframework.beans.BeanWrapperImpl] - Using cached nested BeanWrapper for property 'user'
2004-09-17 11:41:42,276 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke write method [public void com.thyrell.pm.model.User.setFullname(java.lang.String)] on object of class [com.thyrell.pm.model.User]
2004-09-17 11:41:42,286 DEBUG [org.springframework.beans.BeanWrapperImpl] - Invoked write method [public void com.thyrell.pm.model.User.setFullname(java.lang.String)] with value [Andi]
2004-09-17 11:41:42,286 DEBUG [org.springframework.beans.BeanWrapperImpl] - Converting String to [class java.lang.Long] using property editor [org.springframework.beans.propertyeditors.CustomNumberEditor@3650ed]
2004-09-17 11:41:42,286 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke write method [public void com.thyrell.pm.user.web.UserForm.setId(java.lang.Long)] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:41:42,286 DEBUG [org.springframework.beans.BeanWrapperImpl] - Invoked write method [public void com.thyrell.pm.user.web.UserForm.setId(java.lang.Long)] with value of type [java.lang.Long]
2004-09-17 11:41:42,286 DEBUG [org.springframework.validation.ValidationUtils] - Invoking validator [com.thyrell.pm.user.web.UserFormValidator@1ed1dbe]
2004-09-17 11:41:42,286 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public java.lang.Long com.thyrell.pm.user.web.UserForm.getId()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:41:42,286 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:41:42,286 DEBUG [org.springframework.beans.BeanWrapperImpl] - Using cached nested BeanWrapper for property 'user'
2004-09-17 11:41:42,286 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public java.lang.String com.thyrell.pm.model.User.getFullname()] on object of class [com.thyrell.pm.model.User]
2004-09-17 11:41:42,286 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:41:42,306 DEBUG [org.springframework.beans.BeanWrapperImpl] - Using cached nested BeanWrapper for property 'user'
2004-09-17 11:41:42,306 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:41:42,306 DEBUG [org.springframework.beans.BeanWrapperImpl] - Using cached nested BeanWrapper for property 'user'
2004-09-17 11:41:42,306 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public java.lang.String com.thyrell.pm.model.User.getEmail()] on object of class [com.thyrell.pm.model.User]
2004-09-17 11:41:42,306 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:41:42,356 DEBUG [org.springframework.beans.BeanWrapperImpl] - Using cached nested BeanWrapper for property 'user'
2004-09-17 11:41:42,356 DEBUG [org.springframework.validation.ValidationUtils] - Validator found no errors
2004-09-17 11:41:42,356 DEBUG [com.thyrell.pm.user.web.UserFormController] - No errors -> processing submit
2004-09-17 11:41:42,356 WARN [com.thyrell.pm.user.web.UserFormController] - onSubmit called
2004-09-17 11:41:42,356 DEBUG [org.springframework.transaction.interceptor.TransactionInterceptor] - Don't need to create transaction for method 'saveUser' in class [com.thyrell.pm.user.UserService]: this method isn't transactional
2004-09-17 11:41:42,437 DEBUG [org.springframework.transaction.support.TransactionSynchronizationManager] - Retrieved value [org.springframework.orm.hibernate.SessionHolder@1b59919] for key [net.sf.hibernate.impl.SessionFactoryImpl@1ce663c] bound to thread [thread-pool-34]
2004-09-17 11:41:42,437 DEBUG [org.springframework.orm.hibernate.HibernateInterceptor] - Found thread-bound session for Hibernate interceptor
2004-09-17 11:41:42,437 DEBUG [org.springframework.transaction.support.TransactionSynchronizationManager] - Retrieved value [org.springframework.orm.hibernate.SessionHolder@1b59919] for key [net.sf.hibernate.impl.SessionFactoryImpl@1ce663c] bound to thread [thread-pool-34]
2004-09-17 11:41:42,447 DEBUG [org.springframework.transaction.support.TransactionSynchronizationManager] - Retrieved value [org.springframework.orm.hibernate.SessionHolder@1b59919] for key [net.sf.hibernate.impl.SessionFactoryImpl@1ce663c] bound to thread [thread-pool-34]
2004-09-17 11:41:42,447 DEBUG [org.springframework.orm.hibernate.HibernateInterceptor] - Not closing pre-bound Hibernate session after interceptor
2004-09-17 11:41:42,447 DEBUG [org.springframework.web.servlet.DispatcherServlet] - HandlerExceptionResolver returned ModelAndView [ModelAndView: reference to view with name 'dataAccessFailure'; model is {exception=org.springframework.dao.InvalidDataAccessApiUsageException: Write operations are not allowed in read-only mode (FlushMode.NEVER) - turn your Session into FlushMode.AUTO respectively remove 'readOnly' marker from transaction definition}] for exception
2004-09-17 11:41:42,447 WARN [org.springframework.web.servlet.DispatcherServlet] - Handler execution resulted in exception - forwarding to resolved error view
org.springframework.dao.InvalidDataAccessApiUsageException: Write operations are not allowed in read-only mode (FlushMode.NEVER) - turn your Session into FlushMode.AUTO respectively remove 'readOnly' marker from transaction definition
	at org.springframework.orm.hibernate.HibernateTemplate.checkWriteOperationAllowed(HibernateTemplate.java:901)
	at org.springframework.orm.hibernate.HibernateTemplate$13.doInHibernate(HibernateTemplate.java:319)
	at org.springframework.orm.hibernate.HibernateTemplate.execute(HibernateTemplate.java:176)
	at org.springframework.orm.hibernate.HibernateTemplate.saveOrUpdate(HibernateTemplate.java:317)
	at com.thyrell.pm.user.dao.UserDaoImpl.saveOrUpdateUser(Unknown Source)
	at com.thyrell.pm.user.UserServiceImpl.saveUser(Unknown Source)
	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:324)
	at org.springframework.aop.framework.AopProxyUtils.invokeJoinpointUsingReflection(AopProxyUtils.java:61)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:149)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:116)
	at org.springframework.orm.hibernate.HibernateInterceptor.invoke(HibernateInterceptor.java:163)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:138)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:56)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:138)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:152)
	at $Proxy0.saveUser(Unknown Source)
	at com.thyrell.pm.user.web.UserFormController.onSubmit(Unknown Source)
	at org.springframework.web.servlet.mvc.SimpleFormController.onSubmit(SimpleFormController.java:297)
	at org.springframework.web.servlet.mvc.SimpleFormController.onSubmit(SimpleFormController.java:272)
	at org.springframework.web.servlet.mvc.SimpleFormController.processFormSubmission(SimpleFormController.java:223)
	at org.springframework.web.servlet.mvc.AbstractFormController.handleRequestInternal(AbstractFormController.java:237)
	at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:121)
	at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:44)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:495)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:321)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:103)
	at com.caucho.server.dispatch.ServletFilterChain.doFilter(ServletFilterChain.java:113)
	at com.opensymphony.module.sitemesh.filter.PageFilter.parsePage(PageFilter.java:142)
	at com.opensymphony.module.sitemesh.filter.PageFilter.doFilter(PageFilter.java:58)
	at com.caucho.server.dispatch.FilterFilterChain.doFilter(FilterFilterChain.java:84)
	at com.caucho.server.cache.CacheFilterChain.doFilter(CacheFilterChain.java:177)
	at com.caucho.server.webapp.WebAppFilterChain.doFilter(WebAppFilterChain.java:177)
	at com.caucho.server.dispatch.ServletInvocation.service(ServletInvocation.java:221)
	at com.caucho.server.http.HttpRequest.handleRequest(HttpRequest.java:263)
	at com.caucho.server.port.TcpConnection.run(TcpConnection.java:331)
	at com.caucho.util.ThreadPool.runTasks(ThreadPool.java:464)
	at com.caucho.util.ThreadPool.run(ThreadPool.java:408)
	at java.lang.Thread.run(Thread.java:534)
2004-09-17 11:41:42,447 DEBUG [org.springframework.web.servlet.DispatcherServlet] - Will render view in DispatcherServlet with name 'perfectmind'
2004-09-17 11:41:42,457 DEBUG [org.springframework.web.servlet.view.JstlView] - Rendering view with name 'dataAccessFailure' with model {exception=org.springframework.dao.InvalidDataAccessApiUsageException: Write operations are not allowed in read-only mode (FlushMode.NEVER) - turn your Session into FlushMode.AUTO respectively remove 'readOnly' marker from transaction definition} and static attributes {}
2004-09-17 11:41:42,457 DEBUG [org.springframework.web.servlet.view.JstlView] - Added model object 'exception' of type [org.springframework.dao.InvalidDataAccessApiUsageException] to request in InternalResourceView 'dataAccessFailure' 
2004-09-17 11:41:42,457 DEBUG [org.springframework.web.servlet.view.JstlView] - Forwarded to resource [/template/dataAccessFailure.jsp] in InternalResourceView 'dataAccessFailure'
2004-09-17 11:41:42,457 DEBUG [org.springframework.transaction.support.TransactionSynchronizationManager] - Removed value [org.springframework.orm.hibernate.SessionHolder@1b59919] for key [net.sf.hibernate.impl.SessionFactoryImpl@1ce663c] from thread [thread-pool-34]
2004-09-17 11:41:42,457 DEBUG [org.springframework.orm.hibernate.support.OpenSessionInViewInterceptor] - Closing single Hibernate session in OpenSessionInViewInterceptor
2004-09-17 11:41:42,457 DEBUG [org.springframework.orm.hibernate.SessionFactoryUtils] - Closing Hibernate session
2004-09-17 11:41:42,557 DEBUG [net.sf.hibernate.impl.SessionImpl] - closing session
2004-09-17 11:41:42,557 DEBUG [net.sf.hibernate.impl.SessionImpl] - disconnecting session
2004-09-17 11:41:42,557 DEBUG [net.sf.hibernate.impl.SessionImpl] - transaction completion
2004-09-17 11:41:42,557 DEBUG [org.springframework.web.servlet.DispatcherServlet] - Successfully completed request
2004-09-17 11:41:42,557 DEBUG [org.springframework.web.context.support.XmlWebApplicationContext] - Publishing event in context [XmlWebApplicationContext for namespace 'perfectmind-servlet']: RequestHandledEvent: url=[/admin/user/edit.jspa]; time=[661ms]; client=[192.168.0.2]; method=[POST]; servlet=[perfectmind]; session=[agaKYleoLqhe]; user=[null]; status=[OK]
2004-09-17 11:41:42,557 DEBUG [org.springframework.web.context.support.XmlWebApplicationContext] - Publishing event in context [Root XmlWebApplicationContext]: RequestHandledEvent: url=[/admin/user/edit.jspa]; time=[661ms]; client=[192.168.0.2]; method=[POST]; servlet=[perfectmind]; session=[agaKYleoLqhe]; user=[null]; status=[OK]

[bullgod]

continued....

FLUSH_AUTO:

2004-09-17 11:50:48,762 DEBUG [org.springframework.web.servlet.DispatcherServlet] - DispatcherServlet with name 'perfectmind' received request for [/admin/user/edit.jspa]
2004-09-17 11:50:48,762 DEBUG [org.springframework.web.servlet.DispatcherServlet] - Testing handler map [org.springframework.web.servlet.handler.SimpleUrlHandlerMapping@fd1810] in DispatcherServlet with name 'perfectmind'
2004-09-17 11:50:48,762 DEBUG [org.springframework.web.servlet.handler.SimpleUrlHandlerMapping] - Looking up handler for [/admin/user/edit.jspa]
2004-09-17 11:50:48,762 DEBUG [org.springframework.orm.hibernate.support.OpenSessionInViewInterceptor] - Opening single Hibernate session in OpenSessionInViewInterceptor
2004-09-17 11:50:48,762 DEBUG [org.springframework.orm.hibernate.SessionFactoryUtils] - Opening Hibernate session
2004-09-17 11:50:48,772 DEBUG [net.sf.hibernate.impl.SessionImpl] - opened session
2004-09-17 11:50:48,772 DEBUG [org.springframework.transaction.support.TransactionSynchronizationManager] - Bound value [org.springframework.orm.hibernate.SessionHolder@ee6ad6] for key [net.sf.hibernate.impl.SessionFactoryImpl@29ea31] to thread [thread-pool-37]
2004-09-17 11:50:48,772 DEBUG [org.springframework.web.servlet.DispatcherServlet] - Testing handler adapter [org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter@19a0feb]
2004-09-17 11:50:48,772 WARN [com.thyrell.pm.user.web.UserFormController] - formBackingObject called
2004-09-17 11:50:48,772 DEBUG [org.springframework.transaction.interceptor.TransactionInterceptor] - Don't need to create transaction for method 'getUser' in class [com.thyrell.pm.user.UserService]: this method isn't transactional
2004-09-17 11:50:48,772 DEBUG [org.springframework.transaction.support.TransactionSynchronizationManager] - Retrieved value [org.springframework.orm.hibernate.SessionHolder@ee6ad6] for key [net.sf.hibernate.impl.SessionFactoryImpl@29ea31] bound to thread [thread-pool-37]
2004-09-17 11:50:48,772 DEBUG [org.springframework.orm.hibernate.HibernateInterceptor] - Found thread-bound session for Hibernate interceptor
2004-09-17 11:50:48,782 DEBUG [org.springframework.transaction.support.TransactionSynchronizationManager] - Retrieved value [org.springframework.orm.hibernate.SessionHolder@ee6ad6] for key [net.sf.hibernate.impl.SessionFactoryImpl@29ea31] bound to thread [thread-pool-37]
2004-09-17 11:50:48,782 DEBUG [org.springframework.transaction.support.TransactionSynchronizationManager] - Retrieved value [org.springframework.orm.hibernate.SessionHolder@ee6ad6] for key [net.sf.hibernate.impl.SessionFactoryImpl@29ea31] bound to thread [thread-pool-37]
2004-09-17 11:50:48,782 DEBUG [net.sf.hibernate.impl.SessionImpl] - find: select u from User u where u.handle = ?
2004-09-17 11:50:48,782 DEBUG [net.sf.hibernate.engine.QueryParameters] - parameters: [bullgod]
2004-09-17 11:50:48,782 DEBUG [net.sf.hibernate.engine.QueryParameters] - named parameters: {}
2004-09-17 11:50:48,782 DEBUG [net.sf.hibernate.impl.SessionImpl] - flushing session
2004-09-17 11:50:48,782 DEBUG [net.sf.hibernate.impl.SessionImpl] - Flushing entities and processing referenced collections
2004-09-17 11:50:48,782 DEBUG [net.sf.hibernate.impl.SessionImpl] - Processing unreferenced collections
2004-09-17 11:50:48,782 DEBUG [net.sf.hibernate.impl.SessionImpl] - Scheduling collection removes/(re)creates/updates
2004-09-17 11:50:48,782 DEBUG [net.sf.hibernate.impl.SessionImpl] - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
2004-09-17 11:50:48,782 DEBUG [net.sf.hibernate.impl.SessionImpl] - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2004-09-17 11:50:48,782 DEBUG [net.sf.hibernate.impl.SessionImpl] - Dont need to execute flush
2004-09-17 11:50:48,782 DEBUG [net.sf.hibernate.hql.QueryTranslator] - HQL: select u from com.thyrell.pm.model.User u where u.handle = ?
2004-09-17 11:50:48,782 DEBUG [net.sf.hibernate.hql.QueryTranslator] - SQL: select user0_.USER_UID as USER_UID, user0_.TIMEOFLASTUPDATE as TIMEOFLA2_, user0_.TIMEOFCREATION as TIMEOFCR3_, user0_.USERNAME as USERNAME, user0_.`PASSWORD` as y5_, user0_.EMAIL as EMAIL, user0_.FULLNAME as FULLNAME, user0_.DEFAULT_CONTACT_UID as DEFAULT_8_ from USERS user0_ where (user0_.USERNAME=? )
2004-09-17 11:50:48,782 DEBUG [net.sf.hibernate.impl.BatcherImpl] - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-09-17 11:50:48,802 DEBUG [net.sf.hibernate.SQL] - select user0_.USER_UID as USER_UID, user0_.TIMEOFLASTUPDATE as TIMEOFLA2_, user0_.TIMEOFCREATION as TIMEOFCR3_, user0_.USERNAME as USERNAME, user0_.`PASSWORD` as y5_, user0_.EMAIL as EMAIL, user0_.FULLNAME as FULLNAME, user0_.DEFAULT_CONTACT_UID as DEFAULT_8_ from USERS user0_ where (user0_.USERNAME=? )
Hibernate: select user0_.USER_UID as USER_UID, user0_.TIMEOFLASTUPDATE as TIMEOFLA2_, user0_.TIMEOFCREATION as TIMEOFCR3_, user0_.USERNAME as USERNAME, user0_.`PASSWORD` as y5_, user0_.EMAIL as EMAIL, user0_.FULLNAME as FULLNAME, user0_.DEFAULT_CONTACT_UID as DEFAULT_8_ from USERS user0_ where (user0_.USERNAME=? )
2004-09-17 11:50:48,802 DEBUG [net.sf.hibernate.impl.BatcherImpl] - preparing statement
2004-09-17 11:50:48,802 DEBUG [net.sf.hibernate.type.StringType] - binding 'bullgod' to parameter: 1
2004-09-17 11:50:48,812 DEBUG [net.sf.hibernate.loader.Loader] - processing result set
2004-09-17 11:50:48,812 DEBUG [net.sf.hibernate.type.LongType] - returning '3' as column: USER_UID
2004-09-17 11:50:48,812 DEBUG [net.sf.hibernate.loader.Loader] - result row: 3
2004-09-17 11:50:48,812 DEBUG [net.sf.hibernate.loader.Loader] - Initializing object from ResultSet: 3
2004-09-17 11:50:48,812 DEBUG [net.sf.hibernate.loader.Loader] - Hydrating entity: com.thyrell.pm.model.User#3
2004-09-17 11:50:48,812 DEBUG [net.sf.hibernate.type.TimestampType] - returning '2004-09-16 22:59:36' as column: TIMEOFLA2_
2004-09-17 11:50:48,812 DEBUG [net.sf.hibernate.type.TimestampType] - returning '2004-08-30 17:13:17' as column: TIMEOFCR3_
2004-09-17 11:50:48,812 DEBUG [net.sf.hibernate.type.StringType] - returning 'bullgod' as column: USERNAME
2004-09-17 11:50:48,812 DEBUG [net.sf.hibernate.type.StringType] - returning 'bullgod' as column: y5_
2004-09-17 11:50:48,812 DEBUG [net.sf.hibernate.type.StringType] - returning 'andi@bullgod.de' as column: EMAIL
2004-09-17 11:50:48,822 DEBUG [net.sf.hibernate.type.StringType] - returning 'Andreas Aderhold' as column: FULLNAME
2004-09-17 11:50:48,822 DEBUG [net.sf.hibernate.type.LongType] - returning '1' as column: DEFAULT_8_
2004-09-17 11:50:48,822 DEBUG [net.sf.hibernate.impl.SessionImpl] - Version: 2004-09-16 22:59:36.0
2004-09-17 11:50:48,822 DEBUG [net.sf.hibernate.loader.Loader] - done processing result set (1 rows)
2004-09-17 11:50:48,822 DEBUG [net.sf.hibernate.impl.BatcherImpl] - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-09-17 11:50:48,822 DEBUG [net.sf.hibernate.impl.BatcherImpl] - closing statement
2004-09-17 11:50:48,822 DEBUG [net.sf.hibernate.loader.Loader] - total objects hydrated: 1
2004-09-17 11:50:48,822 DEBUG [net.sf.hibernate.impl.SessionImpl] - resolving associations for [com.thyrell.pm.model.User#3]
2004-09-17 11:50:48,822 DEBUG [net.sf.hibernate.impl.SessionImpl] - loading [com.thyrell.pm.model.Contact#1]
2004-09-17 11:50:48,822 DEBUG [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.thyrell.pm.model.Contact#1]
2004-09-17 11:50:48,822 DEBUG [net.sf.hibernate.impl.SessionImpl] - object not resolved in any cache [com.thyrell.pm.model.Contact#1]
2004-09-17 11:50:48,822 DEBUG [net.sf.hibernate.persister.EntityPersister] - Materializing entity: [com.thyrell.pm.model.Contact#1]
2004-09-17 11:50:48,822 DEBUG [net.sf.hibernate.impl.BatcherImpl] - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-09-17 11:50:48,822 DEBUG [net.sf.hibernate.SQL] - select contact0_.CONTACT_UID as CONTACT_1_0_, contact0_.TIMEOFLASTUPDATE as TIMEOFLA2_0_, contact0_.TIMEOFCREATION as TIMEOFCR3_0_, contact0_.CONTACTTYPE as CONTACTT4_0_, contact0_.DESCRIPTION as DESCRIPT5_0_, contact0_.HIDDEN as HIDDEN0_, contact0_.FIRSTNAME as FIRSTNAME0_, contact0_.TITLE as TITLE0_, contact0_.LASTNAME as LASTNAME0_, contact0_.STREET as STREET0_, contact0_.ZIPCODE as ZIPCODE0_, contact0_.CITY as CITY0_, contact0_.STATE as STATE0_, contact0_.COUTNTRY as COUTNTRY0_, contact0_.ICQ as ICQ0_, contact0_.AIM as AIM0_, contact0_.MSN as MSN0_, contact0_.YAHOO as YAHOO0_, contact0_.JABBER as JABBER0_, contact0_.PHONE as PHONE0_, contact0_.FAX as FAX0_, contact0_.CELL as CELL0_, contact0_.EMAIL as EMAIL0_, contact0_.USER_UID as USER_UID0_ from CONTACTS contact0_ where contact0_.CONTACT_UID=?
Hibernate: select contact0_.CONTACT_UID as CONTACT_1_0_, contact0_.TIMEOFLASTUPDATE as TIMEOFLA2_0_, contact0_.TIMEOFCREATION as TIMEOFCR3_0_, contact0_.CONTACTTYPE as CONTACTT4_0_, contact0_.DESCRIPTION as DESCRIPT5_0_, contact0_.HIDDEN as HIDDEN0_, contact0_.FIRSTNAME as FIRSTNAME0_, contact0_.TITLE as TITLE0_, contact0_.LASTNAME as LASTNAME0_, contact0_.STREET as STREET0_, contact0_.ZIPCODE as ZIPCODE0_, contact0_.CITY as CITY0_, contact0_.STATE as STATE0_, contact0_.COUTNTRY as COUTNTRY0_, contact0_.ICQ as ICQ0_, contact0_.AIM as AIM0_, contact0_.MSN as MSN0_, contact0_.YAHOO as YAHOO0_, contact0_.JABBER as JABBER0_, contact0_.PHONE as PHONE0_, contact0_.FAX as FAX0_, contact0_.CELL as CELL0_, contact0_.EMAIL as EMAIL0_, contact0_.USER_UID as USER_UID0_ from CONTACTS contact0_ where contact0_.CONTACT_UID=?
2004-09-17 11:50:48,872 DEBUG [net.sf.hibernate.impl.BatcherImpl] - preparing statement
2004-09-17 11:50:48,882 DEBUG [net.sf.hibernate.type.LongType] - binding '1' to parameter: 1
2004-09-17 11:50:48,902 DEBUG [net.sf.hibernate.loader.Loader] - processing result set
2004-09-17 11:50:48,902 DEBUG [net.sf.hibernate.loader.Loader] - result row: 1
2004-09-17 11:50:48,902 DEBUG [net.sf.hibernate.loader.Loader] - Initializing object from ResultSet: 1
2004-09-17 11:50:48,902 DEBUG [net.sf.hibernate.loader.Loader] - Hydrating entity: com.thyrell.pm.model.Contact#1
2004-09-17 11:50:48,912 DEBUG [net.sf.hibernate.type.TimestampType] - returning '2004-09-03 12:40:52' as column: TIMEOFLA2_0_
2004-09-17 11:50:48,912 DEBUG [net.sf.hibernate.type.TimestampType] - returning '2004-08-30 17:13:17' as column: TIMEOFCR3_0_
2004-09-17 11:50:48,912 DEBUG [net.sf.hibernate.type.StringType] - returning 'Meine privaten Kontaktdaten' as column: DESCRIPT5_0_
2004-09-17 11:50:48,912 DEBUG [net.sf.hibernate.type.BooleanType] - returning 'false' as column: HIDDEN0_
2004-09-17 11:50:48,912 DEBUG [net.sf.hibernate.type.StringType] - returning 'Andreas' as column: FIRSTNAME0_
2004-09-17 11:50:48,922 DEBUG [net.sf.hibernate.type.StringType] - returning 'Herr' as column: TITLE0_
2004-09-17 11:50:48,922 DEBUG [net.sf.hibernate.type.StringType] - returning 'Aderhold' as column: LASTNAME0_
2004-09-17 11:50:48,922 DEBUG [net.sf.hibernate.type.StringType] - returning 'Rheinstraße 38' as column: STREET0_
2004-09-17 11:50:48,922 DEBUG [net.sf.hibernate.type.StringType] - returning '68642' as column: ZIPCODE0_
2004-09-17 11:50:48,922 DEBUG [net.sf.hibernate.type.StringType] - returning 'Bürstadt' as column: CITY0_
2004-09-17 11:50:48,922 DEBUG [net.sf.hibernate.type.StringType] - returning 'HE' as column: STATE0_
2004-09-17 11:50:48,922 DEBUG [net.sf.hibernate.type.LocaleType] - returning 'de_DE' as column: COUTNTRY0_
2004-09-17 11:50:48,922 DEBUG [net.sf.hibernate.type.StringType] - returning '76660606' as column: ICQ0_
2004-09-17 11:50:48,922 DEBUG [net.sf.hibernate.type.StringType] - returning 'herineth' as column: AIM0_
2004-09-17 11:50:48,922 DEBUG [net.sf.hibernate.type.StringType] - returning '' as column: MSN0_
2004-09-17 11:50:48,932 DEBUG [net.sf.hibernate.type.StringType] - returning 'herineth' as column: YAHOO0_
2004-09-17 11:50:48,932 DEBUG [net.sf.hibernate.type.StringType] - returning '' as column: JABBER0_
2004-09-17 11:50:48,932 DEBUG [net.sf.hibernate.type.StringType] - returning '06245-905296' as column: PHONE0_
2004-09-17 11:50:48,932 DEBUG [net.sf.hibernate.type.StringType] - returning '06245-905246' as column: FAX0_
2004-09-17 11:50:48,932 DEBUG [net.sf.hibernate.type.StringType] - returning '0174-2026787' as column: CELL0_
2004-09-17 11:50:48,932 DEBUG [net.sf.hibernate.type.StringType] - returning 'privat@bullgod.de' as column: EMAIL0_
2004-09-17 11:50:48,932 DEBUG [net.sf.hibernate.type.LongType] - returning '3' as column: USER_UID0_
2004-09-17 11:50:48,932 DEBUG [net.sf.hibernate.impl.SessionImpl] - Version: 2004-09-03 12:40:52.0
2004-09-17 11:50:48,932 DEBUG [net.sf.hibernate.loader.Loader] - done processing result set (1 rows)
2004-09-17 11:50:48,932 DEBUG [net.sf.hibernate.impl.BatcherImpl] - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-09-17 11:50:48,932 DEBUG [net.sf.hibernate.impl.BatcherImpl] - closing statement
2004-09-17 11:50:48,932 DEBUG [net.sf.hibernate.loader.Loader] - total objects hydrated: 1
2004-09-17 11:50:48,932 DEBUG [net.sf.hibernate.impl.SessionImpl] - resolving associations for [com.thyrell.pm.model.Contact#1]
2004-09-17 11:50:48,942 DEBUG [net.sf.hibernate.impl.SessionImpl] - loading [com.thyrell.pm.model.User#3]
2004-09-17 11:50:48,942 DEBUG [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.thyrell.pm.model.User#3]
2004-09-17 11:50:48,942 DEBUG [net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.thyrell.pm.model.User#3]
2004-09-17 11:50:48,942 DEBUG [net.sf.hibernate.impl.SessionImpl] - done materializing entity [com.thyrell.pm.model.Contact#1]
2004-09-17 11:50:48,942 DEBUG [net.sf.hibernate.impl.SessionImpl] - creating collection wrapper:[com.thyrell.pm.model.User.contacts#3]
2004-09-17 11:50:48,952 DEBUG [net.sf.hibernate.impl.SessionImpl] - creating collection wrapper:[com.thyrell.pm.model.User.userRoles#3]
2004-09-17 11:50:48,952 DEBUG [net.sf.hibernate.impl.SessionImpl] - creating collection wrapper:[com.thyrell.pm.model.User.roles#3]
2004-09-17 11:50:48,952 DEBUG [net.sf.hibernate.impl.SessionImpl] - creating collection wrapper:[com.thyrell.pm.model.User.previousPasswords#3]
2004-09-17 11:50:48,952 DEBUG [net.sf.hibernate.impl.SessionImpl] - adding entity to second-level cache [com.thyrell.pm.model.User#3]
2004-09-17 11:50:48,952 DEBUG [net.sf.hibernate.cache.ReadWriteCache] - Caching: 3
2004-09-17 11:50:48,952 DEBUG [net.sf.hibernate.cache.EhCache] - key: 3
2004-09-17 11:50:48,952 DEBUG [net.sf.ehcache.store.MemoryStore] - com.thyrell.pm.model.UserCache: MemoryStore hit for 3
2004-09-17 11:50:48,952 DEBUG [net.sf.ehcache.Cache] - 3 now: 1095414648952
2004-09-17 11:50:48,952 DEBUG [net.sf.ehcache.Cache] - 3 Creation Time: 1095414423448 Next To Last Access Time: 0
2004-09-17 11:50:48,952 DEBUG [net.sf.ehcache.Cache] - 3 mostRecentTime: 1095414423448
2004-09-17 11:50:48,952 DEBUG [net.sf.ehcache.Cache] - 3 Age to Idle: 120000 Age Idled: 225504
2004-09-17 11:50:48,952 DEBUG [net.sf.ehcache.Cache] - timeToIdleSeconds exceeded : 3
2004-09-17 11:50:48,952 DEBUG [net.sf.ehcache.Cache] - com.thyrell.pm.model.User: Is element with key 3 expired?: true
2004-09-17 11:50:48,952 DEBUG [net.sf.ehcache.Cache] - com.thyrell.pm.model.User Memory cache hit, but element expired
2004-09-17 11:50:48,952 DEBUG [net.sf.ehcache.Cache] - com.thyrell.pm.model.User cache - Miss
2004-09-17 11:50:48,952 DEBUG [net.sf.hibernate.cache.EhCache] - Element for 3 is null
2004-09-17 11:50:48,952 DEBUG [net.sf.ehcache.Cache] - 3 now: 1095414648952
2004-09-17 11:50:48,952 DEBUG [net.sf.ehcache.Cache] - 3 Creation Time: 1095414648952 Next To Last Access Time: 0
2004-09-17 11:50:48,952 DEBUG [net.sf.ehcache.Cache] - 3 mostRecentTime: 1095414648952
2004-09-17 11:50:48,952 DEBUG [net.sf.ehcache.Cache] - 3 Age to Idle: 120000 Age Idled: 0
2004-09-17 11:50:48,952 DEBUG [net.sf.ehcache.Cache] - com.thyrell.pm.model.User: Is element with key 3 expired?: false
2004-09-17 11:50:48,962 DEBUG [net.sf.hibernate.cache.ReadWriteCache] - Cached: 3
2004-09-17 11:50:48,962 DEBUG [net.sf.hibernate.impl.SessionImpl] - done materializing entity [com.thyrell.pm.model.User#3]
2004-09-17 11:50:48,962 DEBUG [net.sf.hibernate.impl.SessionImpl] - initializing non-lazy collections
2004-09-17 11:50:48,962 DEBUG [org.springframework.transaction.support.TransactionSynchronizationManager] - Retrieved value [org.springframework.orm.hibernate.SessionHolder@ee6ad6] for key [net.sf.hibernate.impl.SessionFactoryImpl@29ea31] bound to thread [thread-pool-37]
2004-09-17 11:50:48,962 DEBUG [org.springframework.orm.hibernate.HibernateInterceptor] - Not closing pre-bound Hibernate session after interceptor
2004-09-17 11:50:48,962 DEBUG [org.springframework.beans.CachedIntrospectionResults] - Using cached introspection results for class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:50:48,962 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:50:48,962 DEBUG [org.springframework.beans.BeanWrapperImpl] - Creating new nested BeanWrapper for property 'user'
2004-09-17 11:50:48,962 DEBUG [org.springframework.beans.CachedIntrospectionResults] - Using cached introspection results for class [com.thyrell.pm.model.User]
2004-09-17 11:50:48,962 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke write method [public void com.thyrell.pm.model.User.setEmail(java.lang.String)] on object of class [com.thyrell.pm.model.User]
2004-09-17 11:50:49,002 DEBUG [org.springframework.beans.BeanWrapperImpl] - Invoked write method [public void com.thyrell.pm.model.User.setEmail(java.lang.String)] with value [andi@bullgod.de]
2004-09-17 11:50:49,002 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:50:49,012 DEBUG [org.springframework.beans.BeanWrapperImpl] - Using cached nested BeanWrapper for property 'user'
2004-09-17 11:50:49,012 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke write method [public void com.thyrell.pm.model.User.setFullname(java.lang.String)] on object of class [com.thyrell.pm.model.User]
2004-09-17 11:50:49,012 DEBUG [org.springframework.beans.BeanWrapperImpl] - Invoked write method [public void com.thyrell.pm.model.User.setFullname(java.lang.String)] with value []
2004-09-17 11:50:49,012 DEBUG [org.springframework.beans.BeanWrapperImpl] - Converting String to [class java.lang.Long] using property editor [org.springframework.beans.propertyeditors.CustomNumberEditor@181b3d4]
2004-09-17 11:50:49,033 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke write method [public void com.thyrell.pm.user.web.UserForm.setId(java.lang.Long)] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:50:49,033 DEBUG [org.springframework.beans.BeanWrapperImpl] - Invoked write method [public void com.thyrell.pm.user.web.UserForm.setId(java.lang.Long)] with value of type [java.lang.Long]
2004-09-17 11:50:49,073 DEBUG [org.springframework.validation.ValidationUtils] - Invoking validator [com.thyrell.pm.user.web.UserFormValidator@42a818]
2004-09-17 11:50:49,073 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public java.lang.Long com.thyrell.pm.user.web.UserForm.getId()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:50:49,073 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:50:49,073 DEBUG [org.springframework.beans.BeanWrapperImpl] - Using cached nested BeanWrapper for property 'user'
2004-09-17 11:50:49,073 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public java.lang.String com.thyrell.pm.model.User.getFullname()] on object of class [com.thyrell.pm.model.User]
2004-09-17 11:50:49,073 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:50:49,073 DEBUG [org.springframework.beans.BeanWrapperImpl] - Using cached nested BeanWrapper for property 'user'
2004-09-17 11:50:49,073 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:50:49,073 DEBUG [org.springframework.beans.BeanWrapperImpl] - Using cached nested BeanWrapper for property 'user'
2004-09-17 11:50:49,073 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public java.lang.String com.thyrell.pm.model.User.getFullname()] on object of class [com.thyrell.pm.model.User]
2004-09-17 11:50:49,083 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:50:49,083 DEBUG [org.springframework.beans.BeanWrapperImpl] - Using cached nested BeanWrapper for property 'user'
2004-09-17 11:50:49,083 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:50:49,083 DEBUG [org.springframework.beans.BeanWrapperImpl] - Using cached nested BeanWrapper for property 'user'
2004-09-17 11:50:49,083 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public java.lang.String com.thyrell.pm.model.User.getEmail()] on object of class [com.thyrell.pm.model.User]
2004-09-17 11:50:49,083 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:50:49,083 DEBUG [org.springframework.beans.BeanWrapperImpl] - Using cached nested BeanWrapper for property 'user'
2004-09-17 11:50:49,083 DEBUG [org.springframework.validation.ValidationUtils] - Validator found 1 errors
2004-09-17 11:50:49,083 DEBUG [com.thyrell.pm.user.web.UserFormController] - Data binding errors: 1
2004-09-17 11:50:49,083 DEBUG [org.springframework.transaction.support.TransactionSynchronizationManager] - Retrieved value [org.springframework.orm.hibernate.SessionHolder@ee6ad6] for key [net.sf.hibernate.impl.SessionFactoryImpl@29ea31] bound to thread [thread-pool-37]
2004-09-17 11:50:49,083 DEBUG [org.springframework.orm.hibernate.support.OpenSessionInViewInterceptor] - Flushing single Hibernate session in OpenSessionInViewInterceptor
2004-09-17 11:50:49,093 DEBUG [org.springframework.orm.hibernate.support.OpenSessionInViewInterceptor] - Eagerly flushing Hibernate session
2004-09-17 11:50:49,093 DEBUG [net.sf.hibernate.impl.SessionImpl] - flushing session
2004-09-17 11:50:49,093 DEBUG [net.sf.hibernate.engine.Cascades] - processing cascades for: com.thyrell.pm.model.User
2004-09-17 11:50:49,093 DEBUG [net.sf.hibernate.engine.Cascades] - cascading to collection: com.thyrell.pm.model.User.contacts
2004-09-17 11:50:49,093 DEBUG [net.sf.hibernate.engine.Cascades] - cascading to collection: com.thyrell.pm.model.User.userRoles
2004-09-17 11:50:49,093 DEBUG [net.sf.hibernate.engine.Cascades] - cascading to collection: com.thyrell.pm.model.User.roles
2004-09-17 11:50:49,093 DEBUG [net.sf.hibernate.engine.Cascades] - done processing cascades for: com.thyrell.pm.model.User
2004-09-17 11:50:49,093 DEBUG [net.sf.hibernate.impl.SessionImpl] - Flushing entities and processing referenced collections
2004-09-17 11:50:49,093 DEBUG [net.sf.hibernate.persister.AbstractEntityPersister] - com.thyrell.pm.model.User.fullname is dirty
2004-09-17 11:50:49,093 DEBUG [net.sf.hibernate.impl.SessionImpl] - Updating entity: [com.thyrell.pm.model.User#3]
2004-09-17 11:50:49,093 DEBUG [net.sf.hibernate.engine.Versioning] - Incrementing: 2004-09-16 22:59:36.0 to 2004-09-17 11:50:49.093
2004-09-17 11:50:49,163 DEBUG [net.sf.hibernate.impl.SessionImpl] - Collection found: [com.thyrell.pm.model.User.contacts#3], was: [com.thyrell.pm.model.User.contacts#3]
2004-09-17 11:50:49,163 DEBUG [net.sf.hibernate.impl.SessionImpl] - Collection found: [com.thyrell.pm.model.User.userRoles#3], was: [com.thyrell.pm.model.User.userRoles#3]
2004-09-17 11:50:49,163 DEBUG [net.sf.hibernate.impl.SessionImpl] - Collection found: [com.thyrell.pm.model.User.roles#3], was: [com.thyrell.pm.model.User.roles#3]
2004-09-17 11:50:49,163 DEBUG [net.sf.hibernate.impl.SessionImpl] - Collection found: [com.thyrell.pm.model.User.previousPasswords#3], was: [com.thyrell.pm.model.User.previousPasswords#3]
2004-09-17 11:50:49,163 DEBUG [net.sf.hibernate.impl.SessionImpl] - Processing unreferenced collections
2004-09-17 11:50:49,163 DEBUG [net.sf.hibernate.impl.SessionImpl] - Scheduling collection removes/(re)creates/updates
2004-09-17 11:50:49,163 DEBUG [net.sf.hibernate.impl.SessionImpl] - Flushed: 0 insertions, 1 updates, 0 deletions to 2 objects
2004-09-17 11:50:49,163 DEBUG [net.sf.hibernate.impl.SessionImpl] - Flushed: 0 (re)creations, 0 updates, 0 removals to 4 collections
2004-09-17 11:50:49,163 DEBUG [net.sf.hibernate.impl.Printer] - listing entities:
2004-09-17 11:50:49,173 DEBUG [net.sf.hibernate.impl.Printer] - com.thyrell.pm.model.Contact{phone=06245-905296, user=User#3, aim=herineth, type=Private, yahoo=herineth, cell=0174-2026787, address=Address{country=de_DE, street=Rheinstraße 38, state=HE, city=Bürstadt, zipcode=68642}, msn=, fax=06245-905246, jabber=, id=1, timeOfLastUpdate=2004-09-03 12:40:52, timeOfCreation=2004-08-30 17:13:17, hidden=false, description=Meine privaten Kontaktdaten, email=privat@bullgod.de, name=Name{title=Herr, firstName=Andreas, lastName=Aderhold}, icq=76660606}
2004-09-17 11:50:49,173 DEBUG [net.sf.hibernate.impl.Printer] - com.thyrell.pm.model.User{password=bullgod, handle=bullgod, timeOfLastUpdate=2004-09-16 22:59:36, previousPasswords=uninitialized, contacts=uninitialized, timeOfCreation=2004-08-30 17:13:17, defaultContact=Contact#1, userRoles=uninitialized, email=andi@bullgod.de, roles=uninitialized, fullname=, id=3}
2004-09-17 11:50:49,173 DEBUG [net.sf.hibernate.impl.SessionImpl] - executing flush
2004-09-17 11:50:49,173 DEBUG [net.sf.hibernate.cache.ReadWriteCache] - Invalidating: 3
2004-09-17 11:50:49,173 DEBUG [net.sf.hibernate.cache.EhCache] - key: 3
2004-09-17 11:50:49,183 DEBUG [net.sf.ehcache.store.MemoryStore] - com.thyrell.pm.model.UserCache: MemoryStore hit for 3
2004-09-17 11:50:49,183 DEBUG [net.sf.ehcache.Cache] - 3 now: 1095414649183
2004-09-17 11:50:49,183 DEBUG [net.sf.ehcache.Cache] - 3 Creation Time: 1095414648952 Next To Last Access Time: 0
2004-09-17 11:50:49,183 DEBUG [net.sf.ehcache.Cache] - 3 mostRecentTime: 1095414648952
2004-09-17 11:50:49,183 DEBUG [net.sf.ehcache.Cache] - 3 Age to Idle: 120000 Age Idled: 231
2004-09-17 11:50:49,183 DEBUG [net.sf.ehcache.Cache] - com.thyrell.pm.model.User: Is element with key 3 expired?: false
2004-09-17 11:50:49,213 DEBUG [net.sf.hibernate.persister.EntityPersister] - Updating entity: [com.thyrell.pm.model.User#3]
2004-09-17 11:50:49,223 DEBUG [net.sf.hibernate.persister.EntityPersister] - Existing version: 2004-09-16 22:59:36.0 -> New version: 2004-09-17 11:50:49.093
2004-09-17 11:50:49,223 DEBUG [net.sf.hibernate.impl.BatcherImpl] - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-09-17 11:50:49,223 DEBUG [net.sf.hibernate.SQL] - update USERS set TIMEOFLASTUPDATE=?, `PASSWORD`=?, EMAIL=?, FULLNAME=?, DEFAULT_CONTACT_UID=? where USER_UID=? and TIMEOFLASTUPDATE=?
Hibernate: update USERS set TIMEOFLASTUPDATE=?, `PASSWORD`=?, EMAIL=?, FULLNAME=?, DEFAULT_CONTACT_UID=? where USER_UID=? and TIMEOFLASTUPDATE=?
2004-09-17 11:50:49,223 DEBUG [net.sf.hibernate.impl.BatcherImpl] - preparing statement
2004-09-17 11:50:49,273 DEBUG [net.sf.hibernate.persister.EntityPersister] - Dehydrating entity: [com.thyrell.pm.model.User#3]
2004-09-17 11:50:49,273 DEBUG [net.sf.hibernate.type.TimestampType] - binding '2004-09-17 11:50:49' to parameter: 1
2004-09-17 11:50:49,273 DEBUG [net.sf.hibernate.type.StringType] - binding 'bullgod' to parameter: 2
2004-09-17 11:50:49,273 DEBUG [net.sf.hibernate.type.StringType] - binding 'andi@bullgod.de' to parameter: 3
2004-09-17 11:50:49,273 DEBUG [net.sf.hibernate.type.StringType] - binding '' to parameter: 4
2004-09-17 11:50:49,283 DEBUG [net.sf.hibernate.type.LongType] - binding '1' to parameter: 5
2004-09-17 11:50:49,283 DEBUG [net.sf.hibernate.type.LongType] - binding '3' to parameter: 6
2004-09-17 11:50:49,283 DEBUG [net.sf.hibernate.type.TimestampType] - binding '2004-09-16 22:59:36' to parameter: 7
2004-09-17 11:50:49,343 DEBUG [net.sf.hibernate.impl.BatcherImpl] - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-09-17 11:50:49,343 DEBUG [net.sf.hibernate.impl.BatcherImpl] - closing statement
2004-09-17 11:50:49,343 DEBUG [net.sf.hibernate.impl.SessionImpl] - post flush
2004-09-17 11:50:49,343 DEBUG [org.springframework.web.servlet.DispatcherServlet] - Will render view in DispatcherServlet with name 'perfectmind'
2004-09-17 11:50:49,343 DEBUG [org.springframework.web.servlet.view.JstlView] - Rendering view with name 'EditUserForm' with model {userForm=com.thyrell.pm.user.web.UserForm@16b9e62, org.springframework.validation.BindException.userForm=org.springframework.validation.BindException: BindException: 1 errors; Field error in object 'userForm' on field 'user.fullname': rejectedValue=[]; codes=[required.userForm.user.fullname,required.user.fullname,required.fullname,required.java.lang.String,required]; arguments=[null]; defaultMessage=[Full name is required.]} and static attributes {}
2004-09-17 11:50:49,343 DEBUG [org.springframework.web.servlet.view.JstlView] - Added model object 'userForm' of type [com.thyrell.pm.user.web.UserForm] to request in InternalResourceView 'EditUserForm' 
2004-09-17 11:50:49,343 DEBUG [org.springframework.web.servlet.view.JstlView] - Added model object 'org.springframework.validation.BindException.userForm' of type [org.springframework.validation.BindException] to request in InternalResourceView 'EditUserForm' 
2004-09-17 11:50:49,533 DEBUG [org.springframework.context.support.ResourceBundleMessageSource] - Creating MessageFormat for pattern [Bitte ausfüllen] and locale 'en_US'
2004-09-17 11:50:49,533 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:50:49,533 DEBUG [org.springframework.beans.BeanWrapperImpl] - Using cached nested BeanWrapper for property 'user'
2004-09-17 11:50:49,533 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:50:49,543 DEBUG [org.springframework.beans.BeanWrapperImpl] - Using cached nested BeanWrapper for property 'user'
2004-09-17 11:50:49,543 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:50:49,553 DEBUG [org.springframework.beans.BeanWrapperImpl] - Using cached nested BeanWrapper for property 'user'
2004-09-17 11:50:49,553 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public java.lang.String com.thyrell.pm.model.User.getEmail()] on object of class [com.thyrell.pm.model.User]
2004-09-17 11:50:49,553 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:50:49,553 DEBUG [org.springframework.beans.BeanWrapperImpl] - Using cached nested BeanWrapper for property 'user'
2004-09-17 11:50:49,553 DEBUG [org.springframework.beans.BeanWrapperImpl] - About to invoke read method [public com.thyrell.pm.model.User com.thyrell.pm.user.web.UserForm.getUser()] on object of class [com.thyrell.pm.user.web.UserForm]
2004-09-17 11:50:49,553 DEBUG [org.springframework.beans.BeanWrapperImpl] - Using cached nested BeanWrapper for property 'user'
2004-09-17 11:50:49,553 DEBUG [org.springframework.web.servlet.view.JstlView] - Forwarded to resource [/admin/user/editUser.jsp] in InternalResourceView 'EditUserForm'
2004-09-17 11:50:49,553 DEBUG [org.springframework.transaction.support.TransactionSynchronizationManager] - Removed value [org.springframework.orm.hibernate.SessionHolder@ee6ad6] for key [net.sf.hibernate.impl.SessionFactoryImpl@29ea31] from thread [thread-pool-37]
2004-09-17 11:50:49,553 DEBUG [org.springframework.orm.hibernate.support.OpenSessionInViewInterceptor] - Closing single Hibernate session in OpenSessionInViewInterceptor
2004-09-17 11:50:49,553 DEBUG [org.springframework.orm.hibernate.SessionFactoryUtils] - Closing Hibernate session
2004-09-17 11:50:49,553 DEBUG [net.sf.hibernate.impl.SessionImpl] - closing session
2004-09-17 11:50:49,553 DEBUG [net.sf.hibernate.impl.SessionImpl] - disconnecting session
2004-09-17 11:50:49,553 DEBUG [net.sf.hibernate.impl.SessionImpl] - transaction completion
2004-09-17 11:50:49,563 DEBUG [net.sf.hibernate.cache.ReadWriteCache] - Releasing: 3
2004-09-17 11:50:49,563 DEBUG [net.sf.hibernate.cache.EhCache] - key: 3
2004-09-17 11:50:49,563 DEBUG [net.sf.ehcache.store.MemoryStore] - com.thyrell.pm.model.UserCache: MemoryStore hit for 3
2004-09-17 11:50:49,563 DEBUG [net.sf.ehcache.Cache] - 3 now: 1095414649563
2004-09-17 11:50:49,563 DEBUG [net.sf.ehcache.Cache] - 3 Creation Time: 1095414649213 Next To Last Access Time: 0
2004-09-17 11:50:49,563 DEBUG [net.sf.ehcache.Cache] - 3 mostRecentTime: 1095414649213
2004-09-17 11:50:49,563 DEBUG [net.sf.ehcache.Cache] - 3 Age to Idle: 120000 Age Idled: 350
2004-09-17 11:50:49,563 DEBUG [net.sf.ehcache.Cache] - com.thyrell.pm.model.User: Is element with key 3 expired?: false
2004-09-17 11:50:49,573 DEBUG [org.springframework.web.servlet.DispatcherServlet] - Successfully completed request
2004-09-17 11:50:49,573 DEBUG [org.springframework.web.context.support.XmlWebApplicationContext] - Publishing event in context [XmlWebApplicationContext for namespace 'perfectmind-servlet']: RequestHandledEvent: url=[/admin/user/edit.jspa]; time=[811ms]; client=[192.168.0.2]; method=[POST]; servlet=[perfectmind]; session=[agaKYleoLqhe]; user=[null]; status=[OK]
2004-09-17 11:50:49,573 DEBUG [org.springframework.web.context.support.XmlWebApplicationContext] - Publishing event in context [Root XmlWebApplicationContext]: RequestHandledEvent: url=[/admin/user/edit.jspa]; time=[811ms]; client=[192.168.0.2]; method=[POST]; servlet=[perfectmind]; session=[agaKYleoLqhe]; user=[null]; status=[OK]

[bullgod]

OK, coming closer now... i guess. the errors seem to occur in ALL cases when i use transaction interceptor with this config:

	<bean id="pmTransactionInterceptor" class="org.springframework.transaction.interceptor.TransactionInterceptor">
    	<property name="transactionManager"><ref bean="pmTransactionManager"/></property>
		<property name="transactionAttributeSource">
			<value>
com.thyrell.pm.user.UserServiceImpl.*=PROPAGATION_REQUIRED
			</value>
		</property>
	</bean>

Whereas it works with those:

	<bean id="pmTransactionInterceptor" class="org.springframework.transaction.interceptor.TransactionInterceptor">
    	<property name="transactionManager"><ref bean="pmTransactionManager"/></property>
		<property name="transactionAttributes">
		    <props>
		      <prop key="*">PROPAGATION_REQUIRED</prop>
		    </props>
		</property>
	</bean>

BUT only if I use HibernateTransactionManager. With JTA wether this nor the above config work. The only case i get it working with JTA is using TransactionProxyFactoryBean with no interceptors at all.

Maybe it's a bug in TransactionInterceptor and the JtaTransactionManager or somewhere in between!?

-andi