[systemd-devel] Springboot and systemd, clean shutdown

Wed Oct 2 16:58:06 UTC 2024

My goal:

  Under SLES12 SP5 running systemd-228, I want to cleanly terminate
  a Java-based SpringBoot application.

My problem: 

  systemd (or at least the version available to me) seemingly is
  terminating my JVM differently than my ExecStop directive should
  yield.

Just for quick background, a SpringBoot application is a self-hosted
web server and web app, and you're excepted to interact with it via
'endpoints', basically several specific URLs.

According to the SpringBoot documentation, the desired way is to
POST to the shutdown URL.

  https://docs.spring.io/spring-boot/api/rest/actuator/shutdown.html

Ignoring systemd: when the JVM is run is the foreground, using the
shutdown endpoint yields a clean exit:

  10-153-68-12:/home/webapp # env SERVER_PORT=8888 LOG_DIR=/home/webapp/log
  JDK_JAVA_OPTIONS=-Dlogging.config=log4j2.properties -Dloader.path=lib/
  SPRING_MAIN_LAZY_INITIALIZATION=true /home/webapp/jdk/bin/java
  -jar webapp.jar; echo $?
  NOTE: Picked up JDK_JAVA_OPTIONS: -Dlogging.config=log4j2.properties
  2024-10-02 12:20:24,685 main ERROR appender File has no parameter
  that matches element Policies
  0

  10-153-68-12:/home/webapp # /usr/bin/curl -X POST localhost:8888/shutdown
  {"message":"Shutting down, bye..."}

(Note the '0' exit status above.)

When I've started my service via my service file, if I manually
invoke the shutdown endpoint, I can see that the JVM exited with
0, but my ExecPost (using curl), was invoked, and that died as there
was no longer a listener:

  10-153-68-12:/home/webapp # systemctl status webapp.service --full
     webapp.service - example webapp
     Loaded: loaded (/etc/systemd/system/webapp.service; disabled; vendor preset: disabled)
     Active: failed (Result: exit-code) since Wed 2024-10-02 12:46:58 EDT; 7s ago
    Process: 27573 ExecStop=/usr/bin/curl -X POST localhost:${SERVER_PORT}/shutdown (code=exited, status=7)
    Process: 27434 ExecStart=/home/webapp/jdk/bin/java -jar ${JAR_FILE} ${JAR_ARGS} (code=exited, status=0/SUCCESS)
   Main PID: 27434 (code=exited, status=0/SUCCESS)

  Oct 02 12:46:40 10-153-68-12 systemd[1]: Started example webapp.
  Oct 02 12:46:40 10-153-68-12 java[27434]: NOTE: Picked up JDK_JAVA_OPTIONS: -Dlogging.config=log4j2.properties -Dloader.path=lib/
  Oct 02 12:46:42 10-153-68-12 java[27434]: 2024-10-02 12:46:42,417 main ERROR appender File has no parameter that matches element Policies
  Oct 02 12:46:58 10-153-68-12 curl[27573]:   % Total    % Received % Xferd Average Speed   Time    Time     Time  Current
  Oct 02 12:46:58 10-153-68-12 curl[27573]: Dload  Upload   Total   Spent    Left  Speed
  Oct 02 12:46:58 10-153-68-12 curl[27573]: [158B blob data]
  Oct 02 12:46:58 10-153-68-12 curl[27573]: curl: (7) Failed to connect to localhost port 8888 after 2 ms: Couldn't connect to server
  Oct 02 12:46:58 10-153-68-12 systemd[1]: webapp.service: Control process exited, code=exited status=7
  Oct 02 12:46:58 10-153-68-12 systemd[1]: webapp.service: Unit entered failed state.
  Oct 02 12:46:58 10-153-68-12 systemd[1]: webapp.service: Failed with result 'exit-code'.

I admit that's not a typical use case, so I'm not very worried, but
it would be nice to harden against that.

But it does show, that using curl to hit the shutdown endpoint does cause the JVM to exit cleanly.

