Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

IllegalStateException when forwarding to jsp with new session #4156

Closed
stuban opened this issue Oct 4, 2019 · 33 comments
Closed

IllegalStateException when forwarding to jsp with new session #4156

stuban opened this issue Oct 4, 2019 · 33 comments
Assignees
Labels
Bug For general bugs on Jetty side High Priority

Comments

@stuban
Copy link

stuban commented Oct 4, 2019

We encountered a regression when upgrading from 9.4.20 to 9.4.21 in the session handling code.
When a servlet creates a new HttpSession and then forwards to another servlet/jsp that tries to access this session the AbstractSessionCache throws a IllegalStateException which leads to a NPE in SessionHandler.getExtendedId().

2019-10-04 14:26:37.641:WARN:oejs.session:qtp650023597-23: 
java.lang.IllegalStateException: Session node0mswjry8jd891hqpdxkcug6a87 already in cache
	at org.eclipse.jetty.server.session.AbstractSessionCache.add(AbstractSessionCache.java:518)
	at org.eclipse.jetty.server.session.SessionHandler.newHttpSession(SessionHandler.java:771)
	at org.eclipse.jetty.server.Request.getSession(Request.java:1606)
	at org.eclipse.jetty.server.Request.getSession(Request.java:1580)
	at org.apache.jasper.runtime.PageContextImpl.initialize(PageContextImpl.java:137)
	at org.apache.jasper.runtime.JspFactoryImpl.internalGetPageContext(JspFactoryImpl.java:109)
	at org.apache.jasper.runtime.JspFactoryImpl.getPageContext(JspFactoryImpl.java:60)
	at org.apache.jsp.index_jsp._jspService(index_jsp.java:100)

Simple test case simulating a login workflow:

package com.ect.test;

import java.io.IOException;
import javax.servlet.ServletException;
import javax.servlet.annotation.WebServlet;
import javax.servlet.http.HttpServlet;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

@WebServlet("/LoginServlet")
public class LoginServlet extends HttpServlet {
       
	protected void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
	    response.sendRedirect("index.jsp");
	}

	protected void doPost(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
	    if (request.getParameter("username") != null) {
	        if (request.getSession() != null) {
	            request.getSession().invalidate();
	        }
	        request.getSession(true).setAttribute("loggedin", request.getParameter("username"));
	        request.getRequestDispatcher("index.jsp").forward(request, response);
	    }
	    response.sendRedirect("index.jsp");
	}

}

and

<%@ page language="java" contentType="text/html; charset=UTF-8" pageEncoding="UTF-8"%>
<!DOCTYPE html>
<html>
<head>
<meta charset="UTF-8">
<title>Hello World</title>
</head>
<body>
Welcome <%= session.getAttribute("loggedin") %>
<form action="LoginServlet" method="POST">
<p>Username: <input type="text" name="username"/></p>
<input type="submit"/>
</form>
</body>
</html>

Did not happen with 9.4.20 so maybe a side effect of #3947

@joakime
Copy link
Contributor

joakime commented Oct 4, 2019

How is your Session Management / Handling setup in Jetty?
Did you customize it? or are you using defaults?
Is this from an embedded-jetty setup? or a jetty-home (or jetty-distribution) setup?

@stuban
Copy link
Author

stuban commented Oct 4, 2019

This is a standalone aka "jetty-home" setup with no customized session handling.


Java Environment:
-----------------
 java.home = /usr/javainst/jdk8u222-b10-jre (null)
 java.vm.vendor = AdoptOpenJDK (null)
 java.vm.version = 25.222-b10 (null)
 java.vm.name = OpenJDK 64-Bit Server VM (null)
 java.vm.info = mixed mode (null)
 java.runtime.name = OpenJDK Runtime Environment (null)
 java.runtime.version = 1.8.0_222-b10 (null)
 java.io.tmpdir = /tmp (null)
 user.dir = /usr/jettyinst/ect-afo (null)
 user.language = de (null)
 user.country = DE (null)

