using DBIdentityLoginModule creates an infinite redirect
johnnythehun Mar 12, 2008 2:58 PMI am an inexperienced JBoss Portal user.
I am using JBoss Portal 2.6.4 + JBoss AS bundle
WinXP
Postgres DB for my data, built in default hsqldb for Portal's data (I've got two datasources: PortalDS and MyDS)
My goal:
I have a custom database with user names and roles. I want Portal to use my database for user authentication and portal/page authorisation. Example: I want JBoss to use my db to let someone in onto the admin portal.
What I have done:
After reading and searching and sweating, I did the following:
1. I updated
server\default\deploy\jboss-portal.sar\conf\login-config.xml
to only contain DBIdentityLoginModule in the portal application policy:
<application-policy name="portal"> <authentication> <login-module code = "org.jboss.portal.identity.auth.DBIdentityLoginModule" flag="sufficient"> <module-option name="dsJndiName">java:/MyDS</module-option> <module-option name="principalsQuery">select username,userpass,id from myuser where username=?</module-option> <module-option name="rolesQuery">SELECT myrole.rolename,'Roles' FROM myrole,myuserroles,myuser where myrole.id=myuserroles.role_id and myuserroles.user_id=myuser.id and myuser.username = ?</module-option> <module-option name="additionalRole">Authenticated</module-option> <module-option name="unauthenticatedIdentity">guest</module-option> </login-module> </authentication> </application-policy>
2. I have a user in myuser table 'janos' who has the following roles defined in myrole dbtable:
role1
admin
Authenticated
Admin
The problem is if I try to access the admin portal
- authentication works
- but authorisation does not, portal doesn't let me access the page
instead it forces the browser into an infinite redirect cycle.
I guess it goes something like:
Login ok -> Page access fail -> Login ok -> page access file -> etc.
A part of the log that describes this:
??/auth/portal/j_security_check 2008-03-11 17:07:36,532 TRACE [org.jboss.security.SecurityAssociation] clear, server=true 2008-03-11 17:07:36,554 DEBUG [org.apache.catalina.connector.CoyoteAdapter] Requested cookie session id is FFB0D9522F65B502095A31191E3A1B37 2008-03-11 17:07:36,555 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Security checking request GET /auth/portal/my_admin 2008-03-11 17:07:36,555 DEBUG [org.apache.catalina.realm.RealmBase] Checking constraint 'SecurityConstraint[Authenticated]' against GET /auth/portal/my_admin --> true 2008-03-11 17:07:36,555 DEBUG [org.apache.catalina.realm.RealmBase] Checking constraint 'SecurityConstraint[Secure]' against GET /auth/portal/my_admin --> false 2008-03-11 17:07:36,555 DEBUG [org.apache.catalina.realm.RealmBase] Checking constraint 'SecurityConstraint[Secure+Authenticated]' against GET /auth/portal/my_admin --> false 2008-03-11 17:07:36,555 DEBUG [org.apache.catalina.realm.RealmBase] Checking constraint 'SecurityConstraint[Authenticated]' against GET /auth/portal/my_admin --> true 2008-03-11 17:07:36,555 DEBUG [org.apache.catalina.realm.RealmBase] Checking constraint 'SecurityConstraint[Secure]' against GET /auth/portal/my_admin --> false 2008-03-11 17:07:36,555 DEBUG [org.apache.catalina.realm.RealmBase] Checking constraint 'SecurityConstraint[Secure+Authenticated]' against GET /auth/portal/my_admin --> false 2008-03-11 17:07:36,555 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling hasUserDataPermission() 2008-03-11 17:07:36,555 DEBUG [org.apache.catalina.realm.RealmBase] User data constraint has no restrictions 2008-03-11 17:07:36,555 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling authenticate() 2008-03-11 17:07:36,555 DEBUG [org.apache.catalina.authenticator.FormAuthenticator] Restore request from session 'FFB0D9522F65B502095A31191E3A1B37' 2008-03-11 17:07:36,555 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Authenticated 'janos' with type 'FORM' 2008-03-11 17:07:36,555 DEBUG [org.apache.catalina.authenticator.FormAuthenticator] Proceed to restored request 2008-03-11 17:07:36,555 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling accessControl() 2008-03-11 17:07:36,556 TRACE [org.jboss.web.tomcat.security.JBossSecurityMgrRealm] Checking roles GenericPrincipal[janos(Authenticated,admin,role1,)] 2008-03-11 17:07:36,556 DEBUG [org.apache.catalina.realm.RealmBase] Username janos has role Authenticated 2008-03-11 17:07:36,556 TRACE [org.jboss.web.tomcat.security.JBossSecurityMgrRealm] No role found: Authenticated 2008-03-11 17:07:36,556 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Successfully passed all security constraints 2008-03-11 17:07:36,556 TRACE [org.jboss.web.tomcat.security.SecurityAssociationValve] Begin invoke, callerGenericPrincipal[janos(Authenticated,admin,role1,)] 2008-03-11 17:07:36,556 TRACE [org.jboss.security.SecurityAssociation] pushRunAsIdentity, runAs=null 2008-03-11 17:07:36,556 TRACE [org.jboss.web.tomcat.security.SecurityAssociationValve] Restoring principal info from cache 2008-03-11 17:07:36,556 TRACE [org.jboss.security.SecurityAssociation] pushSubjectContext, subject=Subject: Principal: PortalPrincipal[janos] Principal: Roles(members:PortalPrincipal[role1],PortalPrincipal[admin],PortalPrincipal[Authenticated]) , sc=org.jboss.security.SecurityAssociation$SubjectContext@102f1ee{principal=janos,subject=10447915} 2008-03-11 17:07:36,556 TRACE [org.jboss.web.tomcat.security.RunAsListener] PortalServletWithPathMapping, runAs: null 2008-03-11 17:07:36,556 TRACE [org.jboss.web.tomcat.security.RunAsListener] PortalServletWithPathMapping, runAs: null 2008-03-11 17:07:36,558 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.jboss.portal.core.identity.UsersActivityStatsService, false) 2008-03-11 17:07:36,558 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,558 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.jboss.portal.core.identity.UsersActivityStatsService) 2008-03-11 17:07:36,558 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,558 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,561 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(java.lang.Long, false) 2008-03-11 17:07:36,561 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.jboss.portal.core.identity.UserActivity, false) 2008-03-11 17:07:36,561 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,562 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.jboss.portal.core.identity.UserActivity) 2008-03-11 17:07:36,562 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,562 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,562 DEBUG [org.jboss.portal.core.identity.UsersActivityStatsServiceImpl] Sending local user activity notification 2008-03-11 17:07:36,562 DEBUG [org.jboss.portal.core.identity.UsersActivityStatsServiceImpl] Handling user activity notification 2008-03-11 17:07:36,566 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization 2008-03-11 17:07:36,566 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4936710785294336 2008-03-11 17:07:36,566 TRACE [org.hibernate.engine.query.QueryPlanCache] unable to locate HQL query plan in cache; generating (from HibernateUserImpl where userName=:userName) 2008-03-11 17:07:36,566 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.jboss.portal.identity.db.HibernateUserImpl, false) 2008-03-11 17:07:36,566 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,566 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.jboss.portal.identity.db.HibernateUserImpl) 2008-03-11 17:07:36,566 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,566 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,567 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.hibernate.hql.ast.HqlToken, false) 2008-03-11 17:07:36,567 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,567 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.hibernate.hql.ast.HqlToken) 2008-03-11 17:07:36,567 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,567 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,571 DEBUG [org.apache.catalina.loader.WebappClassLoader] findResources(commons-logging.properties) 2008-03-11 17:07:36,571 DEBUG [org.apache.catalina.loader.WebappClassLoader] getResourceAsStream(META-INF/services/org.apache.commons.logging.LogFactory) 2008-03-11 17:07:36,571 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,571 DEBUG [org.apache.catalina.loader.WebappClassLoader] findResource(META-INF/services/org.apache.commons.logging.LogFactory) 2008-03-11 17:07:36,571 DEBUG [org.apache.catalina.loader.WebappClassLoader] --> Resource not found, returning null 2008-03-11 17:07:36,571 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader unconditionally java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,575 DEBUG [org.apache.catalina.loader.WebappClassLoader] --> Resource not found, returning null 2008-03-11 17:07:36,575 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.commons.logging.impl.Log4JLogger, false) 2008-03-11 17:07:36,575 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,575 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.apache.commons.logging.impl.Log4JLogger) 2008-03-11 17:07:36,575 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,575 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,575 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Level, false) 2008-03-11 17:07:36,575 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,575 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.apache.log4j.Level) 2008-03-11 17:07:36,575 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,575 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,575 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Logger, false) 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.apache.log4j.Logger) 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Category, false) 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.apache.log4j.Category) 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Priority, false) 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.apache.log4j.Priority) 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Priority, false) 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.apache.log4j.Priority) 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,576 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Level, false) 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.apache.log4j.Level) 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Level, false) 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] Returning class from cache 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Logger, false) 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.apache.log4j.Logger) 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Category, false) 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.apache.log4j.Category) 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Priority, false) 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] Returning class from cache 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Level, false) 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] Returning class from cache 2008-03-11 17:07:36,577 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Logger, false) 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.apache.log4j.Logger) 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Priority, false) 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] Returning class from cache 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Level, false) 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] Returning class from cache 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Logger, false) 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.apache.log4j.Logger) 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Category, false) 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.apache.log4j.Category) 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Priority, false) 2008-03-11 17:07:36,578 DEBUG [org.apache.catalina.loader.WebappClassLoader] Returning class from cache 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Level, false) 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] Returning class from cache 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Logger, false) 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.apache.log4j.Logger) 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Category, false) 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.apache.log4j.Category) 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Priority, false) 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] Returning class from cache 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Level, false) 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] Returning class from cache 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Logger, false) 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.apache.log4j.Logger) 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] Loading class from parent 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.apache.log4j.Priority, false) 2008-03-11 17:07:36,579 DEBUG [org.apache.catalina.loader.WebappClassLoader] Returning class from cache 2008-03-11 17:07:36,579 DEBUG [org.hibernate.hql.ast.QueryTranslatorImpl] parse() - HQL: from org.jboss.portal.identity.db.HibernateUserImpl where userName=:userName 2008-03-11 17:07:36,580 DEBUG [org.apache.catalina.loader.WebappClassLoader] loadClass(org.jboss.portal.identity.db, false) 2008-03-11 17:07:36,580 DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2008-03-11 17:07:36,580 DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(org.jboss.portal.identity.db) 2008-03-11 17:07:36,580 DEBUG [org.apache.catalina.loader.WebappClassLoader] Delegating to parent classloader at end: java.net.FactoryURLClassLoader@16ed0f7 2008-03-11 17:07:36,581 DEBUG [org.hibernate.hql.ast.AST] --- HQL AST --- \-[QUERY] 'query' +-[SELECT_FROM] 'SELECT_FROM' | \-[FROM] 'from' | \-[RANGE] 'RANGE' | \-[DOT] '.' | +-[DOT] '.' | | +-[DOT] '.' | | | +-[DOT] '.' | | | | +-[DOT] '.' | | | | | +-[IDENT] 'org' | | | | | \-[IDENT] 'jboss' | | | | \-[IDENT] 'portal' | | | \-[IDENT] 'identity' | | \-[IDENT] 'db' | \-[IDENT] 'HibernateUserImpl' \-[WHERE] 'where' \-[EQ] '=' +-[IDENT] 'userName' \-[COLON] ':' \-[IDENT] 'userName' 2008-03-11 17:07:36,581 DEBUG [org.hibernate.hql.ast.ErrorCounter] throwQueryException() : no errors 2008-03-11 17:07:36,581 DEBUG [org.hibernate.hql.antlr.HqlSqlBaseWalker] select << begin [level=1, statement=select] 2008-03-11 17:07:36,581 DEBUG [org.hibernate.hql.ast.tree.FromElement] FromClause{level=1} : org.jboss.portal.identity.db.HibernateUserImpl (no alias) -> hibernateu0_ 2008-03-11 17:07:36,581 TRACE [org.hibernate.hql.ast.HqlSqlWalker] attempting to resolve property [userName] as a non-qualified ref 2008-03-11 17:07:36,581 DEBUG [org.hibernate.hql.ast.tree.FromReferenceNode] Resolved : {synthetic-alias} -> {synthetic-alias} 2008-03-11 17:07:36,581 TRACE [org.hibernate.hql.ast.tree.FromElement] handling property dereference [org.jboss.portal.identity.db.HibernateUserImpl (null) -> userName (class)] 2008-03-11 17:07:36,582 DEBUG [org.hibernate.hql.ast.tree.DotNode] getDataType() : userName -> org.hibernate.type.StringType@12cf6d3 2008-03-11 17:07:36,582 DEBUG [org.hibernate.hql.ast.tree.FromReferenceNode] Resolved : {synthetic-alias}.userName -> hibernateu0_.jbp_uname 2008-03-11 17:07:36,582 DEBUG [org.hibernate.hql.antlr.HqlSqlBaseWalker] select : finishing up [level=1, statement=select] 2008-03-11 17:07:36,582 DEBUG [org.hibernate.hql.ast.HqlSqlWalker] processQuery() : ( SELECT ( FromClause{level=1} jbp_users hibernateu0_ ) ( where ( = ( hibernateu0_.jbp_uname {synthetic-alias} userName ) ? ) ) ) 2008-03-11 17:07:36,582 DEBUG [org.hibernate.hql.ast.HqlSqlWalker] Derived SELECT clause created. 2008-03-11 17:07:36,582 DEBUG [org.hibernate.hql.ast.util.JoinProcessor] Using FROM fragment [jbp_users hibernateu0_] 2008-03-11 17:07:36,582 DEBUG [org.hibernate.hql.antlr.HqlSqlBaseWalker] select >> end [level=1, statement=select] 2008-03-11 17:07:36,582 DEBUG [org.hibernate.hql.ast.AST] --- SQL AST --- \-[SELECT] QueryNode: 'SELECT' querySpaces (jbp_users) +-[SELECT_CLAUSE] SelectClause: '{derived select clause}' | +-[SELECT_EXPR] SelectExpressionImpl: 'hibernateu0_.jbp_uid as jbp1_55_' {FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=null,role=null,tableName=jbp_users,tableAlias=hibernateu0_,origin=null,colums={,className=org.jboss.portal.identity.db.HibernateUserImpl}}} | \-[SQL_TOKEN] SqlFragment: 'hibernateu0_.jbp_uname as jbp2_55_, hibernateu0_.jbp_givenname as jbp3_55_, hibernateu0_.jbp_familyname as jbp4_55_, hibernateu0_.jbp_password as jbp5_55_, hibernateu0_.jbp_realemail as jbp6_55_, hibernateu0_.jbp_fakeemail as jbp7_55_, hibernateu0_.jbp_regdate as jbp8_55_, hibernateu0_.jbp_viewrealemail as jbp9_55_, hibernateu0_.jbp_enabled as jbp10_55_' +-[FROM] FromClause: 'from' FromClause{level=1, fromElementCounter=1, fromElements=1, fromElementByClassAlias=[], fromElementByTableAlias=[hibernateu0_], fromElementsByPath=[], collectionJoinFromElementsByPath=[], impliedElements=[]} | \-[FROM_FRAGMENT] FromElement: 'jbp_users hibernateu0_' FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=null,role=null,tableName=jbp_users,tableAlias=hibernateu0_,origin=null,colums={,className=org.jboss.portal.identity.db.HibernateUserImpl}} \-[WHERE] SqlNode: 'where' \-[EQ] BinaryLogicOperatorNode: '=' +-[DOT] DotNode: 'hibernateu0_.jbp_uname' {propertyName=userName,dereferenceType=4,propertyPath=userName,path={synthetic-alias}.userName,tableAlias=hibernateu0_,className=org.jboss.portal.identity.db.HibernateUserImpl,classAlias=null} | +-[IDENT] IdentNode: '{synthetic-alias}' {originalText={synthetic-alias}} | \-[IDENT] IdentNode: 'userName' {originalText=userName} \-[NAMED_PARAM] ParameterNode: '?' {name=userName, expectedType=org.hibernate.type.StringType@12cf6d3} 2008-03-11 17:07:36,582 DEBUG [org.hibernate.hql.ast.ErrorCounter] throwQueryException() : no errors 2008-03-11 17:07:36,582 DEBUG [org.hibernate.hql.ast.QueryTranslatorImpl] HQL: from org.jboss.portal.identity.db.HibernateUserImpl where userName=:userName 2008-03-11 17:07:36,582 DEBUG [org.hibernate.hql.ast.QueryTranslatorImpl] SQL: select hibernateu0_.jbp_uid as jbp1_55_, hibernateu0_.jbp_uname as jbp2_55_, hibernateu0_.jbp_givenname as jbp3_55_, hibernateu0_.jbp_familyname as jbp4_55_, hibernateu0_.jbp_password as jbp5_55_, hibernateu0_.jbp_realemail as jbp6_55_, hibernateu0_.jbp_fakeemail as jbp7_55_, hibernateu0_.jbp_regdate as jbp8_55_, hibernateu0_.jbp_viewrealemail as jbp9_55_, hibernateu0_.jbp_enabled as jbp10_55_ from jbp_users hibernateu0_ where hibernateu0_.jbp_uname=? 2008-03-11 17:07:36,582 DEBUG [org.hibernate.hql.ast.ErrorCounter] throwQueryException() : no errors 2008-03-11 17:07:36,583 TRACE [org.hibernate.engine.query.HQLQueryPlan] HQL param location recognition took 0 mills (from HibernateUserImpl where userName=:userName) 2008-03-11 17:07:36,583 TRACE [org.hibernate.engine.query.QueryPlanCache] located HQL query plan in cache (from HibernateUserImpl where userName=:userName) 2008-03-11 17:07:36,583 TRACE [org.hibernate.engine.query.HQLQueryPlan] find: from HibernateUserImpl where userName=:userName 2008-03-11 17:07:36,583 TRACE [org.hibernate.engine.QueryParameters] named parameters: {userName=janos} 2008-03-11 17:07:36,589 DEBUG [org.hibernate.cache.StandardQueryCache] checking cached query results in region: org.hibernate.cache.StandardQueryCache 2008-03-11 17:07:36,589 DEBUG [org.hibernate.cache.EhCache] key: sql: select hibernateu0_.jbp_uid as jbp1_55_, hibernateu0_.jbp_uname as jbp2_55_, hibernateu0_.jbp_givenname as jbp3_55_, hibernateu0_.jbp_familyname as jbp4_55_, hibernateu0_.jbp_password as jbp5_55_, hibernateu0_.jbp_realemail as jbp6_55_, hibernateu0_.jbp_fakeemail as jbp7_55_, hibernateu0_.jbp_regdate as jbp8_55_, hibernateu0_.jbp_viewrealemail as jbp9_55_, hibernateu0_.jbp_enabled as jbp10_55_ from jbp_users hibernateu0_ where hibernateu0_.jbp_uname=?; parameters: ; named parameters: {userName=janos} 2008-03-11 17:07:36,589 DEBUG [org.hibernate.cache.EhCache] Element for sql: select hibernateu0_.jbp_uid as jbp1_55_, hibernateu0_.jbp_uname as jbp2_55_, hibernateu0_.jbp_givenname as jbp3_55_, hibernateu0_.jbp_familyname as jbp4_55_, hibernateu0_.jbp_password as jbp5_55_, hibernateu0_.jbp_realemail as jbp6_55_, hibernateu0_.jbp_fakeemail as jbp7_55_, hibernateu0_.jbp_regdate as jbp8_55_, hibernateu0_.jbp_viewrealemail as jbp9_55_, hibernateu0_.jbp_enabled as jbp10_55_ from jbp_users hibernateu0_ where hibernateu0_.jbp_uname=?; parameters: ; named parameters: {userName=janos} is null 2008-03-11 17:07:36,589 DEBUG [org.hibernate.cache.StandardQueryCache] query results were not found in cache 2008-03-11 17:07:36,589 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 2008-03-11 17:07:36,589 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection 2008-03-11 17:07:36,590 DEBUG [org.hibernate.SQL] select hibernateu0_.jbp_uid as jbp1_55_, hibernateu0_.jbp_uname as jbp2_55_, hibernateu0_.jbp_givenname as jbp3_55_, hibernateu0_.jbp_familyname as jbp4_55_, hibernateu0_.jbp_password as jbp5_55_, hibernateu0_.jbp_realemail as jbp6_55_, hibernateu0_.jbp_fakeemail as jbp7_55_, hibernateu0_.jbp_regdate as jbp8_55_, hibernateu0_.jbp_viewrealemail as jbp9_55_, hibernateu0_.jbp_enabled as jbp10_55_ from jbp_users hibernateu0_ where hibernateu0_.jbp_uname=? 2008-03-11 17:07:36,590 TRACE [org.hibernate.jdbc.AbstractBatcher] preparing statement 2008-03-11 17:07:36,590 TRACE [org.hibernate.type.StringType] binding 'janos' to parameter: 1 2008-03-11 17:07:36,590 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0) 2008-03-11 17:07:36,590 TRACE [org.hibernate.loader.Loader] processing result set 2008-03-11 17:07:36,590 TRACE [org.hibernate.loader.Loader] done processing result set (0 rows) 2008-03-11 17:07:36,590 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1) 2008-03-11 17:07:36,590 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 2008-03-11 17:07:36,590 TRACE [org.hibernate.jdbc.AbstractBatcher] closing statement 2008-03-11 17:07:36,591 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection 2008-03-11 17:07:36,591 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] 2008-03-11 17:07:36,591 TRACE [org.hibernate.loader.Loader] total objects hydrated: 0 2008-03-11 17:07:36,591 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections 2008-03-11 17:07:36,591 DEBUG [org.hibernate.cache.StandardQueryCache] caching query results in region: org.hibernate.cache.StandardQueryCache; timestamp=4936710785294336 2008-03-11 17:07:36,591 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization 2008-03-11 17:07:36,591 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4936710785396736 2008-03-11 17:07:36,592 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,592 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,592 TRACE [org.hibernate.cache.ReadWriteCache] Cache lookup: org.jboss.portal.core.impl.model.portal.ObjectNode#1 2008-03-11 17:07:36,592 DEBUG [org.hibernate.cache.EhCache] key: org.jboss.portal.core.impl.model.portal.ObjectNode#1 2008-03-11 17:07:36,592 TRACE [org.hibernate.cache.ReadWriteCache] Cache hit: org.jboss.portal.core.impl.model.portal.ObjectNode#1 2008-03-11 17:07:36,592 TRACE [org.hibernate.event.def.DefaultLoadEventListener] assembling entity from second-level cache: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,592 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.PortalObjectImpl#1] 2008-03-11 17:07:36,592 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [org.jboss.portal.core.impl.model.portal.PortalObjectImpl#1] 2008-03-11 17:07:36,592 TRACE [org.hibernate.cache.ReadWriteCache] Cache lookup: org.jboss.portal.core.impl.model.portal.PortalObjectImpl#1 2008-03-11 17:07:36,592 DEBUG [org.hibernate.cache.EhCache] key: org.jboss.portal.core.impl.model.portal.PortalObjectImpl#1 2008-03-11 17:07:36,592 TRACE [org.hibernate.cache.ReadWriteCache] Cache hit: org.jboss.portal.core.impl.model.portal.PortalObjectImpl#1 2008-03-11 17:07:36,592 TRACE [org.hibernate.event.def.DefaultLoadEventListener] assembling entity from second-level cache: [org.jboss.portal.core.impl.model.portal.PortalObjectImpl#1] 2008-03-11 17:07:36,592 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,592 TRACE [org.hibernate.event.def.DefaultLoadEventListener] entity found in session cache 2008-03-11 17:07:36,592 TRACE [org.hibernate.event.def.DefaultLoadEventListener] Cached Version: null 2008-03-11 17:07:36,592 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections 2008-03-11 17:07:36,592 TRACE [org.hibernate.event.def.DefaultLoadEventListener] resolved object in second-level cache: [org.jboss.portal.core.impl.model.portal.PortalObjectImpl#1] 2008-03-11 17:07:36,592 TRACE [org.hibernate.event.def.DefaultLoadEventListener] Cached Version: null 2008-03-11 17:07:36,592 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections 2008-03-11 17:07:36,592 TRACE [org.hibernate.event.def.DefaultLoadEventListener] resolved object in second-level cache: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,593 DEBUG [org.hibernate.loader.entity.CollectionElementLoader] Static select for entity org.jboss.portal.core.impl.model.portal.ObjectNode: select objectnode0_.PK as PK64_1_, objectnode0_.PATH as PATH64_1_, objectnode0_.NAME as NAME64_1_, objectnode0_.PARENT_KEY as PARENT4_64_1_, securityco1_.NODE_KEY as NODE3_3_, securityco1_.PK as PK3_, securityco1_.ROLE as ROLE3_, securityco1_.PK as PK74_0_, securityco1_.ROLE as ROLE74_0_, securityco1_.NODE_KEY as NODE3_74_0_, actions2_.PK as PK4_, actions2_.ACTIONS as ACTIONS4_ from JBP_OBJECT_NODE objectnode0_ left outer join JBP_OBJECT_NODE_SEC securityco1_ on objectnode0_.PK=securityco1_.NODE_KEY left outer join JBP_OBJECT_NODE_SEC_ACTIONS actions2_ on securityco1_.PK=actions2_.PK where objectnode0_.PARENT_KEY=? and objectnode0_.NAME=? 2008-03-11 17:07:36,593 DEBUG [org.hibernate.loader.Loader] loading collection element by index 2008-03-11 17:07:36,593 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 2008-03-11 17:07:36,593 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection 2008-03-11 17:07:36,593 DEBUG [org.hibernate.SQL] select objectnode0_.PK as PK64_1_, objectnode0_.PATH as PATH64_1_, objectnode0_.NAME as NAME64_1_, objectnode0_.PARENT_KEY as PARENT4_64_1_, securityco1_.NODE_KEY as NODE3_3_, securityco1_.PK as PK3_, securityco1_.ROLE as ROLE3_, securityco1_.PK as PK74_0_, securityco1_.ROLE as ROLE74_0_, securityco1_.NODE_KEY as NODE3_74_0_, actions2_.PK as PK4_, actions2_.ACTIONS as ACTIONS4_ from JBP_OBJECT_NODE objectnode0_ left outer join JBP_OBJECT_NODE_SEC securityco1_ on objectnode0_.PK=securityco1_.NODE_KEY left outer join JBP_OBJECT_NODE_SEC_ACTIONS actions2_ on securityco1_.PK=actions2_.PK where objectnode0_.PARENT_KEY=? and objectnode0_.NAME=? 2008-03-11 17:07:36,593 TRACE [org.hibernate.jdbc.AbstractBatcher] preparing statement 2008-03-11 17:07:36,593 TRACE [org.hibernate.type.LongType] binding '1' to parameter: 1 2008-03-11 17:07:36,593 TRACE [org.hibernate.type.StringType] binding 'my_admin' to parameter: 2 2008-03-11 17:07:36,593 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0) 2008-03-11 17:07:36,593 TRACE [org.hibernate.loader.Loader] processing result set 2008-03-11 17:07:36,593 DEBUG [org.hibernate.loader.Loader] result set row: 0 2008-03-11 17:07:36,593 TRACE [org.hibernate.type.LongType] returning '14' as column: PK74_0_ 2008-03-11 17:07:36,593 TRACE [org.hibernate.type.LongType] returning '317' as column: PK64_1_ 2008-03-11 17:07:36,593 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#14], EntityKey[org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,594 TRACE [org.hibernate.loader.Loader] Initializing object from ResultSet: [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#14] 2008-03-11 17:07:36,594 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#14] 2008-03-11 17:07:36,594 TRACE [org.hibernate.type.StringType] returning 'myAdmin' as column: ROLE74_0_ 2008-03-11 17:07:36,594 TRACE [org.hibernate.type.LongType] returning '317' as column: NODE3_74_0_ 2008-03-11 17:07:36,594 TRACE [org.hibernate.loader.Loader] Initializing object from ResultSet: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,594 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,594 TRACE [org.hibernate.type.StringType] returning 'my_admin' as column: NAME64_1_ 2008-03-11 17:07:36,594 TRACE [org.hibernate.type.LongType] returning '1' as column: PARENT4_64_1_ 2008-03-11 17:07:36,594 TRACE [org.hibernate.type.LongType] returning '317' as column: NODE3_3_ 2008-03-11 17:07:36,594 DEBUG [org.hibernate.loader.Loader] found row of collection: [org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints#317] 2008-03-11 17:07:36,594 TRACE [org.hibernate.engine.loading.CollectionLoadContext] starting attempt to find loading collection [[org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints#317]] 2008-03-11 17:07:36,594 TRACE [org.hibernate.engine.loading.CollectionLoadContext] instantiating new collection [key=317, rs=org.hsqldb.jdbc.jdbcResultSet@289784] 2008-03-11 17:07:36,594 TRACE [org.hibernate.type.LongType] returning '14' as column: PK3_ 2008-03-11 17:07:36,594 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#14] 2008-03-11 17:07:36,594 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#14] 2008-03-11 17:07:36,594 TRACE [org.hibernate.event.def.DefaultLoadEventListener] resolved object in session cache: [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#14] 2008-03-11 17:07:36,594 TRACE [org.hibernate.type.StringType] returning 'myAdmin' as column: ROLE3_ 2008-03-11 17:07:36,594 TRACE [org.hibernate.type.LongType] returning '14' as column: PK4_ 2008-03-11 17:07:36,594 DEBUG [org.hibernate.loader.Loader] found row of collection: [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint.actions#14] 2008-03-11 17:07:36,594 TRACE [org.hibernate.engine.loading.CollectionLoadContext] starting attempt to find loading collection [[org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint.actions#14]] 2008-03-11 17:07:36,594 TRACE [org.hibernate.engine.loading.CollectionLoadContext] instantiating new collection [key=14, rs=org.hsqldb.jdbc.jdbcResultSet@289784] 2008-03-11 17:07:36,594 TRACE [org.hibernate.type.StringType] returning 'viewrecursive' as column: ACTIONS4_ 2008-03-11 17:07:36,594 TRACE [org.hibernate.loader.Loader] done processing result set (1 rows) 2008-03-11 17:07:36,594 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1) 2008-03-11 17:07:36,594 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 2008-03-11 17:07:36,594 TRACE [org.hibernate.jdbc.AbstractBatcher] closing statement 2008-03-11 17:07:36,594 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection 2008-03-11 17:07:36,594 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] 2008-03-11 17:07:36,594 TRACE [org.hibernate.loader.Loader] total objects hydrated: 2 2008-03-11 17:07:36,594 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#14] 2008-03-11 17:07:36,594 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,594 TRACE [org.hibernate.event.def.DefaultLoadEventListener] entity found in session cache 2008-03-11 17:07:36,595 DEBUG [org.hibernate.engine.TwoPhaseLoad] adding entity to second-level cache: [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#14] 2008-03-11 17:07:36,595 TRACE [org.hibernate.cache.ReadWriteCache] Caching: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#14 2008-03-11 17:07:36,595 DEBUG [org.hibernate.cache.EhCache] key: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#14 2008-03-11 17:07:36,595 TRACE [org.hibernate.cache.ReadWriteCache] Item was already cached: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#14 2008-03-11 17:07:36,595 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#14] 2008-03-11 17:07:36,595 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,595 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,595 TRACE [org.hibernate.event.def.DefaultLoadEventListener] entity found in session cache 2008-03-11 17:07:36,595 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.PortalObjectImpl#317] 2008-03-11 17:07:36,595 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [org.jboss.portal.core.impl.model.portal.PortalObjectImpl#317] 2008-03-11 17:07:36,595 TRACE [org.hibernate.cache.ReadWriteCache] Cache lookup: org.jboss.portal.core.impl.model.portal.PortalObjectImpl#317 2008-03-11 17:07:36,595 DEBUG [org.hibernate.cache.EhCache] key: org.jboss.portal.core.impl.model.portal.PortalObjectImpl#317 2008-03-11 17:07:36,595 TRACE [org.hibernate.cache.ReadWriteCache] Cache hit: org.jboss.portal.core.impl.model.portal.PortalObjectImpl#317 2008-03-11 17:07:36,595 TRACE [org.hibernate.event.def.DefaultLoadEventListener] assembling entity from second-level cache: [org.jboss.portal.core.impl.model.portal.PortalObjectImpl#317] 2008-03-11 17:07:36,595 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,595 TRACE [org.hibernate.event.def.DefaultLoadEventListener] entity found in session cache 2008-03-11 17:07:36,595 TRACE [org.hibernate.event.def.DefaultLoadEventListener] Cached Version: null 2008-03-11 17:07:36,595 TRACE [org.hibernate.event.def.DefaultLoadEventListener] resolved object in second-level cache: [org.jboss.portal.core.impl.model.portal.PortalObjectImpl#317] 2008-03-11 17:07:36,595 DEBUG [org.hibernate.engine.TwoPhaseLoad] adding entity to second-level cache: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,595 TRACE [org.hibernate.cache.ReadWriteCache] Caching: org.jboss.portal.core.impl.model.portal.ObjectNode#317 2008-03-11 17:07:36,595 DEBUG [org.hibernate.cache.EhCache] key: org.jboss.portal.core.impl.model.portal.ObjectNode#317 2008-03-11 17:07:36,595 TRACE [org.hibernate.cache.ReadWriteCache] Item was already cached: org.jboss.portal.core.impl.model.portal.ObjectNode#317 2008-03-11 17:07:36,595 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,595 TRACE [org.hibernate.engine.loading.CollectionLoadContext] removing collection load entry [org.hibernate.engine.loading.LoadingCollectionEntry<rs=org.hsqldb.jdbc.jdbcResultSet@289784, coll=[org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints#317]>@1f91758] 2008-03-11 17:07:36,595 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] 1 collections were found in result set for role: org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints 2008-03-11 17:07:36,595 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] ending loading collection [org.hibernate.engine.loading.LoadingCollectionEntry<rs=org.hsqldb.jdbc.jdbcResultSet@289784, coll=[org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints#317]>@1f91758] 2008-03-11 17:07:36,595 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] Caching collection: [org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints#317] 2008-03-11 17:07:36,596 TRACE [org.hibernate.cache.ReadWriteCache] Caching: org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints#317 2008-03-11 17:07:36,596 DEBUG [org.hibernate.cache.EhCache] key: org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints#317 2008-03-11 17:07:36,596 TRACE [org.hibernate.cache.ReadWriteCache] Item was already cached: org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints#317 2008-03-11 17:07:36,596 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] collection fully initialized: [org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints#317] 2008-03-11 17:07:36,596 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] 1 collections initialized for role: org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints 2008-03-11 17:07:36,596 TRACE [org.hibernate.engine.loading.CollectionLoadContext] removing collection load entry [org.hibernate.engine.loading.LoadingCollectionEntry<rs=org.hsqldb.jdbc.jdbcResultSet@289784, coll=[org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint.actions#14]>@12f0924] 2008-03-11 17:07:36,596 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] 1 collections were found in result set for role: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint.actions 2008-03-11 17:07:36,596 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] ending loading collection [org.hibernate.engine.loading.LoadingCollectionEntry<rs=org.hsqldb.jdbc.jdbcResultSet@289784, coll=[org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint.actions#14]>@12f0924] 2008-03-11 17:07:36,596 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] Caching collection: [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint.actions#14] 2008-03-11 17:07:36,596 TRACE [org.hibernate.cache.ReadWriteCache] Caching: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint.actions#14 2008-03-11 17:07:36,596 DEBUG [org.hibernate.cache.EhCache] key: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint.actions#14 2008-03-11 17:07:36,596 TRACE [org.hibernate.cache.ReadWriteCache] Item was already cached: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint.actions#14 2008-03-11 17:07:36,596 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] collection fully initialized: [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint.actions#14] 2008-03-11 17:07:36,596 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] 1 collections initialized for role: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint.actions 2008-03-11 17:07:36,596 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections 2008-03-11 17:07:36,597 DEBUG [org.hibernate.loader.Loader] done entity load 2008-03-11 17:07:36,597 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,597 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,597 TRACE [org.hibernate.event.def.DefaultLoadEventListener] resolved object in session cache: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,597 TRACE [org.jboss.security.SecurityAssociation] getSubject, sc=org.jboss.security.SecurityAssociation$SubjectContext@102f1ee{principal=janos,subject=10447915} 2008-03-11 17:07:36,600 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,600 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,600 TRACE [org.hibernate.event.def.DefaultLoadEventListener] resolved object in session cache: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,600 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,600 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,600 TRACE [org.hibernate.event.def.DefaultLoadEventListener] resolved object in session cache: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,601 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints#1] 2008-03-11 17:07:36,601 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2008-03-11 17:07:36,601 TRACE [org.hibernate.cache.ReadWriteCache] Cache lookup: org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints#1 2008-03-11 17:07:36,601 DEBUG [org.hibernate.cache.EhCache] key: org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints#1 2008-03-11 17:07:36,601 TRACE [org.hibernate.cache.ReadWriteCache] Cache hit: org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints#1 2008-03-11 17:07:36,601 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#1] 2008-03-11 17:07:36,601 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#1] 2008-03-11 17:07:36,601 TRACE [org.hibernate.cache.ReadWriteCache] Cache lookup: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#1 2008-03-11 17:07:36,601 DEBUG [org.hibernate.cache.EhCache] key: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#1 2008-03-11 17:07:36,601 TRACE [org.hibernate.cache.ReadWriteCache] Cache hit: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#1 2008-03-11 17:07:36,601 TRACE [org.hibernate.event.def.DefaultLoadEventListener] assembling entity from second-level cache: [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#1] 2008-03-11 17:07:36,601 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,601 TRACE [org.hibernate.event.def.DefaultLoadEventListener] entity found in session cache 2008-03-11 17:07:36,601 TRACE [org.hibernate.event.def.DefaultLoadEventListener] Cached Version: null 2008-03-11 17:07:36,601 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections 2008-03-11 17:07:36,601 TRACE [org.hibernate.event.def.DefaultLoadEventListener] resolved object in second-level cache: [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#1] 2008-03-11 17:07:36,601 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized from cache 2008-03-11 17:07:36,601 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint.actions#1] 2008-03-11 17:07:36,601 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2008-03-11 17:07:36,601 TRACE [org.hibernate.cache.ReadWriteCache] Cache lookup: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint.actions#1 2008-03-11 17:07:36,601 DEBUG [org.hibernate.cache.EhCache] key: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint.actions#1 2008-03-11 17:07:36,601 TRACE [org.hibernate.cache.ReadWriteCache] Cache hit: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint.actions#1 2008-03-11 17:07:36,601 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized from cache 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] resolved object in session cache: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] resolved object in session cache: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] resolved object in session cache: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] resolved object in session cache: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] resolved object in session cache: [org.jboss.portal.core.impl.model.portal.ObjectNode#317] 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,602 TRACE [org.hibernate.event.def.DefaultLoadEventListener] resolved object in session cache: [org.jboss.portal.core.impl.model.portal.ObjectNode#1] 2008-03-11 17:07:36,602 TRACE [org.hibernate.transaction.CacheSynchronization] transaction before completion callback 2008-03-11 17:07:36,602 TRACE [org.hibernate.transaction.CacheSynchronization] automatically flushing session 2008-03-11 17:07:36,602 TRACE [org.hibernate.impl.SessionImpl] automatically flushing session 2008-03-11 17:07:36,602 TRACE [org.hibernate.jdbc.JDBCContext] before transaction completion 2008-03-11 17:07:36,602 TRACE [org.hibernate.impl.SessionImpl] before transaction completion 2008-03-11 17:07:36,602 TRACE [org.hibernate.transaction.CacheSynchronization] transaction before completion callback 2008-03-11 17:07:36,602 TRACE [org.hibernate.transaction.CacheSynchronization] automatically flushing session 2008-03-11 17:07:36,602 TRACE [org.hibernate.impl.SessionImpl] automatically flushing session 2008-03-11 17:07:36,603 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] flushing session 2008-03-11 17:07:36,603 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] processing cascade ACTION_SAVE_UPDATE for: org.jboss.portal.core.impl.model.portal.ContextImpl 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] done processing cascade ACTION_SAVE_UPDATE for: org.jboss.portal.core.impl.model.portal.ContextImpl 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] processing cascade ACTION_SAVE_UPDATE for: org.jboss.portal.core.impl.model.portal.ObjectNode 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] cascade ACTION_SAVE_UPDATE for collection: org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.CascadingAction] cascading to saveOrUpdate: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint 2008-03-11 17:07:36,603 TRACE [org.hibernate.event.def.AbstractSaveEventListener] persistent instance of: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint 2008-03-11 17:07:36,603 TRACE [org.hibernate.event.def.DefaultSaveOrUpdateEventListener] ignoring persistent instance 2008-03-11 17:07:36,603 TRACE [org.hibernate.event.def.DefaultSaveOrUpdateEventListener] object already associated with session: [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#1] 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] done cascade ACTION_SAVE_UPDATE for collection: org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] deleting orphans for collection: org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] done deleting orphans for collection: org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] done processing cascade ACTION_SAVE_UPDATE for: org.jboss.portal.core.impl.model.portal.ObjectNode 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] processing cascade ACTION_SAVE_UPDATE for: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] done processing cascade ACTION_SAVE_UPDATE for: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] processing cascade ACTION_SAVE_UPDATE for: org.jboss.portal.core.impl.model.portal.ObjectNode 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] cascade ACTION_SAVE_UPDATE for collection: org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.CascadingAction] cascading to saveOrUpdate: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint 2008-03-11 17:07:36,603 TRACE [org.hibernate.event.def.AbstractSaveEventListener] persistent instance of: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint 2008-03-11 17:07:36,603 TRACE [org.hibernate.event.def.DefaultSaveOrUpdateEventListener] ignoring persistent instance 2008-03-11 17:07:36,603 TRACE [org.hibernate.event.def.DefaultSaveOrUpdateEventListener] object already associated with session: [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint#14] 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] done cascade ACTION_SAVE_UPDATE for collection: org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] deleting orphans for collection: org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] done deleting orphans for collection: org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] done processing cascade ACTION_SAVE_UPDATE for: org.jboss.portal.core.impl.model.portal.ObjectNode 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] processing cascade ACTION_SAVE_UPDATE for: org.jboss.portal.core.impl.model.portal.PortalImpl 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] done processing cascade ACTION_SAVE_UPDATE for: org.jboss.portal.core.impl.model.portal.PortalImpl 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] processing cascade ACTION_SAVE_UPDATE for: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint 2008-03-11 17:07:36,603 TRACE [org.hibernate.engine.Cascade] done processing cascade ACTION_SAVE_UPDATE for: org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint 2008-03-11 17:07:36,603 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] dirty checking collections 2008-03-11 17:07:36,603 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] Flushing entities and processing referenced collections 2008-03-11 17:07:36,603 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jboss.portal.core.impl.model.portal.PortalObjectImpl.displayNames#1], was: [org.jboss.portal.core.impl.model.portal.PortalObjectImpl.displayNames#1] (uninitialized) 2008-03-11 17:07:36,603 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jboss.portal.core.impl.model.portal.PortalObjectImpl.declaredPropertyMap#1], was: [org.jboss.portal.core.impl.model.portal.PortalObjectImpl.declaredPropertyMap#1] (uninitialized) 2008-03-11 17:07:36,603 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jboss.portal.core.impl.model.portal.ObjectNode.children#1], was: [org.jboss.portal.core.impl.model.portal.ObjectNode.children#1] (uninitialized) 2008-03-11 17:07:36,603 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints#1], was: [org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints#1] (initialized) 2008-03-11 17:07:36,603 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint.actions#14], was: [org.jboss.portal.core.impl.model.portal.ObjectNodeSecurityConstraint.actions#14] (initialized) 2008-03-11 17:07:36,604 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jboss.portal.core.impl.model.portal.ObjectNode.children#317], was: [org.jboss.portal.core.impl.model.portal.ObjectNode.children#317] (uninitialized) 2008-03-11 17:07:36,604 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints#317], was: [org.jboss.portal.core.impl.model.portal.ObjectNode.securityConstraints#317] (initialized) 2008-03-11 17:07:36,604 DEBUG [org.hibe