Logstash停止時の挙動がバージョンにより異なる

[t-nakata (NAKATA)]

logstashを7.6から7.7にバージョンアップしました。
logstashをsystemctlコマンドで停止し、systemctl statusでステータスを確認したときの挙動と、ログの出力のされ方が7.6と7.7にで異なります。
7.6は正常に停止しているように見えるのですが、7.7は停止後のステータスがfailedになっており、停止時に何らかの異常が発生しているように見えます。原因について分かりますでしょうか？

以下に、それぞれのバージョンで停止した時のログとsystemctlでステータスを確認した時の結果を記載します

■7.6のログ

systemd: Stopping logstash...
logstash: [2020-05-29T09:34:41,924][WARN ][logstash.runner          ] SIGTERM received. Shutting down.
start-amazon-cloudwatch-agent: 2020/05/29 09:34:42 Stopping tail as file no longer exists: /var/log/logstash/logstash-plain.log
logstash: [2020-05-29T09:34:42,154][INFO ][filewatch.observingtail  ] QUIT - closing all files and shutting down.
logstash: [2020-05-29T09:34:42,169][INFO ][filewatch.observingtail  ] QUIT - closing all files and shutting down.
logstash: [2020-05-29T09:34:42,185][INFO ][filewatch.observingtail  ] QUIT - closing all files and shutting down.
logstash: [2020-05-29T09:34:42,187][INFO ][filewatch.observingtail  ] QUIT - closing all files and shutting down.
logstash: [2020-05-29T09:34:42,200][INFO ][filewatch.observingtail  ] QUIT - closing all files and shutting down.
logstash: [2020-05-29T09:34:42,205][INFO ][filewatch.observingtail  ] QUIT - closing all files and shutting down.
logstash: [2020-05-29T09:34:42,229][INFO ][filewatch.observingtail  ] QUIT - closing all files and shutting down.
logstash: [2020-05-29T09:34:42,254][INFO ][filewatch.observingtail  ] QUIT - closing all files and shutting down.
logstash: [2020-05-29T09:34:43,518][INFO ][logstash.javapipeline    ] Pipeline terminated {"pipeline.id"=>"ddi_threat"}
logstash: [2020-05-29T09:34:43,528][INFO ][logstash.javapipeline    ] Pipeline terminated {"pipeline.id"=>"ddi_web_reputation"}
logstash: [2020-05-29T09:34:43,555][INFO ][logstash.javapipeline    ] Pipeline terminated {"pipeline.id"=>"ddi_attention_application"}
logstash: [2020-05-29T09:34:43,561][INFO ][logstash.javapipeline    ] Pipeline terminated {"pipeline.id"=>"ddi_system"}
logstash: [2020-05-29T09:34:43,558][INFO ][logstash.javapipeline    ] Pipeline terminated {"pipeline.id"=>"correlation_incident"}
logstash: [2020-05-29T09:34:43,575][INFO ][logstash.javapipeline    ] Pipeline terminated {"pipeline.id"=>"ddi_analyzer_chara"}
logstash: [2020-05-29T09:34:43,580][INFO ][logstash.javapipeline    ] Pipeline terminated {"pipeline.id"=>"ddi_analyzer_rejection"}
logstash: [2020-05-29T09:34:43,596][INFO ][logstash.javapipeline    ] Pipeline terminated {"pipeline.id"=>"ddi_analyzer_analysis"}
logstash: [2020-05-29T09:34:44,957][INFO ][logstash.runner          ] Logstash shut down.

■systemctl statusのステータス

# systemctl status logstash
● logstash.service - logstash
   Loaded: loaded (/etc/systemd/system/logstash.service; disabled; vendor preset: disabled)
   Active: inactive (dead)