Jetty Environment:
-----------------
 jetty.version = 9.4.21.v20190926
 jetty.tag.version = master
 jetty.home = /usr/jettyinst/jetty-distribution-9.4.21.v20190926
 jetty.base = /usr/jettyinst/ect-afo

Config Search Order:
--------------------
 <command-line>
 ${jetty.base} -> /usr/jettyinst/ect-afo
 ${jetty.home} -> /usr/jettyinst/jetty-distribution-9.4.21.v20190926


JVM Arguments:
--------------
 (no jvm args specified)

System Properties:
------------------
 (no system properties specified)

Properties:
-----------
 java.version = 1.8.0_222
 java.version.major = 1
 java.version.micro = 0
 java.version.minor = 8
 java.version.platform = 8
 jetty.base = /usr/jettyinst/ect-afo
 jetty.base.uri = file:///usr/jettyinst/ect-afo
 jetty.console-capture.append = false
 jetty.console-capture.dir = /var/log/jetty/
 jetty.console-capture.timezone = CET
 jetty.deploy.extractWars = false
 jetty.deploy.scanInterval = 0
 jetty.home = /usr/jettyinst/jetty-distribution-9.4.21.v20190926
 jetty.home.uri = file:///usr/jettyinst/jetty-distribution-9.4.21.v20190926
 jetty.http.port = 8082
 jetty.httpConfig.sendServerVersion = false
 jetty.requestlog.append = true
 jetty.requestlog.cookies = false
 jetty.requestlog.dir = /var/log/jetty
 jetty.requestlog.filePath = ${jetty.requestlog.dir}/request-afo-yyyy_mm_dd.log
 jetty.requestlog.loglatency = true
 jetty.requestlog.timezone = CET

Jetty Server Classpath:
-----------------------
Version Information on 29 entries in the classpath.
Note: order presented here is how they would appear on the classpath.
      changes to the --module=name command line options will be reflected here.
 0:      1.4.1.v201005082020 | ${jetty.home}/lib/mail/javax.mail.glassfish-1.4.1.v201005082020.jar
 1:                    (dir) | ${jetty.base}/resources
 2:                    3.1.0 | ${jetty.home}/lib/servlet-api-3.1.jar
 3:                 3.1.0.M0 | ${jetty.home}/lib/jetty-schemas-3.1.jar
 4:         9.4.21.v20190926 | ${jetty.home}/lib/jetty-http-9.4.21.v20190926.jar
 5:         9.4.21.v20190926 | ${jetty.home}/lib/jetty-server-9.4.21.v20190926.jar
 6:         9.4.21.v20190926 | ${jetty.home}/lib/jetty-xml-9.4.21.v20190926.jar
 7:         9.4.21.v20190926 | ${jetty.home}/lib/jetty-util-9.4.21.v20190926.jar
 8:         9.4.21.v20190926 | ${jetty.home}/lib/jetty-io-9.4.21.v20190926.jar
 9:         9.4.21.v20190926 | ${jetty.home}/lib/jetty-jndi-9.4.21.v20190926.jar
