cinder-volumeのトラブルシューティングをしたら意外な原因だった

Table of Contents

はじめに

我が家には趣味で構築した OpenStack 環境があります（環境の詳細はこちらの記事を参照してください）。

普段はこのブログサイトや GitHub self-hosted runner 等を動かしていてそれなりに安定稼働しているのですが、ある日 Cinder Volume を作成しようとしたところ、なぜか作成に失敗してしまいました。

そこから始まったトラブルシューティングで、最終的にたどり着いた原因が予想外すぎて驚いたので、その経験を共有したいと思います。

問題の発見

新規に VM を作成するために Cinder Volume の作成しようとしたところ、“no host available” みたいなエラーが出て失敗してしまいました。そのため、まずは cinder-volume service の状態を確認してみることにしました。

openstack volume service list

すると、なんと cinder-volume サービスが down になっていました。これが直接の原因のようです。

| Binary           | Host          | Zone | Status  | State | Updated At          |
| ---------------- | ------------- | ---- | ------- | ----- | ------------------- |
| cinder-volume    | block-storage | nova | enabled | down  | 2025-XX-XX XX:XX:XX |
| cinder-scheduler | controller    | nova | enabled | up    | 2025-XX-XX XX:XX:XX |

「あれ、cinder-volume が落ちてる…？」というわけで、調査開始です。

調査

サービスの実態を確認

まず、cinder-volume が本当に停止しているのか確認するため、cinder-volume が動いている block storage ホストに SSH でログインしました。

systemctl status cinder-volume
● cinder-volume.service - OpenStack Cinder Volume
     Loaded: loaded (/lib/systemd/system/cinder-volume.service; enabled; vendor preset: enabled)
     Active: active (running) since ...

ん？普通に動いてる…？

ログも確認してみましたが、特にエラーらしいエラーも出ていません。

journalctl -u cinder-volume -f

どうやら正常に動いているようです。ではなぜ cinder-api からは down と判定されているのでしょうか？

Cinderの実装を調査

そこで、cinder-api がどうやって cinder-volume サービスの up/down を判定しているのか、Cinder のソースコードを見に行くことにしました。

見てみると、どうやら以下のようなロジックで判定していることがわかりました：

# cinder/api/contrib/services.py#L87

        for svc in services:
            updated_at = svc.updated_at
            delta = now - (svc.updated_at or svc.created_at)
            delta_sec = delta.total_seconds()
            if svc.modified_at:
                delta_mod = now - svc.modified_at
                if abs(delta_sec) >= abs(delta_mod.total_seconds()):
                    updated_at = svc.modified_at
            alive = abs(delta_sec) <= CONF.service_down_time
            art = "up" if alive else "down"
            active = 'enabled'
            if svc.disabled:
                active = 'disabled'
            if updated_at:
                updated_at = timeutils.normalize_time(updated_at)
            ret_fields = {'binary': svc.binary, 'host': svc.host,
                          'zone': svc.availability_zone,
                          'status': active, 'state': art,
                          'updated_at': updated_at}

https://github.com/openstack/cinder/blob/stable/2024.2/cinder/api/contrib/services.py#L87

cinder-api は、現在時刻と cinder-volume service の updated_at の差分を見る
その差分が service_down_time（デフォルト60秒）を超えたら down と判定

では cinder-volume service の updated_at はちゃんと更新されているのでしょうか？確認してみると、どうやら定期的に更新されていそうです。

openstack volume service list

| Binary           | Host          | Zone | Status  | State | Updated At          |
| ---------------- | ------------- | ---- | ------- | ----- | ------------------- |
| cinder-volume    | block-storage | nova | enabled | down  | 2025-XX-XX XX:XX:XX | # <- ここが数秒おきくらいに更新されていた
| cinder-scheduler | controller    | nova | enabled | up    | 2025-XX-XX XX:XX:XX |

確かにupdated_atは定期的に更新されているようです。しかし、よーく見ると…

あれ？updated_atの時刻が現在時刻より数分遅れてる！？