But, my real concern is when I use systemd to stop this service, I
can see that curl was invoked, got content, and itself exited
cleanly, but somehow my JVM is exiting with an exit status of 143:

  10-153-68-12:/home/webapp # systemctl status webapp.service --full
     webapp.service - example webapp
     Loaded: loaded (/etc/systemd/system/webapp.service; disabled; vendor preset: disabled)
     Active: failed (Result: exit-code) since Wed 2024-10-02 12:30:22 EDT; 9s
  ago
    Process: 24220 ExecStop=/usr/bin/curl -X POST
  localhost:${SERVER_PORT}/shutdown (code=exited, status=0/SUCCESS)
    Process: 23462 ExecStart=/home/webapp/jdk/bin/java -jar ${JAR_FILE} ${JAR_ARGS} (code=exited, status=143)
   Main PID: 23462 (code=exited, status=143)

  Oct 02 12:27:20 10-153-68-12 java[23462]: NOTE: Picked up JDK_JAVA_OPTIONS: -Dlogging.config=log4j2.properties -Dloader.path=lib/
  Oct 02 12:27:23 10-153-68-12 java[23462]: 2024-10-02 12:27:23,015 main ERROR appender File has no parameter that matches element Policies
  Oct 02 12:30:21 10-153-68-12 systemd[1]: Stopping example webapp...
  Oct 02 12:30:21 10-153-68-12 curl[24220]:   % Total    % Received % Xferd Average Speed   Time    Time     Time  Current
  Oct 02 12:30:21 10-153-68-12 curl[24220]: Dload  Upload   Total   Spent    Left  Speed
  Oct 02 12:30:22 10-153-68-12 curl[24220]: [237B blob data]
  Oct 02 12:30:22 10-153-68-12 systemd[1]: webapp.service: Main process exited, code=exited, status=143/n/a
  Oct 02 12:30:22 10-153-68-12 systemd[1]: Stopped example webapp.
  Oct 02 12:30:22 10-153-68-12 systemd[1]: webapp.service: Unit entered failed state.
  Oct 02 12:30:22 10-153-68-12 systemd[1]: webapp.service: Failed with result 'exit-code'.

Further, when I compare logs, I can see that when I use the standalone
execution, I can see the Springboot app cleanly shuts down it's
listener; I don't see these entries when I use systemd to manage
this webapp:

  [INFO ] 2024-10-02 12:27:20.656 [Thread-2] Http11NioProtocol - Pausing ProtocolHandler ["http-nio-8888"]
  [INFO ] 2024-10-02 12:27:20.656 [Thread-2] StandardService - Stopping service [Tomcat]
  [INFO ] 2024-10-02 12:27:20.658 [Thread-2] [/] - Destroying Spring FrameworkServlet 'dispatcherServlet'
  [INFO ] 2024-10-02 12:27:20.661 [Thread-2] Http11NioProtocol - Stopping ProtocolHandler ["http-nio-8888"]
  [INFO ] 2024-10-02 12:27:20.665 [Thread-2] Http11NioProtocol - Destroying ProtocolHandler ["http-nio-8888"]

Does anyone have any insight on why I'm seeing this?

Here's my service file:

  10-153-68-12:/home/webapp # cat /etc/systemd/system/webapp.service
  [Unit]
  Description=example webapp
  Before=getty at tty1.service plymouth-quit.service
  DefaultDependencies=no

  Requires=local-fs.target
  After=local-fs.target

  [Service]
  User=webapp
  Group=webapp

  WorkingDirectory=/home/webapp
  EnvironmentFile=/home/webapp/webapp.env

  PassEnvironment=JAVA_HOME JDK_JAVA_OPTIONS JAR_FILE JAR_ARGS SERVER_PORT

  ExecStart=/home/webapp/jdk/bin/java -jar ${JAR_FILE} ${JAR_ARGS}
  ExecStop=/usr/bin/curl -X POST localhost:${SERVER_PORT}/shutdown

  TimeoutStopSec=30
  KillMode=mixed
  NotifyAccess=all
  Restart=no

  [Install]
  WantedBy=multi-user.target

-- 
Brian Reichert				<reichert at numachi.com>
BSD admin/developer at large	