23rd - RYU + Arista のデバッグで思う

先日、RYU と Arista の組み合わせをテストしようとしていきなりハマった。結局どえらく低レベルなトラブルシュートをする事になった。最終的には RYU のバグが主たる原因だったのだが、このあたりで必要になった作業について書いてみようと思う。どうも SDN 関係ではそう言う「うまく行かなかった」事例の情報が共有されていないように感じるので。

現象:Ryu + SimpleSwitch (1.0) が Arista で正しく動作しない

Arista 7050T が手元にあるのだけれど、その OpenFlow ドライバは OpenFlow 1.0 対応のものだ。とりあえず RYU で正しく動作するかどうか確認しようとすると、まあほとんどの人が自然に SimpleSwitch を試すだろう。(SimpleSwitch は RYU のディストリビューションに含まれている OpenFlow 1.0 対応(専用) L2 Learning Bridge)
ところがこれが動作しない。挙動がおかしい。
詳しくは書かないが、とりあえず Learning Bridge として機能しないし、Arista 側のフローエントリの設定も正しく行われない。いろいろ確認したが失敗した痕跡は無さそうだった。 同じことを Open vSwitch 相手に行うと正しく動作するので、あとは Arista 側の OpenFlow ドライバの何かの設定ミスか、あるいはプロトコル上の問題(不整合、つまりバグ?)かと思われた。 ここで結局パケットモニタリングをして、RYU と Arista のやりとりを OpenFlow プロトコルとして何がどこまで行われているのか確認するところから始める。
モニタリング L2 Learning Switch では以下のような経過を経るはずだ。
  • スイッチに届く最初のパケットは Unknown なパケットとしてコントローラに送られるだろう(PACKET IN)
  • コントローラでは dest MAC をチェックし、それが学習済みのものであれば src MAC と合わせて FLOW MOD (New Flow)を定義するだろう
  • src MAC が未知のものであれば、それを学習する(内部テーブルにストアする)
  • 当該パケット(1.)を転送するためにコントローラからは PACKET OUT が出るだろう
    (このとき dest MAC が既知なら output は特定ポートを指定し、未知なら Flooding となる)
実験では Arista の #5, #6 ポートに各一台の Mac を接続し、#5 から ping (ICMP Echo Request) を出すところを観測した。#5, #6 に接続された Mac ともに双方の MAC アドレスは ARP によらず固定的に arp テーブルに登録してある。(そうでないと最初の ping ではまず ARP が出る)
観測されたパケットは以下の通りだった。

PACKET IN

#5 Mac から ping を出すと、Arista からは以下のように正しく PACKET IN がコントローラに出された。

内容的には正しく In Port が #5 であることと、ICMP パケットが OpenFlow パケットの中に正しく埋め込まれていることがわかる。

FLOW MOD (New Flow)

PACKET IN で上がってきた上のパケットに対して RYU コントローラはすぐに FLOW MOD を返した。

一点注意すべきことがあるが、それについては後述する。
ともかく FLOW MOD は出ている。本来ならばこれに対して Arista は正しくフローエントリを設定しなければならないはずだ。

PACKET OUT

しかし FLOW MOD でそれ以降のパケットを処理したところで、コントローラから PACKET IN で上がってきた最初のパケット ( ICMP Echo Request ) をどうにかしないと通信が進まない。
そこでコントローラは先の PACKET IN パケットを基に PACKET OUT を行う。ところがこれがどうやら正常でない。以下の Buffer Id (ハイライト部分)と Malformed Packet の警告(赤い部分)を見て欲しい。

当初僕はこの Malformed Packet 警告の意味が分からなかったが、調べてみるとその上の Buffer Id と絡んでいた。
Buffer Id については OpenFlow 1.0 Specification の 4.1.2 Asynchronous 節の PACKET IN に記述がある。
If the switch has sufficient memory to buffer packets that are sent to the controller, the packet-in events contain some fraction of the packet header (by default 128 bytes) and a buffer ID to be used by the controller when it is ready for the switch to forward the packet. Switches that do not support internal buffering (or have run out of internal buffering) must send the full packet to the controller as part of the event. つまりバッファ機構のあるスイッチは PACKET IN に際してパケットの先頭部分だけをコントローラに送って(デフォルト 128 バイト)、バッファ ID だけ付けて出せ、バッファ機構がないスイッチはパケット全部付けてコントローラに送れ、と。
そしてバッファしていない場合、Buffer ID は -1 になる。つまり Arista にはバッファ機構は無いので PACKET IN や PACKET OUT などは Buffer ID は 0xffffffff となる。ここまでは正常な動きだ。 しかし Buffer ID が 0xffffffff のときは、PACKET OUT は自身の中にその「output するべきパケットの中身」を含めなければならないのだが、ここで見ると分かるように RYU の出力した PACKET OUT ではそこが空だ。これが Malformed 警告となって出ている。
なお Open vSwitch は Buffering するので、この Buffer ID を設定して PACKET IN を出しており、RYU は正しくその Buffer ID を保持して PACKET OUT を出している。もちろん正しく機能する。