例えば、現在時刻が 12:00:00 なのに、updated_at には 11:57:30 みたいな値が入っていました。この3分近い差があると、service_down_time のデフォルト60秒を余裕で超えてしまうため、サービスが down と判定されてしまっているようです。

時刻同期の確認

時刻がズレているということは、NTP の問題かな？と思い、chrony の状態を確認することにしました。

我が家の OpenStack 環境では、以下のような時刻同期構成になっています：

コントローラサーバー：外部 NTP サーバーと同期
その他のノード（compute、block storage等）：コントローラサーバーと同期

  graph TD
    B[コントローラサーバー<br/>NTP Server] -->|時刻同期| A[外部NTPサーバー<br/>ntp.nict.jp等]
    C[Compute Node 1] -->|時刻同期| B
    D[Compute Node 2] -->|時刻同期| B
    E[Block Storage<br/>cinder-volume] -->|時刻同期| B
    F[その他のノード] -->|時刻同期| B

まずは各ホストで chrony の状態を確認します

chronyc sources

すると驚くべきことに、コントローラサーバーが外部 NTP サーバーとの同期に 100%失敗 していました！

そのため、他のホストもコントローラサーバーを異常と判断し、それぞれローカルの hwclock を使って時刻を刻んでいる状態になっていたのです。これじゃあ時刻がバラバラになるのも当然です。

ネットワークの調査

なぜコントローラサーバーが外部 NTP サーバーと同期できないのか？試しに手元の PC から同じ LAN 内で sntp コマンドを実行してみました。

$ sntp -t 5 ntp.nict.jp
sntp: no reply from ntp.nict.jp within 5 seconds

やはり失敗します。ということは、どこか上流のネットワーク機器で遮断されている可能性が高そうです。

LAN のゲートウェイルーター、そしてその上流にある VPN ルーターの設定を順番に確認していくと…

VPN ルーターの設定で UDP 123 ポート（NTP）が in/out 両方で遮断されていました！

えっ、なんで！？こんな設定した覚えはないのに…デフォルトでこうなっているのでしょうか。謎です。

解決方法

原因がわかったので、解決は簡単でした。

VPN ルーターの管理画面にログインし、UDP 123 ポートの通信を許可するように設定を変更しました。

設定変更後、各ホストで chrony の同期状態を確認：

$ chronyc sources
MS Name/IP address         Stratum Poll Reach LastRx Last sample
===============================================================================
^* ntp.nict.jp                   1   6   377    35   +123us[ +456us] +/-  15ms

よし！ちゃんと同期できるようになりました。

そして、cinder-volume サービスの状態も確認：

openstack volume service list

| Binary           | Host          | Zone | Status  | State | Updated At          |
| ---------------- | ------------- | ---- | ------- | ----- | ------------------- |
| cinder-volume    | block-storage | nova | enabled | up    | 2025-XX-XX XX:XX:XX |
| cinder-scheduler | controller    | nova | enabled | up    | 2025-XX-XX XX:XX:XX |

無事に up になりました！これで Volume の作成も正常にできるようになりました。

まとめ

今回のトラブルシューティングではいろんなことを学べました。

根本原因の追求：顕在した症状（cinder-volume down）から、step by step で原因を追求していくことの面白さ
時刻同期の重要性：たかが時刻同期、されど時刻同期。数分のズレでもサービスが正常に動作しなくなることがある
ネットワーク設定の確認：予期しないところ（今回は VPN ルーター）で通信が遮断されていてびっくり

cinder-volume が動かない原因が VPN router の firewall 設定だとは、、、、かなり意外でした。分散システムにおいて時刻同期がいかに重要かを実体験として学べてよかったです。

あと、ちゃんと監視環境を整えて、こういう問題にすぐ気づけるようにしないとなぁ、と改めて思いました。

というわけで、OpenStack のトラブルシューティングで意外な原因にたどり着いた話でした。最後まで読んでいただき、ありがとうございました。