Re: Springboot and systemd, clean shutdown

[Etienne Doms <etienne.doms@xxxxxxxxx>]

Hi,

https://www.freedesktop.org/software/systemd/man/latest/systemd.service.html#ExecStop=

"Note that it is usually not sufficient to specify a command for this
setting that only asks the service to terminate (for example, by
sending some form of termination signal to it), but does not wait for
it to do so. Since the remaining processes of the services are killed
according to KillMode= and KillSignal= or RestartKillSignal= as
described above immediately after the command exited, this may not
result in a clean stop."

Your curl command just sends an HTTP POST request and waits for the
reply, but at this point I guess your Spring Boot application is just
shutting down, and has not yet cleanly terminated.

I remember in a past life having to deal with POSIX signahandling in a
Java application and I ended up with Runtime.addShutdownHook()



Le mer. 2 oct. 2024 à 20:15, Brian Reichert <reichert@xxxxxxxxxxx> a écrit :
>
> 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@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@xxxxxxxxxxx>
> BSD admin/developer at large