コードを当たる

原因を探るべく SimpleSwitch のコード、つまり simple_switch.py を当たる。
するとコード中、PACKET OUT を生成するコードにそれらしき穴があることが分かる。
        out = datapath.ofproto_parser.OFPPacketOut(
            datapath=datapath, buffer_id=msg.buffer_id, in_port=msg.in_port,
            actions=actions)
        datapath.send_msg(out)
        					
つまり、Buffer ID については PACKET IN から貰った ID をそのまま与えるだけで、パケットデータについては何も手当てをしていない。
本来なら ID が Non-Buffered を意味する 0xffffffff であれば PACKET IN に付けられていたはずのデータをセットしなければならないはずだ。
datapath.ofproto_parser.OFPPacketOut() の実体は ryu-master/ryu/ofproto/ofproto_v1_0_parser.py であり、コードは以下のようになっている。
class OFPPacketOut(MsgBase):
    def __init__(self, datapath, buffer_id=None, in_port=None, actions=None,
                 data=None): 
        super(OFPPacketOut, self).__init__(datapath)
        self.buffer_id = buffer_id
        self.in_port = in_port
        self._actions_len = None
        self.actions = actions
        self.data = data    
						
この引数、data=None を見れば、つまり SimpleSwitch.py は data を一切与えていないので、Non-Buffered な PACKET IN を貰った時はデータを空にしてしまうことがわかる。
そこで SimpleSwitch.py の当該コードを以下のように修正したところ、正常な PACKET OUT が出力され、Arista が RYU の SimpleSwitch で正しく動作するようになった。
        if msg.buffer_id != ofproto.OFP_NO_BUFFER:
            out = datapath.ofproto_parser.OFPPacketOut(
                datapath=datapath, buffer_id=msg.buffer_id, in_port=msg.in_port,
                actions=actions)
        else:
            out = datapath.ofproto_parser.OFPPacketOut(
                datapath=datapath, buffer_id=msg.buffer_id, in_port=msg.in_port,
                actions=actions, data=msg.data)
        datapath.send_msg(out)
						

RYU Developer Mailing List へのフィードバック

僕はこれらがクリアになったところで RYU Developer Mailing List にバグレポートとしてフィードバックを出した。
http://sourceforge.net/p/ryu/mailman/message/32992943/
すると迅速にこれが対応され、反映された。つまり最新のバージョンではこの問題はもう起きない。
https://github.com/osrg/ryu/commit/5021716be31fcdac44bdacb0fa785416227ac394#diff-6275d0c36deeaef4dd2d14a1c19d39d9
なお、simple_switch.py は OpenFlow 1.0 用で、OpenFlow 1.2, 1.3 にはそれぞれ simple_switch_12.py と、同 13.py がある。そして OpenFlow 1.3 用のコードでは当初からこれは正しく処理されていた。
つまり開発者側も気づいていたが 1.0 と 1.2 にはバックポートされなかった、ということではないかと想像するが、まあ 1.3, 1.2, 1.0 のコードはそれぞれ違うので何とも言えない。
なお 1.2 に対して行われた修正は以下の通りである。
https://github.com/osrg/ryu/commit/89c339634bb1a985719d0ab4f95009a3f8b098af#diff-2710f46c394b767ceb9dd024031aff2c

結論

