search

chauth / confluence_http_authenticator

The new home of the Confluence HTTP Authenticator (formerly known as the Confluence Shibboleth Authenticator)
Other
64 stars 36 forks source link

Local login again broken in 2.1.16 #2

Closed erkkiaalto closed 11 years ago

erkkiaalto commented 11 years ago

Logininfo is updated after a local user login, but a functioning session is not created. There was a similar problem in some pre-2.1.15 versions.

garysweaver commented 11 years ago

Erkki,

Are you using the same version of Confluence? Which are you using? Is the Shib setup exactly the same (did you just replace the authenticator in your existing setup?). Could you get your developer to take a look and do a pull request with changes?

Thanks for your help again. The changes we made in 2.1.16 were suggested by Atlassian to support "remember me" and local login, so there seems to be maybe something that works for Atlassian that does not work for you. If you find out what the problem is, and it is different than what Atlassian suggested we use, then we should tell Atlassian so that they can fix their example authenticator code. Also, you may still download 2.1.15 from: https://github.com/chauth/confluence_http_authenticator/blob/master/releases/remoteUserAuth-2.1.15.jar

Gary

erkkiaalto commented 11 years ago

The confluence version is 4.3.7 and I just replaced the autheticator without any other changes. I am not sure if my developer hast time, but I'll try at least to get fulle debug logs.

Erkki 'Örkki' Aalto "Life is divided up into Internet: Erkki.Aalto@Helsinki.FI the horrible and the miserable" Snail: Tietotekniikkakeskus, P.O. Box 28 FI-00014 University of Helsinki, Finland

erkkiaalto commented 11 years ago

Below it can be seen how user admin authenticates successfully. Somehow the session is dysfunctional.

