SONiCの機能が動かないときの調査方法

あれ? 動いてない?

SONiC内の各種サービス(bgpやlldpやsnmpやその他もろもろ)の大半はdockerコンテナ内で動作するようになっている。show servicesコマンドを実行することで、SONiC内で実際に動いているコンテナとそれらの中のプロセスを観ることができる。

最近、SONiCのtelemetry serviceがデフォルト有効にするというcommitが入った。ので、これは動くだろうと思ったが、show servicesを見てもどこにもtelemetry dockerの文字は見当たらない。どうやら動いていないようだ。

admin@sonic-delta:~$ show services|grep telemetry
admin@sonic-delta:~$

最初は設定ミスを疑ったが、とくに設定がなくてもかまわないようだったので追跡調査をしてみた。以下、具体例を交えながら調査の流れを紹介する。

調査1 systemctl

SONiCで動いている各種サービスはsystemdによって制御されている。よってsystemctlコマンドを使うことで、サービスの状態を確認することができる。

admin@sonic-delta:~$ systemctl status telemetry.service
● telemetry.service - Telemetry container
   Loaded: loaded (/etc/systemd/system/telemetry.service; disabled; vendor prese
   Active: failed (Result: start-limit-hit) since Fri 2019-12-06 13:40:52 UTC; 1
  Process: 7370 ExecStop=/usr/bin/telemetry.sh stop (code=exited, status=0/SUCCE
  Process: 7323 ExecStart=/usr/bin/telemetry.sh wait (code=exited, status=0/SUCC
  Process: 7189 ExecStartPre=/usr/bin/telemetry.sh start (code=exited, status=0/
 Main PID: 7323 (code=exited, status=0/SUCCESS)
      CPU: 0
admin@sonic-delta:~$

failしているのが確認できた。

調査2 ログを見る

show loggingでSONiCの動作ログを取得できる。ページャーは挟まらないので、自分でmoreなりlessなり使う必要がある。キーワードtelemetryで検索すれば、そもそもコンテナが起動していないのか、起動後に終了しているのか確認できる。grepしてみてもいいだろう。

admin@sonic-delta:~$ show logging|grep telemetry|tail
Dec  6 13:39:17.221215 sonic-delta INFO telemetry.sh[3988]: Starting existing telemetry container with HWSKU Delta-ag9032v2a
Dec  6 13:39:18.707054 sonic-delta INFO telemetry.sh[5036]: 2
Dec  6 13:39:49.456417 sonic-delta INFO telemetry.sh[6729]: Starting existing telemetry container with HWSKU Delta-ag9032v2a
Dec  6 13:39:50.278980 sonic-delta INFO telemetry.sh[6862]: 2
Dec  6 13:40:21.298643 sonic-delta INFO telemetry.sh[7189]: Starting existing telemetry container with HWSKU Delta-ag9032v2a
Dec  6 13:40:22.106651 sonic-delta INFO telemetry.sh[7323]: 2
admin@sonic-delta:~$

grepせずに中を覗いてみると、起動してすぐに終了、これを何度か繰り返していることがわかった。なぜすぐ終了する?

調査3 コンテナの中で動かしてみる

終了の原因を調べるため、実際にコンテナの中で動かしてみることにする。

3.1 エントリポイントから最初に起動するプログラムを特定

実機上ではなくdockerコンテナをビルドする際の情報を確認する。

dockers/docker-sonic-telemetry/Dockerfile

(大幅に省略)
COPY ["start.sh", "telemetry.sh", "dialout.sh", "/usr/bin/"]
COPY ["supervisord.conf", "/etc/supervisor/conf.d/"]
COPY ["files/supervisor-proc-exit-listener", "/usr/bin"]
COPY ["critical_processes", "/etc/supervisor"]

ENTRYPOINT ["/usr/bin/supervisord"]

supervisordを起動していることがわかる。

3.2 コンテナの起動

dockerコンテナが動作している状態であればdocker execを使うが、動いたいない状態であればdocker runを使って起動しつつ調べることになる。単に起動しただけだと調査できないので、bashを起動させるよう指定する必要がある。

admin@sonic-delta:~$ docker run -it --entrypoint=/bin/bash docker-sonic-telemetry
root@dcb09a6a8409:/# 

3.3 supervisordからなにを起動しているかを確認

起動したコンテナの中で/etc/supervisor/supervisord.confを見てみると/etc/supervisor/conf.d/*.confをincludeしていることがわかるので、そちらを参照する。一部抜粋したものが下記となる。

[program:start.sh]
command=/usr/bin/start.sh
priority=1
autostart=true
autorestart=false

プログラムは複数定義されているがautostart=trueなのはstart.shだけ。つまりこのシェルスクリプトが最初に起動する。

3.4 start.shの中身を見る

start.sh

#!/usr/bin/env bash

mkdir -p /var/sonic
echo "# Config files managed by sonic-config-engine" > /var/sonic/config_status

rm -f /var/run/rsyslogd.pid

supervisorctl start rsyslogd

supervisorctl start telemetry
supervisorctl start dialout

telemetryとdialoutを起動している。これらはそれぞれ/usr/bin/telemetry.shと/usr/bin/dialout.shである。

3.5 telemetry.shを手で動かしてみる

root@dcb09a6a8409:/# /usr/bin/telemetry.sh
Traceback (most recent call last):
  File "/usr/local/bin/sonic-cfggen", line 318, in <module>
    main()
  File "/usr/local/bin/sonic-cfggen", line 266, in main
    configdb.connect()
  File "/usr/local/lib/python2.7/dist-packages/swsssdk/configdb.py", line 64, in connect
    self.db_connect('CONFIG_DB', wait_for_init, retry_on)
(大量すぎたので120行ほど中略)
  File "/usr/local/lib/python2.7/dist-packages/redis/connection.py", line 489, in connect
    raise ConnectionError(self._error_message(e))
redis.exceptions.ConnectionError: Error 111 connecting to 127.0.0.1:6379. Connection refused.
panic: open /var/run/redis/sonic-db/database_config.json: no such file or directory

goroutine 1 [running]:
github.com/Azure/sonic-telemetry/sonic_db_config.DbInit()
        /tmp/go/src/github.com/Azure/sonic-telemetry/sonic_db_config/db_config.go:123 +0xe8
github.com/Azure/sonic-telemetry/sonic_db_config.GetDbList(0xc0000eb750)
        /tmp/go/src/github.com/Azure/sonic-telemetry/sonic_db_config/db_config.go:20 +0xd6
github.com/Azure/sonic-telemetry/proto.setTarget()
        /tmp/go/src/github.com/Azure/sonic-telemetry/proto/sonic.pb.go:33 +0x34
github.com/Azure/sonic-telemetry/proto.init.2()
        /tmp/go/src/github.com/Azure/sonic-telemetry/proto/sonic.pb.go:42 +0x26
root@dcb09a6a8409:/# echo $?
2
root@dcb09a6a8409:/# 

おお、なんてことだ。豪快にエラーが出ている。
エラーの原因と思われる行だけ抜き出すと

redis.exceptions.ConnectionError: Error 111 connecting to 127.0.0.1:6379. Connection refused.
panic: open /var/run/redis/sonic-db/database_config.json: no such file or directory

たしかにtelemetry dockerのコンテナ内に/var/run/redisはなかった。が、これはdocker起動時のコマンドライン不足と思われる。ということは、実際のエラーの原因は上記ではない可能性が高い。

続く。

まとめ

• sytemctlで状態を確認する、ログを見る、実際に動かしてみる、などしてみた。
• 面倒。
• だけど、やってやれないことはない。
• 今回の調査では使わなかったが、gdb入りイメージを作成することもできるので、segfaultするようなときは活用したい。