Heat VM HAのバグ修正

はじめに

Advent Calendarに勢いで飛びついてしまって「何か役立ちそうなことを書こう」と案を練っているうちに12/11を迎えてしまいました。 結局そんな特別なものは用意できませんでした。すいません。。。 「Heat関係」と予告しておいたので、Heatで今年個人的に一番面白かった作業を書こうと思います。

Heatの機能でVM HAという機能があります。 ざっくり説明すると、サービスやVMが異常状態の場合にVMを削除して起動し直してくれる機能です。

この機能、Icehouseのリリース当初は、とあるバグが影響して動かなかったのではと思います。 （もしくはリリース当初は動いていたけれど、以降のバージョンアップでデグレしてしまったとか。 周辺コードをgit blame/git logしても、そういう形跡は見あたらなかったのですが。。） 以下VM HAの詳細と、上記のバグを修正してパッチをコミットした話です。

HeatのVM HA機能について

まずはVM HAについてもう少し詳細を説明します。 公式WikiのHeat/Using-HAを見ると’Create the HA example stack’に2つ例が紹介されています。

• HA（サービス監視）
  • VM内でサービス監視を行い異常の場合、通知を送る（異常通知）
    • /etc/cfn/hooks.confでサービス再起動時にnotify-on-httpd-restartedを実行
    • notify-on-httpd-restartedで、cfn-push-stats --service-failureを実行
  • 監視結果について、異常通知が一定期間に一定回数以上行われることがあるかチェック
    • AWS::CloudWatch::Alarm
  • 上記の場合VMを削除して新規に作成しなおす
    • OS::Heat::HARestarter
• IHA（VM監視）
  • VM内から生存通知を送る（正常通知）
    • cfn-hup-crontabで、cfn-push-stats --heartbeatを毎分実行
  • 監視結果について、正常通知が一定期間に一定回数未満とならないかチェック
    • AWS::CloudWatch::Alarm
  • 上記の場合VMを削除して新規に作成しなおす
    • OS::Heat::HARestarter

上記の部分でVMから正常／異常通知を行う部分が今回のバグを修正した箇所です。

VM HA機能を動かしてみる

さて、上記Wikiのテンプレートを動かしてみます。 （イメージによってインスタンス内のスクリプトとかサービス起動方法とか微修正が必要です。） HAとIHAどちらでも同様の症状が発生すると思いますが、自分はIHAの方で確認していました。 heat stack-createでテンプレートを起動すると仮想リソースが続々作成され、動いた！と思うのですが、数分後に管理画面を見ると、どうもVMのUUIDが変わっています。 VMが定期的に削除されていることに気がつきます orz...

問題解析 - VM

削除される前のVMに乗り込みます。

/var/log/messagesなどに特にVMの起動関係の異常は見当たりません。 使用しているイメージの異常で起動が失敗しているわけではなさそうです。 VM内からHeatに通知を送るheat-cfntools周りのログを調べると、/var/log/cfn-push-statsに403エラーが出力されていることに気づきます。

