I'm fairly new to Hibernate and have NO idea why this is happening. It should be working according to my understanding of how Hibernate works. Please help me out as I've been spinning my wheels on this for days.
I'm trying to get a list of roles in my User object, which I'm also using with Acegi Security. The roles are retreived via a user-defined function in the database (getUserRoles) which uses the user's user_id to find the users roles. The user_roles table only has a subset of a user's actual roles because the roles are heirarchical. Long story short, GetUserRoles returns a lot more roles than just joining the users table on the users_roles table (then on the roles table).
When I remove the "<loader query-ref="GetUserRoles" />", I don't get the exception but I only get a subset of the actual roles that I should be getting. I've stepped through the code and have no idea why my setup isn't working. Somehow, the org.hibernate.collection.PersistentSet internal set field is never initialized when the loader tag is present.
Any help you can provided is much appriciated.
Thanks,
Eric
Hibernate version: 3.2.5 ga
Mapping documents:
Code:
<hibernate-mapping package="com.mypackage.security">
<class name="User" table="users" mutable="false">
<id name="userId" column="user_id" type="long" unsaved-value="-1">
<generator class="assigned" />
</id>
<property name="username" column="handle" type="string" />
<property name="password" column="password" type="string" />
<property name="birthDate" column="age" type="date" />
<property name="firstName" column="first_name" type="string" />
<property name="lastName" column="last_name" type="string" />
<property name="street" column="address" type="string" />
<property name="city" column="city" type="string" />
<property name="state" column="state" type="string" />
<property name="postalCode" column="zip" type="string" />
<property name="country" column="country" type="string" />
<property name="phoneNumber" column="phone" type="string" />
<property name="emailAddress" column="email" type="string" />
<set name="roles" table="users_roles">
<key column="user_id" />
<many-to-many column="role_id" class="Role" />
<loader query-ref="GetUserRoles" />
</set>
</class>
<class name="Role" table="roles" mutable="false">
<id name="roleId" column="id" type="int" unsaved-value="-1">
<generator class="assigned" />
</id>
<property name="name" column="name" type="string" />
</class>
<!-- MSSQL specific -->
<sql-query name="GetUserRoles">
<return class="Role" />
<query-param name="userId" type="long" />
{ call getUserRoles( ? ) }
</sql-query>
</hibernate-mapping>
Full stack trace of any exception that occurs:Code:
ERROR - 2008-01-18 10:30:27,220 (StandardWrapperValve.java:257)
Servlet.service() for servlet default threw exception
org.hibernate.PropertyAccessException: Exception occurred inside setter of com.mypackage.security.User.roles
at org.hibernate.property.BasicPropertyAccessor$BasicSetter.set(BasicPropertyAccessor.java:65)
at org.hibernate.tuple.entity.AbstractEntityTuplizer.setPropertyValues(AbstractEntityTuplizer.java:337)
at org.hibernate.tuple.entity.PojoEntityTuplizer.setPropertyValues(PojoEntityTuplizer.java:200)
at org.hibernate.persister.entity.AbstractEntityPersister.setPropertyValues(AbstractEntityPersister.java:3566)
at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:129)
at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:854)
at org.hibernate.loader.Loader.doQuery(Loader.java:729)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236)
at org.hibernate.loader.Loader.doList(Loader.java:2220)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2104)
at org.hibernate.loader.Loader.list(Loader.java:2099)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:378)
at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:338)
at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:172)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1121)
at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)
at org.hibernate.impl.AbstractQueryImpl.uniqueResult(AbstractQueryImpl.java:811)
at com.mypackage.security.UserDetailsService.loadUserByUsername(UserDetailsService.java:47)
at org.acegisecurity.providers.dao.DaoAuthenticationProvider.retrieveUser(DaoAuthenticationProvider.java:127)
at org.acegisecurity.providers.dao.AbstractUserDetailsAuthenticationProvider.authenticate(AbstractUserDetailsAuthenticationProvider.java:119)
at org.acegisecurity.providers.ProviderManager.doAuthentication(ProviderManager.java:195)
at org.acegisecurity.AbstractAuthenticationManager.authenticate(AbstractAuthenticationManager.java:45)
at org.acegisecurity.ui.webapp.AuthenticationProcessingFilter.attemptAuthentication(AuthenticationProcessingFilter.java:71)
at org.acegisecurity.ui.AbstractProcessingFilter.doFilter(AbstractProcessingFilter.java:252)
at org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:275)
at org.acegisecurity.ui.logout.LogoutFilter.doFilter(LogoutFilter.java:110)
at org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:275)
at org.acegisecurity.context.HttpSessionContextIntegrationFilter.doFilter(HttpSessionContextIntegrationFilter.java:249)
at org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:275)
at org.acegisecurity.util.FilterChainProxy.doFilter(FilterChainProxy.java:149)
at org.acegisecurity.util.FilterToBeanProxy.doFilter(FilterToBeanProxy.java:98)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
at com.mypackage.servlet.DynaWelcomeFilter.doFilter(DynaWelcomeFilter.java:145)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:210)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:174)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:151)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:870)
at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665)
at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528)
at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:685)
at java.lang.Thread.run(Thread.java:619)
Caused by: java.lang.reflect.InvocationTargetException
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.hibernate.property.BasicPropertyAccessor$BasicSetter.set(BasicPropertyAccessor.java:42)
... 47 more
Caused by: java.lang.NullPointerException
at org.hibernate.collection.PersistentSet.toArray(PersistentSet.java:172)
at java.util.LinkedList.addAll(LinkedList.java:269)
at java.util.LinkedList.addAll(LinkedList.java:247)
at com.mypackage.security.User.setRoles(User.java:307)
... 52 more
Name and version of the database you are using: MS SQL 2000
The generated SQL (show_sql=true): See log output below
Debug level Hibernate log excerpt:Code:
DEBUG - 2008-01-18 10:30:26,408 (PathBasedFilterInvocationDefinitionMap.java:106)
Converted URL to lowercase, from: '/j_acegi_security_check'; to: '/j_acegi_security_check'
DEBUG - 2008-01-18 10:30:26,424 (PathBasedFilterInvocationDefinitionMap.java:118)
Candidate is: '/j_acegi_security_check'; pattern is /**; matched=true
DEBUG - 2008-01-18 10:30:26,424 (FilterChainProxy.java:270)
/j_acegi_security_check at position 1 of 7 in additional filter chain; firing Filter: 'org.acegisecurity.context.HttpSessionContextIntegrationFilter@17d56b'
DEBUG - 2008-01-18 10:30:26,424 (HttpSessionContextIntegrationFilter.java:227)
Obtained a valid SecurityContext from ACEGI_SECURITY_CONTEXT to associate with SecurityContextHolder: 'org.acegisecurity.context.SecurityContextImpl@90556c3e: Authentication: org.acegisecurity.providers.anonymous.AnonymousAuthenticationToken@90556c3e: Username: anonymousUser; Password: [PROTECTED]; Authenticated: true; Details: org.acegisecurity.ui.WebAuthenticationDetails@1de6: RemoteIpAddress: 172.16.25.139; SessionId: null; Granted Authorities: ROLE_ANONYMOUS'
DEBUG - 2008-01-18 10:30:26,424 (FilterChainProxy.java:270)
/j_acegi_security_check at position 2 of 7 in additional filter chain; firing Filter: 'org.acegisecurity.ui.logout.LogoutFilter@fe861'
DEBUG - 2008-01-18 10:30:26,424 (FilterChainProxy.java:270)
/j_acegi_security_check at position 3 of 7 in additional filter chain; firing Filter: 'org.acegisecurity.ui.webapp.AuthenticationProcessingFilter@616364'
DEBUG - 2008-01-18 10:30:26,424 (AbstractProcessingFilter.java:245)
Request is to process authentication
DEBUG - 2008-01-18 10:30:26,424 (ProviderManager.java:190)
Authentication attempt using org.acegisecurity.providers.dao.DaoAuthenticationProvider
DEBUG - 2008-01-18 10:30:26,502 (SessionImpl.java:220)
opened session at timestamp: 12006810264
TRACE - 2008-01-18 10:30:26,502 (QueryPlanCache.java:70)
unable to locate HQL query plan in cache; generating (FROM User mpu WHERE mpu.username = ?)
DEBUG - 2008-01-18 10:30:26,564 (QueryTranslatorImpl.java:246)
parse() - HQL: FROM com.mypackage.security.User mpu WHERE mpu.username = ?
DEBUG - 2008-01-18 10:30:26,595 (QueryTranslatorImpl.java:266)
--- HQL AST ---
\-[QUERY] 'query'
+-[SELECT_FROM] 'SELECT_FROM'
| \-[FROM] 'FROM'
| \-[RANGE] 'RANGE'
| +-[DOT] '.'
| | +-[DOT] '.'
| | | +-[DOT] '.'
| | | | +-[IDENT] 'com'
| | | | \-[IDENT] 'mypackage'
| | | \-[IDENT] 'security'
| | \-[IDENT] 'User'
| \-[ALIAS] 'mpu'
\-[WHERE] 'WHERE'
\-[EQ] '='
+-[DOT] '.'
| +-[IDENT] 'mpu'
| \-[IDENT] 'username'
\-[PARAM] '?'
DEBUG - 2008-01-18 10:30:26,595 (ErrorCounter.java:68)
throwQueryException() : no errors
DEBUG - 2008-01-18 10:30:26,642 (HqlSqlBaseWalker.java:111)
select << begin [level=1, statement=select]
DEBUG - 2008-01-18 10:30:26,674 (FromElement.java:108)
FromClause{level=1} : com.mypackage.security.User (mpu) -> u0_
DEBUG - 2008-01-18 10:30:26,674 (FromReferenceNode.java:51)
Resolved : mpu -> u0_.user_id
TRACE - 2008-01-18 10:30:26,674 (FromElement.java:525)
handling property dereference [com.mypackage.security.User (mpu) -> username (class)]
DEBUG - 2008-01-18 10:30:26,674 (DotNode.java:568)
getDataType() : username -> org.hibernate.type.StringType@192c4c
DEBUG - 2008-01-18 10:30:26,674 (FromReferenceNode.java:51)
Resolved : mpu.username -> u0_.handle
DEBUG - 2008-01-18 10:30:26,674 (HqlSqlBaseWalker.java:117)
select : finishing up [level=1, statement=select]
DEBUG - 2008-01-18 10:30:26,674 (HqlSqlWalker.java:509)
processQuery() : ( SELECT ( FromClause{level=1} users u0_ ) ( WHERE ( = ( u0_.handle u0_.user_id username ) ? ) ) )
DEBUG - 2008-01-18 10:30:26,689 (HqlSqlWalker.java:716)
Derived SELECT clause created.
DEBUG - 2008-01-18 10:30:26,689 (JoinProcessor.java:148)
Using FROM fragment [users u0_]
DEBUG - 2008-01-18 10:30:26,689 (HqlSqlBaseWalker.java:123)
select >> end [level=1, statement=select]
DEBUG - 2008-01-18 10:30:26,705 (QueryTranslatorImpl.java:232)
--- SQL AST ---
\-[SELECT] QueryNode: 'SELECT' querySpaces (users)
+-[SELECT_CLAUSE] SelectClause: '{derived select clause}'
| +-[SELECT_EXPR] SelectExpressionImpl: 'u0_.user_id as user1_0_' {FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=mpu,role=null,tableName=users,tableAlias=u0_,origin=null,colums={,className=com.mypackage.security.User}}}
| \-[SQL_TOKEN] SqlFragment: 'u0_.handle as handle0_, u0_.password as password0_, u0_.age as age0_, u0_.first_name as first5_0_, u0_.last_name as last6_0_, u0_.address as address0_, u0_.city as city0_, u0_.state as state0_, u0_.zip as zip0_, u0_.country as country0_, u0_.phone as phone0_, u0_.email as email0_'
+-[FROM] FromClause: 'FROM' FromClause{level=1, fromElementCounter=1, fromElements=1, fromElementByClassAlias=[mpu], fromElementByTableAlias=[u0_], fromElementsByPath=[], collectionJoinFromElementsByPath=[], impliedElements=[]}
| \-[FROM_FRAGMENT] FromElement: 'users u0_' FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=mpu,role=null,tableName=users,tableAlias=u0_,origin=null,colums={,className=com.mypackage.security.User}}
\-[WHERE] SqlNode: 'WHERE'
\-[EQ] BinaryLogicOperatorNode: '='
+-[DOT] DotNode: 'u0_.handle' {propertyName=username,dereferenceType=4,propertyPath=username,path=mpu.username,tableAlias=u0_,className=com.mypackage.security.User,classAlias=mpu}
| +-[ALIAS_REF] IdentNode: 'u0_.user_id' {alias=mpu, className=com.mypackage.security.User, tableAlias=u0_}
| \-[IDENT] IdentNode: 'username' {originalText=username}
\-[PARAM] ParameterNode: '?' {ordinal=0, expectedType=org.hibernate.type.StringType@192c4c}
DEBUG - 2008-01-18 10:30:26,705 (ErrorCounter.java:68)
throwQueryException() : no errors
DEBUG - 2008-01-18 10:30:26,720 (QueryTranslatorImpl.java:216)
HQL: FROM com.mypackage.security.User mpu WHERE mpu.username = ?
DEBUG - 2008-01-18 10:30:26,720 (QueryTranslatorImpl.java:217)
SQL: select u0_.user_id as user1_0_, u0_.handle as handle0_, u0_.password as password0_, u0_.age as age0_, u0_.first_name as first5_0_, u0_.last_name as last6_0_, u0_.address as address0_, u0_.city as city0_, u0_.state as state0_, u0_.zip as zip0_, u0_.country as country0_, u0_.phone as phone0_, u0_.email as email0_ from users u0_ where u0_.handle=?
DEBUG - 2008-01-18 10:30:26,720 (ErrorCounter.java:68)
throwQueryException() : no errors
TRACE - 2008-01-18 10:30:26,720 (HQLQueryPlan.java:269)
HQL param location recognition took 0 mills (FROM User mpu WHERE mpu.username = ?)
TRACE - 2008-01-18 10:30:26,736 (QueryPlanCache.java:76)
located HQL query plan in cache (FROM User mpu WHERE mpu.username = ?)
TRACE - 2008-01-18 10:30:26,736 (HQLQueryPlan.java:150)
find: FROM User mpu WHERE mpu.username = ?
TRACE - 2008-01-18 10:30:26,736 (QueryParameters.java:271)
parameters: [username]
TRACE - 2008-01-18 10:30:26,736 (QueryParameters.java:277)
named parameters: {}
DEBUG - 2008-01-18 10:30:26,736 (AbstractBatcher.java:366)
about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG - 2008-01-18 10:30:26,736 (ConnectionManager.java:421)
opening JDBC connection
DEBUG - 2008-01-18 10:30:26,736 (AbstractBatcher.java:401)
select u0_.user_id as user1_0_, u0_.handle as handle0_, u0_.password as password0_, u0_.age as age0_, u0_.first_name as first5_0_, u0_.last_name as last6_0_, u0_.address as address0_, u0_.city as city0_, u0_.state as state0_, u0_.zip as zip0_, u0_.country as country0_, u0_.phone as phone0_, u0_.email as email0_ from users u0_ where u0_.handle=?
Hibernate: select u0_.user_id as user1_0_, u0_.handle as handle0_, u0_.password as password0_, u0_.age as age0_, u0_.first_name as first5_0_, u0_.last_name as last6_0_, u0_.address as address0_, u0_.city as city0_, u0_.state as state0_, u0_.zip as zip0_, u0_.country as country0_, u0_.phone as phone0_, u0_.email as email0_ from users u0_ where u0_.handle=?
TRACE - 2008-01-18 10:30:26,752 (AbstractBatcher.java:484)
preparing statement
TRACE - 2008-01-18 10:30:26,752 (NullableType.java:133)
binding 'username' to parameter: 1
DEBUG - 2008-01-18 10:30:26,908 (AbstractBatcher.java:382)
about to open ResultSet (open ResultSets: 0, globally: 0)
TRACE - 2008-01-18 10:30:26,908 (Loader.java:694)
processing result set
DEBUG - 2008-01-18 10:30:26,908 (Loader.java:699)
result set row: 0
TRACE - 2008-01-18 10:30:26,908 (NullableType.java:172)
returning '11108' as column: user1_0_
DEBUG - 2008-01-18 10:30:26,908 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.User#11108]
DEBUG - 2008-01-18 10:30:26,924 (User.java:237)
Setting userId to ... 11108
TRACE - 2008-01-18 10:30:26,924 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.User#11108]
TRACE - 2008-01-18 10:30:26,924 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.User#11108]
TRACE - 2008-01-18 10:30:26,924 (NullableType.java:172)
returning 'username' as column: handle0_
TRACE - 2008-01-18 10:30:26,924 (NullableType.java:172)
returning 'password' as column: password0_
TRACE - 2008-01-18 10:30:26,924 (NullableType.java:172)
returning '29 June 1981' as column: age0_
TRACE - 2008-01-18 10:30:26,924 (NullableType.java:172)
returning 'FirstName' as column: first5_0_
TRACE - 2008-01-18 10:30:26,924 (NullableType.java:172)
returning 'LastName' as column: last6_0_
TRACE - 2008-01-18 10:30:26,924 (NullableType.java:172)
returning '777 108th Ave NE, Suite 2000' as column: address0_
TRACE - 2008-01-18 10:30:26,924 (NullableType.java:172)
returning 'City' as column: city0_
TRACE - 2008-01-18 10:30:26,924 (NullableType.java:172)
returning 'State' as column: state0_
TRACE - 2008-01-18 10:30:26,924 (NullableType.java:172)
returning '01234' as column: zip0_
TRACE - 2008-01-18 10:30:26,924 (NullableType.java:172)
returning 'US' as column: country0_
TRACE - 2008-01-18 10:30:26,924 (NullableType.java:172)
returning '123-456-7890' as column: phone0_
TRACE - 2008-01-18 10:30:26,924 (NullableType.java:172)
returning 'myemail@email.com' as column: email0_
TRACE - 2008-01-18 10:30:26,939 (Loader.java:721)
done processing result set (1 rows)
DEBUG - 2008-01-18 10:30:26,939 (AbstractBatcher.java:389)
about to close ResultSet (open ResultSets: 1, globally: 1)
DEBUG - 2008-01-18 10:30:26,939 (AbstractBatcher.java:374)
about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
TRACE - 2008-01-18 10:30:26,939 (AbstractBatcher.java:533)
closing statement
TRACE - 2008-01-18 10:30:26,939 (Loader.java:851)
total objects hydrated: 1
DEBUG - 2008-01-18 10:30:26,939 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.User#11108]
TRACE - 2008-01-18 10:30:27,064 (LoadContexts.java:183)
creating collection wrapper:[com.mypackage.security.User.roles#11108]
DEBUG - 2008-01-18 10:30:27,064 (User.java:251)
Setting username to ... username
DEBUG - 2008-01-18 10:30:27,080 (User.java:284)
Setting birthDate to ... 1981-06-29
TRACE - 2008-01-18 10:30:27,080 (DefaultInitializeCollectionEventListener.java:41)
initializing collection [com.mypackage.security.User.roles#11108]
TRACE - 2008-01-18 10:30:27,080 (DefaultInitializeCollectionEventListener.java:47)
checking second-level cache
TRACE - 2008-01-18 10:30:27,080 (DefaultInitializeCollectionEventListener.java:59)
collection not cached
DEBUG - 2008-01-18 10:30:27,080 (NamedQueryCollectionInitializer.java:34)
initializing collection: com.mypackage.security.User.roles using named query: GetUserRoles
TRACE - 2008-01-18 10:30:27,080 (SessionImpl.java:1289)
setting flush mode to: MANUAL
TRACE - 2008-01-18 10:30:27,080 (QueryPlanCache.java:118)
located native-sql query plan in cache ({ call getUserRoles( ? ) })
TRACE - 2008-01-18 10:30:27,080 (SessionImpl.java:1685)
SQL query: { call getUserRoles( ? ) }
DEBUG - 2008-01-18 10:30:27,095 (AbstractBatcher.java:366)
about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG - 2008-01-18 10:30:27,095 (AbstractBatcher.java:401)
{ call getUserRoles( ? ) }
Hibernate: { call getUserRoles( ? ) }
TRACE - 2008-01-18 10:30:27,095 (AbstractBatcher.java:484)
preparing statement
TRACE - 2008-01-18 10:30:27,095 (NullableType.java:133)
binding '11108' to parameter: 1
DEBUG - 2008-01-18 10:30:27,095 (AbstractBatcher.java:382)
about to open ResultSet (open ResultSets: 0, globally: 0)
TRACE - 2008-01-18 10:30:27,095 (Loader.java:694)
processing result set
DEBUG - 2008-01-18 10:30:27,111 (Loader.java:699)
result set row: 0
TRACE - 2008-01-18 10:30:27,111 (NullableType.java:172)
returning '1' as column: id
DEBUG - 2008-01-18 10:30:27,111 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#1]
TRACE - 2008-01-18 10:30:27,111 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#1]
TRACE - 2008-01-18 10:30:27,111 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#1]
TRACE - 2008-01-18 10:30:27,111 (NullableType.java:172)
returning 'user' as column: name
DEBUG - 2008-01-18 10:30:27,111 (Loader.java:699)
result set row: 1
TRACE - 2008-01-18 10:30:27,111 (NullableType.java:172)
returning '2' as column: id
DEBUG - 2008-01-18 10:30:27,111 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#2]
TRACE - 2008-01-18 10:30:27,111 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#2]
TRACE - 2008-01-18 10:30:27,111 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#2]
TRACE - 2008-01-18 10:30:27,111 (NullableType.java:172)
returning 'prof' as column: name
DEBUG - 2008-01-18 10:30:27,111 (Loader.java:699)
result set row: 2
TRACE - 2008-01-18 10:30:27,111 (NullableType.java:172)
returning '3' as column: id
DEBUG - 2008-01-18 10:30:27,111 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#3]
TRACE - 2008-01-18 10:30:27,111 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#3]
TRACE - 2008-01-18 10:30:27,127 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#3]
TRACE - 2008-01-18 10:30:27,127 (NullableType.java:172)
returning 'lead' as column: name
DEBUG - 2008-01-18 10:30:27,127 (Loader.java:699)
result set row: 3
TRACE - 2008-01-18 10:30:27,127 (NullableType.java:172)
returning '4' as column: id
DEBUG - 2008-01-18 10:30:27,127 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#4]
TRACE - 2008-01-18 10:30:27,127 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#4]
TRACE - 2008-01-18 10:30:27,127 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#4]
TRACE - 2008-01-18 10:30:27,127 (NullableType.java:172)
returning 'owner' as column: name
DEBUG - 2008-01-18 10:30:27,127 (Loader.java:699)
result set row: 4
TRACE - 2008-01-18 10:30:27,127 (NullableType.java:172)
returning '5' as column: id
DEBUG - 2008-01-18 10:30:27,127 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#5]
TRACE - 2008-01-18 10:30:27,127 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#5]
TRACE - 2008-01-18 10:30:27,127 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#5]
TRACE - 2008-01-18 10:30:27,127 (NullableType.java:172)
returning 'org' as column: name
DEBUG - 2008-01-18 10:30:27,127 (Loader.java:699)
result set row: 5
TRACE - 2008-01-18 10:30:27,127 (NullableType.java:172)
returning '6' as column: id
DEBUG - 2008-01-18 10:30:27,127 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#6]
TRACE - 2008-01-18 10:30:27,127 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#6]
TRACE - 2008-01-18 10:30:27,127 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#6]
TRACE - 2008-01-18 10:30:27,127 (NullableType.java:172)
returning 'new_org' as column: name
DEBUG - 2008-01-18 10:30:27,127 (Loader.java:699)
result set row: 6
TRACE - 2008-01-18 10:30:27,127 (NullableType.java:172)
returning '7' as column: id
DEBUG - 2008-01-18 10:30:27,127 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#7]
TRACE - 2008-01-18 10:30:27,127 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#7]
TRACE - 2008-01-18 10:30:27,127 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#7]
TRACE - 2008-01-18 10:30:27,142 (NullableType.java:172)
returning 'reg_org' as column: name
DEBUG - 2008-01-18 10:30:27,142 (Loader.java:699)
result set row: 7
TRACE - 2008-01-18 10:30:27,142 (NullableType.java:172)
returning '8' as column: id
DEBUG - 2008-01-18 10:30:27,142 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#8]
TRACE - 2008-01-18 10:30:27,142 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#8]
TRACE - 2008-01-18 10:30:27,142 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#8]
TRACE - 2008-01-18 10:30:27,142 (NullableType.java:172)
returning 'ex_org' as column: name
DEBUG - 2008-01-18 10:30:27,142 (Loader.java:699)
result set row: 8
TRACE - 2008-01-18 10:30:27,142 (NullableType.java:172)
returning '9' as column: id
DEBUG - 2008-01-18 10:30:27,142 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#9]
TRACE - 2008-01-18 10:30:27,142 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#9]
TRACE - 2008-01-18 10:30:27,142 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#9]
TRACE - 2008-01-18 10:30:27,142 (NullableType.java:172)
returning 'pto' as column: name
DEBUG - 2008-01-18 10:30:27,142 (Loader.java:699)
result set row: 9
TRACE - 2008-01-18 10:30:27,142 (NullableType.java:172)
returning '10' as column: id
DEBUG - 2008-01-18 10:30:27,142 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#10]
TRACE - 2008-01-18 10:30:27,142 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#10]
TRACE - 2008-01-18 10:30:27,142 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#10]
TRACE - 2008-01-18 10:30:27,142 (NullableType.java:172)
returning 'parent' as column: name
DEBUG - 2008-01-18 10:30:27,142 (Loader.java:699)
result set row: 10
TRACE - 2008-01-18 10:30:27,142 (NullableType.java:172)
returning '11' as column: id
DEBUG - 2008-01-18 10:30:27,142 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#11]
TRACE - 2008-01-18 10:30:27,142 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#11]
TRACE - 2008-01-18 10:30:27,142 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#11]
TRACE - 2008-01-18 10:30:27,142 (NullableType.java:172)
returning 'data' as column: name
DEBUG - 2008-01-18 10:30:27,142 (Loader.java:699)
result set row: 11
TRACE - 2008-01-18 10:30:27,142 (NullableType.java:172)
returning '12' as column: id
DEBUG - 2008-01-18 10:30:27,142 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#12]
TRACE - 2008-01-18 10:30:27,142 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#12]
TRACE - 2008-01-18 10:30:27,142 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#12]
TRACE - 2008-01-18 10:30:27,142 (NullableType.java:172)
returning 'admin' as column: name
DEBUG - 2008-01-18 10:30:27,142 (Loader.java:699)
result set row: 12
TRACE - 2008-01-18 10:30:27,142 (NullableType.java:172)
returning '13' as column: id
DEBUG - 2008-01-18 10:30:27,158 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#13]
TRACE - 2008-01-18 10:30:27,158 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#13]
TRACE - 2008-01-18 10:30:27,158 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#13]
TRACE - 2008-01-18 10:30:27,158 (NullableType.java:172)
returning 'prof_a' as column: name
DEBUG - 2008-01-18 10:30:27,158 (Loader.java:699)
result set row: 13
TRACE - 2008-01-18 10:30:27,158 (NullableType.java:172)
returning '17' as column: id
DEBUG - 2008-01-18 10:30:27,158 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#17]
TRACE - 2008-01-18 10:30:27,158 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#17]
TRACE - 2008-01-18 10:30:27,158 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#17]
TRACE - 2008-01-18 10:30:27,158 (NullableType.java:172)
returning 'leag_a' as column: name
DEBUG - 2008-01-18 10:30:27,158 (Loader.java:699)
result set row: 14
TRACE - 2008-01-18 10:30:27,158 (NullableType.java:172)
returning '18' as column: id
DEBUG - 2008-01-18 10:30:27,158 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#18]
TRACE - 2008-01-18 10:30:27,158 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#18]
TRACE - 2008-01-18 10:30:27,158 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#18]
TRACE - 2008-01-18 10:30:27,158 (NullableType.java:172)
returning 'super' as column: name
DEBUG - 2008-01-18 10:30:27,158 (Loader.java:699)
result set row: 15
TRACE - 2008-01-18 10:30:27,158 (NullableType.java:172)
returning '19' as column: id
DEBUG - 2008-01-18 10:30:27,158 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#19]
TRACE - 2008-01-18 10:30:27,158 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#19]
TRACE - 2008-01-18 10:30:27,158 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#19]
TRACE - 2008-01-18 10:30:27,158 (NullableType.java:172)
returning 'to_a' as column: name
DEBUG - 2008-01-18 10:30:27,174 (Loader.java:699)
result set row: 16
TRACE - 2008-01-18 10:30:27,174 (NullableType.java:172)
returning '20' as column: id
DEBUG - 2008-01-18 10:30:27,174 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#20]
TRACE - 2008-01-18 10:30:27,174 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#20]
TRACE - 2008-01-18 10:30:27,174 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#20]
TRACE - 2008-01-18 10:30:27,174 (NullableType.java:172)
returning 'intl_a' as column: name
DEBUG - 2008-01-18 10:30:27,174 (Loader.java:699)
result set row: 17
TRACE - 2008-01-18 10:30:27,174 (NullableType.java:172)
returning '23' as column: id
DEBUG - 2008-01-18 10:30:27,174 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#23]
TRACE - 2008-01-18 10:30:27,174 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#23]
TRACE - 2008-01-18 10:30:27,174 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#23]
TRACE - 2008-01-18 10:30:27,174 (NullableType.java:172)
returning 'fulfil_a' as column: name
DEBUG - 2008-01-18 10:30:27,174 (Loader.java:699)
result set row: 18
TRACE - 2008-01-18 10:30:27,174 (NullableType.java:172)
returning '25' as column: id
DEBUG - 2008-01-18 10:30:27,174 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#25]
TRACE - 2008-01-18 10:30:27,174 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#25]
TRACE - 2008-01-18 10:30:27,174 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#25]
TRACE - 2008-01-18 10:30:27,174 (NullableType.java:172)
returning 'reward_a' as column: name
DEBUG - 2008-01-18 10:30:27,174 (Loader.java:699)
result set row: 19
TRACE - 2008-01-18 10:30:27,174 (NullableType.java:172)
returning '26' as column: id
DEBUG - 2008-01-18 10:30:27,174 (Loader.java:1173)
result row: EntityKey[com.mypackage.security.Role#26]
TRACE - 2008-01-18 10:30:27,174 (Loader.java:1355)
Initializing object from ResultSet: [com.mypackage.security.Role#26]
TRACE - 2008-01-18 10:30:27,174 (AbstractEntityPersister.java:2031)
Hydrating entity: [com.mypackage.security.Role#26]
TRACE - 2008-01-18 10:30:27,174 (NullableType.java:172)
returning 'role_a' as column: name
TRACE - 2008-01-18 10:30:27,174 (Loader.java:721)
done processing result set (20 rows)
DEBUG - 2008-01-18 10:30:27,174 (AbstractBatcher.java:389)
about to close ResultSet (open ResultSets: 1, globally: 1)
DEBUG - 2008-01-18 10:30:27,174 (AbstractBatcher.java:374)
about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
TRACE - 2008-01-18 10:30:27,174 (AbstractBatcher.java:533)
closing statement
TRACE - 2008-01-18 10:30:27,174 (Loader.java:851)
total objects hydrated: 20
DEBUG - 2008-01-18 10:30:27,174 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#1]
DEBUG - 2008-01-18 10:30:27,174 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#1]
DEBUG - 2008-01-18 10:30:27,174 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#2]
DEBUG - 2008-01-18 10:30:27,174 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#2]
DEBUG - 2008-01-18 10:30:27,174 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#3]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#3]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#4]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#4]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#5]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#5]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#6]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#6]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#7]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#7]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#8]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#8]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#9]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#9]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#10]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#10]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#11]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#11]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#12]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#12]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#13]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#13]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#17]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#17]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#18]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#18]
DEBUG - 2008-01-18 10:30:27,189 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#19]
DEBUG - 2008-01-18 10:30:27,205 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#19]
DEBUG - 2008-01-18 10:30:27,205 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#20]
DEBUG - 2008-01-18 10:30:27,205 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#20]
DEBUG - 2008-01-18 10:30:27,205 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#23]
DEBUG - 2008-01-18 10:30:27,205 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#23]
DEBUG - 2008-01-18 10:30:27,205 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#25]
DEBUG - 2008-01-18 10:30:27,205 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#25]
DEBUG - 2008-01-18 10:30:27,205 (TwoPhaseLoad.java:107)
resolving associations for [com.mypackage.security.Role#26]
DEBUG - 2008-01-18 10:30:27,205 (TwoPhaseLoad.java:206)
done materializing entity [com.mypackage.security.Role#26]
TRACE - 2008-01-18 10:30:27,205 (JDBCContext.java:233)
after autocommit
DEBUG - 2008-01-18 10:30:27,205 (ConnectionManager.java:302)
transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!
TRACE - 2008-01-18 10:30:27,205 (SessionImpl.java:422)
after transaction completion
TRACE - 2008-01-18 10:30:27,205 (SessionImpl.java:1289)
setting flush mode to: AUTO
TRACE - 2008-01-18 10:30:27,205 (DefaultInitializeCollectionEventListener.java:61)
collection initialized
TRACE - 2008-01-18 10:30:27,220 (JDBCContext.java:233)
after autocommit
DEBUG - 2008-01-18 10:30:27,220 (ConnectionManager.java:302)
transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!
TRACE - 2008-01-18 10:30:27,220 (SessionImpl.java:422)
after transaction completion
DEBUG - 2008-01-18 10:30:27,220 (HttpSessionContextIntegrationFilter.java:269)
SecurityContextHolder now cleared, as request processing completed