The debug below (see the end) shows that the query for user_permissions returns 2 collections, for some reason. Presumably the correct one is overwritten by the erroneous collection.
Code:
09:36:54,500 DEBUG SQL:237 - select user0_.user_id as user_id0_, user0_.version as version0_, user0_.password as password0_, user0_.enabled_flag as enabled_4_0_, user0_.passwd_expire_date as passwd_e5_0_, user0_.start_dtime as start_dt6_0_, user0_.end_dtime as end_dtime0_, user0_.login_failures as login_fa8_0_ from user user0_ where user0_.user_id=?
Hibernate: select user0_.user_id as user_id0_, user0_.version as version0_, user0_.password as password0_, user0_.enabled_flag as enabled_4_0_, user0_.passwd_expire_date as passwd_e5_0_, user0_.start_dtime as start_dt6_0_, user0_.end_dtime as end_dtime0_, user0_.login_failures as login_fa8_0_ from user user0_ where user0_.user_id=?
09:36:54,500 DEBUG BatcherImpl:241 - preparing statement
09:36:54,546 DEBUG StringType:46 - binding 'owenrh' to parameter: 1
09:36:54,609 DEBUG Loader:197 - processing result set
09:36:54,609 DEBUG Loader:405 - result row: owenrh
09:36:54,609 DEBUG Loader:536 - Initializing object from ResultSet: owenrh
09:36:54,609 DEBUG Loader:605 - Hydrating entity: adaptation.user.User#owenrh
09:36:54,609 DEBUG IntegerType:68 - returning '24' as column: version0_
09:36:54,609 DEBUG StringType:68 - returning 'owen' as column: password0_
09:36:54,625 DEBUG YesNoType:68 - returning 'true' as column: enabled_4_0_
09:36:54,625 DEBUG TimestampType:64 - returning null as column: passwd_e5_0_
09:36:54,625 DEBUG TimestampType:64 - returning null as column: start_dt6_0_
09:36:54,625 DEBUG TimestampType:64 - returning null as column: end_dtime0_
09:36:54,625 DEBUG IntegerType:68 - returning '0' as column: login_fa8_0_
09:36:54,625 DEBUG SessionImpl:1874 - Version: 24
09:36:54,640 DEBUG Loader:226 - done processing result set (1 rows)
09:36:54,656 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
09:36:54,671 DEBUG BatcherImpl:261 - closing statement
09:36:54,687 DEBUG Loader:239 - total objects hydrated: 1
09:36:54,687 DEBUG SessionImpl:2166 - resolving associations for [adaptation.user.User#owenrh]
09:36:54,687 DEBUG SessionImpl:3891 - creating collection wrapper:[adaptation.user.User.permissions#owenrh]
09:36:54,687 DEBUG SessionImpl:3218 - initializing collection [adaptation.user.User.permissions#owenrh]
09:36:54,687 DEBUG SessionImpl:3219 - checking second-level cache
09:36:54,687 DEBUG ReadWriteCache:68 - Cache lookup: owenrh
09:36:54,687 DEBUG ReadWriteCache:84 - Cache miss: owenrh
09:36:54,687 DEBUG SessionImpl:3225 - collection not cached
09:36:54,703 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
09:36:54,703 DEBUG SQL:237 - select permission0_.permission as permission__, permission0_.user_id as user_id__ from user_permission permission0_ where permission0_.user_id=?
Hibernate: select permission0_.permission as permission__, permission0_.user_id as user_id__ from user_permission permission0_ where permission0_.user_id=?
09:36:54,703 DEBUG BatcherImpl:241 - preparing statement
09:36:54,718 DEBUG StringType:46 - binding 'owenrh' to parameter: 1
09:36:54,765 DEBUG Loader:327 - result set contains (possibly empty) collection: [adaptation.user.User.permissions#owenrh]
09:36:54,765 DEBUG SessionImpl:2984 - uninitialized collection: initializing
09:36:54,765 DEBUG Loader:197 - processing result set
09:36:54,765 DEBUG Loader:405 - result row:
09:36:54,765 DEBUG StringType:68 - returning 'owenrh ' as column: user_id__
09:36:54,765 DEBUG Loader:292 - found row of collection: [adaptation.user.User.permissions#owenrh ]
09:36:54,765 DEBUG SessionImpl:2996 - new collection: instantiating
09:36:54,765 DEBUG StringType:68 - returning 'ROLE_SUPERVISOR' as column: permission__
09:36:54,796 DEBUG Loader:226 - done processing result set (1 rows)
09:36:54,812 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
09:36:54,812 DEBUG BatcherImpl:261 - closing statement
09:36:54,828 DEBUG SessionImpl:3043 - 2 collections were found in result set
09:36:54,828 DEBUG SessionImpl:3057 - Caching collection: [adaptation.user.User.permissions#owenrh]
09:36:54,828 DEBUG ReadWriteCache:132 - Caching: owenrh
09:36:54,843 DEBUG ReadWriteCache:143 - Cached: owenrh
09:36:54,843 DEBUG SessionImpl:3061 - collection fully initialized: [adaptation.user.User.permissions#owenrh]
09:36:54,843 DEBUG SessionImpl:3057 - Caching collection: [adaptation.user.User.permissions#owenrh ]
09:36:54,843 DEBUG ReadWriteCache:132 - Caching: owenrh
09:36:54,843 DEBUG ReadWriteCache:143 - Cached: owenrh
09:36:54,843 DEBUG SessionImpl:3061 - collection fully initialized: [adaptation.user.User.permissions#owenrh ]
09:36:54,843 DEBUG SessionImpl:3064 - 2 collections initialized
09:36:54,843 DEBUG SessionImpl:3227 - collection initialized
Permission size on setPermissions call is --->0