Jetty not gracefully shutdown ServletContextListener #6237

scottastanley · 2021-05-06T02:04:24Z

Jetty version
11.0.2

Java version
java version "13.0.2" 2020-01-14
Java(TM) SE Runtime Environment (build 13.0.2+8)
Java HotSpot(TM) 64-Bit Server VM (build 13.0.2+8, mixed mode, sharing)

OS type/version
Linux ip-172-31-44-100 4.9.85-37.55.amzn1.x86_64 #1 SMP Mon Mar 5 19:00:48 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

Description
I have a web application that is deployed in Jetty 11.0.2. I have a ServletContextListener registered in web.xml,

<listener>
    <description>A listener that starts and stops all managed services based on the lifecycle of the web application context.</description>
    <display-name>Service Management Listener</display-name>
    <listener-class>com.bb.base.webservices.servlets.services.ServiceManagementListener</listener-class>
</listener>

When jetty starts and my web application is deployed, the contextInitialized(...) method is being called, however when I shut down jetty using kill -s TERM ${JETTY_PID} the contextDestroyed(...) method is not being called.

In my server.ini file, I have enabled graceful shutdown with,

jetty.server.stopAtShutdown=true
jetty.server.stopTimeout=15000

When jetty shuts down I am seeing it do the clean shutdown. I see;

