Unexpected logout after a few clicks (Alfresco 2.0 Preview)

[mruflin]

I tried to install the Alfresco 2.0 Preview (zip version as well as bundled windows installer), but face a rather strange problem:

After clicking through a couple of pages (1 .. 4), I get directly redirected to the login page. Trying to relogin with admin:admin, I get a "Unable to login - unknown username/password." message.

Then, if I try to go back to the main url (http://localhost:8080/alfresco/), I get following exception:

net.sf.acegisecurity.AuthenticationCredentialsNotFoundException: A valid SecureContext was not provided in the RequestContext
at net.sf.acegisecurity.intercept.AbstractSecurityInterceptor.credentialsNotFound(AbstractSecurityInterceptor.java:477)
at net.sf.acegisecurity.intercept.AbstractSecurityInterceptor.beforeInvocation(AbstractSecurityInterceptor.java:355)
at net.sf.acegisecurity.intercept.method.aopalliance.MethodSecurityInterceptor.invoke(MethodSecurityInterceptor.java:77)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:170)
at org.alfresco.repo.security.permissions.impl.ExceptionTranslatorMethodInterceptor.invoke(ExceptionTranslatorMethodInterceptor.java:41)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:170)
at org.alfresco.repo.audit.AuditComponentImpl.auditImpl(AuditComponentImpl.java:211)
at org.alfresco.repo.audit.AuditComponentImpl.audit(AuditComponentImpl.java:157)
at org.alfresco.repo.audit.AuditMethodInterceptor.invoke(AuditMethodInterceptor.java:61)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:170)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:170)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:176)
at $Proxy14.getProperty(Unknown Source)
at org.alfresco.web.bean.repository.Preferences.getValue(Preferences.java:67)
at org.apache.jsp.index_jsp._jspService(index_jsp.java:84)
at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:98)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:390)
at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:320)
at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:266)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:228)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:212)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:844)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:634)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:445)
at java.lang.Thread.run(Thread.java:619)

I'm using the Jan 19. release, in the zip archive version with MySQL, in the  installer version HSQL.

I'm wondering if somebody else experienced this problem or could give me some hints how to fix it.

Thanks a lot,

Michael

Update: Similar behaviour with the linux alfresco 2.0 preview installer on a different machine, but far less often.

[mruflin]

Copied from the tomcat generated index.jsp:

84: // override with the users preference if they have one
85: User user = 86: (User)session.getAttribute(AuthenticationHelper.AUTHENTICATION_USER);
86: if (user != null && (user.getUserName().equals(PermissionService.GUEST_AUTHORITY) == : false))
87: {
88: // ensure construction of the FacesContext before attemping a service call
89: FacesContext fc = FacesHelper.getFacesContext(request, response, application);
90: String preference = (String)PreferencesService.getPreferences(fc).getValue("start-location");
91: if (preference != null)
‍‍‍‍‍‍‍‍‍‍

The stack trace changed of course, it's now line 90, not 84 🙂

net.sf.acegisecurity.AuthenticationCredentialsNotFoundException: A valid SecureContext was not provided in the RequestContext
at net.sf.acegisecurity.intercept.AbstractSecurityInterceptor.credentialsNotFound(AbstractSecurityInterceptor.java:477)
at net.sf.acegisecurity.intercept.AbstractSecurityInterceptor.beforeInvocation(AbstractSecurityInterceptor.java:355)
at net.sf.acegisecurity.intercept.method.aopalliance.MethodSecurityInterceptor.invoke(MethodSecurityInterceptor.java:77)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:170)
at org.alfresco.repo.security.permissions.impl.ExceptionTranslatorMethodInterceptor.invoke(ExceptionTranslatorMethodInterceptor.java:41)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:170)
at org.alfresco.repo.audit.AuditComponentImpl.auditImpl(AuditComponentImpl.java:211)
at org.alfresco.repo.audit.AuditComponentImpl.audit(AuditComponentImpl.java:157)
at org.alfresco.repo.audit.AuditMethodInterceptor.invoke(AuditMethodInterceptor.java:61)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:170)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:170)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:176)
at $Proxy14.getProperty(Unknown Source)
at org.alfresco.web.bean.repository.Preferences.getValue(Preferences.java:67)
at org.apache.jsp.index_jsp._jspService(index_jsp.java:90)
at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:98)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:390)
at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:320)
at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:266)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:228)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:212)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:844)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:634)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:445)
at java.lang.Thread.run(Thread.java:595) 
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

