Uploaded image for project: 'WildFly'
  1. WildFly
  2. WFLY-9461

Occasional 404 response during graceful shutdown

    Details

    • Steps to Reproduce:
      1. Unzip, build and deploy ha-servlet-counter app (as ROOT.war) to EAP
      2. Unzip, build http-client app
      3. Run EAP
      4. Run http-client by "java -jar http-client.jar" and introduce graceful shutdown ASAP

      Description

      I have simple war app with simple servlet doing:

      		resp.setContentType("text/plain");
      		String servletId = (String) req.getServletContext().getAttribute("servletId");
      		System.out.println("requestedSessionId: " + req.getRequestedSessionId() + ", queryString: " + req.getQueryString());
      
      		HttpSession session = req.getSession();
      		Long counter = (Long) session.getAttribute("counter");
      		if (counter == null) {
      			counter = 0L;
      		}
      
      		counter++;
      		session.setAttribute("counter", counter);
      		PrintWriter writer = resp.getWriter();
      		writer.println(servletId + " " + counter);
      		writer.close();
      

      There are running 256 clients (apache http client) hitting this servlet. When I manually introduce graceful shutdown (timeout 5s) I can occasionally see some 404 (0-10) responses (instead of 503). This response is not listed in the access log. The server log looks like:

      2017-09-13 11:54:21,070 INFO  [org.jboss.as.server] (management-handler-thread - 3) WFLYSRV0211: Suspending server with 5000 ms timeout.
      2017-09-13 11:54:21,072 INFO  [org.jboss.as.ejb3] (management-handler-thread - 3) WFLYEJB0493: EJB subsystem suspension complete
      2017-09-13 11:54:21,074 INFO  [org.jboss.as.server] (Management Triggered Shutdown) WFLYSRV0241: Shutting down in response to management operation 'shutdown'
      2017-09-13 11:54:21,104 INFO  [org.wildfly.extension.undertow] (ServerService Thread Pool -- 2) WFLYUT0022: Unregistered web context: '/' from server 'default-server'
      2017-09-13 11:54:21,121 TRACE [io.undertow.request] (default I/O-1) Opened connection with /127.0.0.1:44328
      2017-09-13 11:54:21,121 TRACE [io.undertow.request] (default I/O-5) Opened connection with /127.0.0.1:44324
      2017-09-13 11:54:21,122 DEBUG [io.undertow.request] (default I/O-1) Matched default handler path /Counter
      2017-09-13 11:54:21,122 DEBUG [io.undertow.request] (default I/O-5) Matched default handler path /Counter
      2017-09-13 11:54:21,132 TRACE [io.undertow.session] (ServerService Thread Pool -- 2) Bumping timeout for session KykwjKuYLFildYvXtaqCr6CHPhlQcFvq715M6CMU to 1505298261132
      ....
      2017-09-13 11:54:21,205 TRACE [io.undertow.session] (ServerService Thread Pool -- 2) Bumping timeout for session KA4RbDMrYmi28CebEz2NzPe7sqAX35OhU95U9jvC to 1505298261205
      2017-09-13 11:54:21,205 TRACE [io.undertow.session] (ServerService Thread Pool -- 2) Removing session attribute counter for session KA4RbDMrYmi28CebEz2NzPe7sqAX35OhU95U9jvC
      2017-09-13 11:54:21,211 INFO  [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-5) WFLYJCA0010: Unbound data source [java:jboss/datasources/ExampleDS]
      2017-09-13 11:54:21,214 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-4) WFLYUT0019: Host default-host stopping
      2017-09-13 11:54:21,217 INFO  [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-5) WFLYJCA0019: Stopped Driver service with driver-name = h2
      2017-09-13 11:54:21,233 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 23) WFLYCLINF0003: Stopped client-mappings cache from ejb container
      2017-09-13 11:54:21,253 TRACE [io.undertow.request] (default I/O-5) Opened connection with /127.0.0.1:44332
      2017-09-13 11:54:21,253 TRACE [io.undertow.server.handlers.ResponseCodeHandler] (default I/O-5) Setting response code 404 for exchange HttpServerExchange{ GET /Counter request {Connection=[Keep-Alive], Accept-Encoding=[gzip,deflate], User-Agent=[Apache-HttpClient/4.3.6.redhat-1 (java 1.5)], Host=[localhost:8080]} response {}}
      2017-09-13 11:54:21,253 TRACE [io.undertow.server.HttpServerExchange] (default I/O-5) Starting to write response for HttpServerExchange{ GET /Counter request {Connection=[Keep-Alive], Accept-Encoding=[gzip,deflate], User-Agent=[Apache-HttpClient/4.3.6.redhat-1 (java 1.5)], Host=[localhost:8080]} response {Connection=[keep-alive], Content-Length=[74], Content-Type=[text/html], Date=[Wed, 13 Sep 2017 09:54:21 GMT]}}
      2017-09-13 11:54:21,262 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-6) WFLYUT0008: Undertow HTTP listener default suspending
      2017-09-13 11:54:21,262 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-4) WFLYUT0008: Undertow HTTPS listener https suspending
      2017-09-13 11:54:21,263 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-4) WFLYUT0007: Undertow HTTPS listener https stopped, was bound to 127.0.0.1:8443
      2017-09-13 11:54:21,263 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-6) WFLYUT0007: Undertow HTTP listener default stopped, was bound to 127.0.0.1:8080
      2017-09-13 11:54:21,264 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-2) WFLYUT0004: Undertow 1.4.18.Final-redhat-1 stopping
      2017-09-13 11:54:21,286 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment ROOT.war (runtime-name: ROOT.war) in 191ms
      

        Gliffy Diagrams

          Attachments

            Issue Links

              Activity

                People

                • Assignee:
                  swd847 Stuart Douglas
                  Reporter:
                  swd847 Stuart Douglas
                • Votes:
                  0 Vote for this issue
                  Watchers:
                  2 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved: