SONiCのデバッグ手法

# はじめに

以前、[SONiCの機能が動かないときの調査方法](https://qiita.com/masru0714/items/f1505b5da626d34a2e7c)という記事を書きましたが、より実践的な内容になります。

# SONiC(master branch)はちゃんと動いてくれない
ホワイトボックススイッチ用のNOSというかソフトウェアコレクションとして公開されている[SONiC](https://azure.github.io/SONiC/)ですが、githubのmasterブランチからビルドしたものはあまり安定していません。開発ブランチなので、これ自体はしかたないと考えます。

といっても何を動かそうとしてもいつもなんかおかしいダメダメだと言ったような感じではなく、commitが加わるとたまに特定機能の動作がおかしくなることがある、と言ったことが多いです。あるいは、うっかり秘孔をついてしまい(設定パラメータの値を変に指定するなどして)、プロセスが異常終了することもあります。ひどいときはビルドが通らないこともありますが、本稿ではビルド自体はできることを前提とします。

## デバッグその前に: ベンダーのサポートは受けられる?

公開版SONiCは基本的にコミュニティによって無償でさまざまな問題に対応しています。スイッチベンダーによるサポートは軽くWeb検索したところ見つけることができたのは

- https://www.dell.com/ja-jp/work/shop/povw/sonic
- https://support.edge-core.com/hc/en-us/categories/360002134713-Edgecore-SONiC

このくらいでした。しっかり探せばもっとあるかもしれません。もちろんスイッチベンダーさんと個別にコンタクトできればそれなりにお話はできるかと思います。(金銭面その他条件あるかと思いますが)頼りにできるのであれば頼っていいと思います。

## さまざまな事象

いろいろあります。

- プロセスが落ちる
- コンテナが予期せず終了した
- スイッチがシャットダウン処理している
- 設定が反映されない
- 設定パラメータの一部が伝わっていない
- 想定していた動作をしてくれない
- 機能がサポートされていない
- 表示が崩れる

個人的にはいずれも経験しています。

# 対応1 `show`コマンドで状況確認する

`show`コマンドを使うと、SONiCの持つ各機能について設定や状態を確認することができます。

## `show interfaces status`

SONiCが管理するフロントポートの情報を表示します。IPアドレスの付与とは関係なく、リンクアップダウンといった情報を得ることができます。

```
admin@sonic:~$ show interfaces status 
  Interface            Lanes    Speed    MTU    FEC            Alias    Vlan    Oper    Admin             Type    Asym PFC
-----------  ---------------  -------  -----  -----  ---------------  ------  ------  -------  ---------------  ----------
  Ethernet0          1,2,3,4     100G   9100     rs   hundredGigE1/1  routed      up       up  QSFP28 or later         N/A
  Ethernet4          5,6,7,8     100G   9100     rs   hundredGigE1/2   trunk      up       up  QSFP28 or later         N/A
  Ethernet8       9,10,11,12     100G   9100     rs   hundredGigE1/3  routed      up       up  QSFP28 or later         N/A
(以下略)
```

`oper`の項目が`N/A`だった場合、なんらかの不具合が発生しています。また、不具合によってはまったくなにも表示されないことも起こりえます。`Type`欄には`QSFP28 or later`や`SFP/SFP+/SFP28`といったようなトランシーバー情報が表示されます。表示されるはずです。表示されなかったら`xcvrd`が動いていないかを確認してみてください。

## `show ip interfaces`

SONiCが管理するインタフェースにIPアドレスを付与すると、それがフロントポートか管理ポートかVLANかはたまたループバックかにかかわらず、`show ip interfaces`コマンドの一覧に表示されるはずです。

```
admin@sonic:~$ show ip interfaces 
Interface    Master    IPv4 address/mask    Admin/Oper    BGP Neighbor    Neighbor IP
-----------  --------  -------------------  ------------  --------------  -------------
Ethernet0              172.21.0.1/24        up/up         N/A             N/A
Ethernet12             10.0.0.3/31          up/up         N/A             N/A
Loopback0              10.1.0.1/32          up/up         N/A             N/A
Vlan2002               10.0.2.1/31          up/up         N/A             N/A
docker0                240.127.1.1/24       up/down       N/A             N/A
eth0                   xxx.xxx.xxx.xxx/24   up/up         N/A             N/A
lo                     127.0.0.1/16         up/up         N/A             N/A
admin@sonic:~$ 
```

IPアドレスを設定したはずのインタフェースが表示されない場合、致命的な問題が発生していると言えます。

## `show services`

SONiCで提供されている各機能はサービスという単位で`docker`コンテナにまとめられています。`show services`を使うと、SONiCが管理しているコンテナのうち動作しているものの一眼を表示させることができます。最低限、

- database docker
- swss docker

は動いていないといけません。BGPが必要であればbgp docker、NATが必要であればnat dockerが動いているかどうかを確認するといいでしょう。もちろん`docker ps`コマンドを使っても確認できます。

# 対応2 ログを見る

## ログを見る前に`swssloglevel`

SONiCのログは通常`NOTICE`レベルまでしか記録されていませんが、より詳細な情報を得るためにログレベルを`INFO`あるいは`DEBUG`に変更することができます。

```
admin@sonic:~$ swssloglevel -l INFO -c orchagent
```

どんなログが出るのが正常ルートか、どういうログが出たらどこがおかしいのかといった知見はソースコードとにらめっこして得るしかないのがつらいところです。

## `show logging`

動きがおかしいと思ったとき、まず最初に確認するのはログです。`show logging`で確認できるので眺めます。コマンドのパラメータを記述ミスしているときは、これで気づくこともあります。しかし、SONiCを構成するプロセスの動作がおかしいこともあり、ログを見るとその痕跡を発見できたりします。

いくつか例を挙げると

- NATの設定が一切ハードウェアに反映されていない
- `syncd`がSAIのエラーを受けてスイッチのシャットダウン処理が走った
- `orchagent`の中で例外が発生し、`SIGABRT`でプロセスが落ちた

といったことをログから把握できたりします。たとえば下記のような感じです(あくまで例です。このログは実際には発生しません)。

```
Oct  5 11:44:37.717490 sonic INFO swss#orchagent: :- addDnatToNhCache: Adding to NH cache indexed by translated ip 172.21.0.2, the DNAT entry with ip 10.0.2.1
Oct  5 11:44:37.719109 sonic INFO swss#supervisord: intfmgrd RTNETLINK answers: File exists
Oct  5 11:44:37.719109 sonic INFO swss#supervisord: orchagent terminate called after throwing an instance of 'std::logic_error'
Oct  5 11:44:37.719109 sonic INFO swss#supervisord: orchagent   what():  basic_string::_M_construct null not valid
```

## `swss.rec`, `sairedis.rec`

SONiCは設定情報を内部でやり取りするのにredis dbを使っています。このDBの情報を直接読むには`sonic-db-dump`を使うなどするのですが、それでは変更履歴をたどることができません。幸いSONiCはDBに加えられた変更をログファイルとして残しておくように作られていて、それが`swss.rec`と`sairedis.rec`です。

どちらのファイルも`/var/log/swss/`に置かれています。`swss.rec`には`APPL_DB`に書かれた内容、`sairedis.rec`には`ASIC_DB`に書かれた内容が時系列順に記録されています。

内容を突き合わせることで、本来設定されているべきデータがどこまで処理されているかを推測することができます。たとえば、

1. NATの設定をする
2. `swss.rec`にNATの設定が記録されている
3. `sairedis.rec`にNATの設定が記録されていない

といった場合、`orchagent`に何らかの問題があることが推測できます。同様にもし`swss.rec`にも何も記録されていない場合、`orchagent`より前段となる`cfgmgr`(NATの場合は`natmgrd`)に何らかの問題があると推測できます。

また、`swss.rec`や`sairedis.rec`には細かなパラメータ情報も記録されていますので、指定したはずのパラメータの値が反映されていないと言った状況も確認することができます。

# 対応3 プロセスが動いているか確認する

ログを見てプロセスが`SIGABRT`を受けて終了した、と言った状況がわかれば改めて確認する必要はないのですが、動いているべきプロセスが動いていないために最終的な動作もおかしいと言ったことは十分ありえます。

SONiCの設定を動作に反映させるため最低限必要なプロセスとして

- `orchagent`
- `syncd`

は欠かせません。これらのプロセスが動いていないとSONiCは正しく動きません。`ps`や`show services`などで確認しましょう。

`cfgmgr`の各種プロセスも重要です。実際、ある日気づくとNATの設定が動作に反映されず、しかも全くログに残らないことがあったのですが、これは`natmgrd`が動いていないことが直接の原因でした。これに関して解説すると

1. 元々`natmgrd`はswss dockerで動いていた
2. ある日の更新で新たにNAT用にnat dockerが用意され、`natmgrd`はそちらで動かすよう変更された
3. `config_db.json`にはどのコンテナを有効化するかの設定があるがnat dockerの設定はなかった
4. nat dockerが起動しないため、`natmgrd`も動いていなかった

ということでした。これは`sudo config feature nat enabled`で解決しました。

# 対応4 `gdb`によるデバッグ

起動時は問題がないのになにか設定するとプロセスが落ちる、と言ったときの調査方法を紹介します。変な動作をしているときも、あたりをつけてbreakpointを設定することで対応できることもあります。原始的な`printf`デバッグでももちろん大丈夫ですが、`gdb`を使うほうが楽ではないかと思います。

## デバッグビルド

`rules/config`に`INSTALL_DEBUG_TOOLS=y`を加えてビルドします。通常よりもビルド時間が増えますので気長に待ちましょう。

## ソースコードを展開する

デバッグビルドのSONiCにはソースコードを`tar.gz`で固めたものが含まれています。広げないと`gdb`が読めませんので、あらかじめ広げておきます。

```
admin@sonic:~$ sudo tar -C / -xvf /src/sonic_src.tar.gz
```

## `gdb`でプロセス監視を開始する

通常`gdb`は、`gdb デバッグ対象コマンド`という形式で対象コマンドのデバッグを開始するのですが、すでに動いているプロセスをデバッグ対象に指定することもできます。`-p プロセス番号`です。

```
admin@sonic:~$ docker exec -it swss bash
# cd /src/sonic-swss/orchagent
# ps ax|grep orch
   43 pts/0    Sl     0:00 /usr/bin/orchagent -d /var/log/swss -b 8192 -m xx:xx:xx:xx:xx:xx
  310 pts/1    S+     0:00 grep orch
# gdb -p 43
(gdb) c
```
breakpointを設定するときはcontinueする間に設定しておきます。

```
(gdb) b routeOrch->getNextHopEntry
(gdb) c
```

`/var/core`にプロセス異常終了時のcoreが出力されていることがありますので、それを使って追うことができる場合はわざわざプロセス監視するまでもないかもしれません。

なお、`gdb`は各コンテナ内に用意されていますがホストには置かれていませんのでご注意ください。

## 問題を発生させ`gdb`でデバッグ

別窓でSONiCにログイン、設定します。`orchagent`が`SIGSEGV`したり`SIGABRT`したり、あるいは事前に設定しておいたbreakpointに到達すると`gdb`のプロンプトが戻ってくるので、`bt`や`p`コマンドなどを使い、状況確認していくといいでしょう。

# 対応(番外) `bcmsh`, `bcmcmd` (Broadcomの場合)

`swss.rec`や`sairedis.rec`は問題ない、ログを見ても設定は反映されていそう、でも動いてないと言った場合、プラットフォームがBroadcomであればSAIよりハードウェアに近いレベルでの状態確認が可能です。それが`bcmsh`と`bcmcmd`です。

`bcmsh`はパラメータ無しで起動します。表示に従いEnterを押すとプロンプトが出て、内蔵コマンドを使っていろいろな状態確認ができ、機能によってはスイッチASICへの設定も可能です。ただし細かいコマンド解説はありませんので、手探りで使うには限度があります。

```
admin@sonic:~$ bcmsh
Press Enter to show prompt.
Press Ctrl+C to exit.
NOTICE: Only one bcmsh or bcmcmd can connect to the shell at same time.



drivshell>?
?
help: "??" or "help" for summary
Commands common to all modes:
?              ??             ASSert         Attach         BackGround     
break          BroadSync      CASE           CD             ClearScreen    
CONFig         CONSole        CoPy           CPUDB          CTEcho         
CTInstall      CTSetup        DATE           DBDump         DBParse        
DeBug          DELAY          DEVice         DIR            DISPatch       
Echo           EXIT           EXPR           FLASHINIT      FLASHSYNC      
FOR            Help           HISTory        IF             IPROCRead      
IPROCWrite     JOBS           KILL           LED            LOCal          
LOG            LOOP           LS             M0             MCSCmd         
MCSDump        MCSLoad        MCSMsg         MCSStatus      MCSTimeStamp   
MKDIR          MODE           MORe           MoVe           NOEcho         
Pause          PCIEPHY        PortMod        PRINTENV       PROBE          
PSCAN          PWD            QUIT           RCCache        RCLoad         
REBOOT         REName         RESET          RM             RMDIR          
RPC            SAVE           SET            SETENV         SHell          
SLeep          TIME           Version        
Commands for current mode:
AGE            ALPM           ASF            Attach         Auth           
BIST           BPDU           BTiMeout       BUFfer         CABLEdiag      
CACHE          CanCun         CHecK          CLEAR          COLOR          
COMBO          COS            CounTeR        CustomSTAT     DDRMemRead     
DDRMemWrite    DDRPhyRead     DDRPhyTune     DDRPhyWrite    DELete         
DETach         DMA            DmaRomTest     DMIRror        DPLL           
DSCP           DTAG           Dump           EditReg        EGRess         
EthernetAV     EXTernalTuning EXTernalTuning2EXTernalTuningSumFieldProcessor 
FLEXport       FlowDb         FlowTracker    FlowTrackerMON FlowTrackerRemoteMON
Getreg         GPORT          H2HIGIG        H2HIGIG2       HASH           
HashDestinationHeaderMode     HSP            IbodSync       INIT           
Insert         INTR           IPFIX          IPG            IPMC           
KNETctrl       L2             L2LEARN        L2MODE         L3             
LATency        LINKscan       LISTmem        Listreg        LLS            
OOKup         MCAST          MemFirst       MemNext        MemSCAN        
MemWatch       MIM            MIRror         MODify         ModMap         
Modreg         MPLS           MSPI           MTiMeout       MultiCast      
OAM            PacketWatcher  PBMP           PHY            PKTIO          
POP            PORT           PortRate       PortSampRate   PortStat       
PROBE          PUSH           PUTREG         PVlan          RATE           
RateBw         RegCMp         RegWatch       REMove         ResTest        
RXCfg          RXInit         RXMon          SCHan          SEArch         
SER            Setreg         SHOW           SOC            SRAM           
SramSCAN       STACKMode      StackPortGet   StackPortSet   STG            
STiMeout       STKMode        StkTask        SW_AN          SwitchControl  
SystemSnake    TCAM           TeCHSupport    TestClear      TestList       
TestMode       TestParameters TestRun        TestSelect     TMCheck        
TMDumpMem      TMShow         TRUNK          TX             TXBeacon       
TXCount        TXSTArt        TXSTOp         VLAN           WARMBOOT       
WLAN           Write          XAUI           
Dynamic commands for all modes:
BCMSAI         
drivshell>
```

`bcmcmd`は、`bcmsh`が提供するコマンドを1行で実行するものです。

```
admin@sonic:~$ bcmcmd 'l3 nat_egress show'
l3 nat_egress show
IDX   TYPE  ID    IP               MASK             L4Port RefCount
1     SNAT  2     10.0.2.1         255.255.255.255  0      1
drivshell>
admin@sonic:~$ 
```

この例では、スイッチASICにSNATの設定(送出側)が入っていることが確認できます。

# 対応5 ソースコードの変更とビルド

## ソースコードの展開

SONiCのソースコードは本体のリポジトリと`git submodule`のリポジトリに分割して管理されています。前出の`orchagent`や`syncd`はsubmodule内にソースコードが格納されていますので、変更が必要であれば本体を`clone`したあとは`make init`でsubmoduleを広げておきましょう。

```
buildhost$ git clone https://github.com/Azure/sonic-buildimage
buildhost$ cd sonic-buildimage
buildhost$ make init
```

## ソースコードの編集

## ビルド

デバッグ時は何度もビルドすることがありますが、一度ビルドが完了したあとは`make clean`しておかないと再ビルドしてくれませんのでご注意ください。(`make`とは……)

```
buildhost$ make configure PLATFORM=broadcom
buildhost$ make clean
buildhost$ make all
```

Broadcomがターゲットの場合は`PLATFORM=broadcom`、Mellanoxであれば`PLATFORM=mellanox`とします。

# 対応6 イメージ更新と動作確認

## 新しいイメージをインストールして再起動

`sonic-installer`コマンドを使えば`/etc/sonic/config_db.json`の内容は新しいイメージに引き継がれますので、これを使って更新することにします。`ONIE`で更新する場合は`config_db.json`の内容を予め保存しておかないと最初から設定しなおしになりますのでご注意ください。

```
% scp sonic-xxxxx.bin admin@xxx.xxx.xxx.xxx:
% ssh admin@xxx.xxx.xxx.xxx
admin@xxx.xxx.xxx.xxx's password:
Linux sonic 4.19.0-9-2-amd64 #1 SMP Debian 4.19.118-2+deb10u1 (2020-06-07) x86_64
You are on
  ____   ___  _   _ _  ____
 / ___| / _ \| \ | (_)/ ___|
 \___ \| | | |  \| | | |
  ___) | |_| | |\  | | |___
 |____/ \___/|_| \_|_|\____|

-- Software for Open Networking in the Cloud --

Unauthorized access and/or use are prohibited.
All access and/or use are subject to monitoring.

Help:    http://azure.github.io/SONiC/

Last login: Thu Oct  8 08:06:01 2020 from yyy.yyy.yyy.yyy
admin@sonic:~$ sonic-installer install -y sonic-xxxxx.bin
(snip)
admin@sonic:~$ sudo shutdown -r now
```

## 注意点

### `resolv.conf`とsshのホスト鍵

事前に準備しておかないと失われます。

気にしないのであれば特に言うことはありません。たとえばマネジメントポートでDHCPクライアントを動かしてIPアドレスを取得しているのであれば、`/etc/resolv.conf`を保持する必要はないでしょう。sshのホスト鍵が変わってもそれに追従すればいいだけであれば、`ssh-keygen -R`で消してしまえばいいだけです。

`/etc/config-setup/`にバックアップとリストアのためのスクリプトを置くことで、更新前の設定を引き継ぐことができます。無保証ですが、下記のようなものを用意します。
https://github.com/iMasaruOki/sonic-config-setup-hooks

いちいち用意するのが面倒であれば、`/host/`に単純にコピーしておいて、新しいイメージで起動後にログインし、`/host/`からコピーで書き戻せばそれでも大丈夫です。

### バージョン名の重複

SONiCのイメージにはビルド時に付与されるバージョン文字列があります。ビルドログを残しておくとわかりますが

```
"SONIC_IMAGE_VERSION"             : "master.0-dc6b388"
```

といったものです。同じバージョンがすでにインストール済みだとSONiCはすでにあるものとみなしてビルドしなおしたイメージをインストールすることができません。

デバッグ時は何度もイメージをビルドしてはインストールを繰り返すことになりますが、手順次第ではバージョン番号が変わりませんのでご注意ください。

すでに(見かけ上)同じバージョンのSONiCがインストールされている場合の対応方法ですが、下記になります。

1. `sonic-installer set-next-boot`を使い、次に起動するバージョンを別のものにする
2. rebootし、別バージョンが起動したら`sonic-installer remove`でもう片方を消す
3. (見かけ上)同じバージョンのSONiCを`sonic-installer install`でインストールする
4. rebootする

# 最後に

やや備忘録気味ですが、SONiCのデバッグ手法についておおまかに解説しました。

しかし、実際のところ`orchagent`や`syncd`の挙動、`APPL_DB`や`ASIC_DB`の構造、SAIライブラリの挙動などがわからないとどうにも手がつけられないと思います。うっかりデバッグする羽目になったら大変と思います。ベンダー提供のSAIライブラリ内の挙動に左右されどうにもできないこともあると思います。がんばれないこともあると思いますが、がんばりましょう。応援します。