2013-02-19 08:37:35,168 DEBUG [TP-Processor17] [atlassian.seraph.filter.BaseLoginFilter] doFilter doFilter : Attempting login for : '/dologin.action' 2013-02-19 08:37:35,168 DEBUG [TP-Processor17] [atlassian.seraph.filter.PasswordBasedLoginFilter] login login : 'admin' and password provided - remember me : false - attempting login request 2013-02-19 08:37:35,170 DEBUG [TP-Processor17] [atlassian.seraph.filter.PasswordBasedLoginFilter] runAuthentication runAuthentication : 'admin' does not require elevated security check. Attempting authentication... 2013-02-19 08:37:35,171 DEBUG [TP-Processor17] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:35,174 DEBUG [TP-Processor17] [net.sf.hibernate.SQL] log select this.id as id0_, this.user_name as username0, this.lower_user_name as lower_us30, this.active as active0_, this.created_date as created_50, this.updated_date as updated_60, this.first_name as firstname0, this.lower_first_name as lower_fi80, this.last_name as lastname0, this.lower_last_name as lower_l100, this.display_name as display110, this.lower_display_name as lower_d120, this.email_address as email_a130, this.lower_email_address as lower_e140, this.directory_id as directo150, this.credential as credential0_ from cwd_user this where this.directory_id=? and this.lower_username=? 2013-02-19 08:37:35,179 DEBUG [TP-Processor17] [net.sf.hibernate.SQL] log select this.id as id0, this.user_id as userid0, this.directory_id as director30, this.attribute_name as attribut40, this.attribute_value as attribut50, this.attribute_lower_value as attribut60 from cwd_user_attribute this where this.user_id=? 2013-02-19 08:37:35,459 DEBUG [TP-Processor17] [net.sf.hibernate.SQL] log update cwd_user_attribute set user_id=?, directory_id=?, attribute_name=?, attribute_value=?, attribute_lower_value=? where id=? 2013-02-19 08:37:35,491 INFO [TP-Processor17] [atlassian.confluence.cache.DeferredOperationsCache] sync Synchronising deferred operations (0 put, 1 remove) to cache [com.atlassian.confluence.user.crowd.CachedCrowdUserDao.ATTRIBUTE_CACHE] 2013-02-19 08:37:35,493 INFO [TP-Processor17] [atlassian.confluence.cache.DeferredOperationsCache] sync Synchronising deferred operations (1 put, 0 remove) to cache [com.atlassian.confluence.user.crowd.CachedCrowdUserDao.USERCACHE] 2013-02-19 08:37:35,493 DEBUG [TP-Processor17] [atlassian.seraph.auth.DefaultAuthenticator] login login : 'admin' has been authenticated 2013-02-19 08:37:35,496 DEBUG [TP-Processor17] [atlassian.seraph.auth.DefaultAuthenticator] authoriseUserAndEstablishSession authoriseUser : 'admin' can login according to the RoleMapper 2013-02-19 08:37:35,497 DEBUG [TP-Processor17] [atlassian.seraph.auth.SessionInvalidator] dumpInfo invalidating session from request: POST 6DC96D60B2685E9F7300E8E8CA606769 /dologin.action 2013-02-19 08:37:35,498 DEBUG [TP-Processor17] [atlassian.seraph.auth.SessionInvalidator] dumpInfo session attribute: atlassian.xsrf.token 2013-02-19 08:37:35,498 DEBUG [TP-Processor17] [atlassian.seraph.auth.SessionInvalidator] dumpInfo session attribute: com.atlassian.labs.botkiller.BotKiller 2013-02-19 08:37:35,499 DEBUG [TP-Processor17] [net.sf.hibernate.SQL] log select userlogini0.id as id, userlogini0.CURFAILED as CURFAILED, userlogini0.TOTALFAILED as TOTALFAI3, userlogini0.SUCCESSDATE as SUCCESSD4, userlogini0.PREVSUCCESSDATE as PREVSUCC5, userlogini0.FAILEDDATE as FAILEDDATE, userlogini0.USERNAME as USERNAME from logininfo userlogini0 where (userlogini0.USERNAME=? ) 2013-02-19 08:37:35,503 DEBUG [TP-Processor17] [net.sf.hibernate.SQL] log update logininfo set CURFAILED=?, TOTALFAILED=?, SUCCESSDATE=?, PREVSUCCESSDATE=?, FAILEDDATE=?, USERNAME=? where id=? 2013-02-19 08:37:35,504 DEBUG [TP-Processor17] [atlassian.seraph.filter.PasswordBasedLoginFilter] runAuthentication runAuthentication : 'admin' was successfully authenticated 2013-02-19 08:37:35,505 DEBUG [TP-Processor17] [net.sf.hibernate.SQL] log select userlogini0.id as id, userlogini0.CURFAILED as CURFAILED, userlogini0.TOTALFAILED as TOTALFAI3, userlogini0.SUCCESSDATE as SUCCESSD4, userlogini0.PREVSUCCESSDATE as PREVSUCC5, userlogini0.FAILEDDATE as FAILEDDATE, userlogini0.USERNAME as USERNAME from logininfo userlogini0 where (userlogini0_.USERNAME=? ) 2013-02-19 08:37:35,506 DEBUG [TP-Processor17] [net.sf.hibernate.SQL] log update logininfo set CURFAILED=?, TOTALFAILED=?, SUCCESSDATE=?, PREVSUCCESSDATE=?, FAILEDDATE=?, USERNAME=? where id=? 2013-02-19 08:37:35,508 DEBUG [TP-Processor17] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:35,509 DEBUG [TP-Processor17] [atlassian.seraph.filter.BaseLoginFilter] doFilter doFilter : Login completed for 'null' - os_authstatus = 'success' 2013-02-19 08:37:35,509 DEBUG [TP-Processor17] [atlassian.seraph.filter.BaseLoginFilter] redirectToOriginalDestination redirectToOriginalDestination : Login redirect to: / 2013-02-19 08:37:35,514 DEBUG [TP-Processor18] [atlassian.seraph.cookie.DefaultCookieHandler] getCookie Looking for a cookie named : 'confluence-language' 2013-02-19 08:37:35,515 DEBUG [TP-Processor18] [atlassian.seraph.cookie.DefaultCookieHandler] getCookie No cookie was found with name :confluence-language 2013-02-19 08:37:35,515 DEBUG [TP-Processor18] [atlassian.seraph.filter.BaseLoginFilter] doFilter doFilter : Attempting login for : '/default.jsp' 2013-02-19 08:37:35,516 DEBUG [TP-Processor18] [atlassian.seraph.filter.PasswordBasedLoginFilter] login login : No user name or password was returned. No authentication attempt will be made. User may still be found via a SecurityFilter later. 2013-02-19 08:37:35,516 DEBUG [TP-Processor18] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:35,517 DEBUG [TP-Processor18] [atlassian.seraph.filter.BaseLoginFilter] doFilter doFilter : Login completed for 'null' - os_authstatus = 'null' 2013-02-19 08:37:35,517 DEBUG [TP-Processor18] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : Storing the originally requested URL (atlassian.core.seraph.original.url=/default.jsp) 2013-02-19 08:37:35,518 DEBUG [TP-Processor18] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : requiredRoles = [] 2013-02-19 08:37:35,518 DEBUG [TP-Processor18] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:35,519 DEBUG [TP-Processor18] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : Setting Auth Context to be 'anonymous ' 2013-02-19 08:37:35,519 DEBUG [TP-Processor18] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:35,533 DEBUG [TP-Processor20] [atlassian.seraph.cookie.DefaultCookieHandler] getCookie Looking for a cookie named : 'confluence-language' 2013-02-19 08:37:35,533 DEBUG [TP-Processor20] [atlassian.seraph.cookie.DefaultCookieHandler] getCookie No cookie was found with name :confluence-language 2013-02-19 08:37:35,533 DEBUG [TP-Processor20] [atlassian.seraph.filter.BaseLoginFilter] doFilter doFilter : Attempting login for : '/homepage.action' 2013-02-19 08:37:35,534 DEBUG [TP-Processor20] [atlassian.seraph.filter.PasswordBasedLoginFilter] login login : No user name or password was returned. No authentication attempt will be made. User may still be found via a SecurityFilter later. 2013-02-19 08:37:35,534 DEBUG [TP-Processor20] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:35,535 DEBUG [TP-Processor20] [atlassian.seraph.filter.BaseLoginFilter] doFilter doFilter : Login completed for 'null' - os_authstatus = 'null' 2013-02-19 08:37:35,535 DEBUG [TP-Processor20] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : Storing the originally requested URL (atlassian.core.seraph.original.url=/homepage.action) 2013-02-19 08:37:35,536 DEBUG [TP-Processor20] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : requiredRoles = [] 2013-02-19 08:37:35,536 DEBUG [TP-Processor20] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:35,537 DEBUG [TP-Processor20] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : Setting Auth Context to be 'anonymous ' 2013-02-19 08:37:35,537 DEBUG [TP-Processor20] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:35,538 DEBUG [TP-Processor20] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:35,547 DEBUG [TP-Processor5] [atlassian.seraph.cookie.DefaultCookieHandler] getCookie Looking for a cookie named : 'confluence-language' 2013-02-19 08:37:35,547 DEBUG [TP-Processor5] [atlassian.seraph.cookie.DefaultCookieHandler] getCookie No cookie was found with name :confluence-language 2013-02-19 08:37:35,548 DEBUG [TP-Processor5] [atlassian.seraph.filter.BaseLoginFilter] doFilter doFilter : ____ Attempting login for : '/dashboard.action' 2013-02-19 08:37:35,549 DEBUG [TP-Processor5] [atlassian.seraph.filter.PasswordBasedLoginFilter] login login : No user name or password was returned. No authentication attempt will be made. User may still be found via a SecurityFilter later. 2013-02-19 08:37:35,549 DEBUG [TP-Processor5] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:35,551 DEBUG [TP-Processor5] [atlassian.seraph.filter.BaseLoginFilter] doFilter doFilter : Login completed for 'null' - os_authstatus = 'null' 2013-02-19 08:37:35,552 DEBUG [TP-Processor5] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : Storing the originally requested URL (atlassian.core.seraph.original.url=/dashboard.action) 2013-02-19 08:37:35,552 DEBUG [TP-Processor5] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : requiredRoles = [] 2013-02-19 08:37:35,553 DEBUG [TP-Processor5] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:35,554 DEBUG [TP-Processor5] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : Setting Auth Context to be 'anonymous ' 2013-02-19 08:37:35,555 DEBUG [TP-Processor5] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:35,556 DEBUG [TP-Processor5] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:35,559 DEBUG [TP-Processor5] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:35,561 INFO [TP-Processor5] [confluence.plugin.webresource.DefaultConfluenceWebResourceManager] requireResource Requiring delayed resource: confluence.web.resources:master-styles 2013-02-19 08:37:35,564 DEBUG [TP-Processor5] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:35,567 INFO [TP-Processor5] [confluence.plugin.webresource.DefaultConfluenceWebResourceManager] requireResource Requiring delayed resource: confluence.web.resources:ajs 2013-02-19 08:37:35,572 INFO [TP-Processor5] [confluence.plugin.webresource.DefaultConfluenceWebResourceManager] requireResource Requiring delayed resource: confluence.web.resources:ajs 2013-02-19 08:37:35,583 INFO [TP-Processor5] [confluence.plugin.webresource.DefaultConfluenceWebResourceManager] requireResource Requiring delayed resource: confluence.macros.dashboard:dashboard-macros-resources 2013-02-19 08:37:35,595 INFO [TP-Processor5] [confluence.plugin.webresource.DefaultConfluenceWebResourceManager] requireResource Requiring delayed resource: confluence.web.resources:breadcrumbs 2013-02-19 08:37:35,605 DEBUG [TP-Processor5] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:35,607 INFO [TP-Processor5] [confluence.plugin.webresource.DefaultConfluenceWebResourceManager] requireResource Requiring delayed resource: confluence.web.resources:print-styles 2013-02-19 08:37:35,608 INFO [TP-Processor5] [confluence.plugin.webresource.DefaultConfluenceWebResourceManager] requireResource Requiring delayed resource: confluence.web.resources:ajs 2013-02-19 08:37:35,609 INFO [TP-Processor5] [confluence.plugin.webresource.DefaultConfluenceWebResourceManager] requireResource Requiring delayed resource: confluence.web.resources:ajs 2013-02-19 08:37:35,611 INFO [TP-Processor5] [confluence.plugin.webresource.DefaultConfluenceWebResourceManager] requireResource Requiring delayed resource: confluence.web.resources:atlassian-effects 2013-02-19 08:37:35,650 INFO [TP-Processor5] [confluence.plugin.webresource.DefaultConfluenceWebResourceManager] requireResource Requiring delayed resource: confluence.web.resources:common-header-resources 2013-02-19 08:37:35,652 INFO [TP-Processor5] [confluence.plugin.webresource.DefaultConfluenceWebResourceManager] requireResource Requiring delayed resource: com.atlassian.confluence.plugins.confluence-mobile:mobile-switch-resources 2013-02-19 08:37:35,653 INFO [TP-Processor5] [confluence.plugin.webresource.DefaultConfluenceWebResourceManager] requireResource Requiring delayed resource: com.atlassian.mywork.mywork-confluence-host-plugin:mw-header-anchor 2013-02-19 08:37:35,681 INFO [TP-Processor5] [confluence.plugin.webresource.DefaultConfluenceWebResourceManager] requireResource Requiring delayed resource: confluence.web.resources:ajs 2013-02-19 08:37:35,688 INFO [TP-Processor5] [confluence.plugin.webresource.DefaultConfluenceWebResourceManager] requireResource Requiring delayed resource: confluence.web.resources:common-header-resources 2013-02-19 08:37:35,690 INFO [TP-Processor5] [confluence.plugin.webresource.DefaultConfluenceWebResourceManager] requireResource Requiring delayed resource: com.atlassian.confluence.plugins.confluence-mobile:mobile-switch-resources 2013-02-19 08:37:35,691 INFO [TP-Processor5] [confluence.plugin.webresource.DefaultConfluenceWebResourceManager] requireResource Requiring delayed resource: com.atlassian.mywork.mywork-confluence-host-plugin:mw-header-anchor 2013-02-19 08:37:36,225 DEBUG [TP-Processor13] [atlassian.seraph.cookie.DefaultCookieHandler] getCookie Looking for a cookie named : 'confluence-language' 2013-02-19 08:37:36,226 DEBUG [TP-Processor13] [atlassian.seraph.cookie.DefaultCookieHandler] getCookie No cookie was found with name :confluence-language 2013-02-19 08:37:36,227 DEBUG [TP-Processor13] [atlassian.seraph.filter.BaseLoginFilter] doFilter doFilter : Attempting login for : '/rest/prototype/1/i18n?locale=en_GB&pluginKeys=com.atlassian.confluence.keyboardshortcuts&pluginKeys=com.atlassian.plugins.editor' 2013-02-19 08:37:36,228 DEBUG [TP-Processor13] [atlassian.seraph.filter.PasswordBasedLoginFilter] login login : No user name or password was returned. No authentication attempt will be made. User may still be found via a SecurityFilter later. 2013-02-19 08:37:36,229 DEBUG [TP-Processor13] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:36,230 DEBUG [TP-Processor13] [atlassian.seraph.filter.BaseLoginFilter] doFilter doFilter : Login completed for 'null' - os_authstatus = 'null' 2013-02-19 08:37:36,231 DEBUG [TP-Processor13] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : Storing the originally requested URL (atlassian.core.seraph.original.url=/rest/prototype/1/i18n?locale=en_GB&pluginKeys=com.atlassian.confluence.keyboardshortcuts&pluginKeys=com.atlassian.plugins.editor) 2013-02-19 08:37:36,232 DEBUG [TP-Processor13] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : requiredRoles = [] 2013-02-19 08:37:36,232 DEBUG [TP-Processor13] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:36,233 DEBUG [TP-Processor13] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : Setting Auth Context to be 'anonymous ' 2013-02-19 08:37:36,234 DEBUG [TP-Processor13] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:36,249 DEBUG [TP-Processor10] [atlassian.seraph.cookie.DefaultCookieHandler] getCookie Looking for a cookie named : 'confluence-language' 2013-02-19 08:37:36,250 DEBUG [TP-Processor10] [atlassian.seraph.cookie.DefaultCookieHandler] getCookie No cookie was found with name :confluence-language 2013-02-19 08:37:36,251 DEBUG [TP-Processor10] [atlassian.seraph.filter.BaseLoginFilter] doFilter doFilter : ____ Attempting login for : '/rest/popular/1/stream/content?days=7&pageSize=20' 2013-02-19 08:37:36,251 DEBUG [TP-Processor10] [atlassian.seraph.filter.PasswordBasedLoginFilter] login login : No user name or password was returned. No authentication attempt will be made. User may still be found via a SecurityFilter later. 2013-02-19 08:37:36,252 DEBUG [TP-Processor10] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:36,253 DEBUG [TP-Processor10] [atlassian.seraph.filter.BaseLoginFilter] doFilter doFilter : Login completed for 'null' - os_authstatus = 'null' 2013-02-19 08:37:36,254 DEBUG [TP-Processor10] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : Storing the originally requested URL (atlassian.core.seraph.original.url=/rest/popular/1/stream/content?days=7&pageSize=20) 2013-02-19 08:37:36,254 DEBUG [TP-Processor10] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : requiredRoles = [] 2013-02-19 08:37:36,255 DEBUG [TP-Processor10] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:37:36,256 DEBUG [TP-Processor10] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : Setting Auth Context to be 'anonymous ' 2013-02-19 08:37:36,257 DEBUG [TP-Processor10] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-02-19 08:38:00,012 INFO [scheduler_Worker-7] [confluence.setup.quartz.AbstractClusterAwareQuartzJobBean] surroundJobExecutionWithLogging Scheduled job : ClusterSafetyJob is starting 2013-02-19 08:38:00,013 INFO [scheduler_Worker-10] [confluence.setup.quartz.AbstractClusterAwareQuartzJobBean] surroundJobExecutionWithLogging Scheduled job : IndexQueueFlusher is starting 2013-02-19 08:38:00,031 DEBUG [scheduler_Worker-10] [confluence.search.lucene.DefaultConfluenceIndexManager] flushQueue flush requested 2013-02-19 08:38:00,032 DEBUG [scheduler_Worker-10] [search.lucene.queue.DatabaseIndexTaskQueue] getIndexQueueEntriesSince Fetching index entries added since: Mon Feb 18 14:59:59 EET 2013 2013-02-19 08:38:00,032 DEBUG [schedulerWorker-10] [net.sf.hibernate.SQL] log select indexqueue0.ENTRYID as ENTRYID, indexqueue0.CREATIONDATE as CREATION2, indexqueue0.TYPE as TYPE, indexqueue0.HANDLE as HANDLE from INDEXQUEUEENTRIES indexqueue0_ where (CREATIONDATE>? ) order by CREATIONDATE , ENTRYID 2013-02-19 08:38:00,046 INFO [scheduler_Worker-8] [confluence.setup.quartz.AbstractClusterAwareQuartzJobBean] surroundJobExecutionWithLogging Scheduled job : MailQueueFlushJob is starting 2013-02-19 08:38:00,046 INFO [scheduler_Worker-8] [confluence.setup.quartz.AbstractClusterAwareQuartzJobBean] surroundJobExecutionWithLogging Scheduled job : MailQueueFlushJob completed 2013-02-19 08:38:00,050 DEBUG [schedulerWorker-7] [net.sf.hibernate.SQL] log select clustersaf0.CLUSTERSAFETYID as CLUSTERS1, clustersaf0.SAFETYNUMBER as SAFETYNU2 from CLUSTERSAFETY clustersaf0 2013-02-19 08:38:00,097 DEBUG [schedulerWorker-9] [net.sf.hibernate.SQL] log select confluence0.BANDANAID as BANDANAID, confluence0.BANDANACONTEXT as BANDANAC2, confluence0.BANDANAKEY as BANDANAKEY, confluence0.BANDANAVALUE as BANDANAV4 from BANDANA confluence0 where (confluence0.BANDANACONTEXT=? )and(confluence0.BANDANAKEY=? ) 2013-02-19 08:38:00,206 DEBUG [scheduler_Worker-9] [net.sf.hibernate.SQL] log update BANDANA set BANDANACONTEXT=?, BANDANAKEY=?, BANDANAVALUE=? where BANDANAID=? 2013-02-19 08:38:00,298 DEBUG [scheduler_Worker-10] [search.lucene.queue.DatabaseIndexTaskQueue] getIndexQueueEntriesSince Fetched 1 entries from datbase. 2013-02-19 08:38:00,299 DEBUG [scheduler_Worker-10] [search.lucene.queue.DatabaseIndexTaskQueue] getIndexQueueEntriesSince Having excluded entries that have previously been flushed, 0 entries remain. 2013-02-19 08:38:00,299 DEBUG [scheduler_Worker-10] [search.lucene.queue.DatabaseIndexTaskQueue] getUnflushedEntries Having excluded entries that have previously been flushed and shrunk list to requested size, 0 entries remain. 2013-02-19 08:38:00,299 DEBUG [scheduler_Worker-10] [search.lucene.queue.DatabaseIndexTaskQueue] flushQueue DatabaseIndexTaskQueue.flushQueue: [] 2013-02-19 08:38:00,300 INFO [scheduler_Worker-10] [confluence.setup.quartz.AbstractClusterAwareQuartzJobBean] surroundJobExecutionWithLogging Scheduled job : IndexQueueFlusher completed 2013-02-19 08:38:00,312 DEBUG [schedulerWorker-7] [net.sf.hibernate.SQL] log select clustersaf0.CLUSTERSAFETYID as CLUSTERS1, clustersaf0.SAFETYNUMBER as SAFETYNU2 from CLUSTERSAFETY clustersaf0 2013-02-19 08:38:00,333 DEBUG [scheduler_Worker-7] [net.sf.hibernate.SQL] log update CLUSTERSAFETY set SAFETYNUMBER=? where CLUSTERSAFETYID=? 2013-02-19 08:38:00,344 INFO [scheduler_Worker-7] [confluence.setup.quartz.AbstractClusterAwareQuartzJobBean] surroundJobExecutionWithLogging Scheduled job : ClusterSafetyJob completed 2013-02-19 08:38:30,006 INFO [scheduler_Worker-7] [confluence.setup.quartz.AbstractClusterAwareQuartzJobBean] surroundJobExecutionWithLogging Scheduled job : ClusterSafetyJob is starting 2013-02-19 08:38:30,007 DEBUG [schedulerWorker-7] [net.sf.hibernate.SQL] log select clustersaf0.CLUSTERSAFETYID as CLUSTERS1, clustersaf0.SAFETYNUMBER as SAFETYNU2 from CLUSTERSAFETY clustersaf0 2013-02-19 08:38:30,036 DEBUG [schedulerWorker-7] [net.sf.hibernate.SQL] log select clustersaf0.CLUSTERSAFETYID as CLUSTERS1, clustersaf0.SAFETYNUMBER as SAFETYNU2 from CLUSTERSAFETY clustersaf0 2013-02-19 08:38:30,063 DEBUG [scheduler_Worker-7] [net.sf.hibernate.SQL] log update CLUSTERSAFETY set SAFETYNUMBER=? where CLUSTERSAFETYID=? 2013-02-19 08:38:30,077 INFO [scheduler_Worker-7] [confluence.setup.quartz.AbstractClusterAwareQuartzJobBean] surroundJobExecutionWithLogging Scheduled job : ClusterSafetyJob completed 2013-02-19 08:39:00,013 INFO [scheduler_Worker-8] [confluence.setup.quartz.AbstractClusterAwareQuartzJobBean] surroundJobExecutionWithLogging Scheduled job : ClusterSafetyJob is starting 2013-02-19 08:39:00,014 INFO [scheduler_Worker-5] [confluence.setup.quartz.AbstractClusterAwareQuartzJobBean] surroundJobExecutionWithLogging Scheduled job : IndexQueueFlusher is starting 2013-02-19 08:39:00,035 INFO [scheduler_Worker-9] [confluence.setup.quartz.AbstractClusterAwareQuartzJobBean] surroundJobExecutionWithLogging Scheduled job : MailQueueFlushJob is starting 2013-02-19 08:39:00,035 INFO [scheduler_Worker-9] [confluence.setup.quartz.AbstractClusterAwareQuartzJobBean] surroundJobExecutionWithLogging Scheduled job : MailQueueFlushJob completed 2013-02-19 08:39:00,043 DEBUG [schedulerWorker-8] [net.sf.hibernate.SQL] log select clustersaf0.CLUSTERSAFETYID as CLUSTERS1, clustersaf0.SAFETYNUMBER as SAFETYNU2 from CLUSTERSAFETY clustersaf0 2013-02-19 08:39:00,086 DEBUG [schedulerWorker-8] [net.sf.hibernate.SQL] log select clustersaf0.CLUSTERSAFETYID as CLUSTERS1, clustersaf0.SAFETYNUMBER as SAFETYNU2 from CLUSTERSAFETY clustersaf0 2013-02-19 08:39:00,119 DEBUG [scheduler_Worker-8] [net.sf.hibernate.SQL] log update CLUSTERSAFETY set SAFETYNUMBER=? where CLUSTERSAFETYID=? 2013-02-19 08:39:00,138 DEBUG [scheduler_Worker-5] [confluence.search.lucene.DefaultConfluenceIndexManager] flushQueue flush requested 2013-02-19 08:39:00,138 DEBUG [scheduler_Worker-5] [search.lucene.queue.DatabaseIndexTaskQueue] getIndexQueueEntriesSince Fetching index entries added since: Mon Feb 18 14:59:59 EET 2013 2013-02-19 08:39:00,139 DEBUG [schedulerWorker-5] [net.sf.hibernate.SQL] log select indexqueue0.ENTRYID as ENTRYID, indexqueue0.CREATIONDATE as CREATION2, indexqueue0.TYPE as TYPE, indexqueue0.HANDLE as HANDLE from INDEXQUEUEENTRIES indexqueue0_ where (CREATIONDATE>? ) order by CREATIONDATE , ENTRYID 2013-02-19 08:39:00,143 DEBUG [scheduler_Worker-5] [search.lucene.queue.DatabaseIndexTaskQueue] getIndexQueueEntriesSince Fetched 1 entries from datbase. 2013-02-19 08:39:00,143 DEBUG [scheduler_Worker-5] [search.lucene.queue.DatabaseIndexTaskQueue] getIndexQueueEntriesSince Having excluded entries that have previously been flushed, 0 entries remain. 2013-02-19 08:39:00,144 DEBUG [scheduler_Worker-5] [search.lucene.queue.DatabaseIndexTaskQueue] getUnflushedEntries Having excluded entries that have previously been flushed and shrunk list to requested size, 0 entries remain. 2013-02-19 08:39:00,144 DEBUG [scheduler_Worker-5] [search.lucene.queue.DatabaseIndexTaskQueue] flushQueue DatabaseIndexTaskQueue.flushQueue: [] 2013-02-19 08:39:00,145 INFO [scheduler_Worker-5] [confluence.setup.quartz.AbstractClusterAwareQuartzJobBean] surroundJobExecutionWithLogging Scheduled job : IndexQueueFlusher completed 2013-02-19 08:39:00,166 DEBUG [schedulerWorker-10] [net.sf.hibernate.SQL] log select confluence0.BANDANAID as BANDANAID, confluence0.BANDANACONTEXT as BANDANAC2, confluence0.BANDANAKEY as BANDANAKEY, confluence0.BANDANAVALUE as BANDANAV4 from BANDANA confluence0 where (confluence0.BANDANACONTEXT=? )and(confluence0.BANDANAKEY=? ) 2013-02-19 08:39:00,196 INFO [scheduler_Worker-8] [confluence.setup.quartz.AbstractClusterAwareQuartzJobBean] surroundJobExecutionWithLogging Scheduled job : ClusterSafetyJob completed 2013-02-19 08:39:00,245 DEBUG [scheduler_Worker-10] [net.sf.hibernate.SQL] log update BANDANA set BANDANACONTEXT=?, BANDANAKEY=?, BANDANAVALUE=? where BANDANAID=?