10:         9.4.21.v20190926 | ${jetty.home}/lib/jetty-security-9.4.21.v20190926.jar
11:                      1.3 | ${jetty.home}/lib/transactions/javax.transaction-api-1.3.jar
12:         9.4.21.v20190926 | ${jetty.home}/lib/jetty-servlet-9.4.21.v20190926.jar
13:         9.4.21.v20190926 | ${jetty.home}/lib/jetty-webapp-9.4.21.v20190926.jar
14:         9.4.21.v20190926 | ${jetty.home}/lib/jetty-plus-9.4.21.v20190926.jar
15:         9.4.21.v20190926 | ${jetty.home}/lib/jetty-annotations-9.4.21.v20190926.jar
16:                      7.1 | ${jetty.home}/lib/annotations/asm-7.1.jar
17:                      7.1 | ${jetty.home}/lib/annotations/asm-analysis-7.1.jar
18:                      7.1 | ${jetty.home}/lib/annotations/asm-commons-7.1.jar
19:                      7.1 | ${jetty.home}/lib/annotations/asm-tree-7.1.jar
20:                      1.3 | ${jetty.home}/lib/annotations/javax.annotation-api-1.3.jar
21:    3.17.0.v20190306-2240 | ${jetty.home}/lib/apache-jsp/org.eclipse.jdt.ecj-3.17.0.jar
22:         9.4.21.v20190926 | ${jetty.home}/lib/apache-jsp/org.eclipse.jetty.apache-jsp-9.4.21.v20190926.jar
23:                   8.5.40 | ${jetty.home}/lib/apache-jsp/org.mortbay.jasper.apache-el-8.5.40.jar
24:                   8.5.40 | ${jetty.home}/lib/apache-jsp/org.mortbay.jasper.apache-jsp-8.5.40.jar
25:         9.4.21.v20190926 | ${jetty.home}/lib/jetty-deploy-9.4.21.v20190926.jar
26:         9.4.21.v20190926 | ${jetty.home}/lib/http2/http2-common-9.4.21.v20190926.jar
27:         9.4.21.v20190926 | ${jetty.home}/lib/http2/http2-hpack-9.4.21.v20190926.jar
28:         9.4.21.v20190926 | ${jetty.home}/lib/http2/http2-server-9.4.21.v20190926.jar

Jetty Active XMLs:
------------------
 ${jetty.home}/etc/jetty-bytebufferpool.xml
 ${jetty.home}/etc/jetty-threadpool.xml
 ${jetty.home}/etc/jetty.xml
 ${jetty.home}/etc/jetty-webapp.xml
 ${jetty.home}/etc/jetty-plus.xml
 ${jetty.home}/etc/jetty-annotations.xml
 ${jetty.base}/etc/console-capture.xml
 ${jetty.home}/etc/jetty-deploy.xml
 ${jetty.home}/etc/jetty-http.xml
 ${jetty.home}/etc/jetty-http2c.xml
 ${jetty.home}/etc/jetty-http-forwarded.xml
 ${jetty.base}/etc/jetty-requestlog.xml

@joakime
Copy link
Contributor

joakime commented Oct 4, 2019

I have been able to replicate with demo project at https://github.com/jetty-project/session-jsp-issue

Full stacktrace ...

java.lang.IllegalStateException: Session node06z2cupnfeokj1t8bg3oxglbsk1 already in cache
	at org.eclipse.jetty.server.session.AbstractSessionCache.add(AbstractSessionCache.java:518)
	at org.eclipse.jetty.server.session.SessionHandler.newHttpSession(SessionHandler.java:771)
	at org.eclipse.jetty.server.Request.getSession(Request.java:1606)
	at org.eclipse.jetty.server.Request.getSession(Request.java:1580)
	at org.apache.jasper.runtime.PageContextImpl.initialize(PageContextImpl.java:137)
	at org.apache.jasper.runtime.JspFactoryImpl.internalGetPageContext(JspFactoryImpl.java:109)
	at org.apache.jasper.runtime.JspFactoryImpl.getPageContext(JspFactoryImpl.java:60)
	at org.apache.jsp.index_jsp._jspService(index_jsp.java:100)
	at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:476)
	at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:386)
	at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:330)
	at org.eclipse.jetty.jsp.JettyJspServlet.service(JettyJspServlet.java:106)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1400)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:554)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1589)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1296)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1559)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1211)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:220)
	at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:79)
	at org.eclipse.jetty.demo.LoginServlet.doPost(LoginServlet.java:27)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1391)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:536)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1589)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1296)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1559)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1211)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:221)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.Server.handle(Server.java:500)
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:386)
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:560)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:378)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:268)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:914)
	at java.base/java.lang.Thread.run(Thread.java:834)
