概要

先日Consulクラスタのアップグレードをしたところちょこちょこ問題にぶち当たって解決に時間がかかったので、同じ症状に遭ったりした人用にメモ。

環境

Consul 1.1.0 -> 1.2.2
Ubuntu 16.04

問題背景

Consulはクライアントエージェントが追加されたり死んだりしても自動でjoin・leaveを行ってくれるので、サーバエージェントも同様に１台ずつAMIを更新すれば自動でjoin・leaveしてくれる＆Key/Valueデータもレプリケーションを自動でやってくれるから問題ないはずと勝手に期待してやってみたのが問題でした。

問題の流れ

Consulを更新したAMIをpackerで作成
Terraformで１台ずつConsulを更新
古いConsulを削除したがCritical Stateのノードとしてメンバーにずっと残る　←そのうち消えると勝手に思い込む
リーダーを更新した時に、↑のノードも投票リクエスト対象として残ったままで、可動してるサーバが過半数に満たなくなる
リーダーが選出できなくなる

対応

リーダー選出ができないせいでConsulがまともに動かなくなってしまったので１つ１つ対応してみました

古いConsulを削除したがCritical Stateのノードとしてメンバーにずっと残る

Consulにはクラスタから外れるコマンドconsul leaveがありますが、すでにノードを削除してしまったので使えません。
なので別のノードから強制的に対象ノードを外すコマンドforce-leaveがあるのでそれを実行しました。

$ consul force-leave 対象ノードIP

これによってconsul membersで表示されるステータスがfailedからleftに変わりました。

※今回のようにリーダー消失ではなく、単純にfailedノードがずっと残った場合は各サーバのローリングでの再起動で解決しました

↑のノードも投票リクエスト対象として残ったまま

leftステータスになったものの、投票リクエストは成功しませんでした。エラーとしては

Aug 01 06:44:14 consul-1a.jun06t.dev consul[28272]: raft: Node at 10.1.219.221:8300 [Follower] entering Follower state (Leader: "")
Aug 01 06:44:18 consul-1a.jun06t.dev consul[28272]:     2018/08/01 06:44:18 [ERR] raft: Failed to make RequestVote RPC to {Voter 952d793d-da68-8688-0ea2-f269915a9130 10.1.220.92:8300}: dial tcp <nil>->10.1.220.92:8300: i/o timeout
Aug 01 06:44:18 consul-1a.jun06t.dev consul[28272]: raft: Failed to make RequestVote RPC to {Voter 952d793d-da68-8688-0ea2-f269915a9130 10.1.220.92:8300}: dial tcp <nil>->10.1.220.92:8300: i/o timeout
Aug 01 06:44:18 consul-1a.jun06t.dev consul[28272]:     2018/08/01 06:44:18 [ERR] raft: Failed to make RequestVote RPC to {Voter 3fbf3bc8-9d33-536b-3aa1-34c3bca0d4ac 10.1.221.201:8300}: dial tcp <nil>->10.1.221.201:8300: i/o timeout
Aug 01 06:44:18 consul-1a.jun06t.dev consul[28272]: raft: Failed to make RequestVote RPC to {Voter 3fbf3bc8-9d33-536b-3aa1-34c3bca0d4ac 10.1.221.201:8300}: dial tcp <nil>->10.1.221.201:8300: i/o timeout
Aug 01 06:44:44 consul-1a.jun06t.dev consul[28272]:     2018/08/01 06:44:44 [ERR] agent: failed to sync remote state: No cluster leader
Aug 01 06:44:44 consul-1a.jun06t.dev consul[28272]: agent: failed to sync remote state: No cluster leader
Aug 01 06:44:45 consul-1a.jun06t.dev consul[28272]:     2018/08/01 06:44:45 [ERR] agent: Coordinate update error: No cluster leader
Aug 01 06:44:45 consul-1a.jun06t.dev consul[28272]: agent: Coordinate update error: No cluster leader

がずっと出ており、このtimeout先のノード10.1.220.92と10.1.221.201はすでに削除済みで、前述のforce-leaveも実行したものでしたが残り続けていました。

この時consul infoでRaftのpeers(latest_configurationの部分)をチェックすると

raft:
    applied_index = 950506
    commit_index = 0
    fsm_pending = 0
    last_contact = 59.251460351s
    last_log_index = 957303
    last_log_term = 9
    last_snapshot_index = 950506
    last_snapshot_term = 2
    latest_configuration = [{Suffrage:Voter ID:952d793d-da68-8688-0ea2-f269915a9130 Address:10.1.220.92:8300} {Suffrage:Voter ID:dad6c035-6eda-c5da-3cdb-83bd552445f6 Address:10.1.219.221:8300} {Suffrage:Voter ID:3fbf3bc8-9d33-536b-3aa1-34c3bca0d4ac Address:10.1.221.201:8300} {Suffrage:Voter ID:52012323-a6e3-69fd-4df9-c0fa73475520 Address:10.1.221.147:8300}]
    latest_configuration_index = 955709
    num_peers = 3
    protocol_version = 3
    protocol_version_max = 3
    protocol_version_min = 0
    snapshot_version_max = 1
    snapshot_version_min = 0
    state = Candidate
    term = 500

