This appears to be caused by the recent change to dispose-window: it is now a standard JSF form post for increased compatibility; however, this means that the JSF lifecycle may be attempted after the session has expired. The dispose-window logic needs to be made aware of session validity and should exit immediately if a session is not available.

Assigning to Deryk for assignment.

The logging level of a window ID mismatch has been reduced to FINE since these mismatches are expected to occur on every session timeout.

The second stack trace in the description is still logged but it appears to be a JSF issue. Moving to 2.0 so that we can investigate the cause more precisely and determine what we might be able to do.

Additional logging in ExtendedExceptionHandler shows that the logging is actually being produced within the wrapped ExceptionHandler. Looking at the code there, it appears that FacesException subclasses are perhaps not logged.

Exception published
org.icefaces.application.SessionExpiredException: Session has expired
at org.icefaces.impl.application.ExtendedExceptionHandler.handle(ExtendedExceptionHandler.java:103)
at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:115)
at com.sun.faces.lifecycle.RestoreViewPhase.doPhase(RestoreViewPhase.java:107)
at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:114)
at javax.faces.webapp.FacesServlet.service(FacesServlet.java:308)
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:233)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:852)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
at java.lang.Thread.run(Thread.java:637)
getWrapped.handle

SessionExpiredExceptions are still encountered:

org.icefaces.application.SessionExpiredException: Session has expired
at org.icefaces.impl.application.ExtendedExceptionHandler.handle(ExtendedExceptionHandler.java:103)
at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:115)
at com.sun.faces.lifecycle.RestoreViewPhase.doPhase(RestoreViewPhase.java:107)
at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:114)
at javax.faces.webapp.FacesServlet.service(FacesServlet.java:308)
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:233)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:857)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
at java.lang.Thread.run(Thread.java:637)

org.icefaces.application.SessionExpiredException: Session has expired
at org.icefaces.impl.application.SessionExpiredListener.sessionDestroyed(SessionExpiredListener.java:61)
at org.apache.catalina.session.StandardSession.expire(StandardSession.java:708)
at org.apache.catalina.session.StandardSession.expire(StandardSession.java:643)
at org.apache.catalina.session.StandardSession.invalidate(StandardSession.java:1148)
at org.apache.catalina.session.StandardSessionFacade.invalidate(StandardSessionFacade.java:150)
at com.sun.faces.context.ExternalContextImpl.invalidateSession(ExternalContextImpl.java:654)
at org.icefaces.impl.application.SessionTimeoutMonitor.isResourceRequest(SessionTimeoutMonitor.java:68)
at org.icefaces.impl.push.servlet.ICEpushResourceHandler.isResourceRequest(ICEpushResourceHandler.java:134)
at org.icefaces.impl.push.DynamicResourceDispatcher.isResourceRequest(DynamicResourceDispatcher.java:107)
at javax.faces.application.ResourceHandlerWrapper.isResourceRequest(ResourceHandlerWrapper.java:131)
at org.icefaces.impl.application.WindowScopeManager.isResourceRequest(WindowScopeManager.java:115)
at org.icefaces.impl.util.CharacterEncodingHandler.isResourceRequest(CharacterEncodingHandler.java:71)
at javax.faces.webapp.FacesServlet.service(FacesServlet.java:305)
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:233)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:857)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
at java.lang.Thread.run(Thread.java:637)

Please note that the SessionExpiryExceptions are not a caused by for the RuntimeException

Additionally these SessionExpiryExceptions don't seem to have a log timestamp preceding it.

I had to hunt around quite a bit to see where this was being dumped out from. It turns out that it's in the com.sun.faces.context.AjaxExceptionHandlerImp. Then handle method has this bit of logic:

public void handle() throws FacesException {

for (Iterator<ExceptionQueuedEvent> i = getUnhandledExceptionQueuedEvents().iterator(); i.hasNext(); ) {
ExceptionQueuedEvent event = i.next();
ExceptionQueuedEventContext context = (ExceptionQueuedEventContext) event.getSource();
try {
Throwable t = context.getException();
if (isRethrown(t)) {
handled = event;
t.printStackTrace();

I put my own System.out in there to make sure:

AjaxExceptionHandlerImpl.handle: org.icefaces.application.SessionExpiredException: the session has expired (published)
org.icefaces.application.SessionExpiredException: the session has expired (published)
at org.icefaces.impl.application.ExtendedExceptionHandler.handle(ExtendedExceptionHandler.java:103)
at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:115)
at com.sun.faces.lifecycle.RestoreViewPhase.doPhase(RestoreViewPhase.java:107)
at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:114)
at javax.faces.webapp.FacesServlet.service(FacesServlet.java:308)
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:233)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:849)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:454)
at java.lang.Thread.run(Thread.java:637)

Now moving on to what can be done about it.

So in checking the mojarra repository for the history of the line of code that prints the stack trace, I discovered that it occurs as part of a large merge of state saving code back into the trunk

6845 16/03/09 10:23 PM rlubke Merge STATE_SAVING_20081211 to trunk

It looks like it may have been some debugging code that was perhaps left in inadvertently. I found it on the 2.0.4 branch as well as the trunk but not really sure why it's there.

So the printStackTrace in the Mojarra code is one issue.

Another is the inability to determine whether or not a session is "valid". In the code we use to morph a ViewExpiredException into a SessionExpiredException, we'd like to be able to determine if a session is currently valid. However, it seem that in a couple of our resource handlers, we are using this call

ExternalContext.getSessionMap()

which automatically creates a new session if one doesn't yet exist. Now trying to determine if this is the behaviour we want or not.

There are a couple of places where we use the following call in our ResourceHandlers:

Map sessionMap = externalContext.getSessionMap();

WindowScopeManager is the main one (but also SessionTimeoutMonitor). This method, according to the JavaDoc, will automatically create a session of a valid one is not available. Because of this, we may be inadvertently creating sessions when we shouldn't be. For example, right after a session expires, the next request is going through our resource handlers and a new session is created immediately.

There is currently another JIRA (http://jira.icefaces.org/browse/ICE-6189) for looking at lazy instantiation of Window Scope. As part of this work, we should ensure that session creation is not done unless absolutely necessary. Once that is complete, we can revist the strategy for sending Session Expired messages to the client. It may be that we turn it off or make it configurable.

For the spurious stack trace in the Mojarra class, I've opened a ticket in their system:

https://mojarra.dev.java.net/issues/show_bug.cgi?id=4

Looks like the original case that I logged got lost in the transition to the new JIRA tracking system to I opened another ticket:

http://java.net/jira/browse/JAVASERVERFACES-1883.

This is a Mojarra JSF bug.