Python, logging, Logger, デバッグ

お題

トイドローン Tello のプログラミング記事です。

前回の予告とは少し内容が変わってしまうのですが、ドローンを飛ばして遊んでいるうちに「プログラムが終了できない」という現象がかなりの頻度で発生するということがわかったため、ひとまずこの問題の解決を試みたいと思います。

発生している問題

現在発生している問題は以下になります。

  • プログラムが終了できないときがある。
  • ドローンとの接続ができていない場合は100%終了できない。

原因調査

まずは「どの処理に問題があるのか」を特定してみたいと思います。 とりあえずはメインループを受け持つ dashboard.py を眺めてみました。

while True:
    msg = ""

    # (1) 画面の状態を読み取る
    event, values = window.read(timeout=1)
    window["state"].update(f'battery: {info.get_state("bat"):.1f}%')

    # (2) ドローンからの画像を取得する
    image = info.get_image()

    # (3) 画像が取得できなければ continue
    if image is None:
        continue

    (...)

    # (4) 画面のクローズボタンか「Quit」ボタンがクリックされたらループを抜ける
    if event == sg.WINDOW_CLOSED or event == "Quit":
        break

このプログラムは (1) で画面の状態を読み取って event 変数に格納する → (4) で event 変数の値を見てループから抜けるという流れを想定しています。

ところがドローンと接続ができない場合には、 (2) のドローンからの画像取得ができないので (3) の continue でループの先頭に戻ってしまいます。そうすると絶対に (4) にはたどりつけないので結果的に「プログラムが終了できない」となります。

ということで以下のように処理の順番を入れ替えます(差分)。

while True:
    msg = ""

    # (1) 画面の状態を読み取る
    event, values = window.read(timeout=1)

    # (2) 画面のクローズボタンか「Quit」ボタンがクリックされたらループを抜ける
    if event == sg.WINDOW_CLOSED or event == "Quit":
        break

    window["state"].update(f'battery: {info.get_state("bat"):.1f}%')

    # (3) ドローンからの画像を取得する
    image = info.get_image()

    # (4) 画像が取得できなければ continue
    if image is None:
        continue

    (...)

この状態で動作確認してみます。

するとウインドウは閉じられるようになったのですがプログラム自体は終了しませんでした。 ということは「メインスレッド以外の処理で終了していないものがある」と推測できます。

今のままでは「どのスレッド上の処理に問題があるのか」はわかりません。そこで各処理の起動・終了時にログ出力を仕込みます。 「終了時にログ出力されない処理≒終了できないスレッド」と考えられるためです。

ログ出力には logging.Logger を使用します。これを便利に使うために、Logger のインスタンスを取得する共通関数 get_logger を作ります(コード全体)。

import logging

# 引数 name には「ログ出力の呼び出し元」を指定する
def get_logger(name: str) -> logging.Logger:
    logger = logging.getLogger(name)
    logger.setLevel(logging.DEBUG)
    handler = logging.StreamHandler()
    handler.setLevel(logger.level)

    # 出力例: INFO 2022-06-23 07:26:30,293 [drone_command_requester] start
    formatter = logging.Formatter("%(levelname)s %(asctime)s [%(name)s] %(message)s")
    handler.setFormatter(formatter)
    logger.addHandler(handler)
    return logger

これを使って dashboard.py を以下のように変更すればログ出力が行えます(差分)。

from logger import get_logger

(...)

class Dashboard(Runnable):
    def run(self, info: Info) -> None:
        # get_logger で Logger のインスタンスを取得する
        logger = get_logger(__name__)

        # "start" を INFO レベルで出力する
        logger.info("start")

        (...)

        while True:
          (...)

        # ループを抜けたら "done" を出力する
        logger.info("done")

他のクラスにも同様に開始・終了のログを仕込んで、実行してみると以下のような形でログ出力されました。

INFO 2022-06-24 22:01:05,965 [drone_command_requester] start
INFO 2022-06-24 22:01:05,967 [drone_state_receiver] start
INFO 2022-06-24 22:01:05,968 [drone_video_receiver] start
INFO 2022-06-24 22:01:05,968 [dashboard] start
INFO 2022-06-24 22:01:09,086 [dashboard] done
INFO 2022-06-24 22:01:36,418 [drone_video_receiver] done

