systemdのstatusでfailedになったりinactiveになったりする件

#はじめに
先日記事にしたAzure Database for MySQLの移行手順作ってるときに
DB使ってるアプリケーションのサービス停止した後のステータス確認方法で悩んだのでメモしとく。

ベンダが提供してくれた手順だと以下の通り

$ sudo systemctl stop usher
$ sudo systemctl status usher
● usher.service
   Loaded: loaded (/etc/systemd/system/usher.service; enabled; vendor preset: disabled)
   Active: failed (Result: signal) since Tue 2020-05-26 22:03:15 UTC; 50s ago
  Process: 65681 ExecStop=/var/opt/MicroStrategy/Usher/UsherServer/usherApps/shardIDM/bin/tomcat.sh stop (code=exited, status=0/SUCCESS)
  Process: 31550 ExecStart=/var/opt/MicroStrategy/Usher/UsherServer/usherApps/shardIDM/bin/tomcat.sh start (code=exited, status=0/SUCCESS)
 Main PID: 31559 (code=killed, signal=KILL)

May 26 22:02:53  systemd[1]: Stopping usher.service...
May 26 22:02:53  tomcat.sh[65681]: Stopping Tomcat
May 26 22:03:14  tomcat.sh[65681]: Tomcat did not stop in time.
May 26 22:03:14  tomcat.sh[65681]: To aid diagnostics a thread dump has been written to standard out.
May 26 22:03:14  tomcat.sh[65681]: Killing Tomcat with the PID: 31559
May 26 22:03:14  systemd[1]: usher.service: main process exited, code=killed, status=9/KILL
May 26 22:03:15  tomcat.sh[65681]: The Tomcat process has been killed.
May 26 22:03:15  systemd[1]: Stopped usher.service.
May 26 22:03:15  systemd[1]: Unit usher.service entered failed state.
May 26 22:03:15  systemd[1]: usher.service failed.

実際にやってみると

$ sudo systemctl stop usher
$ sudo systemctl status usher
● usher.service
   Loaded: loaded (/etc/systemd/system/usher.service; enabled; vendor preset: disabled)
   Active: inactive (dead) since Sun 2020-06-28 04:39:35 UTC; 1 weeks 2 days ago
 Main PID: 58294 (java)
   CGroup: /system.slice/usher.service
           ‣ 58294 /var/opt/MicroStrategy/_jre/bin/java -Dnop -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djdk.tls.ephemeralDHKeySize=2048 -Djava.protocol.handler.pkgs=org.apache.catalina.webresources -Dorg.apac...

Jun 28 04:39:35  systemd[1]: Stopping usher.service...
Jun 28 04:39:35  tomcat.sh[58285]: Stopping Tomcat
Jun 28 04:39:37  tomcat.sh[58285]: Tomcat stopped.
Jun 28 04:39:37  systemd[1]: Stopped usher.service.

比べてみると

   Active: failed (Result: signal) # ベンダ手順
   Active: inactive (dead)         # 実際の結果

2パターンあります・・・。
調べてみると

・Active: inactive (dead)
　正常に停止された場合はこうなる。

・Active: failed (Result: signal)
　正常に停止されなかった場合にこうなる。
　（正常に起動できなかった場合も同じ。）

とのこと。
確かに正常に停止できた時のログを見ると

Jun 28 04:39:35  systemd[1]: Stopping usher.service...
Jun 28 04:39:35  tomcat.sh[58285]: Stopping Tomcat
Jun 28 04:39:37  tomcat.sh[58285]: Tomcat stopped.
Jun 28 04:39:37  systemd[1]: Stopped usher.service.

すんなり停止している。
では正常に停止できなかった場合はどうか。

May 26 22:02:53  systemd[1]: Stopping usher.service...
May 26 22:02:53  tomcat.sh[65681]: Stopping Tomcat
May 26 22:03:14  tomcat.sh[65681]: Tomcat did not stop in time.
May 26 22:03:14  tomcat.sh[65681]: Killing Tomcat with the PID: 31559
May 26 22:03:14  systemd[1]: usher.service: main process exited, code=killed, status=9/KILL
May 26 22:03:15  tomcat.sh[65681]: The Tomcat process has been killed.
May 26 22:03:15  systemd[1]: Stopped usher.service.
May 26 22:03:15  systemd[1]: Unit usher.service entered failed state.
May 26 22:03:15  systemd[1]: usher.service failed.

Tomcatのプロセス（PID:31559）が時間内に停止しなかったからKillされたらしい。
その時間は約20秒（22:03:14-22:02:53）。

systemdがkillしたのかな、と思いタイムアウトを確認すると

$ systemctl show usher -p TimeoutStopUSec
TimeoutStopUSec=1min 30s

あれ、90秒？
もう1度ログをよく見ると

May 26 22:03:14  tomcat.sh[65681]: Killing Tomcat with the PID: 31559

killしたのはtomcat.shとのこと。
一応中を見ておこう。

$ sudo systemctl show usher
・・・
ExecStop={ path=/var/opt/MicroStrategy/Usher/UsherServer/usherApps/shardIDM/bin/tomcat.sh ; argv[]=/var/opt/MicroStrategy/Usher/UsherServer/usherApps/shardIDM/bin/tomcat.sh stop ; ignore_errors=no ; start_time=[n/a] ; stop_time=[n/a] ; p
・・・

tomcat.shのフルパスをゲット。

$ sudo cat /var/opt/MicroStrategy/Usher/UsherServer/usherApps/shardIDM/bin/tomcat.sh
・・・
CATALINA_HOME=/opt/bin/apache-tomcat-9
・・・
  stop)
    echo "Stopping Tomcat"
        $CATALINA_HOME/bin/shutdown.sh 20 -force    
    ;;
・・・

tomcat.shの中ではshutdown.shを呼んでました。

$sudo cat /opt/bin/apache-tomcat-9/bin/shutdown.sh
・・・
PRG="$0"
PRGDIR=`dirname "$PRG"`
EXECUTABLE=catalina.sh
・・・
exec "$PRGDIR"/"$EXECUTABLE" stop "$@"
・・・

shutdown.shの中でさらにはcatalina.shを呼んでました。
この感じ懐かしい。
商用のトラブルシュートしてるときにこんな感じでたらい回しにされてめっちゃイライラするやつ。
あ"あ"！さっきのパス、コピっとくの忘れた！！とか。

$ sudo cat  /opt/bin/apache-tomcat-9/bin/catalina.sh
・・・
elif [ "$1" = "stop" ] ; then
・・・
        echo "Killing Tomcat with the PID: $PID"
        kill -9 $PID
                rm -f "$CATALINA_PID" >/dev/null 2>&1
・・・
                echo "The Tomcat process has been killed."
・・・ 

ちゃんとSIGKILLしてPIDファイルも消してくれてますね。
ということで長くなりましたがtomcat.shがtomcatのプロセスをkillしたことが確認できました。

#結論
ということでsystemctlコマンドでstatusを確認したときに以下2パターン出ますが、

   Active: failed (Result: signal) # ベンダ手順
   Active: inactive (dead)         # 実際の結果

####どっちでもOK
ということにしました。
調子よければinactiveだし調子悪くて20秒で止まらなかったらfailedってことで。

自分とこのアプリで20秒停止できなかったら何でだっけ？って深堀りますが、
製品ベンダの出してるパッケージなので今回は追いません。

#おわりに
そのあとマニュアルよく読んでたらこんなの見つけた。

# sudo systemctl is-active usher
active / failed

これで一発じゃん！
RHEL7世代の人にとっては当たり前ですかね。

systemdちゃんと勉強せねば。