2019-10-04 10:43:25.245:WARN:oejs.HttpChannel:qtp1625082366-47: /login
javax.servlet.ServletException: org.apache.jasper.JasperException: javax.servlet.ServletException: java.lang.NullPointerException
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:162)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.Server.handle(Server.java:500)
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:386)
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:560)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:378)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:268)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:914)
	at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: 
org.apache.jasper.JasperException: javax.servlet.ServletException: java.lang.NullPointerException
	at org.apache.jasper.servlet.JspServletWrapper.handleJspException(JspServletWrapper.java:634)
	at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:499)
	at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:386)
	at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:330)
	at org.eclipse.jetty.jsp.JettyJspServlet.service(JettyJspServlet.java:106)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1400)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:554)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1589)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1296)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1559)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1211)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:220)
	at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:79)
	at org.eclipse.jetty.demo.LoginServlet.doPost(LoginServlet.java:27)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1391)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:536)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1589)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1296)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1559)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1211)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:221)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.Server.handle(Server.java:500)
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:386)
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:560)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:378)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:268)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:914)
	at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: 
javax.servlet.ServletException: java.lang.NullPointerException
	at org.apache.jsp.index_jsp._jspService(index_jsp.java:138)
	at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:476)
	at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:386)
	at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:330)
	at org.eclipse.jetty.jsp.JettyJspServlet.service(JettyJspServlet.java:106)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1400)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:554)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1589)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1296)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1559)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1211)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:220)
	at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:79)
	at org.eclipse.jetty.demo.LoginServlet.doPost(LoginServlet.java:27)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1391)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:536)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1589)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1296)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1559)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1211)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:221)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.Server.handle(Server.java:500)
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:386)
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:560)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:378)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:268)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:914)
	at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: 
java.lang.NullPointerException
	at org.eclipse.jetty.server.session.SessionHandler.getExtendedId(SessionHandler.java:751)
	at org.eclipse.jetty.server.session.SessionHandler.getSessionCookie(SessionHandler.java:651)
	at org.eclipse.jetty.server.Request.getSession(Request.java:1607)
	at org.eclipse.jetty.server.Request.getSession(Request.java:1580)
	at org.apache.jasper.runtime.PageContextImpl.initialize(PageContextImpl.java:137)
	at org.apache.jasper.runtime.JspFactoryImpl.internalGetPageContext(JspFactoryImpl.java:109)
	at org.apache.jasper.runtime.JspFactoryImpl.getPageContext(JspFactoryImpl.java:60)
	at org.apache.jsp.index_jsp._jspService(index_jsp.java:100)
	at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:476)
	at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:386)
	at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:330)
	at org.eclipse.jetty.jsp.JettyJspServlet.service(JettyJspServlet.java:106)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1400)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:554)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1589)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1296)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1559)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1211)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:220)
	at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:79)
	at org.eclipse.jetty.demo.LoginServlet.doPost(LoginServlet.java:27)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1391)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:536)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1589)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1296)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1559)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1211)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:221)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.Server.handle(Server.java:500)
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:386)
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:560)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:378)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:268)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:914)
	at java.base/java.lang.Thread.run(Thread.java:834)

@joakime joakime added Bug For general bugs on Jetty side High Priority labels Oct 4, 2019
@joakime joakime added this to To do in Jetty 9.4.22 via automation Oct 4, 2019
@joakime joakime moved this from To do to In progress in Jetty 9.4.22 Oct 4, 2019
joakime added a commit that referenced this issue Oct 4, 2019
Signed-off-by: Joakim Erdfelt <joakim.erdfelt@gmail.com>
@joakime
Copy link
Contributor

joakime commented Oct 4, 2019

A unit test that replicates the issue is now present in branch jetty-9.4.x-4156-session-already-in-cache on commit 50d7b8c

I'll give it a go on fixing this, but ultimately this is in @janbartel's wheelhouse.

@gregw
Copy link
Contributor