DEBUG [2014-12-10 23:09:02,410] cfn-push-stats called Namespace(cpu_util=False, credential_file='/etc/cfn/cfn-credentials', disk_path='/', disk_space_avail=False, disk_space_used=False, disk_space_util=False, disk_units='megabytes', haproxy=False, haproxy_latency=False, heartbeat=True, mem_avail=False, mem_used=False, mem_util=False, memory_units='megabytes', metric=None, service_failure=False, swap_used=False, swap_util=False, units=None, value=None, verbose=False, watch='test-HeartbeatFailureAlarm') 
DEBUG [2014-12-10 23:09:02,413] Using access key provided by client.
DEBUG [2014-12-10 23:09:02,413] Using secret key provided by client.
INFO [2014-12-10 23:09:02,414] Sending metric Heartbeat, Units Counter, Value 1
DEBUG [2014-12-10 23:09:02,415] Method: POST
DEBUG [2014-12-10 23:09:02,415] Path: /v1/
DEBUG [2014-12-10 23:09:02,415] Data: 
DEBUG [2014-12-10 23:09:02,415] Headers: {}
DEBUG [2014-12-10 23:09:02,416] Host: 192.168.190.4
DEBUG [2014-12-10 23:09:02,417] Port: 8003
DEBUG [2014-12-10 23:09:02,417] Params: {'MetricData.member.1.Dimensions.member.2.Value': 'test-HeartbeatFailureAlarm', 'MetricData.member.1.Dimensions.member.2.Name': 'AlarmName', 'Namespace': 'system/linux', 'MetricData.member.1.Unit': 'Counter', 'MetricData.member.1.Value': 1, 'Action': 'PutMetricData', 'MetricData.member.1.Dimensions.member.1.Name': 'InstanceId', 'Version': '2010-08-01', 'MetricData.member.1.Dimensions.member.1.Value': u'614680ad-1052-4c4c-9d28-970f59fa2205', 'MetricData.member.1.MetricName': 'Heartbeat'}
DEBUG [2014-12-10 23:09:02,417] establishing HTTP connection: kwargs={'port': 8003, 'timeout': 70}
DEBUG [2014-12-10 23:09:02,417] Token: None
DEBUG [2014-12-10 23:09:02,418] CanonicalRequest:
POST
/v1/

host:192.168.190.4:8003
x-amz-date:20141210T140902Z

host;x-amz-date
09f60093d26fc1ad29338da6af21ad82e7118b2d53919aaf674203df74c0fc8f
DEBUG [2014-12-10 23:09:02,419] StringToSign:
AWS4-HMAC-SHA256
20141210T140902Z
20141210/168/192/aws4_request
52a207ed2f1a65fbab6b80a2e7c32793299c2e2b9e64e4e03587523e9ba0d4d9
DEBUG [2014-12-10 23:09:02,419] Signature:
f34c5f50ab202a149964ed8649f39b3df33c4eeb2174b590844b2cdd3defac33
DEBUG [2014-12-10 23:09:02,457] <ErrorResponse><Error><Message>User is not authorized to perform action</Message><Code>AccessDenied</Code><Type>Sender</Type></Error></ErrorResponse>
ERROR [2014-12-10 23:09:02,457] 403 AccessDenied
ERROR [2014-12-10 23:09:02,458] <ErrorResponse><Error><Message>User is not authorized to perform action</Message><Code>AccessDenied</Code><Type>Sender</Type></Error></ErrorResponse>

？？？。403なので対向のサーバにはリクエストが届いていそうです。 同じテンプレート内に記述があり、同じくVMから通信するcfn-signalは問題なく動いています。 とりあえずcfn-*の送信内容をtcpdumpで回収して、対向側を調べます。

問題解析 - 対向サーバ（Heat）

先ほどのcfn-push-statsの対向側は8003番ポートを使っているheat-api-cloudwatchのサービスです。 デバッグを行います。自分はサービス起動を停止し、普通のプロセスとして’環境変数 python -m pdb .py’経由で起動することで特定の位置にブレークポイントを設定して問題を追っていきます。（Horizonとかだとimport pdb; pdb.set_trace()です。もっと効率的なやり方もあるかも。） 上記の起動時の環境変数や.pyの部分は、bash -x service openstack-heat-api-cloudwatch startというふうに、スクリプト起動時の変数など含めて調べます。（2段階実施して調べます。） 毎回Heatでスタックを作成すると大変なので、今回は先ほど回収したtcpdumpの内容をもとに、curlでHTTPのダミーリクエストを飛ばせるようにしました。

heat-api-cloudwatchを見ていくと、keystone-clientのライブラリを使ってEC2リクエストについて改変されていないか確認しています。 その際、シグネチャー確認をしている箇所で不一致になっていて403を返していることがわかります。 POSTの際のクエリパラメータを、URLのパスにも含めシグネチャー計算するか否か、シグネチャー計算するクライアント側とサーバ側でロジックが一致していないようです。

問題解析 - シグネチャー計算ロジックの比較

heat-cfntools側のシグネチャー計算は、botoのライブラリの中で行っているようです。