このように古いノードがRaftのpeerに残ってしまい、投票リクエストを延々と投げ続けてしまってることが分かりました。

そこでraftで強制的にpeerを削除するコマンドを実行してみましたが

$ consul operator raft remove-peer -id=952d793d-da68-8688-0ea2-f269915a9130
Error removing peer: Unexpected response code: 500 (No cluster leader)

このように

リーダー選出のために存在しないpeerを削除したい
削除コマンドはリーダーがいないと使えない

という堂々巡りの状態に陥りました。

リーダーが選出できなくなった時のリカバリ

ですがHashicorpはそんな人のためにリカバリ方法を用意してくれていました。

learn.hashicorp.com

consulのデータディレクトリには

$ ls
checkpoint-signature  node-id  proxy  raft  serf
$ cd raft/
$ ls
peers.info  raft.db  snapshots

とraft/ディレクトリにpeers.infoというものがあり、これをいじる形でpeers.jsonとすると、それを優先してpeer情報としてリカバリしてくれます。
ただしRaftのプロトコルによって

バージョン２

[
  "10.1.0.1:8300",
  "10.1.0.2:8300",
  "10.1.0.3:8300"
]

バージョン３

[
  {
    "id": "adf4238a-882b-9ddc-4a9d-5b6758e4159e",
    "address": "10.1.0.1:8300",
    "non_voter": false
  },
  {
    "id": "8b6dda82-3103-11e7-93ae-92361f002671",
    "address": "10.1.0.2:8300",
    "non_voter": false
  },
  {
    "id": "97e17742-3103-11e7-93ae-92361f002671",
    "address": "10.1.0.3:8300",
    "non_voter": false
  }
]

とフォーマットが異なります。
そしてconsul membersで表示されるプロトコルバージョン2はConsulの内部通信のプロトコルであってRaftとは別なので注意してください。
前述のconsul infoのraftの項目で分かりますが、プロトコルバージョンは3です。

Please note that the Raft protocol is different from Consul's internal protocol as described on the Protocol Compatibility Promise page, and as is shown in commands like consul members and consul version. To see the version of the Raft protocol in use on each server, use the consul operator raft list-peers command.

ref: Upgrading Specific Versions - Consul by HashiCorp

peers.jsonを用意して再起動

各サーバノードにpeers.jsonを用意し、

$ sudo systemctl restart consul

と再起動したところ見事クラスタが新しいノードだけで投票を再開して復帰しました！！
復旧できるとpeers.jsonは自動的に削除されます。

ちなみに間違ったプロトコル（バージョン２）だと以下のようにコケます。

Aug 01 07:23:23 consul-1d.jun06t.dev consul[30897]: bootstrap_expect > 0: expecting 3 servers
Aug 01 07:23:23 consul-1d.jun06t.dev consul[30897]: ==> Starting Consul agent...
Aug 01 07:23:23 consul-1d.jun06t.dev consul[30897]: consul: found peers.json file, recovering Raft configuration...
Aug 01 07:23:23 consul-1d.jun06t.dev consul[30897]: consul: shutting down server
Aug 01 07:23:23 consul-1d.jun06t.dev consul[30897]: ==> Error starting agent: Failed to start Consul server: Failed to start Raft: recovery failed to parse peers.json: json: cannot unmarshal string into Go value of type raft.configEntry

今後のアップグレード手順

今回の反省を活かしてアップグレード手順をまとめると

新しいノードを追加
古いノードはあらかじめconsul leaveする
↑でRaftのpeerからも外れる
古いノードを削除

にすると問題なくできそうです。

その他Error・Warnログ

serf: attempting reconnect to xxx

leftノードなのに

2018/08/03 01:36:54 [INFO] serf: EventMemberFailed: 8229b2f766fc.dc1 172.20.0.8
2018/08/03 01:36:54 [INFO] consul: Handled member-failed event for server "8229b2f766fc.dc1" in area "wan"
2018/08/03 01:37:09 [INFO] serf: attempting reconnect to 8229b2f766fc.dc1 172.20.0.8:8302
2018/08/03 01:37:42 [INFO] serf: attempting reconnect to 2a41b3ba26ac.dc1 172.20.0.9:8302
2018/08/03 01:38:15 [INFO] serf: attempting reconnect to 8229b2f766fc.dc1 172.20.0.8:8302
2018/08/03 01:38:48 [INFO] serf: attempting reconnect to 8229b2f766fc.dc1 172.20.0.8:8302

といった感じでずっとserf: attempting ...が残るは既知のバグのようです。

github.com

Carpe Diem

備忘録

Consulクラスタをアップグレードした時に起きた問題と対応

概要

環境