Please note that this provoked exception is not the root cause of the whole problem. http://localhost:8080/alfresco/faces/jsp/login.jsp doesn't allow to log in with admin:admin anymore once alfresco kicks you out.

Actually I found an even simpler way to reproduce my problem:
1. log in as admin:admin
2. log out
3. log in -> fails!

Following the tomcat output (maybe I oversee something here)

CompilerOracle: exclude org/apache/lucene/index/IndexReader$1 doBody
CompilerOracle: exclude org/alfresco/repo/search/impl/lucene/index/IndexInfo$Merger mergeIndexes
CompilerOracle: exclude org/alfresco/repo/search/impl/lucene/index/IndexInfo$Merger mergeDeletions
01.02.2007 14:29:54 org.apache.catalina.core.AprLifecycleListener init
INFO: The Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: C:\Programs\jdk1.5.0\bin;.;C:\WINDOWS\system32;C:\WINDOWS;C:\Programs\CollabNetSubversion;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program File
s\Wave Systems Corp\Dell Preboot Manager\Access Client\v5\;C:\Programs\CollabNetSubversion;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program Files\Wave Systems Corp\Dell Preboot Manager\Access Client\v5\;C:\Programs\MySQLServer5.0\bin;C:\php;C:\Programs\dlls;C:\Programs\svn-win32-1.
3.2\bin;C:\Programs\apache-ant-1.7.0\bin
01.02.2007 14:29:54 org.apache.coyote.http11.Http11Protocol init
INFO: Initializing Coyote HTTP/1.1 on http-8080
01.02.2007 14:29:54 org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 781 ms
01.02.2007 14:29:54 org.apache.catalina.core.StandardService start
INFO: Starting service Catalina
01.02.2007 14:29:54 org.apache.catalina.core.StandardEngine start
INFO: Starting Servlet Engine: Apache Tomcat/6.0.7
01.02.2007 14:29:54 org.apache.catalina.core.StandardHost start
INFO: XML validation disabled
01.02.2007 14:29:54 org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive alfresco.war
14:30:40,128 WARN  [remoting.rmi.RmiRegistryFactoryBean] Could not detect RMI registry - creating new one
14:31:01,550 WARN  [remoting.rmi.RmiServiceExporter] Could not detect RMI registry - creating new one
14:31:03,957 WARN  [alfresco.util.OpenOfficeConnectionTester] A connection to OpenOffice could not be established.
14:31:10,082 INFO  [repo.admin.ConfigurationChecker] The Alfresco root data directory ('dir.root') is: c:\Work\AlfrescoSVN\alf_data
14:31:10,253 INFO  [admin.patch.PatchExecuter] Checking for patches to apply …
14:31:10,285 INFO  [admin.patch.PatchExecuter] No patches were required.
14:31:10,285 INFO  [repo.module.ModuleServiceImpl] Found 0 module(s).
14:31:10,550 INFO  [service.descriptor.DescriptorService] Alfresco JVM - v1.5.0_11-b03; maximum heap size 493.063MB
14:31:10,550 WARN  [service.descriptor.DescriptorService] Alfresco JVM - WARNING - maximum heap size 493.063MB is less than recommended 512MB
14:31:10,550 INFO  [service.descriptor.DescriptorService] Alfresco started (Community Network): Current version 2.0.0 (Preview @build-number@) schema 35 - Installed version 2.0.0 (Preview @build-number@) schema 35
01.02.2007 14:31:12 org.apache.coyote.http11.Http11Protocol start
INFO: Starting Coyote HTTP/1.1 on http-8080
01.02.2007 14:31:12 org.apache.jk.common.ChannelSocket init
INFO: JK: ajp13 listening on /0.0.0.0:8009
01.02.2007 14:31:12 org.apache.jk.server.JkMain start
INFO: Jk running ID=0 time=0/328  config=null
01.02.2007 14:31:12 org.apache.catalina.startup.Catalina start
INFO: Server startup in 78000 ms
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

