JBoss EAP HTTP Sessions are not expiring or timing out as expected.
Environment
- Red Hat JBoss Enterprise Application Platform (EAP)
- 4.x
- 5.x
- 6.x
Issue
-
The session expiry time has been specified in the application's web.xml, but the actual time the session getd invalidated seems random. There are cases where it is still active after a couple of hours. The web.xml contains the following:
<session-config> <session-timeout>30</session-timeout> </session-config> -
Jboss is not cleaning up the expired sessions even after the timeout value for the session has reached
-
Sessions are expiring prematurely for certain applications. End users are getting kicked out of their session before the predetermined 30 minutes. It is as quick as 2 minutes, depending on seemingly random activity.
- We are facing frequent session timeouts in our application which is deployed over JBoss EAP 5.1.2 and having JBoss EWS as front end web server.
Resolution
-
A session will remain active as long as it is accessed within the timeout period at least once, which resets the counter for the timeout. If a session continues to stay open past the timeout period, this is typically an indication that the session is accessed at some point during that time period, or is continuing to be accessed thus preventing the session from timing out. See What is the session timeout hierarchy in JBoss EAP? for a full session timeout hierarchy.
-
However, it is also possible the
ContainerBackgroundProcessthread that expires abandoned sessions is hung or not working properly as the result of application code. In these cases it will be necessary to fix the application code at issue. -
If using async requests with very long timeouts, consider the following settings to allow expiration of a session in use by requests:
-Dorg.apache.catalina.STRICT_SERVLET_COMPLIANCE=false -Dorg.apache.catalina.session.StandardSession.ACTIVITY_CHECK=false
Root Cause
- Sessions will not expire by default if in use by a request. So you may need to consider long stalled requests or async requests with excessively long timeouts preventing session expiration.
- If using clustered SSO, check Clustered session and sso entry expire unexpectedly after a cluster member is stopped
- There is at least one issue we've seen with ATG code and problems expiring sessions. ATG appears inject itself and intercede in the default JBoss Web behaviour of expiring sessions. Whereas a typical thread dump will show the
ContainerBackgroundProcessorThread, which is responsible for calling the code that checks if sessions need to be expired, as follows:
Thread: ContainerBackgroundProcessor[StandardEngine[jboss.web]] : priority:5, demon:true, threadId:37, threadState:TIMED_WAITING, lockName:null
java.lang.Thread.sleep(Native Method)
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1533)
java.lang.Thread.run(Thread.java:619)
- When ATG is in the mix the stack trace may look like the following:
"ContainerBackgroundProcessor[StandardEngine[jboss.web]]" daemon prio=1
tid=0x0000002b8858f400 nid=0x63eb in Object.wait()
[0x0000000041130000..0x0000000041131d30]
at java.lang.Object.wait(Native Method)
at atg.service.lockmanager.ClientLockEntry.acquireReadLock(ClientLockEntry.java:610)
- locked <0x0000002b12aa7570> (a atg.service.lockmanager.ClientLockEntry)
at atg.service.lockmanager.ClientLockManager.acquireReadLock(ClientLockManager.java:1092)
at atg.adapter.gsa.ItemTransactionState.acquireReadLock(ItemTransactionState.java:751)
at atg.adapter.gsa.GSAItem.getPersistentPropertyValue(GSAItem.java:1076)
at atg.adapter.gsa.GSAItem.getPropertyValue(GSAItem.java:971)
at atg.adapter.gsa.GSAItem.getPropertyValue(GSAItem.java:1249)
at atg.repository.RepositoryItemImpl.getPropertyValue(RepositoryItemImpl.java:128)
at atg.adapter.composite.CompositeItem.getPropertyValue(CompositeItem.java:430)
at com.abc.userprofiling.SiteVisitSource.fireSiteViewMessage(SitevisitSource.java:142)
at atg.userprofiling.SiteVisitRequest.doStopService(SiteVisitRequest.java:226)
at atg.nucleus.GenericService.stopService(GenericService.java:534)
- locked <0x0000002b0dc02858> (a java.lang.Object)
at atg.nucleus.GenericContext.doStopService(GenericContext.java:385)
at atg.nucleus.GenericService.stopService(GenericService.java:534)
- locked <0x0000002b0dc027c8> (a java.lang.Object)
at atg.nucleus.GenericContext.doStopService(GenericContext.java:385)
at atg.nucleus.GenericService.stopService(GenericService.java:534)
- locked <0x0000002b0dbf1b48> (a java.lang.Object)
at atg.nucleus.GenericContext.doStopService(GenericContext.java:385)
at atg.nucleus.GenericService.stopService(GenericService.java:534)
- locked <0x0000002b0dbf1ad0> (a java.lang.Object)
at atg.nucleus.GenericContext.doStopService(GenericContext.java:385)
at atg.nucleus.GenericService.stopService(GenericService.java:534)
- locked <0x0000002b0dbe5f90> (a java.lang.Object)
at atg.nucleus.GenericContext.doStopService(GenericContext.java:385)
at atg.nucleus.GenericService.stopService(GenericService.java:534)
- locked <0x0000002b0dbd65b0> (a java.lang.Object)
at atg.servlet.SessionNameContext.stopSession(SessionNameContext.java:512)
at atg.servlet.SessionNameContext.decrementWrapperCount(SessionNameContext.java:222)
at atg.servlet.SessionBindingReporter.valueUnbound(SessionBindingReporter.java:206)
- locked <0x0000002aea6e41f0> (a atg.servlet.SessionBindingReporter)
at org.apache.catalina.session.StandardSession.removeAttributeInternal(StandardSession.java:1649)
at org.apache.catalina.session.StandardSession.expire(StandardSession.java:756)
- locked <0x0000002b1c913848> (a org.apache.catalina.session.StandardSession)
at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:592)
at org.apache.catalina.session.ManagerBase.processExpires(ManagerBase.java:682)
at org.apache.catalina.session.ManagerBase.backgroundProcess(ManagerBase.java:667)
at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1270)
at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1555)
at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1564)
at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1564)
at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1544)
at java.lang.Thread.run(Thread.java:595)
Notice that the ContainerBackgroundProcessor is in Object.wait() locked in atg.service.lockmanager.ClientLockEntry.acquireReadLock, which is apparently preventing the sessions from completely expiration.
The way JBoss Web expires sessions is not complicated at all. When JBoss Web starts a daemon thread called ContainerBackgroundProcess located in ContainerBase is kicked off. This thread sleeps for the backgroundProcessorDelay, which defaults to 6 seconds, then every 6 seconds calls the manager.backgroundProcess() method.
public void backgroundProcess() {
count = (count + 1) % processExpiresFrequency;
if (count == 0)
processExpires();
}
Which calls the processExpires() in ManagerBase.java
/**
* Invalidate all sessions that have expired.
*/
public void processExpires() {
long timeNow = System.currentTimeMillis();
Session sessions[] = findSessions();
int expireHere = 0 ;
if(log.isDebugEnabled())
log.debug("Start expire sessions " + getName() + " at " + timeNow + " sessioncount " + sessions.length);
for (int i = 0; i < sessions.length; i++) {
if (!sessions[i].isValid()) {
expireHere++;
}
}
long timeEnd = System.currentTimeMillis();
if(log.isDebugEnabled())
log.debug("End expire sessions " + getName() + " processingTime " + (timeEnd - timeNow) + " expired sessions: " + expireHere);
processingTime += ( timeEnd - timeNow );
}
Note that if an exception is thrown in the for loop above, session iteration will be short circuited, delaying session expiration of any sessions that were not checked until the next time the ContainerBackgroundProcessor thread runs. For example, this will happen if the object stored in the session implements HttpSessionBindingListener and an error is thrown in the valueUnbound() method.
It is in the StandardSession.isValid() method that ultimately expires the actual session.
/**
* Return the <code>isValid</code> flag for this session.
*/
public boolean isValid() {
if (this.expiring) {
return true;
}
if (!this.isValid) {
return false;
}
if (ACTIVITY_CHECK && accessCount.get() > 0) {
return true;
}
if (maxInactiveInterval >= 0) {
long timeNow = System.currentTimeMillis();
int timeIdle = (int) ((timeNow - thisAccessedTime) / 1000L);
if (timeIdle >= maxInactiveInterval) {
expire(true);
}
}
return (this.isValid);
}
Where the expire(true) method in StandardSession ultimately calls back to ManagerBase
public void remove(Session session) { sessions.remove(session.getIdInternal());}
Where sessions refers to
protected Map sessions = new ConcurrentHashMap();
Diagnostic Steps
Request the following
-
$JBOSS_HOME/server/$PROFILE/deploy/$JBOSSWEB/conf/web.xml -
web.xmlfrom the application -
Confirm the usage of
setMaxInactiveInterval()in the application. -
The following shell script will look at the Manager MBean for the webapplication in question, query each
jsessionidthen get thelastAccessTimeon the session for each of those jsessionids. Look for any last access times that are greater than the timeout period. Note: last access times of greater than the timeout period have been seen in logs before, though this may seem impossible, it is usually to do with something blocking the expiring of the sessions, thread dumps should be gathered if this is the case#!/usr/bin/env bash # NOTE: you need to modify the path=/webapp to your specific webapp context. Also make the modification on the second twiddle command # NOTE: modify the localhost to your server ip if you are listening on a specific ip JSESSIONIDS=`./twiddle.sh -s localhost:1099 -u admin -p admin invoke "jboss.web:host=localhost,path=/webapp,type=Manager" listSessionIds` declare -a JSESSIONIDS for JSESSIONID in ${JSESSIONIDS[@]} do LAST_ACCESS_TIME=`./twiddle.sh -s localhost:1099 -u admin -p admin invoke "jboss.web:host=localhost,path=/webapp,type=Manager" getLastAccessedTime $JSESSIONID` echo "JSESSIONID: $JSESSIONID LAST_ACCESS_TIME: $LAST_ACCESS_TIME" done -
May be able to glean some additional information by implementing Content from java.sun.com is not included.HttpSessionListener[1] and analysing the times the sessions are created/destroyed
package com.listeners; import java.util.Date; import javax.servlet.*; import javax.servlet.http.*; public class CustomHttpSessionListener implements HttpSessionListener{ public void sessionCreated(HttpSessionEvent sessionEvent){ //print timestamp & session & getMaxInactiveInterval // use date.toString() for the time HttpSession session = sessionEvent.getSession(); Date date = new Date(); System.out.println(">>> Created Session : ["+session.getId() +"] at ["+ date.toString()+"] <<<"); } public void sessionDestroyed(HttpSessionEvent sessionEvent){ // print timestamp & sessionId at the point it is destroyed // use date.toString() for the time HttpSession session = sessionEvent.getSession(); Date date = new Date(); System.out.println(">>> Destroyed Session : ["+session.getId() +"] at ["+ date.toString()+"] <<<"); } }
And to the application's web.xml add
<listener>
<listener-class>com.listeners.CustomHttpSessionListener</listener-class>
</listener>
[1] Content from java.sun.com is not included.Content from java.sun.com is not included.http://java.sun.com/javaee/5/docs/api/javax/servlet/http/HttpSessionListener.html
- To verify the ManagerBase.processExprires() method is being run, temporarily set the ManagerBase logging level to debug. In jmx-console, click the "jboss.system" link in the left navigation pane, and then click the "service=Logging,type=Log4jService" link on the right. Go to the setLoggerLevel function and enter the following:
The name of the logger to set: org.apache.catalina.session.ManagerBase
The log level to set: DEBUG
Then click "Invoke". If ManagerBase.processExpires() is being executed, there will be the following periodic logging in the JBoss server log:
DEBUG [org.apache.catalina.session.ManagerBase] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) Start expire sessions StandardManager at 1287172242019 sessioncount 0 DEBUG [org.apache.catalina.session.ManagerBase] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) End expire sessions StandardManager processingTime 0 expired sessions: 0 - Check the server log for exceptions related to the ContainerBackgroundProcessor thread. For example:
WARN [org.apache.catalina.core.ContainerBase] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) Exception processing manager org.apache.catalina.session.StandardManager@c0c0c0c background process java.lang.IllegalStateException: removeAttribute: Session already invalidated at java.lang.Throwable.<init>(Throwable.java:67) at org.apache.catalina.session.StandardSession.removeAttribute(StandardSession.java:1207) at org.apache.catalina.session.StandardSession.removeAttribute(StandardSession.java:1183) at org.apache.catalina.session.StandardSessionFacade.removeAttribute(StandardSessionFacade.java:140) at com.example.web.SessionObject.valueUnbound(SessionObject.java:123) at org.apache.catalina.session.StandardSession.removeAttributeInternal(StandardSession.java:1649) at org.apache.catalina.session.StandardSession.expire(StandardSession.java:756) at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:592) at org.apache.catalina.session.ManagerBase.processExpires(ManagerBase.java:682) at org.apache.catalina.session.ManagerBase.backgroundProcess(ManagerBase.java:667) at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1327) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1612) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1621) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1621) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1601) at java.lang.Thread.run(Thread.java:736)
This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.