erkkiaalto commented 11 years ago

Actually, the log above does not tell what the authenticator is doing. It comes to a different file:

2013-02-19 15:04:53,788 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/login.action, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-02-19 15:04:53,788 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/login.action, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-02-19 15:04:53,790 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-02-19 15:04:53,790 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-02-19 15:04:53,791 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication. 2013-02-19 15:04:53,791 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication. 2013-02-19 15:04:53,792 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] loginFailed Login failed for user null. request=com.atlassian.seraph.filter.BaseLoginFilter$SecurityHttpRequestWrapper@1b79649, username=null, remoteHost=128.214.228.83, remoteIP=128.214.228.83, reason=NoUsername 2013-02-19 15:04:53,792 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] loginFailed Login failed for user null. request=com.atlassian.seraph.filter.BaseLoginFilter$SecurityHttpRequestWrapper@1b79649, username=null, remoteHost=128.214.228.83, remoteIP=128.214.228.83, reason=NoUsername 2013-02-19 15:04:53,813 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Authenticator is returning null from call to public Principal getUser(HttpServletRequest request, HttpServletResponse response) 2013-02-19 15:04:53,813 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Authenticator is returning null from call to public Principal getUser(HttpServletRequest request, HttpServletResponse response) 2013-02-19 15:04:53,847 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/login.action, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-02-19 15:04:53,847 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/login.action, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-02-19 15:04:53,848 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-02-19 15:04:53,848 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-02-19 15:04:53,849 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication. 2013-02-19 15:04:53,849 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication. 2013-02-19 15:04:53,849 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] loginFailed Login failed for user null. request=com.atlassian.seraph.filter.BaseLoginFilter$SecurityHttpRequestWrapper@1b79649, username=null, remoteHost=128.214.228.83, remoteIP=128.214.228.83, reason=NoUsername 2013-02-19 15:04:53,849 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] loginFailed Login failed for user null. request=com.atlassian.seraph.filter.BaseLoginFilter$SecurityHttpRequestWrapper@1b79649, username=null, remoteHost=128.214.228.83, remoteIP=128.214.228.83, reason=NoUsername 2013-02-19 15:04:53,850 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Authenticator is returning null from call to public Principal getUser(HttpServletRequest request, HttpServletResponse response) 2013-02-19 15:04:53,850 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Authenticator is returning null from call to public Principal getUser(HttpServletRequest request, HttpServletResponse response) 2013-02-19 15:04:53,854 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/login.action, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-02-19 15:04:53,854 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/login.action, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-02-19 15:04:53,855 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-02-19 15:04:53,855 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-02-19 15:04:53,856 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication. 2013-02-19 15:04:53,856 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication. 2013-02-19 15:04:53,858 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] loginFailed Login failed for user null. request=com.atlassian.plugin.servlet.PluginHttpRequestWrapper@19fd297, username=null, remoteHost=128.214.228.83, remoteIP=128.214.228.83, reason=NoUsername 2013-02-19 15:04:53,858 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] loginFailed Login failed for user null. request=com.atlassian.plugin.servlet.PluginHttpRequestWrapper@19fd297, username=null, remoteHost=128.214.228.83, remoteIP=128.214.228.83, reason=NoUsername 2013-02-19 15:04:53,859 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Authenticator is returning null from call to public Principal getUser(HttpServletRequest request, HttpServletResponse response) 2013-02-19 15:04:53,859 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Authenticator is returning null from call to public Principal getUser(HttpServletRequest request, HttpServletResponse response) 2013-02-19 15:04:53,859 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/login.action, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-02-19 15:04:53,859 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/login.action, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-02-19 15:04:53,860 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-02-19 15:04:53,860 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-02-19 15:04:53,861 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication. 2013-02-19 15:04:53,861 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication. 2013-02-19 15:04:53,861 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] loginFailed Login failed for user null. request=com.atlassian.plugin.servlet.PluginHttpRequestWrapper@19fd297, username=null, remoteHost=128.214.228.83, remoteIP=128.214.228.83, reason=NoUsername 2013-02-19 15:04:53,861 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] loginFailed Login failed for user null. request=com.atlassian.plugin.servlet.PluginHttpRequestWrapper@19fd297, username=null, remoteHost=128.214.228.83, remoteIP=128.214.228.83, reason=NoUsername 2013-02-19 15:04:53,862 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Authenticator is returning null from call to public Principal getUser(HttpServletRequest request, HttpServletResponse response) 2013-02-19 15:04:53,862 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Authenticator is returning null from call to public Principal getUser(HttpServletRequest request, HttpServletResponse response) 2013-02-19 15:04:54,104 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/login.action, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-02-19 15:04:54,104 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/login.action, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-02-19 15:04:54,106 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-02-19 15:04:54,106 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-02-19 15:04:54,107 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication. 2013-02-19 15:04:54,107 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication. 2013-02-19 15:04:54,108 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] loginFailed Login failed for user null. request=com.atlassian.plugin.servlet.PluginHttpRequestWrapper@19fd297, username=null, remoteHost=128.214.228.83, remoteIP=128.214.228.83, reason=NoUsername 2013-02-19 15:04:54,108 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] loginFailed Login failed for user null. request=com.atlassian.plugin.servlet.PluginHttpRequestWrapper@19fd297, username=null, remoteHost=128.214.228.83, remoteIP=128.214.228.83, reason=NoUsername 2013-02-19 15:04:54,109 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Authenticator is returning null from call to public Principal getUser(HttpServletRequest request, HttpServletResponse response) 2013-02-19 15:04:54,109 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Authenticator is returning null from call to public Principal getUser(HttpServletRequest request, HttpServletResponse response) 2013-02-19 15:04:54,417 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/login.action, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-02-19 15:04:54,417 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/login.action, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-02-19 15:04:54,419 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-02-19 15:04:54,419 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-02-19 15:04:54,420 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication. 2013-02-19 15:04:54,420 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication. 2013-02-19 15:04:54,423 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] loginFailed Login failed for user null. request=com.atlassian.plugin.servlet.PluginHttpRequestWrapper@19fd297, username=null, remoteHost=128.214.228.83, remoteIP=128.214.228.83, reason=NoUsername 2013-02-19 15:04:54,423 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] loginFailed Login failed for user null. request=com.atlassian.plugin.servlet.PluginHttpRequestWrapper@19fd297, username=null, remoteHost=128.214.228.83, remoteIP=128.214.228.83, reason=NoUsername 2013-02-19 15:04:54,425 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Authenticator is returning null from call to public Principal getUser(HttpServletRequest request, HttpServletResponse response) 2013-02-19 15:04:54,425 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Authenticator is returning null from call to public Principal getUser(HttpServletRequest request, HttpServletResponse response) 2013-02-19 15:04:54,521 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/login.action, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-02-19 15:04:54,521 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/login.action, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-02-19 15:04:54,523 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-02-19 15:04:54,523 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-02-19 15:04:54,524 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication. 2013-02-19 15:04:54,524 DEBUG [TP-Processor3] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication.

