ザ☆シュビドゥヴァーズの日記

毎日更新されたりされなかったりする日記

怪奇!! チャットbot 沈黙事件

さらです。

多くの合唱団がそうであるように当団も団運用のためのチャットbotが稼働しています。

例えばシュビのLINEには "jervis" というbotが常駐しています。

f:id:the_shubidovers:20190929000443p:plain

団で実施している会議 (オンラインの音声会議) で話したい事項は、このjervisに議題として投げることにしています。 botが自動でタスク管理ツールにいい感じに起票して、ついでに議事録のページなども用意してくれます。

9/25 22:20頃 突如沈黙

先日のことですが、そんなjervisちゃんが議題の依頼に何の返事も返さなくなってしまいました。

上に載せた画像のように、基本的に議題メッセージがあれば即座に応答してくれるのですが、このようなメッセージに対してなんの返事も返さなくなりました。死んでしまいました。

f:id:the_shubidovers:20190928233855p:plain

チャットルームが悲しみに包まれます。

jervisを経由しない場合は、私が自分でポチポチ議事録ファイルを用意しないといけないというくらいで、実のところbot経由できなくて悲しみに包まれるのは私だけですね正直。

まぁ常駐のアプリが特に何もしていないのに謎の不調を起こし、再起動したら直ったみたいのはよくある話(良くないんですけどね)なので、再起動すれば直るだろくらいに思っていました。

事件の調査

このbotは以下のような仕組みで動いています。

  1. LINEチャンネル上のメッセージを受け取る
  2. メッセージをいい感じに解析する
  3. メッセージが議題について言及しているものであればタスク管理ツールにアクセスして色々起票する

実はよくある壊れ方については概ね検討がついています。 大抵は 1. のLINEメッセージを受け取るところがおかしくなるんです。 証明書切れとかそういうやつですね。良くないんですけどね。

LINE -> botまでのアクセス

ということでLINEの開発者ポータルにログインし、正しくbotにテストメッセージを飛ばせるか調べます。

ポータル画面に「接続確認」というボタンが付いていて、これを押すとテストrequestが飛びます。 これにより LINEのメッセージをbotが受け取れる状態であるかどうか が確認できます。 成功したか失敗したかが画面に表示されます。

これで失敗しましたと表示されれば、またゲートウェイ再起動したり証明書の確認したりしｔ……

f:id:the_shubidovers:20190928234034p:plain
「成功しました」

ちゃんと飛ぶじゃん……

bot -> タスク管理ツールへのアクセス

当てが外れて困ってしまいました。 とりあえずbotのサーバに入ってログを見たところ、議題のメッセージに反応しているログがちゃんと残っていました。

Wed Sep 25 22:20:35 JST 2019
{"message":{"text":"agenda\n- 議題1\n- 議題2\n- 議題3"},"source":{"groupId":"yyyyyyyy","type":"group","userId":"yyyyyyy"}}
----
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/usr/local/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/var/lib/bot_jervis/actions/create_task.py", line 6, in <module>
    from ctask.handler import Task
ImportError: cannot import name 'Task'

※ 一部情報を書き換えてあります

このログファイルは、議題に関連するメッセージと、タスク管理ツールへのアクセス結果を記録しているものなのですが、途中から ImportError のエラーメッセージが残っています。 メッセージの解析までは上手くいった上で、タスク管理ツールにアクセスしようとして力尽きた経緯が記録されているということです。

具体的には、

  • タスク管理ツールに起票する際には Task という名前のモジュールを呼び出せとコードに書かれている
  • しかし Task とかいう名前のモジュールがコードに書かれていない

みたいなメッセージが残っています。

実際にサーバに置かれているコードを見に行ったところ、

class TaskHandler(object):   # <-- これは以前Taskという名前だった
    TEXT_CONTENT_SPELL = 'hogehoge'

    def __init__(self, token: str, room: str,
                 space='', project=''):

Task というモジュールがあったっぽい位置には TaskHandler という名前のモジュールが置かれていました。 たぶんどこかのコード改良のタイミングで名前を変更したのでしょう。

このコードはどこかから買ってきたわけではなく、全て自分らで実装したものです。

つまり、 誰かがコードを改良した際に、依存関係を十分に確認しなかったため、バグってしまった ということです。

一体誰だよ…ふざけんなよ…

犯人探し

犯人を見つけたいので git blame というコマンドを使います。

blame ("咎める") というコマンド名の通り、"最後にいつ誰かが書き換えたのか"を、コードの各行について表示してくれるコマンドです。

gitはこの辺の記録が確実に残るので言い逃れはできません。 先ほどの TaskHandler が置かれていた行を見てみると

d957xxxx (sara-san  2019-05-25 12:48:14 +0900  11) class TaskHandler(object):
ecd7xxxx (sara-san  2019-05-25 13:05:50 +0900  12)     TEXT_CONTENT_SPELL = 'hogehoge'
aad4xxxx (sara-san  2019-05-25 14:40:33 +0900  13)
6e6cxxxx (sara-san  2018-10-05 18:07:19 +0900  14)     def __init__(self, token: str, room: str,
6e6cxxxx (sara-san  2018-10-05 18:07:19 +0900  15)                  space='', project=''):

2019/05/25 に "さらさん" という人が壊したらしいです！！

f:id:the_shubidovers:20190928234659p:plain
サイコパス扱いされる開発者

ということで私が自分で壊しておきながら「なんだよまたおかしくなったのかよめんどくせぇな」みたいな気分で調査してました。謙虚になりましょう。

まぁぶっちゃけこのbotは私が遊びで作っているだけなのでどう考えても私以外に変更を加えないんですけどね。

まとめ

ちゃんとテストは書きましょう。