この結果をまとめると以下になります。

  • 正常終了できたもの (done が出力されているもの)
    • dashboard
    • drone_video_receiver
  • 終了できなかったもの (done が出力されていないもの)
    • drone_command_requester
    • drone_state_receiver

となると次に調査すべきは「drone_command_requester と drone_state_receiver のどの部分でプログラムが停止しているか？」となります。

調査方法としては、「一行ずつ print 文を仕込む」てなやり方もありですが、それも面倒なので Visual Studio Code のデバッガを使ってみます。

  1. main.py を開いて、サイドバーを Run and Debug (Ctrl+Shift+D) に切り替えます。 デバッグ 1
  2. サイドバー上の Run and Debug ボタンをクリックして実行します。 デバッグ 2
  3. Pause (F6) をクリックして一時停止します。 デバッグ 3
  4. 左下に表示される CALL STACK にスレッドごとの停止箇所が表示されます。drone_command_requester.py をクリックすると停止箇所が確認できます。 デバッグ 4
  5. 同様に drone_state_receiver.py についてもどこで止まっているかを確認します。 デバッグ 5

この調査によって、drone_command_requester.py も drone_state_receiver.py も recvfrom() で停止していることがわかりました。

recvfrom() はドローンからの通信を受信する処理です。そして今回の問題は「ドローンとの接続ができていない場合は100%終了できない」でした。

  • この両者を合わせて考えると、以下の状況が起こっていることが想像できます。
    1. ドローンとの接続ができていないにもかかわらず、drone_command_requester.py や drone_state_receiver.py が recvfrom() でドローンからの情報を受信しようとする。
    2. ドローンとの接続ができていないので、ドローンからの情報は いつまでたっても受信できない。

drone_command_requester.py や drone_state_receiver.py はいずれも以下のように「info.is_active() が false になればループを抜ける」というコード記述がされています (Quitボタンがクリックされるとinfo.is_active() は false になります)。

  # info.is_active() が false ならばループを抜ける
  while info.is_active():
      try:
          # ドローンからの情報を受信する
          data, _ = state_sock.recvfrom(1024)
      (...)

したがって今回の問題発生の原因は、

  • いつまで待っても recvfrom() が終わらないのでループ先頭の終了判定 (info.is_active()) にたどり着けず、結果としてプログラムが終了できない

であると考えられます。

解決策

問題の根本原因は「いつまで待っても recvfrom() が終わらない」なので、これを「一定時間待っても受信できない場合はひとまずあきらめる」という動きにすればよさそうです。 調べると settimeout() を使えばこれが実現できそうです。

それぞれ以下のように修正します。

drone_state_receiver.py (差分)

  state_sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
  state_sock.settimeout(10)
  state_sock.bind(("", 8890))

drone_command_requester.py (差分)

  sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
  sock.settimeout(10)
  sock.bind(("", 8889))

この修正によって「10秒待っても受信できなかったらあきらめる」という動きになるはずです。

早速動かしてみると、想定通りしばらく待つと終了するようになりました。

現行コードの問題点

終了するようにはなったのですが、コンソール上には以下のようにごちゃっとエラーっぽい出力がされるようになりました。

INFO 2022-06-25 09:12:00,196 [drone_command_requester] start
INFO 2022-06-25 09:12:00,196 [drone_state_receiver] start
INFO 2022-06-25 09:12:00,197 [drone_video_receiver] start
Exception in thread Thread-1 (start):

Exit . . .

Traceback (most recent call last):
  File "C:\Python310\lib\threading.py", line 1009, in _bootstrap_inner
INFO 2022-06-25 09:12:10,208 [drone_state_receiver] done
    self.run()
  File "C:\Python310\lib\threading.py", line 946, in run
    self._target(*self._args, **self._kwargs)
  File "d:\projects\tello-example\drone_command_requester.py", line 20, in start
    sock.recvfrom(1024)
TimeoutError: timed out
INFO 2022-06-25 09:12:30,427 [drone_video_receiver] done

ちょっと不穏な感じがするのでこの情報を出力している部分のコードを確認します。

まずは drone_state_receiver.py です。

  while info.is_active():
      try:
          # ドローンからの情報を受信する
          data, _ = state_sock.recvfrom(1024)
          info.set_states(self.__get_drone_state(data))
      except Exception:
          # 受信に失敗したときは以下の処理が動く
          print("\nExit . . .\n")
          break