gregw commented Oct 4, 2019

The problem appears to be that with the refactor we are now always doing a context level dispatch for forward. The SessionHandler is calling doScope again and nulling out the existing session... then for some reason when it looks for an existing session, it is finding a different one???

Perhaps we need to make SessionHandler.doScope a noop if we are already in the same session scope? But we also need to understand why it is not finding the same session?

@gregw
Copy link
Contributor

gregw commented Oct 4, 2019

Ah the problem is that because the existing session has been invalidated and a new session created before the forward, the new session array inside the request now has 2 sessions for the context - one invalid. But the getSession(SessionHandler handler) method doesn't check for validity and just returns the first one.

So simple fix is probably to just check for validity in that method. That should resolve the bug we just added.

But a better fix may be to look at why we are re-initializing the session for a dispatch to the same context.

gregw added a commit that referenced this issue Oct 4, 2019
+ check validity of sessions in getSession(SessionHandler)
+ do not replace session in doScope if SessionHandler is the same.

Signed-off-by: Greg Wilkins <gregw@webtide.com>
@gregw
Copy link
Contributor

gregw commented Oct 4, 2019

@janbartel I've pushed a possible fix in 8b08b0f, but I think we need to walk through it again just in case I've missed something

@joakime
Copy link
Contributor

joakime commented Oct 6, 2019

Opened PR #4159

gregw added a commit that referenced this issue Oct 14, 2019
* Issue #4156 - Adding test to replicate issue

Signed-off-by: Joakim Erdfelt <joakim.erdfelt@gmail.com>

* Issue #4156 Session already in cache

+ check validity of sessions in getSession(SessionHandler)
+ do not replace session in doScope if SessionHandler is the same.

Signed-off-by: Greg Wilkins <gregw@webtide.com>
@gregw gregw closed this as completed Oct 14, 2019
Jetty 9.4.22 automation moved this from Review in progress to Done Oct 14, 2019
@ofrias
Copy link

ofrias commented Oct 29, 2019

We keep getting this error also in 9.4.22:

java.lang.NullPointerException
at org.eclipse.jetty.server.session.SessionHandler.getExtendedId(SessionHandler.java:751)
at org.eclipse.jetty.server.session.SessionHandler.getSessionCookie(SessionHandler.java:651)
at org.eclipse.jetty.server.Request.getSession(Request.java:1608)

@joakime
Copy link
Contributor

joakime commented Oct 29, 2019

@ofrias include the complete stacktrace please.
It tells us where you attempted to access the session.

@ofrias
Copy link

ofrias commented Oct 29, 2019

Of course, this is an example of the full stack trace:

java.lang.NullPointerException
        at org.eclipse.jetty.server.session.SessionHandler.getExtendedId(SessionHandler.java:751)
        at org.eclipse.jetty.server.session.SessionHandler.getSessionCookie(SessionHandler.java:651)
        at org.eclipse.jetty.server.Request.getSession(Request.java:1608)
        at com.trabber.servlets.BaseServlet.doPost(BaseServlet.java:45)
        at com.trabber.servlets.BaseServlet.doGet(BaseServlet.java:36)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
        at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1401)
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:554)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1592)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:54)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1296)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1562)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1211)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
        at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:220)
        at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:79)
        at org.eclipse.jetty.server.ResourceService.sendWelcome(ResourceService.java:433)
        at org.eclipse.jetty.server.ResourceService.doGet(ResourceService.java:251)
        at org.eclipse.jetty.servlet.DefaultServlet.doGet(DefaultServlet.java:454)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
        at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1401)
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:554)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1592)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:54)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1296)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1562)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1211)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
        at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:220)
        at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:79)
        at com.trabber.filters.CountryAndLanguageFilter.doFilter(CountryAndLanguageFilter.java:171)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
        at com.trabber.filters.CharsetFilter.doFilter(CharsetFilter.java:23)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
        at com.trabber.filters.RedirectFilter.doFilter(RedirectFilter.java:272)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1596)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:545)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:512)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1592)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:54)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1296)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1562)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1211)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
        at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:221)
        at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
        at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:767)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.Server.handle(Server.java:500)
        at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:386)
        at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:562)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:378)
        at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:388)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
        at java.base/java.lang.Thread.run(Thread.java:834)