garysweaver commented 11 years ago

I can definitely see the code changes now that caused the problem, and you probably can too.

Georg had provided this patch to get local login working: https://github.com/chauth/confluence_http_authenticator/commit/d38af85bc058a80575accf1a56f0a9b0cfa23eb3#src/main/java/shibauth/confluence/authentication/shibboleth/RemoteUserAuthenticator.java

But then in the process of trying to get Joe/Atlassian's changes in, a lot of that changed: https://github.com/chauth/confluence_http_authenticator/commit/2729a0936b2cf9914e648a53bf3b39b995bf3b6d#src/main/java/shibauth/confluence/authentication/shibboleth/RemoteUserAuthenticator.java

Will try to get in a fix soon, but does 2.1.15 work for you? If so, please use it for now: https://github.com/chauth/confluence_http_authenticator/blob/master/releases/remoteUserAuth-2.1.15.jar

If not, let me know.

Sorry for the trouble. I'm fairly sure that when I took that code out it was because of compilation issues and API changes rather than me trying to intentionally remove Georg's code, but I should have noticed that it was evicerating his code when I looked at the diff. It's much easier to see what I did now that we have the nice GitHub diffs.

erkkiaalto commented 11 years ago

2.1.15 works perfectly in our production environment. I was just testing without any urgent practical need. (Probably not ugrading to 5.x before Christmas)