boto/boto/auth.py

class HmacAuthV4Handler(AuthHandler, HmacKeys):

    def canonical_query_string(self, http_request):
        # POST requests pass parameters in through the
        # http_request.body field.
        if http_request.method == 'POST':
            return ""
        l = []
        for param in sorted(http_request.params):
            value = boto.utils.get_utf8_value(http_request.params[param])
            l.append('%s=%s' % (urllib.parse.quote(param, safe='-_.~'),
                                urllib.parse.quote(value, safe='-_.~')))
        return '&'.join(l)

HeatはAWS CloudFormationをもとに作られていて一部互換性もあるので、AWS製のheat-cfntools（aws-cfn-bootstrap）にも同様のロジックがあるはずです。 aws-cfn-bootstrapはBootstrapping Applications using AWS CloudFormationからダウンロードできます。ライセンスもApacheなので参考にしても問題なさそうです。確認してみます。

cfnbootstrap/aws_client.py

class V4Signer(Signer):

    def sign(self, verb, base_url, params, creds, in_headers=None, timestamp=None):

        (canonical_headers, signed_headers) = self._canonicalize_headers(new_headers)
        canonical_request += canonical_headers + '\n' + signed_headers + '\n'
        canonical_request += hashlib.sha256(Client.construct_query(params).encode('utf-8') if verb == 'POST' else '').hexdigest()

やっぱりこっちもPOSTの場合はクエリパラメータをシグネチャー計算に含めていないです。

一方、サーバー側は下のファイルです。

keystoneclient/contrib/ec2/utils.py

class Ec2Signer(object):

    def _calc_signature_4(self, params, verb, server_string, path,
                          headers,
                          body_hash):
        """Generate AWS signature version 4 string."""

        # Create canonical request:
        # http://docs.aws.amazon.com/general/latest/gr/
        # sigv4-create-canonical-request.html
        # Get parameters and headers in expected string format
        cr = "\n".join((verb.upper(), path,
                        self._canonical_qs(params),
                        canonical_header_str(),
                        auth_param('SignedHeaders'),
                        body_hash))

    @staticmethod
    def _canonical_qs(params):
        """Construct a sorted, correctly encoded query string as required for                                                                         
        _calc_signature_2 and _calc_signature_4.                                                                                                      
        """
        keys = list(params)
        keys.sort()
        pairs = []
        for key in keys:
            val = Ec2Signer._get_utf8_value(params[key])
            val = urllib.parse.quote(val, safe='-_~')
            pairs.append(urllib.parse.quote(key, safe='') + '=' + val)
        qs = '&'.join(pairs)
        return qs

こちらはPOSTの場合に特にクエリパラメータをシグネチャー計算から除外していません。（クエリパラメータをシグネチャー計算に含めています。）

AWSの仕様調査

AWSの仕様を確認してみます。 Signing AWS Requests By Using Signature Version 4に仕様が書かれていますが、どうもPOSTの処理について不明瞭な箇所があります。（すいません。記事執筆段階で時間がなく上記ページのどこが具体的に問題だったか再確認できませんでした。）

まとめると

• シグネチャー計算のロジックについて実装が一致していない
• aws-cfn-bootstrap、および（heat-cfntoolsが使う）botoの場合
  • POSTの場合、クエリパラメータをシグネチャー計算に含めない
• keystone-clientの場合
  • POSTの場合、クエリパラメータをシグネチャー計算に含める
• AWSの仕様ドキュメントに不明瞭な箇所がある
  • POSTの処理について記述が矛盾
• cfn-push-statsはPOST処理を使用。そのため問題がおきてる。

keystone-client内のEC2互換コードがAWSの実装からずれているようなので、これを修正するのが良さそうです。

パッチ作成＆パッチ投稿

修正箇所も少なく参考にできる実装もあるので、パッチ作成は簡単です。 keystone-clientの該当部分のコードの前後と合わせ、下のようなコードになりました。