@janbartel
Copy link
Contributor

janbartel commented Oct 29, 2019

@ofrias,

Please post the log output - I'm looking for a warning message just before this stack trace.

Please also describe the sequence of what is happening - I'm guessing from the stack trace that you send a request that results in a forward to the welcome servlet, but I can't tell if there is already supposed to be a session or not.

Please also provide your welcome file set up and servlet mapping set up.

In fact, it would be ideal if you could provide a small reproduction.

@ofrias
Copy link

ofrias commented Oct 30, 2019

Hello.

We don't know the exact sequence because these are logs that we get randomly in production, we don't know how to reproduce the issue.

I think it is not related to the welcome servlet because it happens also with other servlets.

This is another example log:

I think this is the warning that you were referring to:

2019-10-29 19:18:09.435:WARN:oejs.session:qtp1307904972-2020: 
java.lang.IllegalStateException: Session bran1f0pllf6hll8v16yttpe3ljdvr5068 already in cache
        at org.eclipse.jetty.server.session.AbstractSessionCache.add(AbstractSessionCache.java:518)
        at org.eclipse.jetty.server.session.SessionHandler.newHttpSession(SessionHandler.java:771)
        at org.eclipse.jetty.server.Request.getSession(Request.java:1607)
        at com.trabber.gwt.common.server.BaseRemoteServiceServlet.onBeforeRequestDeserialized(BaseRemoteServiceServlet.java:69)
        at com.google.gwt.user.server.rpc.RemoteServiceServlet.processPost(RemoteServiceServlet.java:368)
        at com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doPost(AbstractRemoteServiceServlet.java:62)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
        at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1401)
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:554)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1592)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:54)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1296)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1562)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1211)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
        at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:220)
        at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:79)
        at com.trabber.filters.CountryAndLanguageFilter.doFilter(CountryAndLanguageFilter.java:171)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
        at com.trabber.filters.CharsetFilter.doFilter(CharsetFilter.java:23)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
        at com.trabber.filters.RedirectFilter.doFilter(RedirectFilter.java:272)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1596)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:545)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:512)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1592)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:54)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1296)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1562)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1211)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
        at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:221)
        at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
        at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:717)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.Server.handle(Server.java:500)
        at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:386)
        at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:562)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:378)
        at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135)
        at org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:170)
        at org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:125)
        at org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:348)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:388)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
        at java.base/java.lang.Thread.run(Thread.java:834)

And this is the error:

java.lang.NullPointerException
        at org.eclipse.jetty.server.session.SessionHandler.getExtendedId(SessionHandler.java:751)
        at org.eclipse.jetty.server.session.SessionHandler.getSessionCookie(SessionHandler.java:651)
        at org.eclipse.jetty.server.Request.getSession(Request.java:1608)
        at com.trabber.gwt.common.server.BaseRemoteServiceServlet.onBeforeRequestDeserialized(BaseRemoteServiceServlet.java:69)
        at com.google.gwt.user.server.rpc.RemoteServiceServlet.processPost(RemoteServiceServlet.java:368)
        at com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doPost(AbstractRemoteServiceServlet.java:62)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
        at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1401)
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:554)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1592)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:54)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1296)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1562)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1211)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
        at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:220)
        at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:79)
        at com.trabber.filters.CountryAndLanguageFilter.doFilter(CountryAndLanguageFilter.java:171)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
        at com.trabber.filters.CharsetFilter.doFilter(CharsetFilter.java:23)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
        at com.trabber.filters.RedirectFilter.doFilter(RedirectFilter.java:272)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1596)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:545)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:512)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1592)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:54)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1296)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1562)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1211)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
        at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:221)
        at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
        at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:717)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.Server.handle(Server.java:500)
        at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:386)
        at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:562)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:378)
        at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135)
        at org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:170)
        at org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:125)
        at org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:348)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:388)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
        at java.base/java.lang.Thread.run(Thread.java:834)