erkkiaalto commented 11 years ago

I tested with authheticator 2.2.0 and Confluence 5.0.1. Local login still not working. Logs say this:

2013-03-08 10:27:06,820 DEBUG [TP-Processor5] [atlassian.seraph.filter.BaseLoginFilter] doFilter doFilter : Attempting login for : '/dologin.action' 2013-03-08 10:27:06,821 DEBUG [TP-Processor5] [atlassian.seraph.filter.PasswordBasedLoginFilter] login login : 'admin' and password provided - remember me : false - attempting login request 2013-03-08 10:27:06,823 DEBUG [TP-Processor5] [atlassian.seraph.filter.PasswordBasedLoginFilter] runAuthentication runAuthentication : 'admin' does not require elevated security check. Attempting authentication... 2013-03-08 10:27:06,824 DEBUG [TP-Processor5] [confluence.authentication.shibboleth.RemoteUserAuthenticator] login login(...) called. requestURL=https://nautawiki.it.helsinki.fi/dologin.action, username=admin, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-03-08 10:27:06,825 DEBUG [TP-Processor5] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-03-08 10:27:06,825 DEBUG [TP-Processor5] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-03-08 10:27:06,826 DEBUG [TP-Processor5] [confluence.authentication.shibboleth.RemoteUserAuthenticator] login Remote user was null or empty. 2013-03-08 10:27:06,827 DEBUG [TP-Processor5] [confluence.authentication.shibboleth.RemoteUserAuthenticator] login Trying local login for user admin 2013-03-08 10:27:06,831 DEBUG [TP-Processor5] [net.sf.hibernate.SQL] log select this.id as id0_, this.user_id as userid0, this.directory_id as director30, this.attribute_name as attribut40, this.attribute_value as attribut50, this.attribute_lower_value as attribut60 from cwd_user_attribute this where this.user_id=? 2013-03-08 10:27:07,158 DEBUG [TP-Processor5] [net.sf.hibernate.SQL] log update cwd_user_attribute set user_id=?, directory_id=?, attribute_name=?, attribute_value=?, attribute_lower_value=? where id=? 2013-03-08 10:27:07,204 INFO [TP-Processor5] [atlassian.confluence.cache.DeferredOperationsCache] sync Synchronising deferred operations (0 put, 1 remove) to cache [com.atlassian.confluence.user.crowd.CachedCrowdUserDao.ATTRIBUTECACHE] 2013-03-08 10:27:07,206 DEBUG [TP-Processor5] [atlassian.seraph.auth.DefaultAuthenticator] login login : 'admin' has been authenticated 2013-03-08 10:27:07,207 DEBUG [TP-Processor5] [atlassian.seraph.auth.DefaultAuthenticator] authoriseUserAndEstablishSession authoriseUser : 'admin' can login according to the RoleMapper 2013-03-08 10:27:07,210 DEBUG [TP-Processor5] [atlassian.seraph.auth.SessionInvalidator] dumpInfo invalidating session from request: POST 948875E0E59353E48DC7B366253A04BB /dologin.action 2013-03-08 10:27:07,211 DEBUG [TP-Processor5] [atlassian.seraph.auth.SessionInvalidator] dumpInfo session attribute: atlassian.xsrf.token 2013-03-08 10:27:07,212 DEBUG [TP-Processor5] [atlassian.seraph.auth.SessionInvalidator] dumpInfo session attribute: com.atlassian.labs.botkiller.BotKiller 2013-03-08 10:27:07,214 DEBUG [TP-Processor5] [confluence.authentication.shibboleth.RemoteUserAuthenticator] loginSuccessful Logging in user admin. request=com.atlassian.seraph.filter.BaseLoginFilter$SecurityHttpRequestWrapper@311587, response=com.atlassian.oauth.serviceprovider.internal.servlet.OAuthFilter$OAuthWWWAuthenticateAddingResponse@7c71f7, username=admin, user=com.atlassian.confluence.user.crowd.CachedCrowdUser@198cc6f, user.getName=admin, remoteHost=128.214.228.83, remoteIP=128.214.228.83 2013-03-08 10:27:07,218 DEBUG [TP-Processor5] [net.sf.hibernate.SQL] log select userlogini0.id as id, userlogini0.CURFAILED as CURFAILED, userlogini0.TOTALFAILED as TOTALFAI3, userlogini0.SUCCESSDATE as SUCCESSD4, userlogini0.PREVSUCCESSDATE as PREVSUCC5, userlogini0.FAILEDDATE as FAILEDDATE, userlogini0.USERNAME as USERNAME from logininfo userlogini0 where (userlogini0.USERNAME=? ) 2013-03-08 10:27:07,222 DEBUG [TP-Processor5] [net.sf.hibernate.SQL] log update logininfo set CURFAILED=?, TOTALFAILED=?, SUCCESSDATE=?, PREVSUCCESSDATE=?, FAILEDDATE=?, USERNAME=? where id=? 2013-03-08 10:27:07,232 DEBUG [TP-Processor5] [confluence.authentication.shibboleth.RemoteUserAuthenticator] login Authenticator is returning true from call to public boolean login(HttpServletRequest request, HttpServletResponse response, String username, String password, boolean cookie) 2013-03-08 10:27:07,233 DEBUG [TP-Processor5] [atlassian.seraph.filter.PasswordBasedLoginFilter] runAuthentication runAuthentication : 'admin' was successfully authenticated 2013-03-08 10:27:07,234 DEBUG [TP-Processor5] [net.sf.hibernate.SQL] log select userlogini0.id as id, userlogini0.CURFAILED as CURFAILED, userlogini0.TOTALFAILED as TOTALFAI3, userlogini0.SUCCESSDATE as SUCCESSD4, userlogini0.PREVSUCCESSDATE as PREVSUCC5, userlogini0.FAILEDDATE as FAILEDDATE, userlogini0.USERNAME as USERNAME from logininfo userlogini0 where (userlogini0_.USERNAME=? ) 2013-03-08 10:27:07,236 DEBUG [TP-Processor5] [net.sf.hibernate.SQL] log update logininfo set CURFAILED=?, TOTALFAILED=?, SUCCESSDATE=?, PREVSUCCESSDATE=?, FAILEDDATE=?, USERNAME=? where id=? 2013-03-08 10:27:07,239 DEBUG [TP-Processor5] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/dologin.action, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-03-08 10:27:07,239 DEBUG [TP-Processor5] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-03-08 10:27:07,240 DEBUG [TP-Processor5] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-03-08 10:27:07,241 DEBUG [TP-Processor5] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication. 2013-03-08 10:27:07,242 DEBUG [TP-Processor5] [confluence.authentication.shibboleth.RemoteUserAuthenticator] loginFailed Login failed for user null. request=com.atlassian.plugin.servlet.PluginHttpRequestWrapper@1e75b86, username=null, remoteHost=128.214.228.83, remoteIP=128.214.228.83, reason=NoUsername 2013-03-08 10:27:07,243 DEBUG [TP-Processor5] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Authenticator is returning null from call to public Principal getUser(HttpServletRequest request, HttpServletResponse response) 2013-03-08 10:27:07,244 DEBUG [TP-Processor5] [atlassian.seraph.filter.BaseLoginFilter] doFilter doFilter : Login completed for 'null' - os_authstatus = 'success' 2013-03-08 10:27:07,245 DEBUG [TP-Processor5] [atlassian.seraph.filter.BaseLoginFilter] redirectToOriginalDestination redirectToOriginalDestination : Login redirect to: / 2013-03-08 10:27:07,253 DEBUG [TP-Processor8] [atlassian.seraph.cookie.DefaultCookieHandler] getCookie Looking for a cookie named : 'confluence-language' 2013-03-08 10:27:07,253 DEBUG [TP-Processor8] [atlassian.seraph.cookie.DefaultCookieHandler] getCookie No cookie was found with name :confluence-language 2013-03-08 10:27:07,255 DEBUG [TP-Processor8] [atlassian.seraph.filter.BaseLoginFilter] doFilter doFilter : Attempting login for : '/default.jsp' 2013-03-08 10:27:07,255 DEBUG [TP-Processor8] [atlassian.seraph.filter.PasswordBasedLoginFilter] login login : No user name or password was returned. No authentication attempt will be made. User may still be found via a SecurityFilter later. 2013-03-08 10:27:07,256 DEBUG [TP-Processor8] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-03-08 10:27:07,257 DEBUG [TP-Processor8] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-03-08 10:27:07,258 DEBUG [TP-Processor8] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-03-08 10:27:07,259 DEBUG [TP-Processor8] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication. 2013-03-08 10:27:07,259 DEBUG [TP-Processor8] [confluence.authentication.shibboleth.RemoteUserAuthenticator] loginFailed Login failed for user null. request=com.atlassian.plugin.servlet.PluginHttpRequestWrapper@ae740, username=null, remoteHost=128.214.228.83, remoteIP=128.214.228.83, reason=NoUsername 2013-03-08 10:27:07,261 DEBUG [TP-Processor8] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Authenticator is returning null from call to public Principal getUser(HttpServletRequest request, HttpServletResponse response) 2013-03-08 10:27:07,261 DEBUG [TP-Processor8] [atlassian.seraph.filter.BaseLoginFilter] doFilter doFilter : Login completed for 'null' - os_authstatus = 'null' 2013-03-08 10:27:07,262 DEBUG [TP-Processor8] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : Storing the originally requested URL (atlassian.core.seraph.original.url=/default.jsp) 2013-03-08 10:27:07,263 DEBUG [TP-Processor8] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : requiredRoles = [] 2013-03-08 10:27:07,264 DEBUG [TP-Processor8] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-03-08 10:27:07,264 DEBUG [TP-Processor8] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-03-08 10:27:07,265 DEBUG [TP-Processor8] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-03-08 10:27:07,266 DEBUG [TP-Processor8] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication. 2013-03-08 10:27:07,267 DEBUG [TP-Processor8] [confluence.authentication.shibboleth.RemoteUserAuthenticator] loginFailed Login failed for user null. request=com.atlassian.seraph.filter.BaseLoginFilter$SecurityHttpRequestWrapper@1aaae60, username=null, remoteHost=128.214.228.83, remoteIP=128.214.228.83, reason=NoUsername 2013-03-08 10:27:07,268 DEBUG [TP-Processor8] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Authenticator is returning null from call to public Principal getUser(HttpServletRequest request, HttpServletResponse response) 2013-03-08 10:27:07,269 DEBUG [TP-Processor8] [atlassian.seraph.filter.SecurityFilter] doFilter doFilter : Setting Auth Context to be 'anonymous ' 2013-03-08 10:27:07,270 DEBUG [TP-Processor8] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-03-08 10:27:07,271 DEBUG [TP-Processor8] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-03-08 10:27:07,271 DEBUG [TP-Processor8] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched. 2013-03-08 10:27:07,272 DEBUG [TP-Processor8] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Remote user was null or empty, can not perform authentication. 2013-03-08 10:27:07,273 DEBUG [TP-Processor8] [confluence.authentication.shibboleth.RemoteUserAuthenticator] loginFailed Login failed for user null. request=com.atlassian.plugin.servlet.PluginHttpRequestWrapper@ae740, username=null, remoteHost=128.214.228.83, remoteIP=128.214.228.83, reason=NoUsername 2013-03-08 10:27:07,274 DEBUG [TP-Processor8] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser Authenticator is returning null from call to public Principal getUser(HttpServletRequest request, HttpServletResponse response) 2013-03-08 10:27:07,288 DEBUG [TP-Processor1] [atlassian.seraph.cookie.DefaultCookieHandler] getCookie Looking for a cookie named : 'confluence-language' 2013-03-08 10:27:07,288 DEBUG [TP-Processor1] [atlassian.seraph.cookie.DefaultCookieHandler] getCookie No cookie was found with name :confluence-language 2013-03-08 10:27:07,290 DEBUG [TP-Processor1] [atlassian.seraph.filter.BaseLoginFilter] doFilter doFilter : ____ Attempting login for : '/homepage.action' 2013-03-08 10:27:07,291 DEBUG [TP-Processor1] [atlassian.seraph.filter.PasswordBasedLoginFilter] login login : No user name or password was returned. No authentication attempt will be made. User may still be found via a SecurityFilter later. 2013-03-08 10:27:07,291 DEBUG [TP-Processor1] [confluence.authentication.shibboleth.RemoteUserAuthenticator] getUser getUser(...) called. requestURL=https://nautawiki.it.helsinki.fi/homepage.action, remoteIP=128.214.228.83, remoteHost=128.214.228.83 2013-03-08 10:27:07,292 DEBUG [TP-Processor1] [atlassian.seraph.auth.DefaultAuthenticator] getUserFromCookie getUserFromCookie : Got username : 'null' from cookie, attempting to authenticate user is known 2013-03-08 10:27:07,293 DEBUG [TP-Processor1] [confluence.authentication.shibboleth.RemoteUserAuthenticator] createSafeUserid Remote user is returned as is, mappers do not matched.

garysweaver commented 11 years ago

Yes, this is known. This issue is still not fixed. Thanks for testing it. Are you planning to upgrade to 5.0 quickly?

erkkiaalto commented 11 years ago

No, I just started testing 5.x early to find possible problems in time.

garysweaver commented 11 years ago

Once I have time, I hope to try to fix this issue in the 2.1.x (Confluence 4.1.x-4.x) and 2.2.x (Confluence 5.0.x) branches. I know what was done between 2.1.15 and 2.1.16, so I can try to reapply the fix. I'm not absolutely certain, though.

KatiKomulainen commented 11 years ago

Any news about this issue? We are trying to install Confluence 5.0 with HTTP authenticator and enable access for local users also.

erkkiaalto commented 11 years ago

I have now a suggestion for a fix:

These lines to getUser:

final Principal localUser = super.getUser(request,response); if (localUser != null) { if (log.isDebugEnabled()) { log.debug(String.format("Login for user %s succeeded via local login", localUser.getName())); } return localUser; }

At least in our small test system this broke nothing.

garysweaver commented 11 years ago

integrated patch into master, thanks!

garysweaver commented 11 years ago

released in v2.3.0