org.apache.shiro.session.ExpiredSessionException: Session with id异常排查

系统运行过程中报出异常

Caused by: org.apache.shiro.session.ExpiredSessionException: Session with id [aa21ba8b-7f3a-4236-a2f8-3b440524f55e] has expired. Last access time: 3/14/22 2:55 PM. Current time: 3/14/22 3:26 PM. Session timeout is set to 1800 seconds (30 minutes) at org.apache.shiro.session.mgt.SimpleSession.validate(SimpleSession.java:292) ~[shiro-core-1.6.0.jar:1.6.0] at org.apache.shiro.session.mgt.AbstractValidatingSessionManager.doValidate(AbstractValidatingSessionManager.java:186) ~[shiro-core-1.6.0.jar:1.6.0] at org.apache.shiro.session.mgt.AbstractValidatingSessionManager.validate(AbstractValidatingSessionManager.java:143) ~[shiro-core-1.6.0.jar:1.6.0] at org.apache.shiro.session.mgt.AbstractValidatingSessionManager.doGetSession(AbstractValidatingSessionManager.java:120) ~[shiro-core-1.6.0.jar:1.6.0] at org.apache.shiro.session.mgt.AbstractNativeSessionManager.lookupSession(AbstractNativeSessionManager.java:148) ~[shiro-core-1.6.0.jar:1.6.0] at org.apache.shiro.session.mgt.AbstractNativeSessionManager.lookupRequiredSession(AbstractNativeSessionManager.java:152) ~[shiro-core-1.6.0.jar:1.6.0] at org.apache.shiro.session.mgt.AbstractNativeSessionManager.getAttribute(AbstractNativeSessionManager.java:249) ~[shiro-core-1.6.0.jar:1.6.0] at org.apache.shiro.session.mgt.DelegatingSession.getAttribute(DelegatingSession.java:141) ~[shiro-core-1.6.0.jar:1.6.0] at org.apache.shiro.session.ProxiedSession.getAttribute(ProxiedSession.java:121) ~[shiro-core-1.6.0.jar:1.6.0] at org.apache.shiro.subject.support.DelegatingSubject.getRunAsPrincipalsStack(DelegatingSubject.java:473) ~[shiro-core-1.6.0.jar:1.6.0] at org.apache.shiro.subject.support.DelegatingSubject.getPrincipals(DelegatingSubject.java:157) ~[shiro-core-1.6.0.jar:1.6.0] at org.apache.shiro.subject.support.DelegatingSubject.getPrincipal(DelegatingSubject.java:153) ~[shiro-core-1.6.0.jar:1.6.0] at org.apache.shiro.web.servlet.ShiroHttpServletRequest.getSubjectPrincipal(ShiroHttpServletRequest.java:96) ~[shiro-web-1.6.0.jar:1.6.0] at org.apache.shiro.web.servlet.ShiroHttpServletRequest.getUserPrincipal(ShiroHttpServletRequest.java:112) ~[shiro-web-1.6.0.jar:1.6.0] at org.springframework.web.servlet.FrameworkServlet.getUsernameForRequest(FrameworkServlet.java:1159) ~[spring-webmvc-5.1.6.RELEASE.jar:5.1.6.RELEASE] at org.springframework.web.servlet.FrameworkServlet.publishRequestHandledEvent(FrameworkServlet.java:1144) ~[spring-webmvc-5.1.6.RELEASE.jar:5.1.6.RELEASE] at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1022) ~[spring-webmvc-5.1.6.RELEASE.jar:5.1.6.RELEASE] at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:908) ~[spring-webmvc-5.1.6.RELEASE.jar:5.1.6.RELEASE] at javax.servlet.http.HttpServlet.service(HttpServlet.java:648) ~[servlet-api.jar:?] at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:882) ~[spring-webmvc-5.1.6.RELEASE.jar:5.1.6.RELEASE] at javax.servlet.http.HttpServlet.service(HttpServlet.java:729) ~[servlet-api.jar:?] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:292) ~[catalina.jar:8.0.51] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207) ~[catalina.jar:8.0.51] at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) ~[tomcat-websocket.jar:8.0.51] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240) ~[catalina.jar:8.0.51] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207) ~[catalina.jar:8.0.51] at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:61) ~[shiro-web-1.6.0.jar:1.6.0] at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108) ~[shiro-web-1.6.0.jar:1.6.0] at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137) ~[shiro-web-1.6.0.jar:1.6.0] … 66 more