2021-05-01 05:19:16.605:INFO :oejs.Server:JettyShutdownThread: Stopped Server@7a6d7e92{STOPPING}[11.0.2,sto=15000]
2021-05-01 05:19:16.606:INFO :oejs.Server:JettyShutdownThread: Shutdown Server@7a6d7e92{STOPPING}[11.0.2,sto=15000]
2021-05-01 05:19:16.630:INFO :oejs.AbstractConnector:JettyShutdownThread: Stopped ServerConnector@60db1c0e{SSL, (ssl, http/1.1)}{0.0.0.0:8443}
2021-05-01 05:19:16.631:INFO :oejs.AbstractConnector:JettyShutdownThread: Stopped ServerConnector@3b5fad2d{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
2021-05-01 05:19:16.631:INFO :oejsh.ContextHandler:JettyShutdownThread: Stopped o.e.j.s.h.ContextHandler@2dd80673{/.well-known,null,STOPPED}
2021-05-01 05:19:17.093:INFO :oejsh.ContextHandler:JettyShutdownThread: Stopped o.e.j.w.WebAppContext@c5dc4a2{Fermenation,/,null,STOPPED}{/opt/fermenation/live/jettyCfg/code/services-3.4.4.war}

The last line being the shutdown of my web app context. However, my listener is never called.

This logic used to work in earlier versions of jetty. I am pretty sure it worked in jetty 9.4, however I unfortunately don't have the log files anymore so I can not see it for certain. May have been an earlier version of jetty when I implemented this to begin with which is the only time I know beyond a doubt it worked.

The text was updated successfully, but these errors were encountered:

gregw · 2021-05-06T03:20:54Z

@lorban Can you have a look at this one.

lorban · 2021-05-06T08:46:30Z

I can confirm that the problem is reproducible.

It seems that registering a ServletContextListener via a web.xml <listener> tag does not properly register the listener in the ContextHandler which means nor the contextInitialized nor the contextDestroyed methods are ever called.

This issue is very specific to Jetty 11 as replacing the jakarta packages with javax.servlet in the listener impl and deploying on jetty 10 does make the listener called as it should be.

I'm now investigating why those listeners aren't registered.

lorban · 2021-05-06T09:12:08Z

Okay, digging deeper I think I figured the root cause. In the test I wrote to reproduce this issue, I mistakenly placed the jetty-jakarta-servlet-api jar in WEB-INF/lib of the jakarta version of the test app and did the same with the jetty-servlet-api jar of the javax version of the test app.

It happens that Jetty 10 happily ignores this jar and prefers the parent classloader to load the javax.servlet.* classes while Jetty 11 did load the jakarta.servlet.* classes using the webapp's classloader. This ends up breaking instanceof comparisons which eventually prevents the listeners from being registered.

@scottastanley can you confirm that this is the problem you're having? If that's the case, making sure there is no jar containing jakarta.servlet.* classes in the webapp's WEB-INF/lib should solve your issue.

I also believe that Jetty 11 should be modified to force loading jakarta.servlet.* classes from the parent classloader like Jetty 10 does for the jakarta.servlet.* classes.

gregw · 2021-05-06T11:50:18Z

This may already be fixed in #6125

lorban · 2021-05-06T11:53:55Z

It indeed seems to be, thanks for the link.

scottastanley · 2021-05-06T14:38:52Z

I do not include either of these jar files in my war file.

MacBook-Air:3.4.1 sstanley$ tar -tvf services-3.4.1.war  | grep lib | grep servlet

MacBook-Air:3.4.1 sstanley$ tar -tvf services-3.4.1.war  | grep lib | grep jakarta
-rw-r--r--  0 0      0       27927 Apr  3 13:43 WEB-INF/lib/jakarta.transaction-api-2.0.0.jar

MacBook-Air:3.4.1 sstanley$ tar -tvf services-3.4.1.war  | grep lib | grep jetty
-rw-r--r--  0 0      0       68227 Apr  3 13:43 WEB-INF/lib/jetty-plus-11.0.2.jar
-rw-r--r--  0 0      0       47387 Apr  3 13:43 WEB-INF/lib/jetty-jndi-11.0.2.jar
-rw-r--r--  0 0      0       48538 Apr  3 13:43 WEB-INF/lib/jetty-jaas-11.0.2.jar
-rw-r--r--  0 0      0      536805 Apr  3 13:43 WEB-INF/lib/jetty-util-11.0.2.jar

If it helps, I can probably standup a server and try and go back and re-deploy the jetty 10, and maybe jetty 9.4, versions, and assess the behavior. I think I have backups sufficient to let me do this. I only upgraded to jetty 11 in the last few months.

joakime · 2021-05-06T15:06:45Z

Why do you have those jetty jars in your WEB-INF/lib ?
I cannot imagine a scenario where a webapp could use plus/jndi/jaas directly like that.

scottastanley · 2021-05-06T16:31:42Z

I have to admit I wondered the same thing when I found those. I run jetty locally for development inside of Eclipse. I suspect I had to add those to my pom to get running locally to work and then forgot to exclude them from the war file. I have already filed a ticket in my project to remove those from the war. Need to check on util as well. Not sure if I even use that directly or not.

janbartel · 2021-05-07T00:24:16Z

I can't reproduce this problem with jetty-11 with the following settings in server.ini:

jetty.server.stopAtShutdown=true
jetty.server.stopTimeout=5000

We are going to need some more details about your setup and what is happening when you issue the kill command - for example are there requests in flight, or is the server idle?

scottastanley · 2021-05-07T01:01:19Z

Generally the server is idle. I am logged in, but not actively doing anything to trigger server activity. Let me do some looking tonight myself and make sure there is not anything else I missed that might cause this.

scottastanley · 2021-05-09T04:58:05Z

Well, I am hoping this helps. Although I will admit the last observation I have makes the whole thing super confusing for me. Should have never done that last check...

With that prelude said, I went through today and came up with a simple case which reproduces this problem. I first observed this problem in my environment in AWS (hence the OS type above), so I cloned my web server and pared the code for my application down so I have a pretty simple case which reproduces this problem. I am attaching two files;

example_config.tar.zip : A tar file containing a directory example_config with a runnable example which reproduces this problem. The contents of this directory are as follows;

jettyDist - The 11.0.2 jetty distribution I am running against.
jettyCfg - the Jetty Base directory with the full configuration for jetty. There is a war file in the webapp subdirectory under here which contains the compiled web application I am deploying.
jetty - A script to start/stop jetty. To start/stop jetty, simply change in to the example_config directory and run "./jetty start" and "./jetty stop"
tmp - The directory used to unpack the war files. Not really important

test-webservice.tar.zip : The source code for the web application. Nothing really here except for the listener and WEB-INF directory and the pom.xml for building.

In AWS, when I start then stop jetty, it is calling the listener when the web application is started, but not when it is stopped. This is a log of this process. As above, the listener is called on startup (log line "IN ServiceManagementListener::contextInitialized()") but not called when the WebAppContext is stopped (last line).

2021-05-09 03:59:57.844:WARN :testLogger:main: ===========================================
2021-05-09 03:59:57.845:WARN :testLogger:main: ========== DEPLOYING Test ==========
2021-05-09 03:59:57.845:WARN :testLogger:main: ===========================================
2021-05-09 03:59:57.863:INFO :oejw.StandardDescriptorProcessor:main: NO JSP Support for /test-webservice-1, did not find org.eclipse.jetty.jsp.JettyJspServlet
03:59:58.541 [main] FATAL ServiceManagementListener - Instantiating ServiceManagementListener
2021-05-09 03:59:58.562:INFO :oejss.DefaultSessionIdManager:main: Session workerName=node0
03:59:58.583 [main] FATAL ServiceManagementListener - IN ServiceManagementListener::contextInitialized()
2021-05-09 03:59:58.613:INFO :oejsh.ContextHandler:main: Started o.e.j.w.WebAppContext@1e16c0aa{Test,/test-webservice-1,file:///opt/fermenation/live/tmp/jetty-0_0_0_0-8080-test-webservice-1_war-_test-webservice-1-any-8170596185236762120/webapp/,AVAILABLE}{/opt/fermenation/live/jettyCfg/webapps/test-webservice-1.war}
2021-05-09 03:59:58.637:INFO :oejs.AbstractConnector:main: Started ServerConnector@1bc715b8{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
2021-05-09 03:59:58.639:INFO :oejs.Server:main: Started Server@75d3a5e0{STARTING}[11.0.2,sto=15000] @3052ms
2021-05-09 04:00:08.095:INFO :oejs.Server:JettyShutdownThread: Stopped Server@75d3a5e0{STOPPING}[11.0.2,sto=15000]
2021-05-09 04:00:08.095:INFO :oejs.Server:JettyShutdownThread: Shutdown Server@75d3a5e0{STOPPING}[11.0.2,sto=15000]
2021-05-09 04:00:08.117:INFO :oejs.AbstractConnector:JettyShutdownThread: Stopped ServerConnector@1bc715b8{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
2021-05-09 04:00:08.123:INFO :oejsh.ContextHandler:JettyShutdownThread: Stopped o.e.j.w.WebAppContext@1e16c0aa{Test,/test-webservice-1,null,STOPPED}{/opt/fermenation/live/jettyCfg/webapps/test-webservice-1.war}

Something I observed when trying to simplify the configuration as much as possible was that if I removed the jaas.ini file from the jettyCfg/start.d directory the shutdown logic worked successfully. In this case, this is the logs I get. Here you can see the call to the listener on startup as well as a call on shutdown (see the 2nd to last line; "IN ServiceManagementListener::contextDestroyed()").

2021-05-09 04:01:38.910:WARN :testLogger:main: ===========================================
2021-05-09 04:01:38.912:WARN :testLogger:main: ========== DEPLOYING Test ==========
2021-05-09 04:01:38.913:WARN :testLogger:main: ===========================================
2021-05-09 04:01:38.934:INFO :oejw.StandardDescriptorProcessor:main: NO JSP Support for /test-webservice-1, did not find org.eclipse.jetty.jsp.JettyJspServlet
04:01:39.632 [main] FATAL ServiceManagementListener - Instantiating ServiceManagementListener
2021-05-09 04:01:39.648:INFO :oejss.DefaultSessionIdManager:main: Session workerName=node0
04:01:39.671 [main] FATAL ServiceManagementListener - IN ServiceManagementListener::contextInitialized()
2021-05-09 04:01:39.698:INFO :oejsh.ContextHandler:main: Started o.e.j.w.WebAppContext@41330d4f{Test,/test-webservice-1,file:///opt/fermenation/live/tmp/jetty-0_0_0_0-8080-test-webservice-1_war-_test-webservice-1-any-18152874458996110787/webapp/,AVAILABLE}{/opt/fermenation/live/jettyCfg/webapps/test-webservice-1.war}
2021-05-09 04:01:39.726:INFO :oejs.AbstractConnector:main: Started ServerConnector@20b5f2ac{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
2021-05-09 04:01:39.728:INFO :oejs.Server:main: Started Server@4b741d6d{STARTING}[11.0.2,sto=15000] @3005ms
2021-05-09 04:01:44.668:INFO :oejs.Server:JettyShutdownThread: Stopped Server@4b741d6d{STOPPING}[11.0.2,sto=15000]
2021-05-09 04:01:44.669:INFO :oejs.Server:JettyShutdownThread: Shutdown Server@4b741d6d{STOPPING}[11.0.2,sto=15000]
2021-05-09 04:01:44.677:INFO :oejs.AbstractConnector:JettyShutdownThread: Stopped ServerConnector@20b5f2ac{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
04:01:44.688 [JettyShutdownThread] FATAL ServiceManagementListener - IN ServiceManagementListener::contextDestroyed()
2021-05-09 04:01:44.700:INFO :oejsh.ContextHandler:JettyShutdownThread: Stopped o.e.j.w.WebAppContext@41330d4f{Test,/test-webservice-1,null,STOPPED}{/opt/fermenation/live/jettyCfg/webapps/test-webservice-1.war}

Maybe there is something with the jaas module triggering this behavior??

test-webservice.tar.zip
example_config.tar.zip

scottastanley · 2021-05-09T05:06:59Z

Okay, now for the weird last observation...

When I put the example above together I was trying hard to carve this down to something that could be run locally. In this I was successful. I am able to run and reproduce the same behavior on my Macbook Air where the listener is not called on shutdown. However, when I tried to reproduce the correct behavior where the listener is called on shutdown when the jaas.ini file is not present, it does not work. In this case the listener is still not called on shutdown. I guess this is better than it not failing at all locally... That would have been super frustrating!

I am not sure if this datapoint is of any use at all whatsoever. But in case it is, my local environment is this.

uname -a
Darwin MacBook-Air.local 20.3.0 Darwin Kernel Version 20.3.0: Thu Jan 21 00:07:06 PST 2021; root:xnu-7195.81.3~1/RELEASE_X86_64 x86_64

 java -version
java version "13.0.2" 2020-01-14
Java(TM) SE Runtime Environment (build 13.0.2+8)
Java HotSpot(TM) 64-Bit Server VM (build 13.0.2+8, mixed mode, sharing)

I tried the same thing locally with java 11.0.9 and saw the same behavior.

janbartel · 2021-05-10T06:13:16Z

@scottastanley so your test webapp in your test base works for me :) One major change - I just put in a System.err.println() in the contextInitialized() and contextDestroyed() methods and I see those printlns on the output. I don't see the output from the log4j log.fatal() in the contextDestroyed() method, so I assume that the logging system is suppressing that output. But the contextDestroyed() method is definitely being called. You could try attaching a debugger and follow through what is happening in the logging system when contextDestroyed() is called.

joakime · 2021-05-10T14:49:50Z

If you turn on the log4j status logging ...

[jettyCfg]$ java -Dlog4j.debug=true -jar ../jettyDist/start.jar

You'll see the following ...

...(snip)...
DEBUG StatusLogger LoggerContext[name=1fd14d74, org.apache.logging.log4j.core.LoggerContext@71984c3] started OK.
09:44:04.238 [main] FATAL ServiceManagementListener - Instantiating ServiceManagementListener
2021-05-10 09:44:04.244:INFO :oejss.DefaultSessionIdManager:main: Session workerName=node0
09:44:04.252 [main] FATAL ServiceManagementListener - IN ServiceManagementListener::contextInitialized()
2021-05-10 09:44:04.264:INFO :oejsh.ContextHandler:main: Started o.e.j.w.WebAppContext@4d518b32{Test,/test-webservice-1,file:///tmp/jetty-0_0_0_0-8080-test-webservice-1_war-_test-webservice-1-any-589666964959778801/webapp/,AVAILABLE}{/home/joakim/tmp/issue-6237/example_config/jettyCfg/webapps/test-webservice-1.war}
2021-05-10 09:44:04.282:INFO :oejs.AbstractConnector:main: Started ServerConnector@56fc5db2{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
2021-05-10 09:44:04.287:INFO :oejs.Server:main: Started Server@5b799640{STARTING}[11.0.2,sto=15000] @1429ms
^C
DEBUG StatusLogger Stopping LoggerContext[name=1fd14d74, org.apache.logging.log4j.core.LoggerContext@71984c3]
DEBUG StatusLogger Stopping LoggerContext[name=1fd14d74, org.apache.logging.log4j.core.LoggerContext@71984c3]...
2021-05-10 09:44:07.189:INFO :oejs.Server:JettyShutdownThread: Stopped Server@5b799640{STOPPING}[11.0.2,sto=15000]
TRACE StatusLogger Unregistering 1 MBeans: [org.apache.logging.log4j2:type=1fd14d74]
2021-05-10 09:44:07.189:INFO :oejs.Server:JettyShutdownThread: Shutdown Server@5b799640{STOPPING}[11.0.2,sto=15000]
TRACE StatusLogger Unregistering 1 MBeans: [org.apache.logging.log4j2:type=1fd14d74,component=StatusLogger]
TRACE StatusLogger Unregistering 1 MBeans: [org.apache.logging.log4j2:type=1fd14d74,component=ContextSelector]
...(snip)...

This shows you that the log4j2 runtime shutdown hook runs before the Jetty graceful runtime shutdown hook.
That's why you don't see the logging events via log4j.
As log4j is shutdown / cleared out / you have no loggers, then the graceful shutdown kicks off and executes.

This behavior is documented at https://logging.apache.org/log4j/log4j-2.2/manual/webapp.html

scottastanley · 2021-05-12T04:49:21Z

Let me look in to it a bit more. My original reason for getting concerned on this was that the resources that are released in the listener shutdown logic were not being cleanly released. I noticed on startup I was getting complaints that the resources were not cleanly closed. I actually removed all of that resource shutdown logic when I put this example together. Maybe that original problem was due to some other reason, but not sure what it would have been.

Let me add the system log messages outside of log4j and try them in my EC2 node and make sure I am seeing the same behavior. Maybe what I was originally seeing was due to a totally different issue... If this is the case then I am sorry for any wasted time!

scottastanley · 2021-05-16T23:34:58Z

I added the output to System.out and I can confirm that on my EC2 node where I normally deploy the test application does indeed call the contextDestroyed method cleanly. Sorry about the wasted effort on this guys. I appreciate the effort you guys put in to making sure this worked cleanly. I'll look elsewhere for the unclean resource shutdown problem I see. Thought I had it sorted, but I guess not.

Closing this bug.

gregw assigned lorban May 6, 2021

lorban added the Bug For general bugs on Jetty side label May 6, 2021

lorban added this to the 11.0.x milestone May 6, 2021

janbartel added More Info Required Unable To Replicate and removed Bug For general bugs on Jetty side labels May 7, 2021

janbartel removed the More Info Required label May 10, 2021

scottastanley closed this as completed May 16, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Jetty not gracefully shutdown ServletContextListener #6237

Jetty not gracefully shutdown ServletContextListener #6237

scottastanley commented May 6, 2021 •

edited

Loading

gregw commented May 6, 2021

lorban commented May 6, 2021

lorban commented May 6, 2021 •

edited

Loading

gregw commented May 6, 2021

lorban commented May 6, 2021

scottastanley commented May 6, 2021

joakime commented May 6, 2021

scottastanley commented May 6, 2021 •

edited

Loading

janbartel commented May 7, 2021

scottastanley commented May 7, 2021

scottastanley commented May 9, 2021 •

edited

Loading

scottastanley commented May 9, 2021

janbartel commented May 10, 2021

joakime commented May 10, 2021

scottastanley commented May 12, 2021

scottastanley commented May 16, 2021

Jetty not gracefully shutdown ServletContextListener #6237

Jetty not gracefully shutdown ServletContextListener #6237

Comments

scottastanley commented May 6, 2021 • edited Loading

gregw commented May 6, 2021

lorban commented May 6, 2021

lorban commented May 6, 2021 • edited Loading

gregw commented May 6, 2021

lorban commented May 6, 2021

scottastanley commented May 6, 2021

joakime commented May 6, 2021

scottastanley commented May 6, 2021 • edited Loading

janbartel commented May 7, 2021

scottastanley commented May 7, 2021

scottastanley commented May 9, 2021 • edited Loading

scottastanley commented May 9, 2021

janbartel commented May 10, 2021

joakime commented May 10, 2021

scottastanley commented May 12, 2021

scottastanley commented May 16, 2021

scottastanley commented May 6, 2021 •

edited

Loading

lorban commented May 6, 2021 •

edited

Loading

scottastanley commented May 6, 2021 •

edited

Loading

scottastanley commented May 9, 2021 •

edited

Loading