Hi We recently got crowd setup to handle SSO for a number of Atlassian apps. The directory we used was a basic crowd directory with basic authentication. Now we are trying to setup a second directory for active directory authentication but when we click on add directory the crowd app hangs.
I cant even stop the service, I have to kill the process after finding it in process explorer.
I dont see any errors in the atlassian-crowd.log file or the event viewer.
We eventually time out and get the following.
Proxy Error
The proxy server received an invalid response from an upstream server.
The proxy server could not handle the request GET /crowd/console/secure/application/browse.action.
Reason: Error reading from remote server
with logging set to all and profiling enabled we got a some information from the log file but we cant see any problems.
2011-09-12 13:12:43,376 http-8095-3 DEBUG [atlassian.util.profiling.UtilTimerStack] [3ms] - AOP: SecurityServer.isValidPrincipalToken()
[1ms] - AOP: SOAPService.validateSOAPService()
[0ms] - AOP: CrowdLicenseManager.isLicenseValid()
[1ms] - AOP: TokenAuthenticationManager.validateApplicationToken()
[0ms] - AOP: TokenManager.findByRandomHash()
[0ms] - AOP: PropertyManager.getSessionTime()
[0ms] - AOP: TokenManager.update()
[0ms] - AOP: ApplicationManager.findByName()
[0ms] - AOP: PropertyManager.isCacheEnabled()
[2ms] - AOP: TokenAuthenticationManager.validateUserToken()
[1ms] - AOP: TokenManager.findByRandomHash()
[0ms] - AOP: PropertyManager.getSessionTime()
[1ms] - AOP: TokenManager.update()
[0ms] - AOP: PropertyManager.isCacheEnabled()
2011-09-12 13:12:43,386 http-8095-3 DEBUG [atlassian.util.profiling.UtilTimerStack] [6ms] - AOP: SecurityServer.findPrincipalByToken()
[1ms] - AOP: SOAPService.validateSOAPService()
[0ms] - AOP: CrowdLicenseManager.isLicenseValid()
[1ms] - AOP: TokenAuthenticationManager.validateApplicationToken()
[0ms] - AOP: TokenManager.findByRandomHash()
[0ms] - AOP: PropertyManager.getSessionTime()
[1ms] - AOP: TokenManager.update()
[0ms] - AOP: ApplicationManager.findByName()
[0ms] - AOP: PropertyManager.isCacheEnabled()
[5ms] - AOP: TokenAuthenticationManager.findUserByToken()
[1ms] - AOP: ApplicationManager.findByName()
[0ms] - AOP: TokenManager.findByRandomHash()
[4ms] - AOP: DirectoryManager.findUserByName()
[0ms] - AOP: AliasManager.findAliasByUsername()
2011-09-12 13:12:43,394 http-8095-3 DEBUG [atlassian.util.profiling.UtilTimerStack] [3ms] - AOP: SecurityServer.getGrantedAuthorities()
[2ms] - AOP: SOAPService.validateSOAPService()
[0ms] - AOP: CrowdLicenseManager.isLicenseValid()
[1ms] - AOP: TokenAuthenticationManager.validateApplicationToken()
[1ms] - AOP: TokenManager.findByRandomHash()
[0ms] - AOP: PropertyManager.getSessionTime()
[0ms] - AOP: TokenManager.update()
[0ms] - AOP: ApplicationManager.findByName()
[0ms] - AOP: PropertyManager.isCacheEnabled()
2011-09-12 13:12:43,399 http-8095-3 DEBUG [atlassian.util.profiling.UtilTimerStack] [2ms] - AOP: SecurityServer.getCookieInfo()
[1ms] - AOP: SOAPService.validateSOAPService()
[0ms] - AOP: CrowdLicenseManager.isLicenseValid()
[1ms] - AOP: TokenAuthenticationManager.validateApplicationToken()
[0ms] - AOP: TokenManager.findByRandomHash()
[1ms] - AOP: PropertyManager.getSessionTime()
[0ms] - AOP: TokenManager.update()
[0ms] - AOP: ApplicationManager.findByName()
[0ms] - AOP: PropertyManager.isCacheEnabled()
[0ms] - AOP: PropertyManager.getDomain()
[1ms] - AOP: PropertyManager.isSecureCookie()
2011-09-12 13:12:46,464 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: ApplicationManager.findByName()
2011-09-12 13:12:46,539 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [68ms] - AOP: ApplicationManager.authenticate()
2011-09-12 13:12:47,296 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: ApplicationManager.findByName()
2011-09-12 13:12:47,306 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [9ms] - AOP: ApplicationService.searchGroups()
[9ms] - AOP: ApplicationService.searchGroups()
[9ms] - AOP: ApplicationService.searchGroups()
[7ms] - AOP: DirectoryManager.searchGroups()
2011-09-12 13:12:47,353 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: ApplicationManager.findByName()
2011-09-12 13:12:47,357 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [2ms] - AOP: ApplicationService.searchGroups()
[2ms] - AOP: ApplicationService.searchGroups()
[2ms] - AOP: ApplicationService.searchGroups()
[1ms] - AOP: DirectoryManager.searchGroups()
2011-09-12 13:12:47,367 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [9ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[9ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[9ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[9ms] - AOP: DirectoryManager.searchDirectGroupRelationships()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
2011-09-12 13:12:47,370 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: DirectoryManager.searchDirectGroupRelationships()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
2011-09-12 13:12:47,372 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: DirectoryManager.searchDirectGroupRelationships()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
2011-09-12 13:12:47,374 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: DirectoryManager.searchDirectGroupRelationships()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
2011-09-12 13:12:47,377 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: DirectoryManager.searchDirectGroupRelationships()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
2011-09-12 13:12:47,379 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[0ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[0ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[0ms] - AOP: DirectoryManager.searchDirectGroupRelationships()
2011-09-12 13:12:47,380 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: DirectoryManager.searchDirectGroupRelationships()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
2011-09-12 13:12:47,381 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[0ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[0ms] - AOP: DirectoryManager.searchDirectGroupRelationships()
2011-09-12 13:12:47,382 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: DirectoryManager.searchDirectGroupRelationships()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
2011-09-12 13:12:47,385 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[0ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[0ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[0ms] - AOP: DirectoryManager.searchDirectGroupRelationships()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
2011-09-12 13:12:47,387 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: DirectoryManager.searchDirectGroupRelationships()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
2011-09-12 13:12:47,388 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[0ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[0ms] - AOP: DirectoryManager.searchDirectGroupRelationships()
2011-09-12 13:12:47,389 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: DirectoryManager.searchDirectGroupRelationships()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
2011-09-12 13:12:47,392 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [2ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: ApplicationService.searchDirectGroupRelationships()
[1ms] - AOP: DirectoryManager.searchDirectGroupRelationships()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
2011-09-12 13:12:47,428 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [11ms] - AOP: ApplicationService.searchUsers()
[10ms] - AOP: ApplicationService.searchUsers()
[10ms] - AOP: ApplicationService.searchUsers()
[9ms] - AOP: DirectoryManager.searchUsers()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[0ms] - AOP: AliasManager.findAliasByUsername()
[1ms] - AOP: AliasManager.findAliasByUsername()
2011-09-12 13:12:59,236 http-8095-3 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: PropertyManager.isGzipEnabled()
2011-09-12 13:12:59,241 http-8095-3 DEBUG [atlassian.util.profiling.UtilTimerStack] [4ms] - AOP: SecurityServer.isValidPrincipalToken()
[2ms] - AOP: SOAPService.validateSOAPService()
[0ms] - AOP: CrowdLicenseManager.isLicenseValid()
[1ms] - AOP: TokenAuthenticationManager.validateApplicationToken()
[1ms] - AOP: TokenManager.findByRandomHash()
[0ms] - AOP: PropertyManager.getSessionTime()
[0ms] - AOP: TokenManager.update()
[1ms] - AOP: ApplicationManager.findByName()
[0ms] - AOP: PropertyManager.isCacheEnabled()
[2ms] - AOP: TokenAuthenticationManager.validateUserToken()
[1ms] - AOP: TokenManager.findByRandomHash()
[0ms] - AOP: PropertyManager.getSessionTime()
[0ms] - AOP: TokenManager.update()
[0ms] - AOP: PropertyManager.isCacheEnabled()
2011-09-12 13:12:59,251 http-8095-3 DEBUG [atlassian.util.profiling.UtilTimerStack] [5ms] - AOP: SecurityServer.findPrincipalByToken()
[1ms] - AOP: SOAPService.validateSOAPService()
[0ms] - AOP: CrowdLicenseManager.isLicenseValid()
[1ms] - AOP: TokenAuthenticationManager.validateApplicationToken()
[0ms] - AOP: TokenManager.findByRandomHash()
[1ms] - AOP: PropertyManager.getSessionTime()
[0ms] - AOP: TokenManager.update()
[0ms] - AOP: ApplicationManager.findByName()
[0ms] - AOP: PropertyManager.isCacheEnabled()
[4ms] - AOP: TokenAuthenticationManager.findUserByToken()
[1ms] - AOP: ApplicationManager.findByName()
[1ms] - AOP: TokenManager.findByRandomHash()
[2ms] - AOP: DirectoryManager.findUserByName()
[0ms] - AOP: AliasManager.findAliasByUsername()
2011-09-12 13:12:59,258 http-8095-3 DEBUG [atlassian.util.profiling.UtilTimerStack] [2ms] - AOP: SecurityServer.getGrantedAuthorities()
[1ms] - AOP: SOAPService.validateSOAPService()
[0ms] - AOP: CrowdLicenseManager.isLicenseValid()
[1ms] - AOP: TokenAuthenticationManager.validateApplicationToken()
[0ms] - AOP: TokenManager.findByRandomHash()
[0ms] - AOP: PropertyManager.getSessionTime()
[1ms] - AOP: TokenManager.update()
[0ms] - AOP: ApplicationManager.findByName()
[0ms] - AOP: PropertyManager.isCacheEnabled()
2011-09-12 13:12:59,264 http-8095-3 DEBUG [atlassian.util.profiling.UtilTimerStack] [2ms] - AOP: SecurityServer.getCookieInfo()
[2ms] - AOP: SOAPService.validateSOAPService()
[0ms] - AOP: CrowdLicenseManager.isLicenseValid()
[1ms] - AOP: TokenAuthenticationManager.validateApplicationToken()
[1ms] - AOP: TokenManager.findByRandomHash()
[0ms] - AOP: PropertyManager.getSessionTime()
[0ms] - AOP: TokenManager.update()
[1ms] - AOP: ApplicationManager.findByName()
[0ms] - AOP: PropertyManager.isCacheEnabled()
[0ms] - AOP: PropertyManager.getDomain()
[0ms] - AOP: PropertyManager.isSecureCookie()
2011-09-12 13:12:59,267 http-8095-4 DEBUG [console.action.options.UpdateLoggingProfiling] New log configuration saved
2011-09-12 13:12:59,268 http-8095-4 DEBUG [atlassian.xwork.interceptors.TransactionalInvocation] Committing transaction for action /console/secure/admin/loggingProfiling.action (UpdateLoggingProfiling.default())
2011-09-12 13:12:59,268 http-8095-4 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,269 http-8095-4 DEBUG [atlassian.xwork.interceptors.TransactionalInvocation] Creating transaction for action result: /console/secure/admin/loggingProfiling.action (UpdateLoggingProfiling.default())
2011-09-12 13:12:59,269 http-8095-4 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,269 http-8095-4 DEBUG [apache.catalina.core.StandardWrapper] Returning non-STM instance
2011-09-12 13:12:59,270 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] JspEngine --> /console/secure/admin/logging_profiling.jsp
2011-09-12 13:12:59,270 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] ServletPath: /console/secure/admin/logging_profiling.jsp
2011-09-12 13:12:59,270 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] PathInfo: null
2011-09-12 13:12:59,270 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] RealPath: E:\JiraStuff\crowd-2.3.2\atlassian-crowd-2.3.2\apache-tomcat\webapps\..\..\crowd-webapp\console\secure\admin\logging_profiling.jsp
2011-09-12 13:12:59,271 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] RequestURI: /crowd/console/secure/admin/logging_profiling.jsp
2011-09-12 13:12:59,271 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] QueryString: null
2011-09-12 13:12:59,273 http-8095-4 DEBUG [apache.catalina.core.StandardWrapper] Returning non-STM instance
2011-09-12 13:12:59,274 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] JspEngine --> /template/xhtml/hidden.jsp
2011-09-12 13:12:59,274 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] ServletPath: /console/secure/admin/logging_profiling.jsp
2011-09-12 13:12:59,274 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] PathInfo: null
2011-09-12 13:12:59,275 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] RealPath: E:\JiraStuff\crowd-2.3.2\atlassian-crowd-2.3.2\apache-tomcat\webapps\..\..\crowd-webapp\template\xhtml\hidden.jsp
2011-09-12 13:12:59,275 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] RequestURI: /crowd/console/secure/admin/logging_profiling.jsp
2011-09-12 13:12:59,276 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] QueryString: null
2011-09-12 13:12:59,278 http-8095-4 DEBUG [apache.catalina.core.StandardWrapper] Returning non-STM instance
2011-09-12 13:12:59,278 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] JspEngine --> /template/xhtml/hidden.jsp
2011-09-12 13:12:59,279 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] ServletPath: /console/secure/admin/logging_profiling.jsp
2011-09-12 13:12:59,279 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] PathInfo: null
2011-09-12 13:12:59,280 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] RealPath: E:\JiraStuff\crowd-2.3.2\atlassian-crowd-2.3.2\apache-tomcat\webapps\..\..\crowd-webapp\template\xhtml\hidden.jsp
2011-09-12 13:12:59,280 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] RequestURI: /crowd/console/secure/admin/logging_profiling.jsp
2011-09-12 13:12:59,280 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] QueryString: null
2011-09-12 13:12:59,281 http-8095-4 DEBUG [apache.catalina.core.StandardWrapper] Returning non-STM instance
2011-09-12 13:12:59,282 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] JspEngine --> /template/xhtml/form_messages.jsp
2011-09-12 13:12:59,282 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] ServletPath: /console/secure/admin/logging_profiling.jsp
2011-09-12 13:12:59,283 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] PathInfo: null
2011-09-12 13:12:59,283 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] RealPath: E:\JiraStuff\crowd-2.3.2\atlassian-crowd-2.3.2\apache-tomcat\webapps\..\..\crowd-webapp\template\xhtml\form_messages.jsp
2011-09-12 13:12:59,284 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] RequestURI: /crowd/console/secure/admin/logging_profiling.jsp
2011-09-12 13:12:59,284 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] QueryString: null
2011-09-12 13:12:59,290 http-8095-4 DEBUG [[Catalina].[localhost].[/crowd].[jsp]] Disabling the response for futher output
2011-09-12 13:12:59,290 http-8095-4 DEBUG [[Catalina].[localhost].[/crowd].[jsp]] The Response is vehiculed using a wrapper: com.opensymphony.module.sitemesh.filter.PageResponseWrapper
2011-09-12 13:12:59,290 http-8095-4 DEBUG [atlassian.xwork.interceptors.TransactionalInvocation] Committing transaction for action /console/secure/admin/loggingProfiling.action (UpdateLoggingProfiling.default())
2011-09-12 13:12:59,290 http-8095-4 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,291 http-8095-4 DEBUG [apache.catalina.core.StandardWrapper] Returning non-STM instance
2011-09-12 13:12:59,292 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] JspEngine --> /console/decorator/default.jsp
2011-09-12 13:12:59,292 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] ServletPath: /console/secure/admin/loggingProfiling!updateLogging.action
2011-09-12 13:12:59,292 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] PathInfo: null
2011-09-12 13:12:59,293 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] RealPath: E:\JiraStuff\crowd-2.3.2\atlassian-crowd-2.3.2\apache-tomcat\webapps\..\..\crowd-webapp\console\decorator\default.jsp
2011-09-12 13:12:59,293 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] RequestURI: /crowd/console/secure/admin/loggingProfiling!updateLogging.action
2011-09-12 13:12:59,293 http-8095-4 DEBUG [apache.jasper.servlet.JspServlet] QueryString: null
2011-09-12 13:12:59,295 http-8095-4 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,295 http-8095-4 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,295 http-8095-4 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,295 http-8095-4 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,305 http-8095-4 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,305 http-8095-4 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,306 http-8095-4 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,306 http-8095-4 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,306 http-8095-4 DEBUG [crowd.console.filter.CrowdOpenSessionInViewFilter] Closing single Hibernate Session in OpenSessionInViewFilter
2011-09-12 13:12:59,328 http-8095-4 DEBUG [apache.catalina.core.StandardWrapper] Returning non-STM instance
2011-09-12 13:12:59,328 http-8095-4 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,328 http-8095-4 DEBUG [sf.ehcache.store.MemoryStore] com.atlassian.crowd.model.property.PropertyCache: com.atlassian.crowd.model.property.PropertyMemoryStore hit for com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@1776c7a0
2011-09-12 13:12:59,329 http-8095-4 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,329 http-8095-4 DEBUG [crowd.console.filter.CrowdOpenSessionInViewFilter] Using SessionFactory 'sessionFactory' for OpenSessionInViewFilter
2011-09-12 13:12:59,329 http-8095-4 DEBUG [crowd.console.filter.CrowdOpenSessionInViewFilter] Opening single Hibernate Session in OpenSessionInViewFilter
2011-09-12 13:12:59,329 http-8095-4 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,329 http-8095-4 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,329 http-8095-4 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,330 http-8095-4 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: CrowdLicenseManager.isLicenseValid()
2011-09-12 13:12:59,330 http-8095-4 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,330 http-8095-4 DEBUG [integration.http.util.CrowdHttpTokenHelperImpl] Checking for a SSO token that will need to be verified by Crowd.
2011-09-12 13:12:59,330 http-8095-4 DEBUG [integration.http.util.CrowdHttpTokenHelperImpl] No request attribute token could be found, now checking the browser submitted cookies.
2011-09-12 13:12:59,330 http-8095-3 DEBUG [apache.catalina.core.StandardWrapper] Returning non-STM instance
2011-09-12 13:12:59,331 http-8095-4 DEBUG [integration.http.util.CrowdHttpTokenHelperImpl] Cookie name/value: JSESSIONID / DBB2AF925F0128088465E09F04E73B02
2011-09-12 13:12:59,331 http-8095-4 DEBUG [integration.http.util.CrowdHttpTokenHelperImpl] Cookie name/value: crowd.token_key / xJ8rA0Rbm33aqigs7wrf2g00
2011-09-12 13:12:59,331 http-8095-4 DEBUG [integration.http.util.CrowdHttpTokenHelperImpl] Accepting the SSO cookie value: xJ8rA0Rbm33aqigs7wrf2g00
2011-09-12 13:12:59,331 http-8095-3 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,331 http-8095-4 DEBUG [integration.http.util.CrowdHttpTokenHelperImpl] Existing token value yet to be verified by Crowd: xJ8rA0Rbm33aqigs7wrf2g00
2011-09-12 13:12:59,331 http-8095-4 DEBUG [crowd.integration.springsecurity.CrowdAuthenticationProvider] Processing a CrowdSSOAuthenticationToken
2011-09-12 13:12:59,331 http-8095-3 DEBUG [sf.ehcache.store.MemoryStore] com.atlassian.crowd.model.property.PropertyCache: com.atlassian.crowd.model.property.PropertyMemoryStore hit for com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@1776c7a0
2011-09-12 13:12:59,332 http-8095-4 DEBUG [service.soap.client.SecurityServerClientImpl] Connection URL: http://crowd.onlifehealth.com/crowd/services/SecurityServer<br< a=""> />2011-09-12 13:12:59,332 http-8095-3 DEBUG [atlassian.util.profiling.UtilTimerStack] [1ms] - AOP: PropertyManager.isGzipEnabled()
2011-09-12 13:12:59,332 http-8095-4 DEBUG [service.soap.client.SecurityServerClientImpl] Using existing token: PpjcHnqzbz178O5RLwNN0A00
2011-09-12 13:12:59,332 http-8095-3 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,332 http-8095-3 DEBUG [crowd.console.filter.CrowdOpenSessionInViewFilter] Using SessionFactory 'sessionFactory' for OpenSessionInViewFilter
2011-09-12 13:12:59,332 http-8095-3 DEBUG [crowd.console.filter.CrowdOpenSessionInViewFilter] Opening single Hibernate Session in OpenSessionInViewFilter
2011-09-12 13:12:59,333 http-8095-3 DEBUG [crowd.console.filter.CrowdOpenSessionInViewFilter] Closing single Hibernate Session in OpenSessionInViewFilter
2011-09-12 13:12:59,333 http-8095-4 DEBUG [httpclient.wire.header] >> "POST /crowd/services/SecurityServer HTTP/1.1[\r][\n]"
2011-09-12 13:12:59,333 http-8095-4 DEBUG [httpclient.wire.header] >> "SOAPAction: ""[\r][\n]"
2011-09-12 13:12:59,333 http-8095-4 DEBUG [httpclient.wire.header] >> "Content-Type: text/xml; charset=UTF-8[\r][\n]"
2011-09-12 13:12:59,333 http-8095-4 DEBUG [httpclient.wire.header] >> "Accept-Encoding: gzip[\r][\n]"
2011-09-12 13:12:59,333 http-8095-4 DEBUG [httpclient.wire.header] >> "User-Agent: Mozilla/5.0 (Crowd Client 2.3.2; XFire Client)[\r][\n]"
2011-09-12 13:12:59,333 http-8095-4 DEBUG [httpclient.wire.header] >> "Host: crowd.onlifehealth.com[\r][\n]"
2011-09-12 13:12:59,334 http-8095-4 DEBUG [httpclient.wire.header] >> "Expect: 100-continue[\r][\n]"
2011-09-12 13:12:59,334 http-8095-4 DEBUG [httpclient.wire.header] >> "Content-Length: 845[\r][\n]"
2011-09-12 13:12:59,334 http-8095-4 DEBUG [httpclient.wire.header] >> "[\r][\n]"
2011-09-12 13:12:59,334 http-8095-4 DEBUG [httpclient.wire.header] << "HTTP/1.1 100 Continue[\r][\n]"
2011-09-12 13:12:59,334 http-8095-4 DEBUG [httpclient.wire.content] >> "<soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"><soap:Body><ns1:isValidPrincipalToken xmlns:ns1="urn:SecurityServer"><ns1:in0><name xmlns="http://authentication.integration.crowd.atlassian.com">crowd</name><token xmlns="http://authentication.integration.crowd.atlassian.com">PpjcHnqzbz178O5RLwNN0A00</token></ns1:in0><ns1:in1>xJ8rA0Rbm33aqigs7wrf2g00</ns1:in1><ns1:in2><ns2:ValidationFactor xmlns:ns2="http://authentication.integration.crowd.atlassian.com"><name xmlns="http://authentication.integration.crowd.atlassian.com">remote_address</name><value xmlns="http://authentication.integration.crowd.atlassian.com">10.243.2.193</value></ns2:ValidationFactor></ns1:in2></ns1:isValidPrincipalToken></soap:Body></soap:Envelope>"
2011-09-12 13:12:59,334 http-8095-3 DEBUG [apache.catalina.core.StandardWrapper] Returning non-STM instance
2011-09-12 13:12:59,335 http-8095-4 DEBUG [httpclient.wire.header] << "HTTP/1.1 100 Continue[\r][\n]"
2011-09-12 13:12:59,335 http-8095-3 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,335 http-8095-3 DEBUG [sf.ehcache.store.MemoryStore] com.atlassian.crowd.model.property.PropertyCache: com.atlassian.crowd.model.property.PropertyMemoryStore hit for com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@1776c7a0
2011-09-12 13:12:59,335 http-8095-3 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,335 http-8095-3 DEBUG [com.atlassian.gzipfilter.GzipFilter] GZIP supported, compressing.
2011-09-12 13:12:59,336 http-8095-3 DEBUG [crowd.console.filter.CrowdOpenSessionInViewFilter] Using SessionFactory 'sessionFactory' for OpenSessionInViewFilter
2011-09-12 13:12:59,336 http-8095-3 DEBUG [crowd.console.filter.CrowdOpenSessionInViewFilter] Opening single Hibernate Session in OpenSessionInViewFilter
2011-09-12 13:12:59,336 http-8095-3 DEBUG [service.soap.xfire.XFireInLoggingMethodHandler] SOAP service method: isValidPrincipalToken
com.atlassian.crowd.integration.authentication.AuthenticatedToken@187a6dd[name=crowd,token=PpjcHnqzbz178O5RLwNN0A00]
xJ8rA0Rbm33aqigs7wrf2g00
com.atlassian.crowd.integration.authentication.ValidationFactor@dc2a37[name=remote_address,value=10.243.2.193]
2011-09-12 13:12:59,336 http-8095-3 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,337 http-8095-3 DEBUG [crowd.service.soap.SOAPService] validating license key
2011-09-12 13:12:59,337 http-8095-3 DEBUG [crowd.service.soap.SOAPService] validating application token: PpjcHnqzbz178O5RLwNN0A00
2011-09-12 13:12:59,337 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] genericValidateToken
2011-09-12 13:12:59,337 http-8095-3 DEBUG [sf.ehcache.store.MemoryStore] com.atlassian.crowd.model.property.PropertyCache: com.atlassian.crowd.model.property.PropertyMemoryStore hit for com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@83d0b418
2011-09-12 13:12:59,337 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] checking if the token is expired:
2011-09-12 13:12:59,337 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] now: 1315858379337
2011-09-12 13:12:59,338 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] last accessed: 2011-09-12 13:12:59.263
2011-09-12 13:12:59,338 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] difference: 74
2011-09-12 13:12:59,338 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] allowed elapse: 1800000
2011-09-12 13:12:59,339 http-8095-3 DEBUG [manager.token.factory.TokenKeyGeneratorImpl] Generating Token for principal: crowd
2011-09-12 13:12:59,340 http-8095-3 DEBUG [manager.token.factory.TokenKeyGeneratorImpl] Adding remote address of 10.243.2.193
2011-09-12 13:12:59,340 http-8095-3 DEBUG [manager.token.factory.TokenKeyGeneratorImpl] Adding remote_host of com.atlassian.crowd.model.authentication.ValidationFactor@e88006[name=remote_host,value=10.243.2.193]
2011-09-12 13:12:59,340 http-8095-3 DEBUG [manager.token.factory.TokenKeyGeneratorImpl] Adding NAME of com.atlassian.crowd.model.authentication.ValidationFactor@2d40bf[name=NAME,value=crowd]
2011-09-12 13:12:59,340 http-8095-3 DEBUG [manager.token.factory.TokenKeyGeneratorImpl] Generating Token for principal: crowd
2011-09-12 13:12:59,340 http-8095-3 DEBUG [manager.token.factory.TokenKeyGeneratorImpl] Adding remote address of 10.243.2.193
2011-09-12 13:12:59,340 http-8095-3 DEBUG [manager.token.factory.TokenKeyGeneratorImpl] Adding remote_host of com.atlassian.crowd.model.authentication.ValidationFactor@e88006[name=remote_host,value=10.243.2.193]
2011-09-12 13:12:59,340 http-8095-3 DEBUG [manager.token.factory.TokenKeyGeneratorImpl] Adding NAME of com.atlassian.crowd.model.authentication.ValidationFactor@2d40bf[name=NAME,value=crowd]
2011-09-12 13:12:59,340 http-8095-3 DEBUG [manager.token.factory.TokenKeyGeneratorImpl] Adding Random-Number of com.atlassian.crowd.model.authentication.ValidationFactor@f5df97[name=Random-Number,value=8463542941642422637]
2011-09-12 13:12:59,340 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] Current Validation Factors:
com.atlassian.crowd.model.authentication.ValidationFactor@2a55df[name=remote_address,value=10.243.2.193]com.atlassian.crowd.model.authentication.ValidationFactor@e88006[name=remote_host,value=10.243.2.193]com.atlassian.crowd.model.authentication.ValidationFactor@2d40bf[name=NAME,value=crowd]
2011-09-12 13:12:59,340 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] comparing existing token com.atlassian.crowd.model.token.Token@4766005e with a validation token com.atlassian.crowd.model.token.Token@4766005e
2011-09-12 13:12:59,340 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] returning validated token, with updated last accessed time
2011-09-12 13:12:59,340 http-8095-3 DEBUG [crowd.dao.token.TokenDAOHibernate] Updating object: com.atlassian.crowd.model.token.Token@4766005e
2011-09-12 13:12:59,340 http-8095-3 DEBUG [crowd.service.soap.SOAPService] loading application: crowd
2011-09-12 13:12:59,341 http-8095-3 DEBUG [sf.ehcache.store.MemoryStore] com.atlassian.crowd.manager.proxy.TrustedProxyManagerImpl_requested_proxiesCache: com.atlassian.crowd.manager.proxy.TrustedProxyManagerImpl_requested_proxiesMemoryStore hit for 10.243.2.193
2011-09-12 13:12:59,341 http-8095-3 DEBUG [crowd.manager.validation.ClientValidationManagerImpl] Client address: 10.243.2.193
2011-09-12 13:12:59,341 http-8095-3 DEBUG [sf.ehcache.store.MemoryStore] com.atlassian.crowd.model.property.PropertyCache: com.atlassian.crowd.model.property.PropertyMemoryStore hit for com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@723225c8
2011-09-12 13:12:59,341 http-8095-3 DEBUG [sf.ehcache.store.MemoryStore] interface com.atlassian.crowd.model.application.Applicationclass java.net.InetAddresscacheCache: interface com.atlassian.crowd.model.application.Applicationclass java.net.InetAddresscacheMemoryStore hit for crowd#10.243.2.193
2011-09-12 13:12:59,341 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] validateUserToken: xJ8rA0Rbm33aqigs7wrf2g00
2011-09-12 13:12:59,342 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] genericValidateToken
2011-09-12 13:12:59,343 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] checking if the token is expired:
2011-09-12 13:12:59,343 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] now: 1315858379343
2011-09-12 13:12:59,343 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] last accessed: 2011-09-12 13:12:59.24
2011-09-12 13:12:59,343 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] difference: 103
2011-09-12 13:12:59,343 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] allowed elapse: 1800000
2011-09-12 13:12:59,343 http-8095-3 DEBUG [manager.token.factory.TokenKeyGeneratorImpl] Generating Token for principal: admin
2011-09-12 13:12:59,343 http-8095-3 DEBUG [manager.token.factory.TokenKeyGeneratorImpl] Adding remote address of 10.243.2.193
2011-09-12 13:12:59,343 http-8095-3 DEBUG [manager.token.factory.TokenKeyGeneratorImpl] Generating Token for principal: admin
2011-09-12 13:12:59,343 http-8095-3 DEBUG [manager.token.factory.TokenKeyGeneratorImpl] Adding remote address of 10.243.2.193
2011-09-12 13:12:59,343 http-8095-3 DEBUG [manager.token.factory.TokenKeyGeneratorImpl] Adding Random-Number of com.atlassian.crowd.model.authentication.ValidationFactor@fa1477[name=Random-Number,value=6803031573376869959]
2011-09-12 13:12:59,343 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] Current Validation Factors:
com.atlassian.crowd.model.authentication.ValidationFactor@55b715[name=remote_address,value=10.243.2.193]
2011-09-12 13:12:59,343 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] comparing existing token com.atlassian.crowd.model.token.Token@1d280cb4 with a validation token com.atlassian.crowd.model.token.Token@1d280cb4
2011-09-12 13:12:59,343 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] returning validated token, with updated last accessed time
2011-09-12 13:12:59,343 http-8095-3 DEBUG [crowd.dao.token.TokenDAOHibernate] Updating object: com.atlassian.crowd.model.token.Token@1d280cb4
2011-09-12 13:12:59,344 http-8095-3 DEBUG [sf.ehcache.store.MemoryStore] com.atlassian.crowd.manager.cache.CacheManagerEhcacheCache: com.atlassian.crowd.manager.cache.CacheManagerEhcacheMemoryStore hit for crowdxJ8rA0Rbm33aqigs7wrf2g00
2011-09-12 13:12:59,344 http-8095-3 DEBUG [crowd.manager.authentication.TokenAuthenticationManagerImpl] user has access to the application <crowd>
2011-09-12 13:12:59,344 http-8095-3 DEBUG [atlassian.util.profiling.UtilTimerStack] [7ms] - AOP: SecurityServer.isValidPrincipalToken()
[4ms] - AOP: SOAPService.validateSOAPService()
[0ms] - AOP: CrowdLicenseManager.isLicenseValid()
[3ms] - AOP: TokenAuthenticationManager.validateApplicationToken()
[0ms] - AOP: TokenManager.findByRandomHash()
[0ms] - AOP: PropertyManager.getSessionTime()
[0ms] - AOP: TokenManager.update()
[1ms] - AOP: ApplicationManager.findByName()
[0ms] - AOP: PropertyManager.isCacheEnabled()
[3ms] - AOP: TokenAuthenticationManager.validateUserToken()
[1ms] - AOP: TokenManager.findByRandomHash()
[0ms] - AOP: PropertyManager.getSessionTime()
[1ms] - AOP: TokenManager.update()
[0ms] - AOP: PropertyManager.isCacheEnabled()
2011-09-12 13:12:59,345 http-8095-3 DEBUG [mchange.v2.resourcepool.BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1edf84f [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b1fea4)
2011-09-12 13:12:59,345 http-8095-3 DEBUG [service.soap.xfire.XFireOutLoggingMethodHandler] SOAP service method: isValidPrincipalToken
true
Any ideas what could be causing this?