重点查看：SimpleSession.validate(SimpleSession.java:292)、FrameworkServlet.publishRequestHandledEvent(FrameworkServlet.java:1144)

产生原因

根据异常栈信息排查出业务逻辑链：接口在调用时（耗时大概20s），方法入栈后，shiro中的session在此时过期，方法出栈后，进入FrameworkServlet类调用发布事件方法publishRequestHandledEvent，（该方法用于请求完毕后发布请求事件，给开发人员提供扩展使用，如果没有该事件的订阅对象，这个时间不会产生影响）该方法需要获取session中信息，此时shiro进行校验时发现过期，抛出异常。

注：正常流程session在进入请求时会续期，但是由于项目情况特殊，报错请求的接口被续期排除，导致后续报错。

参考：

FrameworkServlet

/**
* FrameworkServlet为spring的抽象类，DispatcherServlet就是继承了他，这里在处理请求之后，发布了ServletRequestHandledEvent事件，错误就是构建事件时* getUsernameForRequest方法，导致shiro校验session抛出异常。
* Process this request, publishing an event regardless of the outcome.
* <p>The actual event handling is performed by the abstract
* {@link #doService} template method.
*/
protected final void processRequest(HttpServletRequest request, HttpServletResponse response)throws ServletException, IOException {long startTime = System.currentTimeMillis();Throwable failureCause = null;LocaleContext previousLocaleContext = LocaleContextHolder.getLocaleContext();LocaleContext localeContext = buildLocaleContext(request);RequestAttributes previousAttributes = RequestContextHolder.getRequestAttributes();ServletRequestAttributes requestAttributes = buildRequestAttributes(request, response, previousAttributes);WebAsyncManager asyncManager = WebAsyncUtils.getAsyncManager(request);asyncManager.registerCallableInterceptor(FrameworkServlet.class.getName(), new RequestBindingInterceptor());initContextHolders(request, localeContext, requestAttributes);try {doService(request, response);}catch (ServletException | IOException ex) {failureCause = ex;throw ex;}catch (Throwable ex) {failureCause = ex;throw new NestedServletException("Request processing failed", ex);}finally {resetContextHolders(request, previousLocaleContext, previousAttributes);if (requestAttributes != null) {requestAttributes.requestCompleted();}logResult(request, response, failureCause, asyncManager);publishRequestHandledEvent(request, response, startTime, failureCause);}
}

shiro的SimpleSession

/**
* shiro校验session代码
* 在许多流程中，shiro都会进行校验，如果有类似错误，基本都是由于shiro的校验引起
*/
public void validate() throws InvalidSessionException {//check for stopped:if (isStopped()) {//timestamp is set, so the session is considered stopped:String msg = "Session with id [" + getId() + "] has been " +"explicitly stopped.  No further interaction under this session is " +"allowed.";throw new StoppedSessionException(msg);}//check for expirationif (isTimedOut()) {expire();//throw an exception explaining details of why it expired:Date lastAccessTime = getLastAccessTime();long timeout = getTimeout();Serializable sessionId = getId();DateFormat df = DateFormat.getInstance();String msg = "Session with id [" + sessionId + "] has expired. " +"Last access time: " + df.format(lastAccessTime) +".  Current time: " + df.format(new Date()) +".  Session timeout is set to " + timeout / MILLIS_PER_SECOND + " seconds (" +timeout / MILLIS_PER_MINUTE + " minutes)";if (log.isTraceEnabled()) {log.trace(msg);}throw new ExpiredSessionException(msg);}
}

解决方案

考虑到FrameworkServlet为spring的基础类，不太好从中扩展，并且观察最后异常是由shiro的session的validate方法抛出的异常，那么可以尝试继承SimpleSession类来完成自己的定制逻辑。