hubot-slackで発生した「ERROR An error occurred while processing. RTM event: a is not defined.」と格闘した話（解決）

はじめに

Google Home、Raspberry Pi、Hubot、IFTTT、学習リモコン（RM3-Mini）を使って音声で家電操作をしていたのですが、ある時Hubotが「ERROR An error occurred while processing. RTM event: a is not defined.」というエラーを出力するようになりました。
調査・対応方法について、日本語の記事が見つからなかったので、残しておきます。

何が起きたのか？

今年の年始に、10ドルのRM Mini3とGoogle Homeで家電を操作する方法に取り組みました。初めて作ったときはきちんと動作していたのですが、Raspberry Piを新しいものに取り替えることになり、先月セットアップし直したところ、動作しなくなりました。
あれこれ動作確認をしたところ、以下のような状況であることがわかりました。

• Google Home（Google Assistant）から使用すると動作しない。
• IFTTTアプリから実行すると動作しない。
• slackアプリでhubotに直接メッセージを送ると動作する。

以上のことから、IFTTTから送られたメッセージをうまく認識できなくなっているようです。

動作環境

• hubot-slack version:4.5.1
• node version:v8.11.3
• OS version(s):Raspbian 9.1（Raspberry Pi 3）

原因を調べてみる

ログを確認する

hubotの実行ログを見てみます。

bin/hubot --adapter slack
npm WARN hubot-help@0.2.2 requires a peer of coffee-script@^1.12.6 but none is installed. You must install peer dependencies yourself.

audited 391 packages in 9.825s
[Sun Jun 24 2018 08:21:15 GMT+0000 (UTC)] INFO hubot-slack adapter v4.5.1
warn: SlackDataStore is deprecated and will be removed in the next major version. See project documentation for a migration guide.
warn: SlackDataStore is deprecated and will be removed in the next major version. See project documentation for a migration guide.
[Sun Jun 24 2018 08:21:16 GMT+0000 (UTC)] INFO Logged in as @homebot in workspace home
[Sun Jun 24 2018 08:21:16 GMT+0000 (UTC)] INFO Connected to Slack RTM
[Sun Jun 24 2018 08:21:18 GMT+0000 (UTC)] INFO hubot-redis-brain: Using default redis on localhost:6379
[Sun Jun 24 2018 08:21:18 GMT+0000 (UTC)] INFO hubot-redis-brain: Data for hubot brain retrieved from Redis
Discovered Broadlink RM device at xxx.xxx.xxx.xxx (xx:xx:xx:xx:xx:xx)

[Sun Jun 24 2018 08:21:48 GMT+0000 (UTC)] ERROR An error occurred while processing an RTM event: a is not defined.

「ERROR An error occurred while processing an RTM event: a is not defined.」
なんでしょう・・・このエラーは・・・。
「RTM event」とは、この場合はslackのことを指しています。「a」というものが何者かわかりませんが、これがnot defined.であるためにその後の処理がされていないのでしょうね。

デバッグログを出力して更に調べる

hubotは、環境変数を設定することで標準出力にデバッグログを出力させることができます。
bin/hubotをテキストエディタで開いて、設定を追加します。

bin/hubot

#!/bin/sh

set -e

npm install
export PATH="node_modules/.bin:node_modules/hubot/node_modules/.bin:$PATH"
export HUBOT_SLACK_TOKEN=XXXX-XXXXXXXXXXXX-XXXXXXXXXXXXXXXXXXXXXXXX

# 追加 start
export HUBOT_LOG_LEVEL=debug
export HUBOT_SLACK_RTM_RTM_CLIENT_OPTS='{ "logLevel": "debug"}'
# 追加 end

exec node_modules/.bin/hubot --name "homebot" "$@"

再度bin/hubotを実行すると、デバッグログが大量に出力されます。問題のエラーの直前で気になるログを見つけました。

[Sun Jun 24 2018 17:14:17 GMT+0000 (UTC)] DEBUG Received text message in channel: XXXXXXXXX, from: undefined (bot)
[Sun Jun 24 2018 17:14:17 GMT+0000 (UTC)] ERROR An error occurred while processing an RTM event: a is not defined.

from: 「undefined (bot)」
この部分ですね。slackアプリからメッセージを送ったときの出力と比べてみました。

DEBUG Received text message in channel: XXXXXXXXX, from: XXXXXXXXX (human)

正常に動作する場合、fromに値が設定されていました。ソースコードを見てみると

bot.coffee

@robot.logger.debug "Received text message in channel: #{channel}, from: #{user.id} (bot)"

記述から察するに、from（＝メッセージの送信元ユーザID）が"undefined"になっていることが原因のようです。

原因判明

その後もhubot-slackのソースコードを読んでみたのですが、行き詰まってしまったためGithubからhubot-slackのコミッタへ問い合わせてみました。
1日も立たずにコミッタの方から回答があり、なんとhubot-slack 4.5.1のバグとのことでした。

An error occurs when IFTTT processes a message linked to slack #500

コミッタの方の説明によると、IFTTTから送られてきたメッセージの処理に問題があったようです。

修正版（Ver4.5.3）がリリースされました！

コミッタの方からのアドバイスで、修正版（Ver4.5.2）のリリースを待ってほしいということだったのでリリースを待ちました。そして、今週Ver4.5.2がリリースされました！！
hubot-slackをアップデートし、満を持して実行すると・・・エラーは出なくなりましたが、hubot自体もなんの反応もしません。（おや〜？）
前回同様、デバッグログを出してみます。
shell
DEBUG Received text message in channel: XXXXXXXXX, from: undefined (bot)
DEBUG No listeners executed; falling back to catch-all

エラーは出ていませんが、from: undefinedはまだ健在でした。
う〜ん・・・。残念ながらまだ解消できていないようです。

(2018/7/22 更新)
先日、Ver4.5.3がリリースされ、問題が解消されていることを確認しました。
更新方法ですが、package.jsonのバージョンを更新し、再インストールするのが一番簡単だと思います。

package.json（抜粋）

  "dependencies": {
    "coffee-script": "^1.12.7",
    "hubot": "^2.19.0",
    "hubot-broadlink-rm": "^0.7.1",
    "hubot-diagnostics": "0.0.2",
    "hubot-google-images": "^0.2.7",
    "hubot-google-translate": "^0.2.1",
    "hubot-help": "^0.2.2",
    "hubot-heroku-keepalive": "^1.0.3",
    "hubot-maps": "0.0.3",
    "hubot-pugme": "^0.1.1",
    "hubot-redis-brain": "0.0.4",
    "hubot-rules": "^0.1.2",
    "hubot-scripts": "^2.17.2",
    "hubot-shipit": "^0.2.1",
    "hubot-slack": "^4.5.3"    ←　バージョン番号を4.5.3に変更

package.json変更後に実行するコマンド

rm -Rf node_modules
npm install

おわりに

解決に１ヶ月近くかかりましたが、再びスマートハウス生活を取り戻すことができました。
hubot-slackのコミッタの方、この投稿にコメントをくださったみなさんに感謝します。