ドローンからの受信が失敗すると (10秒待ってもドローンからの受信ができないときは)、 例外処理 (except) に移行して Exit . . . と表示してループを抜ける (break) という処理になっています。

drone_command_requester.py は以下になります。

  while info.is_active():
      time.sleep(0.1)
      msg = info.pick_command()
      if msg == "":
          continue

      sock.sendto(msg.encode(), DRONE_ADDRESS)
      info.set_command_result("")
      info.set_sent_command(msg)
      start = time.time()
      data, _ = sock.recvfrom(1024)
      info.set_command_result(f"{data.decode()} {time.time() - start:.1f}")

こちらには例外処理 (try … except) がありません。 そのため「コンソール上にスタックトレースが出力されて終了」という動きになります。

こうやって改めてコードを眺めてみると、なんかいまいちな感じがします。 いままで真面目にエラー処理を考えてなかったので、まあ当然といえば当然なのですが。。

ということでまじめにエラー処理を考えてみると、以下2点の改善が必要そうです。

  • 通信中にエラーが発生した場合、「そのタイミングだけ偶然うまく動作しなかった」という可能性もあるため、終了せずに処理を継続する。
  • とはいえ「エラーが起きた事実」と「エラーの発生箇所」は把握しておきたいので、エラー発生時にはスタックトレース表示する。

エラー処理の改善

上記の方針に従って改善を施すと以下のようになります。

まずは drone_state_receiver.py (差分)。

変更前:

except Exception:
    print("\nExit . . .\n")
    break

変更後:

except Exception:
    logger.exception("communication error")
  • 変更点は以下2点:
    1. print をやめて、代わりにスタックトレースをログ出力する。
    2. break を外して、ループから抜けないようにする。

次に drone_command_requester.py ですが、こちらは以下のように recvfrom を実行している場所が3箇所もあります。

    sock.sendto("command".encode(), DRONE_ADDRESS)
    sock.recvfrom(1024)
    sock.sendto("streamon".encode(), DRONE_ADDRESS)
    sock.recvfrom(1024)

    while info.is_active():
      (...)
      data, _ = sock.recvfrom(1024)

3箇所それぞれに例外処理を組み込むとコードが冗長になってしまうため、「コマンド送信、結果受信、例外処理」という一連の流れを共通関数 __send として切り出す形にしたいと思います(差分)。

def start(self, info: Info) -> None:
    (...)

    self.__send(sock, "command", info, logger)
    self.__send(sock, "streamon", info, logger)

    while info.is_active():
        (...)
        self.__send(sock, msg, info, logger)
  (...)


def __send(self, sock: socket.socket, msg: str, info: Info, logger: Logger) -> None:
    try:
        sock.sendto(msg.encode(), ("192.168.10.1", 8889))
        info.set_sent_command(msg)
        start = time.time()
        data, _ = sock.recvfrom(1024)
        info.set_command_result(f"{data.decode()} {time.time() - start:.1f}")
    except Exception:
        logger.exception("communication error")

この状態で実行すると、以下のようにエラー箇所が出力されるようになります。

INFO 2022-06-25 10:11:57,135 [drone_command_requester] start
INFO 2022-06-25 10:11:57,136 [drone_state_receiver] start
INFO 2022-06-25 10:11:57,136 [drone_video_receiver] start
TimeoutError: timed out
ERROR 2022-06-25 10:12:07,143 [drone_state_receiver] communication error
Traceback (most recent call last):
  File "d:\projects\tello-example\drone_state_receiver.py", line 20, in start
    data, _ = state_sock.recvfrom(1024)
TimeoutError: timed out
INFO 2022-06-25 10:12:07,145 [drone_state_receiver] done
ERROR 2022-06-25 10:12:17,145 [drone_command_requester] communication error
Traceback (most recent call last):
  File "d:\projects\tello-example\drone_command_requester.py", line 37, in __send
    data, _ = sock.recvfrom(1024)
TimeoutError: timed out
INFO 2022-06-25 10:12:17,147 [drone_command_requester] done
INFO 2022-06-25 10:12:27,341 [drone_video_receiver] done

もちろん終了も問題なく行えます。

次回

すっきり気持ちよく終了できるようになったので、次回こそは本筋に戻ります。

です。

Tello 関連記事

かわかみしんいち。島根県津和野町在住のフリーランスエンジニア。複合現実(Mixed Reality)と3DUXでおもちゃを作るのが趣味。 https://github.com/ototadana