diff --git a/keystoneclient/contrib/ec2/utils.py b/keystoneclient/contrib/ec2/utils.py
index 3b722f2..899b95a 100644
--- a/keystoneclient/contrib/ec2/utils.py
+++ b/keystoneclient/contrib/ec2/utils.py
@@ -232,12 +232,19 @@ class Ec2Signer(object):
                 header_list.append('%s:%s' % (h, headers_lower[h]))
             return '\n'.join(header_list) + '\n'

+        def canonical_query_str(verb, params):
+            # POST requests pass parameters in through the request body
+            canonical_qs = ''
+            if verb.upper() != 'POST':
+                canonical_qs = self._canonical_qs(params)
+            return canonical_qs
+
         # Create canonical request:
         # http://docs.aws.amazon.com/general/latest/gr/
         # sigv4-create-canonical-request.html
         # Get parameters and headers in expected string format
         cr = "\n".join((verb.upper(), path,
-                        self._canonical_qs(params),
+                        canonical_query_str(verb, params),
                         canonical_header_str(),
                         auth_param('SignedHeaders'),
                         body_hash))

動作確認したところ、確かに動きます。やった、とりあえず解決！

openstack-devのメーリングリストに報告します。（普通は問題解析する前に調査・報告するほうが良いと思います。誰かもうやっている可能性があるので。） HeatとKeystoneまたがっていて両方に報告する必要がありそうです。そのときのメールは下のような感じでした。

[openstack-dev] [Heat] [Keystone] Heat cfn-push-stats failed with '403 SignatureDoesNotMatch', it may be Keystone problem.

その後launchpadに起票して、Gerritにパッチ投稿します。

• Bug #1360892 “EC2 v4 signature calculation is wrong, in case of ...”
• Change Iad4e3921: fix EC2 Signature Version 4 calculation, in the case of POST

ちなみに自分はCentOS + RDOというあまり開発向けでない環境で動かしているため、masterとの差分が存在する可能性があります。 今回パッチ部分についてgit logなどで更新がないか確認してからGerritに投稿しました。

また上記のパッチだけだとパッチ適用有無に限らずユニットテストを通ってしまいます。 なので、パッチ適用していない場合にユニットテストを通らなくなるテストコードも追加し、今後デグレが発生しないようにしておきました。

投稿してCIを通過したのを確認してからIRQでレビュー依頼をしてみます。 が、feature freezeも近づいておりレビュアーの方が忙しいのか、なかなかレビューが進みません。 2週間くらい反応がなく、再度IRQでレビュー依頼をしたところ、Morgan Fainbergさんが対応してくれました。 が、どうも今回の部分はあまり詳しくなくて自分では判断できないとのこと。 そこを見ている人に連絡してくれるということだったので、しょうがなくまた置いておくことになりました。 VM HAってわりと興味がある人がいると思うので、動かないままJunoがリリースされてしまうのは嫌だなー、と思い見ていると、feature freeze直前で+2レビューされて、なんとか無事マージされたようです。

環境

もし上の現象を実際に試してみたいという方がいれば（いないでしょうけど）、Icehouseリリースで試してみてください。 自分の環境はCentOS 6 + RDOで、パッケージのバージョンは下記で試しています。

• クライアント側

  • cloud-init-0.7.4-2.el6.noarch
  • heat-cfntools-1.2.6-2.el6.noarch
  • python-boto-2.27.0-1.el6.noarch

• サーバ側

  • python-keystoneclient-0.9.0-1.el6.noarch
  • python-keystone-2014.1.1-1.el6.noarch
  • openstack-keystone-2014.1.1-1.el6.noarch

おわりに

冒頭Heatの話と言っておきながら、終着点はkeystone-clientでした。 Junoの開発後半でマージされているので、Junoでは問題なくVM HAは動作しているはずです。

今年の自分の印象に残った作業はこんな感じです。 来年は、もっと多くのパッチを書いたり新機能の確認など行えたら良いなと思っています。 特にTokyo Summitもありますしね。どんどん盛り上がっていきたいです。

免責

上記記事の内容は過去の作業を思い出しながら書いているので、部分的に間違った内容を含んでいる可能性があります。ご了承ください。