Open Source って素晴らしい。以上。 で終わりたいところだが、そう簡単でもない。
僕はこれ以外にもやはり OpenFlow プロトコル処理レベルのことでうまく動作しない問題を追跡したことがある。つまり往々にしてパケットダンプを取って正常状態と異常状態を one by one で見比べる、といった地べたを這うようなデバッグをやる必要がある、ということだ。これ自体はネットワーク屋の常道で、特別なことではないと思う。
一方で、この SimpleSwitch のバグは随分多くの人が遭遇したのではないか?と想像する。何しろ最も簡単なサンプルアプリが SimpleSwitch で、今でこそ 1.3 対応のハードスイッチはある程度出ているが、ついこの間までは長い間 1.0 対応製品ばかりだった。つまり多くのエンジニアが RYU + SimpleSwitch で自社あるいは購入したハードウェアスイッチを試験し、正しく動かない状況に陥ったのではないか。(実際に他の知人からそうした現象に遭遇したが追わずに諦めたケースを聞いた)
僕がやったように、誰かしら追跡して、誰かしら報告すれば皆ハッピーになるわけで、Open Source Software というのはそうして育ってきた。やはりこれ自体もソフト屋としては常道だと思う。
SDN というのはちょっとこの点で厄介な部分がある。つまりネットワークを触れて、かつコードを読み書きできるエンジニアが必要な場面が(少なくとも今は)ある、ということだ。上に書いたネットワーク屋の作業と、ソフト屋の文化と、その両方だ。これが案外難しいのかも知れない、とSDNを見た最初に思ったが、今回の RYU + Arista のトラブルシュートを通してこの問題を再び妙な実感つきで感じることになった。
今後、こうした(地道な)作業をやって、公開していく(オープンな世界にフィードバックしていく)人が増えると良いなあ、と思う。

おまけ:FLOW MOD パケットの WireShark によるデコード

既に示した(実は正常な) FLOW MOD パケットだが、WireShark によるデコードが若干乱暴なためにハマったところがあるので出しておく。

上図では Flags: をハイライトしているが、その理由は WireShark がデコードするのはこれが再後端のフィールドだからだ。
しかし実際には(第三ペインのハイライト部分を見入ると分かるように)、それ以降に 00 00 00 08 00 06 ff e5 なるデータが存在する。
OpenFlow 1.0 Specification の 5.3.3 Modify State Messages に、OFPT_FLOW_MOD message の仕様がある。
/* Flow setup and teardown (controller -> datapath). */
struct ofp_flow_mod {
    struct ofp_header header;
    struct ofp_match match;      /* Fields to match */
    uint64_t cookie;             /* Opaque controller-issued identifier. */
    /* Flow actions. */
    uint16_t command;            /* One of OFPFC_*. */
    uint16_t idle_timeout;       /* Idle time before discarding (seconds). */
    uint16_t hard_timeout;       /* Max time before discarding (seconds). */
    uint16_t priority;           /* Priority level of flow entry. */
    uint32_t buffer_id;          /* Buffered packet to apply to (or -1).
                                    Not meaningful for OFPFC_DELETE*. */
    uint16_t out_port;           /* For OFPFC_DELETE* commands, require
                                    matching entries to include this as an
                                    output port.  A value of OFPP_NONE
                                    indicates no restriction. */
    uint16_t flags;              /* One of OFPFF_*. */
    struct ofp_action_header actions[0]; /* The action length is inferred
                                            from the length field in the
                                            header. */
};
OFP_ASSERT(sizeof(struct ofp_flow_mod) == 72);
						
このうち WireShark がデコードしているのは flags までだ。actions については全くデコードしない。デコードしなくても「ここにあるよ」と出してくれれば良いのに、まるで何もデータが存在しないかのようだ。
しかし実際には以下の 8 バイトがそこにある。
00 00 00 08 00 06 ff e5
ofp_action_header については 5.2.4 Flow Action Structures に説明がある。
An action_output has the following fields:
/* Action structure for OFPAT_OUTPUT, which sends packets out ’port’.
 * When the ’port’ is the OFPP_CONTROLLER, ’max_len’ indicates the max
 * number of bytes to send.  A ’max_len’ of zero means no bytes of the
 * packet should be sent.*/
struct ofp_action_output {
    uint16_t type;    /* OFPAT_OUTPUT. */
    uint16_t len;     /* Length is 8. */
    uint16_t port;    /* Output port. */
    uint16_t max_len; /* Max length to send to controller. */
};
OFP_ASSERT(sizeof(struct ofp_action_output) == 8);
						
つまり 00 00 00 08 - 00 03 ff e5 をこれに当てはめると、
type = 00 00
len = 00 08
port = 00 06
max_len = ff e5 (65509)
となり、正しく MOD_FLOW パケットが出ていることがわかるが、現場では恐らくこうした WireShark が幾らか不完全なデコードをする場面に遭遇することを頭に入れておかないと相当混乱するだろう。
なお利用した WireShark のバージョンは 1.12.1 (v1.12.1-0-g01b65bf from master-1.12) と、当時最新だったはずで、執筆現在(2014/12/23)でも最新の stable は 1.2.2 でそう古くは無い。

References