2 Replies Latest reply on Mar 19, 2008 8:38 AM by Boleslaw Dawidowicz

    using DBIdentityLoginModule creates an infinite redirect

    John Gerevich Newbie

      I 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