@janbartel
Copy link
Contributor

janbartel commented Oct 30, 2019

@ofrias are you absolutely positive that you're running 9.4.22? All of the tests that we put in for this bug are passing in the 9.4.22 release, and a test I put in yesterday that does the sequence I guessed your code is doing also passed, so if your server logs confirm you're running 9.4.22, then we will need your help to pin down exactly what is happening. I suggest you turn on debug logging for sessions (-Dorg.eclipse.jetty.server.session.LEVEL=DEBUG) and post the log. Also start thinking about a small repro webapp/unit test.

@joakime
Copy link
Contributor

joakime commented Oct 30, 2019

The line numbers on his stacktrace ...

        at org.eclipse.jetty.server.session.SessionHandler.getExtendedId(SessionHandler.java:751)
        at org.eclipse.jetty.server.session.SessionHandler.getSessionCookie(SessionHandler.java:651)
        at org.eclipse.jetty.server.Request.getSession(Request.java:1608)

... correspond to Jetty 9.4.22 release

Example: if we use 9.4.21 Request.java on line 1608 we get ...

https://github.com/eclipse/jetty.project/blob/jetty-9.4.21.v20190926/jetty-server/src/main/java/org/eclipse/jetty/server/Request.java#L1608

https://github.com/eclipse/jetty.project/blob/72970db61a2904371e1218a95a3bef5d79788c33/jetty-server/src/main/java/org/eclipse/jetty/server/Request.java#L1606-L1609

@janbartel
Copy link
Contributor

@ofrias can you also please report what your session configuration is? Session time-out value etc etc.

@ofrias
Copy link

ofrias commented Oct 31, 2019

This is our session-config:

    <session-config>
        <session-timeout>30</session-timeout>
        <cookie-config>
            <http-only>true</http-only>
        </cookie-config>
    </session-config>

@janbartel
Copy link
Contributor

@ofrias can you attach jetty log output that contains the error please?

@janbartel janbartel reopened this Nov 3, 2019
@ofrias
Copy link

ofrias commented Nov 4, 2019

I attach Jetty log.
jetty_error.zip

@janbartel
Copy link
Contributor

@ofrias sorry, I meant a log that shows the error with debug logging for sessions turned on as I commented earlier. I need to see the lifecycle of these errored sessions.

PS you might want to rationalize the jars you have in web-inf/lib: seems like there are multiple jars with the same classes, hence all the warnings from the annotation scanner.

@ofrias
Copy link

ofrias commented Nov 5, 2019

@janbartel Which is the configuration that we should use to enable session logging?

@janbartel
Copy link
Contributor

I'm not near a computer so this will have to be brief. Please look back to my comments 5 days ago, it contains the session debug log command line arguments to use.

@janbartel
Copy link
Contributor

@ofrias to enable debug logging for sessions when using the jetty stderr logger, set this system property: org.eclipse.jetty.server.session.LEVEL=DEBUG. Either put it on the command line, or if you have a jetty-logging.properties file you can define it in there instead. If using a different logging system, ensure that the package org.eclipse.jetty.server.session is set to the most verbose logging level for that system.

@ofrias
Copy link

ofrias commented Nov 11, 2019

I attach a new log now with session logging enabled.
jetty.zip

@janbartel
Copy link
Contributor

janbartel commented Nov 12, 2019

@ofrias thanks, that is very helpful.

Can you please post more of the log? I need to see the full lifecycle for session id bran1mhhe4al4weg9182u738ifhgjy6833. In particular, I want to see where it was created, accessed and if it timed out.

