i just isntalled acegi yesterday, and now i have been noticing Hibernate log entries that say "Unclosed Connection". Anybody else seen this before? As a result of this (I assume), HTTP request begin to stall (freezing) during a query for the user account (its a hibernate DAO query).
I am using spring 1.1, hibernate 2.1.6, acegi 0.8.1.
Here is a snipet from my log where it shows a WARN log message that there was an unclosed session.
Here is a snipet of where an unclose session message appearsCode:[DEBUG][net.sf.acegisecurity.intercept.AbstractSecurityInterceptor] - Authenticated: net.sf.acegisecurity.providers.UsernamePasswordAuthenticationToken@f3d040: Username: com.ccg.domain.Account@3b5d6b[id=1,u....security.Group@1e668b2[id=1,name=Users,description=Intranet Application User,roles=[com.ccg.security.Role@1523624]]]]; Password: [PROTECTED]; Authenticated: true; Details: net.sf.acegisecurity.ui.WebAuthenticationDetails@1aa38c7: RemoteIpAddress: 127.0.0.1; SessionId: 5E2D43C38FC1C20DC88CFE0C69121D19; Granted Authorities: ROLE_USER [DEBUG][net.sf.acegisecurity.intercept.AbstractSecurityInterceptor] - Authorization successful [DEBUG][net.sf.acegisecurity.intercept.AbstractSecurityInterceptor] - RunAsManager did not change Authentication object [DEBUG][net.sf.hibernate.impl.SessionImpl] - opened session [DEBUG][net.sf.hibernate.transaction.JDBCTransaction] - begin [DEBUG][net.sf.hibernate.transaction.JDBCTransaction] - current autocommit status:true [DEBUG][net.sf.hibernate.transaction.JDBCTransaction] - disabling autocommit [DEBUG][net.sf.hibernate.impl.SessionImpl] - flushing session [DEBUG][net.sf.hibernate.impl.SessionImpl] - Flushing entities and processing referenced collections [DEBUG][net.sf.hibernate.impl.SessionImpl] - Processing unreferenced collections [DEBUG][net.sf.hibernate.impl.SessionImpl] - Scheduling collection removes/(re)creates/updates [DEBUG][net.sf.hibernate.impl.SessionImpl] - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects [DEBUG][net.sf.hibernate.impl.SessionImpl] - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections [DEBUG][net.sf.hibernate.impl.SessionImpl] - Dont need to execute flush [DEBUG][net.sf.hibernate.impl.BatcherImpl] - about to open: 0 open PreparedStatements, 0 open ResultSets [DEBUG][net.sf.hibernate.impl.BatcherImpl] - select this.id as id0_, this.name as name0_, this.code as code0_, this.clientRoot as clientRoot0_, this.drive as drive0_, this.rootLinuxPath as rootLinu6_0_, this.rootWindowsPath as rootWind7_0_ from client this where 1=1 [DEBUG][net.sf.hibernate.impl.BatcherImpl] - preparing statement [DEBUG][net.sf.hibernate.impl.SessionImpl] - running Session.finalize() [WARN ][net.sf.hibernate.impl.SessionImpl] - finalizing unclosed session with closed connection [DEBUG][net.sf.hibernate.loader.Loader] - processing result set [DEBUG][net.sf.hibernate.type.NullableType] - returning '1' as column: id0_ [DEBUG][net.sf.hibernate.loader.Loader] - result row: 1 [DEBUG][net.sf.hibernate.loader.Loader] - Initializing object from ResultSet: 1 [DEBUG][net.sf.hibernate.loader.Loader] - Hydrating entity: com.ccg.domain.Client#1 [DEBUG][net.sf.hibernate.type.NullableType] - returning 'Best Buy' as column: name0_ [DEBUG][net.sf.hibernate.type.NullableType] - returning 'BTBY' as column: code0_ [DEBUG][net.sf.hibernate.type.NullableType] - returning 'BTBY - Best Buy' as column: clientRoot0_ [DEBUG][net.sf.hibernate.type.NullableType] - returning 'I:' as column: drive0_ [DEBUG][net.sf.hibernate.type.NullableType] - returning '/var/intranet_files' as column: rootLinu6_0_ [DEBUG][net.sf.hibernate.type.NullableType] - returning 'INTRANET V6/CLIENTS' as column: rootWind7_0_ [DEBUG][net.sf.hibernate.type.NullableType] - returning '2' as column: id0_ [DEBUG][net.sf.hibernate.loader.Loader] - result row: 2 [DEBUG][net.sf.hibernate.loader.Loader] - Initializing object from ResultSet: 2 [DEBUG][net.sf.hibernate.loader.Loader] - Hydrating entity: com.ccg.domain.Client#2
Whats going on here?Code:[DEBUG][net.sf.acegisecurity.context.HttpSessionContextIntegrationFilter] - Obtained from ACEGI_SECURITY_CONTEXT a valid Context and set to ContextHolder: 'net.sf.acegisecurity.context.security.SecureContextImpl@e335ef: Authentication: net.sf.acegisecurity.providers.UsernamePasswordAuthenticationToken@fa1477: Username: com.ccg.domain.Account@9530a5[id=1,u....security.Group@f28c1f[id=1,name=Users,description=Intranet Application User,roles=[com.ccg.security.Role@8629d1]]]]; Password: [PROTECTED]; Authenticated: true; Details: net.sf.acegisecurity.ui.WebAuthenticationDetails@1aa38c7: RemoteIpAddress: 127.0.0.1; SessionId: 5E2D43C38FC1C20DC88CFE0C69121D19; Granted Authorities: ROLE_USER' [DEBUG][net.sf.acegisecurity.providers.anonymous.AnonymousProcessingFilter] - ContextHolder not replaced with anonymous token, as ContextHolder already contained: 'net.sf.acegisecurity.providers.UsernamePasswordAuthenticationToken@fa1477: Username: com.ccg.domain.Account@9530a5[id=1,u....security.Group@f28c1f[id=1,name=Users,description=Intranet Application User,roles=[com.ccg.security.Role@8629d1]]]]; Password: [PROTECTED]; Authenticated: true; Details: net.sf.acegisecurity.ui.WebAuthenticationDetails@1aa38c7: RemoteIpAddress: 127.0.0.1; SessionId: 5E2D43C38FC1C20DC88CFE0C69121D19; Granted Authorities: ROLE_USER' [DEBUG][net.sf.acegisecurity.intercept.web.PathBasedFilterInvocationDefinitionMap] - Converted URL to lowercase, from: '/list_zones_ez.html'; to: '/list_zones_ez.html' [DEBUG][net.sf.acegisecurity.intercept.web.PathBasedFilterInvocationDefinitionMap] - Candidate is: '/list_zones_ez.html'; pattern is /signon.html*; matched=false [DEBUG][net.sf.acegisecurity.intercept.web.PathBasedFilterInvocationDefinitionMap] - Candidate is: '/list_zones_ez.html'; pattern is /welcome.html; matched=false [DEBUG][net.sf.acegisecurity.intercept.web.PathBasedFilterInvocationDefinitionMap] - Candidate is: '/list_zones_ez.html'; pattern is /reference.html; matched=false [DEBUG][net.sf.acegisecurity.intercept.web.PathBasedFilterInvocationDefinitionMap] - Candidate is: '/list_zones_ez.html'; pattern is /styles/**; matched=false [DEBUG][net.sf.acegisecurity.intercept.web.PathBasedFilterInvocationDefinitionMap] - Candidate is: '/list_zones_ez.html'; pattern is /images/**; matched=false [DEBUG][net.sf.acegisecurity.intercept.web.PathBasedFilterInvocationDefinitionMap] - Candidate is: '/list_zones_ez.html'; pattern is /**; matched=true [DEBUG][net.sf.acegisecurity.intercept.AbstractSecurityInterceptor] - Secure object: FilterInvocation: URL: /list_zones_ez.html; ConfigAttributes: [ROLE_USER] [DEBUG][net.sf.acegisecurity.providers.ProviderManager] - Authentication attempt using net.sf.acegisecurity.providers.dao.DaoAuthenticationProvider [DEBUG][net.sf.hibernate.impl.SessionImpl] - opened session [DEBUG][net.sf.hibernate.impl.SessionImpl] - flushing session [DEBUG][net.sf.hibernate.impl.SessionImpl] - Flushing entities and processing referenced collections [DEBUG][net.sf.hibernate.impl.SessionImpl] - Processing unreferenced collections [DEBUG][net.sf.hibernate.impl.SessionImpl] - Scheduling collection removes/(re)creates/updates [DEBUG][net.sf.hibernate.impl.SessionImpl] - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects [DEBUG][net.sf.hibernate.impl.SessionImpl] - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections [DEBUG][net.sf.hibernate.impl.SessionImpl] - Dont need to execute flush [DEBUG][net.sf.hibernate.impl.BatcherImpl] - about to open: 0 open PreparedStatements, 0 open ResultSets [DEBUG][net.sf.hibernate.impl.BatcherImpl] - select this.id as id0_, this.username as username0_, this.password as password0_, this.accountNonLocked as accountN4_0_, this.enabled as enabled0_ from account this where this.username=? [DEBUG][net.sf.hibernate.impl.BatcherImpl] - preparing statement [DEBUG][net.sf.hibernate.type.NullableType] - binding 'jvargas' to parameter: 1 [DEBUG][net.sf.hibernate.loader.Loader] - processing result set [DEBUG][net.sf.hibernate.type.NullableType] - returning '1' as column: id0_ [DEBUG][net.sf.hibernate.loader.Loader] - result row: 1 [DEBUG][net.sf.hibernate.loader.Loader] - Initializing object from ResultSet: 1 [DEBUG][net.sf.hibernate.loader.Loader] - Hydrating entity: com.ccg.domain.Account#1 [DEBUG][net.sf.hibernate.type.NullableType] - returning 'jvargas' as column: username0_ [DEBUG][net.sf.hibernate.type.NullableType] - returning 'jvargas' as column: password0_ [DEBUG][net.sf.hibernate.type.NullableType] - returning 'true' as column: accountN4_0_ [DEBUG][net.sf.hibernate.type.NullableType] - returning 'true' as column: enabled0_ [DEBUG][net.sf.hibernate.loader.Loader] - done processing result set (1 rows) [DEBUG][net.sf.hibernate.impl.BatcherImpl] - done closing: 0 open PreparedStatements, 0 open ResultSets [DEBUG][net.sf.hibernate.impl.BatcherImpl] - closing statement [DEBUG][net.sf.hibernate.loader.Loader] - total objects hydrated: 1 [DEBUG][net.sf.hibernate.impl.SessionImpl] - resolving associations for [com.ccg.domain.Account#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - creating collection wrapper:[com.ccg.domain.Account.groups#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - done materializing entity [com.ccg.domain.Account#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - initializing non-lazy collections [DEBUG][net.sf.hibernate.impl.SessionImpl] - initializing collection [com.ccg.domain.Account.groups#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - checking second-level cache [DEBUG][net.sf.hibernate.impl.SessionImpl] - collection not cached [DEBUG][net.sf.hibernate.impl.BatcherImpl] - about to open: 0 open PreparedStatements, 0 open ResultSets [DEBUG][net.sf.hibernate.impl.BatcherImpl] - select groups0_.accountId as accountId__, groups0_.groupId as groupId__, group1_.id as id0_, group1_.description as descript2_0_, group1_.name as name0_ from account_securityGroup groups0_ inner join securityGroup group1_ on groups0_.groupId=group1_.id where groups0_.accountId=? [DEBUG][net.sf.hibernate.impl.BatcherImpl] - preparing statement [DEBUG][net.sf.hibernate.type.NullableType] - binding '1' to parameter: 1 [DEBUG][net.sf.hibernate.loader.Loader] - result set contains (possibly empty) collection: [com.ccg.domain.Account.groups#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - uninitialized collection: initializing [DEBUG][net.sf.hibernate.loader.Loader] - processing result set [DEBUG][net.sf.hibernate.type.NullableType] - returning '1' as column: id0_ [DEBUG][net.sf.hibernate.loader.Loader] - result row: 1 [DEBUG][net.sf.hibernate.loader.Loader] - Initializing object from ResultSet: 1 [DEBUG][net.sf.hibernate.loader.Loader] - Hydrating entity: com.ccg.security.Group#1 [DEBUG][net.sf.hibernate.type.NullableType] - returning 'Intranet Application User' as column: descript2_0_ [DEBUG][net.sf.hibernate.type.NullableType] - returning 'Users' as column: name0_ [DEBUG][net.sf.hibernate.type.NullableType] - returning '1' as column: accountId__ [DEBUG][net.sf.hibernate.loader.Loader] - found row of collection: [com.ccg.domain.Account.groups#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - reading row [DEBUG][net.sf.hibernate.type.NullableType] - returning '1' as column: groupId__ [DEBUG][net.sf.hibernate.impl.SessionImpl] - loading [com.ccg.security.Group#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.ccg.security.Group#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.ccg.security.Group#1] [DEBUG][net.sf.hibernate.loader.Loader] - done processing result set (1 rows) [DEBUG][net.sf.hibernate.impl.BatcherImpl] - done closing: 0 open PreparedStatements, 0 open ResultSets [DEBUG][net.sf.hibernate.impl.BatcherImpl] - closing statement [DEBUG][net.sf.hibernate.loader.Loader] - total objects hydrated: 1 [DEBUG][net.sf.hibernate.impl.SessionImpl] - resolving associations for [com.ccg.security.Group#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - creating collection wrapper:[com.ccg.security.Group.accounts#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - creating collection wrapper:[com.ccg.security.Group.roles#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - done materializing entity [com.ccg.security.Group#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - 1 collections were found in result set [DEBUG][net.sf.hibernate.impl.SessionImpl] - collection fully initialized: [com.ccg.domain.Account.groups#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - 1 collections initialized [DEBUG][net.sf.hibernate.impl.SessionImpl] - collection initialized [DEBUG][net.sf.hibernate.impl.SessionImpl] - initializing collection [com.ccg.security.Group.roles#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - checking second-level cache [DEBUG][net.sf.hibernate.impl.SessionImpl] - collection not cached [DEBUG][net.sf.hibernate.impl.BatcherImpl] - about to open: 0 open PreparedStatements, 0 open ResultSets [DEBUG][net.sf.hibernate.impl.BatcherImpl] - select roles0_.groupId as groupId__, roles0_.roleId as roleId__, role1_.id as id0_, role1_.description as descript2_0_, role1_.value as value0_ from securityGroup_securityRole roles0_ inner join securityRole role1_ on roles0_.roleId=role1_.id where roles0_.groupId=? [DEBUG][net.sf.hibernate.impl.BatcherImpl] - preparing statement [DEBUG][net.sf.hibernate.type.NullableType] - binding '1' to parameter: 1 [DEBUG][net.sf.hibernate.loader.Loader] - result set contains (possibly empty) collection: [com.ccg.security.Group.roles#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - uninitialized collection: initializing [DEBUG][net.sf.hibernate.loader.Loader] - processing result set [DEBUG][net.sf.hibernate.type.NullableType] - returning '1' as column: id0_ [DEBUG][net.sf.hibernate.loader.Loader] - result row: 1 [DEBUG][net.sf.hibernate.loader.Loader] - Initializing object from ResultSet: 1 [DEBUG][net.sf.hibernate.loader.Loader] - Hydrating entity: com.ccg.security.Role#1 [DEBUG][net.sf.hibernate.type.NullableType] - returning 'User' as column: descript2_0_ [DEBUG][net.sf.hibernate.type.NullableType] - returning 'ROLE_USER' as column: value0_ [DEBUG][net.sf.hibernate.type.NullableType] - returning '1' as column: groupId__ [DEBUG][net.sf.hibernate.loader.Loader] - found row of collection: [com.ccg.security.Group.roles#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - reading row [DEBUG][net.sf.hibernate.type.NullableType] - returning '1' as column: roleId__ [DEBUG][net.sf.hibernate.impl.SessionImpl] - loading [com.ccg.security.Role#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.ccg.security.Role#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.ccg.security.Role#1] [DEBUG][net.sf.hibernate.loader.Loader] - done processing result set (1 rows) [DEBUG][net.sf.hibernate.impl.BatcherImpl] - done closing: 0 open PreparedStatements, 0 open ResultSets [DEBUG][net.sf.hibernate.impl.BatcherImpl] - closing statement [DEBUG][net.sf.hibernate.loader.Loader] - total objects hydrated: 1 [DEBUG][net.sf.hibernate.impl.SessionImpl] - resolving associations for [com.ccg.security.Role#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - done materializing entity [com.ccg.security.Role#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - 1 collections were found in result set [DEBUG][net.sf.hibernate.impl.SessionImpl] - collection fully initialized: [com.ccg.security.Group.roles#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - 1 collections initialized [DEBUG][net.sf.hibernate.impl.SessionImpl] - collection initialized [DEBUG][net.sf.hibernate.impl.SessionImpl] - initializing collection [com.ccg.security.Group.accounts#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - checking second-level cache [DEBUG][net.sf.hibernate.impl.SessionImpl] - collection not cached [DEBUG][net.sf.hibernate.impl.BatcherImpl] - about to open: 0 open PreparedStatements, 0 open ResultSets [DEBUG][net.sf.hibernate.impl.BatcherImpl] - select accounts0_.groupId as groupId__, accounts0_.accountId as accountId__, account1_.id as id0_, account1_.username as username0_, account1_.password as password0_, account1_.accountNonLocked as accountN4_0_, account1_.enabled as enabled0_ from account_securityGroup accounts0_ inner join account account1_ on accounts0_.accountId=account1_.id where accounts0_.groupId=? [DEBUG][net.sf.hibernate.impl.BatcherImpl] - preparing statement [DEBUG][net.sf.hibernate.type.NullableType] - binding '1' to parameter: 1 [DEBUG][net.sf.hibernate.loader.Loader] - result set contains (possibly empty) collection: [com.ccg.security.Group.accounts#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - uninitialized collection: initializing [DEBUG][net.sf.hibernate.loader.Loader] - processing result set [DEBUG][net.sf.hibernate.type.NullableType] - returning '1' as column: id0_ [DEBUG][net.sf.hibernate.loader.Loader] - result row: 1 [DEBUG][net.sf.hibernate.type.NullableType] - returning '1' as column: groupId__ [DEBUG][net.sf.hibernate.loader.Loader] - found row of collection: [com.ccg.security.Group.accounts#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - reading row [DEBUG][net.sf.hibernate.type.NullableType] - returning '1' as column: accountId__ [DEBUG][net.sf.hibernate.impl.SessionImpl] - loading [com.ccg.domain.Account#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.ccg.domain.Account#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.ccg.domain.Account#1] [DEBUG][net.sf.hibernate.loader.Loader] - done processing result set (1 rows) [DEBUG][net.sf.hibernate.impl.BatcherImpl] - done closing: 0 open PreparedStatements, 0 open ResultSets [DEBUG][net.sf.hibernate.impl.BatcherImpl] - closing statement [DEBUG][net.sf.hibernate.loader.Loader] - total objects hydrated: 0 [DEBUG][net.sf.hibernate.impl.SessionImpl] - 1 collections were found in result set [DEBUG][net.sf.hibernate.impl.SessionImpl] - collection fully initialized: [com.ccg.security.Group.accounts#1] [DEBUG][net.sf.hibernate.impl.SessionImpl] - 1 collections initialized [DEBUG][net.sf.hibernate.impl.SessionImpl] - collection initialized [DEBUG][net.sf.acegisecurity.intercept.AbstractSecurityInterceptor] - Authenticated: net.sf.acegisecurity.providers.UsernamePasswordAuthenticationToken@1c200d0: Username: com.ccg.domain.Account@1737301[id=1,....security.Group@3540ce[id=1,name=Users,description=Intranet Application User,roles=[com.ccg.security.Role@6a67ab]]]]; Password: [PROTECTED]; Authenticated: true; Details: net.sf.acegisecurity.ui.WebAuthenticationDetails@1aa38c7: RemoteIpAddress: 127.0.0.1; SessionId: 5E2D43C38FC1C20DC88CFE0C69121D19; Granted Authorities: ROLE_USER [DEBUG][net.sf.acegisecurity.intercept.AbstractSecurityInterceptor] - Authorization successful [DEBUG][net.sf.acegisecurity.intercept.AbstractSecurityInterceptor] - RunAsManager did not change Authentication object [DEBUG][net.sf.hibernate.impl.SessionImpl] - opened session [DEBUG][net.sf.hibernate.transaction.JDBCTransaction] - begin [DEBUG][net.sf.hibernate.transaction.JDBCTransaction] - current autocommit status:true [DEBUG][net.sf.hibernate.transaction.JDBCTransaction] - disabling autocommit [DEBUG][net.sf.hibernate.impl.SessionImpl] - flushing session [DEBUG][net.sf.hibernate.impl.SessionImpl] - Flushing entities and processing referenced collections [DEBUG][net.sf.hibernate.impl.SessionImpl] - running Session.finalize() [WARN ][net.sf.hibernate.impl.SessionImpl] - unclosed connection [DEBUG][net.sf.hibernate.impl.SessionImpl] - Processing unreferenced collections [DEBUG][net.sf.hibernate.impl.SessionImpl] - Scheduling collection removes/(re)creates/updates [DEBUG][net.sf.hibernate.impl.SessionImpl] - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects [DEBUG][net.sf.hibernate.impl.SessionImpl] - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections [DEBUG][net.sf.hibernate.impl.SessionImpl] - Dont need to execute flush [DEBUG][net.sf.hibernate.impl.BatcherImpl] - about to open: 0 open PreparedStatements, 0 open ResultSets [DEBUG][net.sf.hibernate.impl.BatcherImpl] - select this.id as id0_, this.type as type0_, this.name as name0_, this.classification as classifi4_0_, this.alias as alias0_, this.description as descript6_0_, this.designation as designat7_0_, this.expiration as expiration0_ from zone this where 1=1 [DEBUG][net.sf.hibernate.impl.BatcherImpl] - preparing statement [DEBUG][net.sf.hibernate.loader.Loader] - processing result set [DEBUG][net.sf.hibernate.type.NullableType] - returning '1' as column: id0_ [DEBUG][net.sf.hibernate.loader.Loader] - result row: 1


Reply With Quote