May 29 09:34:43 ip-10-0-21-13.ap-northeast-1.compute.internal logstash[4390]: [2020-05-29T09:34:43,518][INFO ][logstash.ja..."}
May 29 09:34:43 ip-10-0-21-13.ap-northeast-1.compute.internal logstash[4390]: [2020-05-29T09:34:43,528][INFO ][logstash.ja..."}
May 29 09:34:43 ip-10-0-21-13.ap-northeast-1.compute.internal logstash[4390]: [2020-05-29T09:34:43,555][INFO ][logstash.ja..."}
May 29 09:34:43 ip-10-0-21-13.ap-northeast-1.compute.internal logstash[4390]: [2020-05-29T09:34:43,561][INFO ][logstash.ja..."}
May 29 09:34:43 ip-10-0-21-13.ap-northeast-1.compute.internal logstash[4390]: [2020-05-29T09:34:43,558][INFO ][logstash.ja..."}
May 29 09:34:43 ip-10-0-21-13.ap-northeast-1.compute.internal logstash[4390]: [2020-05-29T09:34:43,575][INFO ][logstash.ja..."}
May 29 09:34:43 ip-10-0-21-13.ap-northeast-1.compute.internal logstash[4390]: [2020-05-29T09:34:43,580][INFO ][logstash.ja..."}
May 29 09:34:43 ip-10-0-21-13.ap-northeast-1.compute.internal logstash[4390]: [2020-05-29T09:34:43,596][INFO ][logstash.ja..."}
May 29 09:34:44 ip-10-0-21-13.ap-northeast-1.compute.internal logstash[4390]: [2020-05-29T09:34:44,957][INFO ][logstash.ru...n.
May 29 09:34:45 ip-10-0-21-13.ap-northeast-1.compute.internal systemd[1]: Stopped logstash.
Hint: Some lines were ellipsized, use -l to show in full.

■7.7のログ

systemd: Stopping logstash...
systemd: logstash.service stop-sigterm timed out. Killing.
systemd: logstash.service still around after SIGKILL. Ignoring.
systemd: logstash.service stop-final-sigterm timed out. Killing.
systemd: logstash.service: main process exited, code=killed, status=9/KILL
systemd: Stopped logstash.
systemd: Unit logstash.service entered failed state.
systemd: logstash.service failed.

■systemctl statusのステータス

# systemctl status logstash
● logstash.service - logstash
   Loaded: loaded (/etc/systemd/system/logstash.service; enabled; vendor preset: disabled)
   Active: failed (Result: signal) since Fri 2020-05-29 10:06:26 JST; 11s ago
  Process: 10390 ExecStart=/usr/share/logstash/bin/logstash --path.settings /etc/logstash (code=killed, signal=KILL)
 Main PID: 10390 (code=killed, signal=KILL)

May 29 09:53:18 ip-10-0-22-107.ap-northeast-1.compute.internal logstash[10390]: [2020-05-29T09:53:18,780][INFO ][logstash.ag...
May 29 09:53:19 ip-10-0-22-107.ap-northeast-1.compute.internal logstash[10390]: [2020-05-29T09:53:19,304][INFO ][logstash....0}
May 29 10:06:26 ip-10-0-22-107.ap-northeast-1.compute.internal systemd[1]: Stopping logstash...
May 29 10:06:26 ip-10-0-22-107.ap-northeast-1.compute.internal systemd[1]: logstash.service stop-sigterm timed out. Killing.
May 29 10:06:26 ip-10-0-22-107.ap-northeast-1.compute.internal systemd[1]: logstash.service still around after SIGKILL. I...ng.
May 29 10:06:26 ip-10-0-22-107.ap-northeast-1.compute.internal systemd[1]: logstash.service stop-final-sigterm timed out....ng.
May 29 10:06:26 ip-10-0-22-107.ap-northeast-1.compute.internal systemd[1]: logstash.service: main process exited, code=ki...ILL
May 29 10:06:26 ip-10-0-22-107.ap-northeast-1.compute.internal systemd[1]: Stopped logstash.
May 29 10:06:26 ip-10-0-22-107.ap-northeast-1.compute.internal systemd[1]: Unit logstash.service entered failed state.
May 29 10:06:26 ip-10-0-22-107.ap-northeast-1.compute.internal systemd[1]: logstash.service failed.
Hint: Some lines were ellipsized, use -l to show in full.

[bruce_shimizu (Yukiya Shimizu)]

@t-nakataさん

必ずしも7.7だから、というわけではないかと思われます。以前からSIGTERMで綺麗に落ちない、という話は度々あったようです。

Stopping Logstash on Debian times out

Logstash自体のShutdown時の動きは以下URLにある通り、状況に寄る部分がありますので、参考にしてみてください。
https://www.elastic.co/guide/en/logstash/current/shutdown.html#_what_happens_during_a_controlled_shutdown

ちなみに、Logstash7.7でも綺麗に落ちる時は落ちました（ちなみに同じConfigでもt-nakataさんと同じようなケースもありました）。

root@br-tst-1:/etc/logstash/conf.d# systemctl status logstash.service
● logstash.service - logstash
   Loaded: loaded (/etc/systemd/system/logstash.service; disabled; vendor preset: enabled)
   Active: inactive (dead)

Jun 02 10:09:29 br-tst-1 systemd[1]: Stopping logstash...
Jun 02 10:09:29 br-tst-1 logstash[8763]: [2020-06-02T10:09:29,202][WARN ][logstash.runner          ] SIGTERM received. Shutting down.
Jun 02 10:09:30 br-tst-1 logstash[8763]: [2020-06-02T10:09:30,697][INFO ][org.reflections.Reflections] Reflections took 90 ms to scan 1 urls, producing 21 keys and 41 
Jun 02 10:09:32 br-tst-1 logstash[8763]: [2020-06-02T10:09:32,434][WARN ][org.logstash.instrument.metrics.gauge.LazyDelegatingGauge][main] A gauge metric of an unknown
Jun 02 10:09:32 br-tst-1 logstash[8763]: [2020-06-02T10:09:32,461][INFO ][logstash.javapipeline    ][main] Starting pipeline {:pipeline_id=>"main", "pipeline.workers"=
Jun 02 10:09:34 br-tst-1 logstash[8763]: [2020-06-02T10:09:34,349][INFO ][logstash.javapipeline    ][main] Pipeline started {"pipeline.id"=>"main"}
Jun 02 10:09:34 br-tst-1 logstash[8763]: [2020-06-02T10:09:34,610][INFO ][logstash.agent           ] Pipelines running {:count=>1, :running_pipelines=>[:main], :non_ru
Jun 02 10:09:35 br-tst-1 logstash[8763]: [2020-06-02T10:09:35,084][INFO ][logstash.agent           ] Successfully started Logstash API endpoint {:port=>9600}
Jun 02 10:09:39 br-tst-1 logstash[8763]: [2020-06-02T10:09:39,857][INFO ][logstash.runner          ] Logstash shut down.
Jun 02 10:09:40 br-tst-1 systemd[1]: Stopped logstash.