Can you also please tell me:

  • is it possible for that session to be active on another node at the same time?
  • If there is another node that referenced the session, please also post session debug logging from that node also.
  • Do you have sticky sessions or not?
  • Was this session created by a previous invocation of jetty, or was this session created in this same invocation of jetty?
  • Are you using the JDBSessionDataStore? If not, which SessionDataStore are you using?
  • When you create a session, do you set an attribute on it or not? Please post the session creation code snippet to confirm.
  • What is the value of jetty.session.flushOnResponseCommit?
  • What is the value of jetty.session.saveOnCreate?

@ofrias
Copy link

ofrias commented Nov 12, 2019

Hello.

Thanks for your help. I include the session logs for bran server and also for arya server.

jetty-sessions-bran.zip
jetty-sessions-arya.zip

Answers follow:

  • is it possible for that session to be active on another node at the same time?

This should not happen because we use haproxy load balancer with source IP balancing.

  • If there is another node that referenced the session, please also post session debug logging from that node also.

Posted.

  • Do you have sticky sessions or not?

We balance based on source IP so the same session should always go to the same server if it is available.

  • Was this session created by a previous invocation of jetty, or was this session created in this same invocation of jetty?

I don't know.

  • Are you using the JDBSessionDataStore? If not, which SessionDataStore are you using?

Yes.

  • When you create a session, do you set an attribute on it or not? Please post the session creation code snippet to confirm.

This depends on the case, sometimes we add an attribute and sometimes not.

  • What is the value of jetty.session.flushOnResponseCommit?

We are not setting it, so it should have its default value.

  • What is the value of jetty.session.saveOnCreate?

We are not setting it, so it should have its default value.

@janbartel
Copy link
Contributor

@ofrias thanks for those docs and the info. I believe I've worked out what the problem could be, and I'm working on a fix.

janbartel added a commit that referenced this issue Nov 13, 2019
… loading.

Also cleanup of unneeded code/comments in tests.

Signed-off-by: Jan Bartel <janb@webtide.com>
@janbartel
Copy link
Contributor

Created PR #4304

janbartel added a commit that referenced this issue Nov 13, 2019
Signed-off-by: Jan Bartel <janb@webtide.com>
janbartel added a commit that referenced this issue Nov 14, 2019
Signed-off-by: Jan Bartel <janb@webtide.com>
@joakime joakime added this to To do in Jetty 9.4.23 via automation Nov 14, 2019
@joakime joakime moved this from To do to In progress in Jetty 9.4.23 Nov 14, 2019
janbartel added a commit that referenced this issue Nov 17, 2019
… loading (#4304)

* Issue #4156 Remove use of PlaceHolderSession for simultaneous session loading.
@janbartel
Copy link
Contributor

@ofrias I've committed a fix to the jetty-9.4.x branch. Can you build and test with in in your environment? We'd like to make it part of the soon-to-be-released 9.4.23 version, but I'd like some level of assurance that it's been tested in the field first, if possible.

@gregw gregw moved this from In progress to Review in progress in Jetty 9.4.23 Nov 17, 2019
@ofrias
Copy link

ofrias commented Nov 18, 2019

Thanks a lot for your help. Unfortunately we cannot use a development build in production so I am afraid we cannot test it on our side yet. We could test it as soon as 9.4.23 is released (or even with the release candidate if available).

@joakime joakime moved this from Review in progress to Done in Jetty 9.4.23 Nov 18, 2019
@janbartel
Copy link
Contributor

@ofrias
Copy link

ofrias commented Nov 21, 2019

We have been running 9.4.23 in production for more than 24 hours, and we haven't seen any of these errors. Thanks a lot for your help!

@janbartel
Copy link
Contributor

@ofrias thanks for that info. I'll close this issue as resolved.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug For general bugs on Jetty side High Priority
Projects
No open projects
Jetty 9.4.22
  
Done
Jetty 9.4.23
  
Done
Development

No branches or pull requests

5 participants