{"action":"created","issue":{"url":"https://api.github.com/repos/eclipse/jetty.project/issues/2712","repository_url":"https://api.github.com/repos/eclipse/jetty.project","labels_url":"https://api.github.com/repos/eclipse/jetty.project/issues/2712/labels{/name}","comments_url":"https://api.github.com/repos/eclipse/jetty.project/issues/2712/comments","events_url":"https://api.github.com/repos/eclipse/jetty.project/issues/2712/events","html_url":"https://github.com/eclipse/jetty.project/issues/2712","id":340449988,"node_id":"MDU6SXNzdWUzNDA0NDk5ODg=","number":2712,"title":"Early EOF in request body causes servlet to run multiple times","user":{"login":"AgentME","id":577345,"node_id":"MDQ6VXNlcjU3NzM0NQ==","avatar_url":"https://avatars0.githubusercontent.com/u/577345?v=4","gravatar_id":"","url":"https://api.github.com/users/AgentME","html_url":"https://github.com/AgentME","followers_url":"https://api.github.com/users/AgentME/followers","following_url":"https://api.github.com/users/AgentME/following{/other_user}","gists_url":"https://api.github.com/users/AgentME/gists{/gist_id}","starred_url":"https://api.github.com/users/AgentME/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/AgentME/subscriptions","organizations_url":"https://api.github.com/users/AgentME/orgs","repos_url":"https://api.github.com/users/AgentME/repos","events_url":"https://api.github.com/users/AgentME/events{/privacy}","received_events_url":"https://api.github.com/users/AgentME/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":6,"created_at":"2018-07-12T00:31:00Z","updated_at":"2018-07-12T18:55:00Z","closed_at":null,"author_association":"NONE","body":"I was curious how Jetty reacted to POST requests where the connection terminates early while the client is sending the request body (because of shoddy wifi, proxies going down, etc), so I decided to test it. I hoped that Jetty would block such connections from getting to my servlets or throw an error when the body is parsed (like when request.getParameter(\"...\") is called), so that my servlets don't try to process corrupt incomplete data from users.\r\n\r\nI got some very surprising results in the latest version of Jetty (9.4.11.v20180605) that seems like it must be a bug.\r\n\r\nHere's the example program I'm testing with. It's in Kotlin. Sorry if anyone isn't familiar, but the example is hopefully pretty run-of-the-mill without many moving parts so it shouldn't be too hard to follow.\r\n\r\n```kotlin\r\nimport org.eclipse.jetty.server.Server\r\nimport org.eclipse.jetty.server.ServerConnector\r\nimport org.eclipse.jetty.servlet.ServletHandler\r\nimport org.eclipse.jetty.servlet.ServletHolder\r\nimport org.eclipse.jetty.util.thread.QueuedThreadPool\r\nimport javax.servlet.http.HttpServlet\r\nimport javax.servlet.http.HttpServletRequest\r\nimport javax.servlet.http.HttpServletResponse\r\n\r\nfun main(args: Array<String>) {\r\n    val server = HttpServer()\r\n    server.servletHandler.addServletWithMapping(ServletHolder(FooServlet()), \"/foo\")\r\n    server.start()\r\n    server.join()\r\n}\r\n\r\nclass FooServlet : HttpServlet() {\r\n    override fun doGet(req: HttpServletRequest, resp: HttpServletResponse) {\r\n        resp.writer.println(\"received get\")\r\n    }\r\n\r\n    override fun doPost(req: HttpServletRequest, resp: HttpServletResponse) {\r\n        println(\"original status: ${resp.status}\")\r\n        println(\"bar parameter: ${req.getParameter(\"bar\")}\")\r\n        resp.writer.println(\"received post ${req.getParameter(\"bar\")}\")\r\n    }\r\n}\r\n\r\nclass HttpServer {\r\n    companion object {\r\n        private const val PORT = 8080\r\n        private const val MAX_SERVER_THREADS = 12\r\n    }\r\n\r\n    private val server: Server\r\n    val servletHandler: ServletHandler // consumers should use methods like addServletWithMapping on this before starting\r\n\r\n    init {\r\n        val threadPool = QueuedThreadPool(MAX_SERVER_THREADS)\r\n        threadPool.isDaemon = true\r\n        server = Server(threadPool)\r\n        val connector = ServerConnector(server)\r\n        connector.port = PORT\r\n        server.addConnector(connector)\r\n\r\n        servletHandler = ServletHandler()\r\n        server.handler = servletHandler\r\n    }\r\n\r\n    fun start() {\r\n        server.start()\r\n    }\r\n\r\n    fun join() {\r\n        server.join()\r\n    }\r\n\r\n    fun stop() {\r\n        server.stop()\r\n    }\r\n}\r\n```\r\n\r\nThe test setup so that someone can follow along. (The \"badRequest\" file was generated by using curl against `nc -l 8081 | tee badRequest`, and then I edited badRequest to have its Content-Length value be one higher than it should be.)\r\n\r\n```\r\n$ echo 'UE9TVCAvZm9vIEhUVFAvMS4xDQpIb3N0OiBsb2NhbGhvc3Q6ODA4MQ0KVXNlci1BZ2VudDogY3VybC83LjU0LjANCkFjY2VwdDogKi8qDQpDb250ZW50LUxlbmd0aDogMTINCkNvbnRlbnQtVHlwZTogYXBwbGljYXRpb24veC13d3ctZm9ybS11cmxlbmNvZGVkDQoNCmJhcj0xMjMmYz0x' | base64 --decode > badRequest\r\n$ cat badRequest ; echo\r\nPOST /foo HTTP/1.1\r\nHost: localhost:8081\r\nUser-Agent: curl/7.54.0\r\nAccept: */*\r\nContent-Length: 12\r\nContent-Type: application/x-www-form-urlencoded\r\n\r\nbar=123&c=1\r\n```\r\n\r\n## jetty 9.4.11.v20180605\r\n\r\n```\r\n$ nc localhost 8080 < badRequest\r\nHTTP/1.1 500 Server Error\r\nContent-Length: 18\r\nConnection: close\r\nServer: Jetty(9.4.11.v20180605)\r\n\r\nreceived post 123\r\n```\r\n\r\nServer log:\r\n\r\n```\r\n[main] INFO org.eclipse.jetty.util.log - Logging initialized @1496ms to org.eclipse.jetty.util.log.Slf4jLog\r\n[main] INFO org.eclipse.jetty.server.Server - jetty-9.4.11.v20180605; built: 2018-06-05T18:24:03.829Z; git: d5fc0523cfa96bfebfbda19606cad384d772f04c; jvm 1.8.0_131-b11\r\n[main] INFO org.eclipse.jetty.server.AbstractConnector - Started ServerConnector@5158b42f{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}\r\n[main] INFO org.eclipse.jetty.server.Server - Started @2810ms\r\noriginal status: 200\r\noriginal status: 500\r\nbar parameter: 123\r\n```\r\n\r\nIt seems like calling request.getParameter(\"bar\") throws an exception that Jetty silently catches, Jetty sets the response status to 500, and then Jetty re-runs the servlet for the same request. I assume this last part (re-running the servlet) is a bug because side effects in the servlet before the body is parsed are run twice and it implies a strange API (is every servlet supposed to check the response status first thing to detect if there's a parsing error?). I assume that after Jetty set the response status to 500, it was supposed to send an error message to the client and end the connection, but there happens to be a bug that causes it to loop back to the servlet.\r\n\r\n## jetty 9.4.0.v20161208, 9.3.18.v20170406\r\n\r\nI decided to test on some older version too to see what happened so I could figure out if the current behavior might be a recent bug (possibly caused by work mentioned in https://github.com/eclipse/jetty.project/issues/2562).\r\n\r\n```\r\n$ nc localhost 8080 < badRequest\r\nHTTP/1.1 200 OK\r\nDate: Wed, 11 Jul 2018 23:49:19 GMT\r\nContent-Length: 18\r\nServer: Jetty(9.4.0.v20161208)\r\n\r\nreceived post 123\r\n```\r\n\r\nServer log:\r\n\r\n```\r\n[main] INFO org.eclipse.jetty.util.log - Logging initialized @1589ms to org.eclipse.jetty.util.log.Slf4jLog\r\n[main] INFO org.eclipse.jetty.server.Server - jetty-9.4.0.v20161208\r\n[main] INFO org.eclipse.jetty.server.AbstractConnector - Started ServerConnector@281a887{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}\r\n[main] INFO org.eclipse.jetty.server.Server - Started @2283ms\r\noriginal status: 200\r\nbar parameter: 123\r\n[qtp399931359-18] WARN org.eclipse.jetty.server.Request - org.eclipse.jetty.io.EofException: Early EOF\r\n```\r\n\r\n(It seems to be non-deterministic where the WARN log messages appears relative to the original status and bar parameter lines, probably because the WARN goes through a Logger and stderr instead of just stdout.)\r\n\r\nThis old behavior seems unsurprising, but disappointing in that the early EOF exception doesn't seem to be exposed to the servlet at all, and the servlet goes on to process a corrupt request body."},"comment":{"url":"https://api.github.com/repos/eclipse/jetty.project/issues/comments/404614774","html_url":"https://github.com/eclipse/jetty.project/issues/2712#issuecomment-404614774","issue_url":"https://api.github.com/repos/eclipse/jetty.project/issues/2712","id":404614774,"node_id":"MDEyOklzc3VlQ29tbWVudDQwNDYxNDc3NA==","user":{"login":"AgentME","id":577345,"node_id":"MDQ6VXNlcjU3NzM0NQ==","avatar_url":"https://avatars0.githubusercontent.com/u/577345?v=4","gravatar_id":"","url":"https://api.github.com/users/AgentME","html_url":"https://github.com/AgentME","followers_url":"https://api.github.com/users/AgentME/followers","following_url":"https://api.github.com/users/AgentME/following{/other_user}","gists_url":"https://api.github.com/users/AgentME/gists{/gist_id}","starred_url":"https://api.github.com/users/AgentME/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/AgentME/subscriptions","organizations_url":"https://api.github.com/users/AgentME/orgs","repos_url":"https://api.github.com/users/AgentME/repos","events_url":"https://api.github.com/users/AgentME/events{/privacy}","received_events_url":"https://api.github.com/users/AgentME/received_events","type":"User","site_admin":false},"created_at":"2018-07-12T18:55:00Z","updated_at":"2018-07-12T18:55:00Z","author_association":"NONE","body":"@joakime It seems like the bug is specific to ServletHandler. (Your example used ServletContextHandler. Thanks for the tip for it! I didn't know about it and I'll be updating my projects for it.) Modifying your example like this reproduces the running-servlet-twice issue:\r\n\r\n```java\r\npackage com.streak.emailmanager;\r\n\r\nimport java.io.IOException;\r\n\r\nimport javax.servlet.ServletException;\r\nimport javax.servlet.http.HttpServlet;\r\nimport javax.servlet.http.HttpServletRequest;\r\nimport javax.servlet.http.HttpServletResponse;\r\n\r\nimport org.eclipse.jetty.http.BadMessageException;\r\nimport org.eclipse.jetty.io.RuntimeIOException;\r\nimport org.eclipse.jetty.server.Server;\r\nimport org.eclipse.jetty.server.handler.DefaultHandler;\r\nimport org.eclipse.jetty.server.handler.HandlerList;\r\nimport org.eclipse.jetty.servlet.ServletContextHandler;\r\nimport org.eclipse.jetty.servlet.ServletHandler;\r\n\r\npublic class Demo\r\n{\r\n\tpublic static void main(String[] args) throws Exception\r\n\t{\r\n\t\tServer server = new Server(8081);\r\n\r\n//\t\tServletContextHandler context = new ServletContextHandler();\r\n//\t\tcontext.setContextPath(\"/\");\r\n//\t\tcontext.addServlet(FooServlet.class, \"/foo\");\r\n\r\n\t\tServletHandler servletHandler = new ServletHandler();\r\n\t\tservletHandler.addServletWithMapping(FooServlet.class, \"/foo\");\r\n\r\n//\t\tHandlerList handlers = new HandlerList();\r\n//\t\thandlers.addHandler(context);\r\n//\t\thandlers.addHandler(new DefaultHandler());\r\n\r\n//\t\tserver.setHandler(handlers);\r\n\t\tserver.setHandler(servletHandler);\r\n\r\n\t\ttry\r\n\t\t{\r\n\t\t\tserver.start();\r\n\t\t\tserver.join();\r\n\t\t}\r\n\t\tcatch (Throwable t)\r\n\t\t{\r\n\t\t\tt.printStackTrace();\r\n\t\t}\r\n\t\tfinally\r\n\t\t{\r\n\t\t\tserver.stop();\r\n\t\t}\r\n\t}\r\n\r\n\tpublic static class FooServlet extends HttpServlet\r\n\t{\r\n\t\t@Override\r\n\t\tprotected void service(HttpServletRequest req, HttpServletResponse resp) throws ServletException, IOException\r\n\t\t{\r\n\t\t\tSystem.out.println(\"Entered Servlet: \" + req);\r\n\t\t\tsuper.service(req, resp);\r\n\t\t}\r\n\r\n\t\t@Override\r\n\t\tprotected void doGet(HttpServletRequest req, HttpServletResponse resp) throws IOException\r\n\t\t{\r\n\t\t\tresp.getWriter().println(\"received get\");\r\n\t\t}\r\n\r\n\t\t@Override\r\n\t\tprotected void doPost(HttpServletRequest req, HttpServletResponse resp) throws IOException\r\n\t\t{\r\n\t\t\tSystem.out.printf(\"original status: %s%n\", resp.getStatus());\r\n\t\t\tString barValue;\r\n\r\n//\t\t\ttry\r\n//\t\t\t{\r\n\t\t\t\tbarValue = req.getParameter(\"bar\");\r\n//\t\t\t}\r\n//\t\t\tcatch (BadMessageException e)\r\n//\t\t\t{\r\n//\t\t\t\t// we got the message, but there's a syntax / formatting / spec fault\r\n//\t\t\t\tbarValue = String.format(\"[BadMessageException: %s]\", e.getMessage());\r\n//\t\t\t\te.printStackTrace(System.out);\r\n//\t\t\t}\r\n//\t\t\tcatch (RuntimeIOException e)\r\n//\t\t\t{\r\n//\t\t\t\t// something wrong with how we read from the socket\r\n//\t\t\t\tbarValue = String.format(\"[RuntimeIOException: %s]\", e.getMessage());\r\n//\t\t\t\te.printStackTrace(System.out);\r\n//\t\t\t}\r\n//\t\t\tcatch (Throwable t)\r\n//\t\t\t{\r\n//\t\t\t\t// all other errors\r\n//\t\t\t\tbarValue = String.format(\"[Throwable: %s]\", t.getMessage());\r\n//\t\t\t\tt.printStackTrace(System.out);\r\n//\t\t\t}\r\n\r\n\t\t\tSystem.out.printf(\"bar parameter: %s%n\", barValue);\r\n\t\t\tresp.getWriter().printf(\"received post %s\", barValue);\r\n\t\t}\r\n\t}\r\n}\r\n```\r\n\r\n```\r\n$ nc localhost 8081 < badRequest \r\nHTTP/1.1 500 Server Error\r\nContent-Length: 17\r\nConnection: close\r\nServer: Jetty(9.4.11.v20180605)\r\n\r\nreceived post 123\r\n```\r\n\r\n```\r\n[main] INFO org.eclipse.jetty.util.log - Logging initialized @970ms to org.eclipse.jetty.util.log.Slf4jLog\r\n[main] INFO org.eclipse.jetty.server.Server - jetty-9.4.11.v20180605; built: 2018-06-05T18:24:03.829Z; git: d5fc0523cfa96bfebfbda19606cad384d772f04c; jvm 1.8.0_131-b11\r\n[main] INFO org.eclipse.jetty.server.AbstractConnector - Started ServerConnector@6a192cfe{HTTP/1.1,[http/1.1]}{0.0.0.0:8081}\r\n[main] INFO org.eclipse.jetty.server.Server - Started @1920ms\r\nEntered Servlet: Request(POST //localhost:8081/foo)@35ea7fc6\r\noriginal status: 200\r\nEntered Servlet: Request(POST //localhost:8081/foo)@35ea7fc6\r\noriginal status: 500\r\nbar parameter: 123\r\n```\r\n\r\nNote the two entered-servlet and original-status lines."}}
{"actor":{"display_login":"AgentME"}}