I know OO is not running, but I had the same problem with running OO.

Given that I'm not the only one with that problem, it makes probably sense to investigate this further. If it helps, I can enable log4j or put a printStackTrace into whatever code you like.

Michael

[kevinr]

going back to :http://localhost:8080/alfresco/ i get:

java.lang.NullPointerException

Hide Details

java.lang.NullPointerException
at org.springframework.web.jsf.FacesContextUtils.getWebApplicationContext(FacesContextUtils.java:47)
at org.springframework.web.jsf.FacesContextUtils.getRequiredWebApplicationContext(FacesContextUtils.java:77)
at org.alfresco.web.bean.repository.Repository.getConfigurableService(Repository.java:433)
at org.alfresco.web.bean.repository.User.getUserPreferencesRef(User.java:176)
at org.alfresco.web.bean.repository.User.getPreferences(User.java:160)
at org.alfresco.web.bean.repository.PreferencesService.getPreferences(PreferencesService.java:61)
at org.apache.jsp.index_jsp._jspService(index_jsp.java:73)
…

The solution I posted fixes issue quoted above. The SecurityContext issue you mention was a problem with transaction wrappers around AuthenticationService methods that caused issues in the 2.0 preview but were fixed last week. The code in HEAD should not have this issue. Our QA department cannot reproduce either issue with the latest code including my fix.

>I applied the diff onto the current trunk (revision 459), but the problem still exists.
Very strange! We cannot reproduce the issue on any machine here now. I assume if you create a fresh Alfresco instance from the latest SVN source (which should include the latest fix now) then you still get the problem?

Thanks,

Kevin

[mruflin]

> Very strange! We cannot reproduce the issue on any machine here now. I assume if you create a fresh Alfresco instance from the latest SVN source (which should include the latest fix now) then you still get the problem?

Yes I do, indeed very strange.

Even stranger is the fact that the 2.0 Preview build works on my machine - but only if I log in with German.

Hard to know whether this is all my fault or a bug 😞
Somebody else building from sources and experiencing this problem?

[kevinr]

Can you tell me what is the default locale of the server machine English or German? And what does your web-client-config languages override look like? I'm just asking to try and completely reproduce your situation as maybe there is a case we have missed.

Thanks,

Kevin

[mruflin]

The version that is working with german locale is the 2.0 preview:

AlfrescoCommunity-2.0Preview-Setup.exe as of January 19th.
Choose German as installation language, default database and location.

I haven't tried the german trick with the current sources yet, will try to do that later today (to see whether this is just a strange coincidence or not).

[mruflin]

I've switched now from Tomcat 6.0.7 to 5.5.20, together with MySQLServer5.0, English WinXp professional, regional settings set to German (Switzerland) with German (Switzerland) as default for non-unicode programs.

Same problem still exists, but again, using German as language I was able to use alfresco normally. Strangely it doesn't work with Spanish though…

I set up tomcat the following way:

- Compiled a new alfresco.war from yesterday's sources (ant build-tomcat)

- Copied shared/classes/alfresco folder from the 2.0 preview tomcat installation over to the new tomcat installation

- Deleted all xml files in /shared/classes/alfresco except /extension/web-client-config-custom.xml and the messages/*.properties

Thanks,

Michael

[derek]

http://issues.alfresco.com/browse/AWC-1138

I've managed to get similar-looking behaviour.  Hopefully it's the same thing and we can sort it out.

Regards

[kevinr]

We reproduced the issue in QA - it has been upgraded to a BLOCKER issue.

Thanks,

Kevin

[cj_deb]

I second that !

Unfortunately I just upgraded to final 2.0 GA and the problem still occurs.

Any update ?

Thx & cheers
Christian

[kevinr]

Are you 100% you fully upgraded - cleaned out all tmp and work folders etc. - can you confirm the version of Alfresco in the About dialog? I'm asking as I've just asked QA to confirm that the issue is not present and it is ok on both Community and Enterprise.

Thanks,

Kevin