LINE DevelopesのWebhook URLの接続確認でエラーが出る件について

#オウム返しLINEBOTを作ってみようで起きたこと

Webhookが無効なHTTPステータスコードを返しました（期待されるステータスコードは200です）

これについて世の中の見解。

「そういうもの」

実際、様々なエラーで、200 OK以外が返ることはあるが、
正常に(想定通り)に実装して、500 errorが返ってくるのは割と納得できなかった。

#実行環境

• LINE DevelopersのMessaging API SDKのPython
• heroku

#とりあえず対処

公式SDKのサンプルプログラムを参考に解説しているサイトは、軒並み、この現象に陥る。
調べた結果の個人的見解としては、LINE Developersから送られてきたメッセージに含まれている、
"replyToken": "00000000000000000000000000000000"
は有効なreplyTokenではないと判断してエラーにしているのではないかと。

ということで、エラー発生個所であるreply_messageの作成部分を、
ピンポイントでこのreplyTokenが来たとき、回避するようにした。

main.py(変更前)

@handler.add(MessageEvent, message=TextMessage)
def handle_message(event):
    line_bot_api.reply_message(
        event.reply_token,
        TextSendMessage(text=event.message.text))

main.py(変更後)

@handler.add(MessageEvent, message=TextMessage)
def handle_message(event):
    if event.reply_token == "00000000000000000000000000000000":
        return

    line_bot_api.reply_message(
        event.reply_token,
        TextSendMessage(text=event.message.text))

これで、そのほかの問題が起きていなければ、200 OKが返るはずである。

#調査方法
###/indexを作ってみた。

まず、webhookのテストだけなら、/callbackとは別に、/indexでも作って、とにかく、OKを返してみればいいと思う。

main.py(/index追加)

@app.route("/index", methods=['POST'])
def index():
    return 'OK'

これで、LINE DesignerのWebhook URLをcallbackではなくindexにしてアクセスする。

これを行ったとき、本当に何もしてないのにOKになるんだってことがわかり、
herokuやLINE Developersの問題ではないということを確信した(問題の切り分け)
callback内で何か問題が起きてるからOKが返らなくなってしまったのだと。

###herokuのログ

herokuのログを眺めることで、何が起きているか予想がたてられた。

heroku logs --tail

###herokuにログ出力
単純にprint()を行えば出力してくれた。
ログ出力というよりは標準出力先がherokuってことなのかな。

main.py(ログ出力追加)

    # get request body as text
    body = request.get_data(as_text=True)
    app.logger.info("Request body: " + body)
    print("----1----")
    print(body)
    print("----2----")

仕込むログとしてはダサいけど、一時的な試みだし、探す労力削減のため、こんな感じで。
次のような感じでログが見れる。

2019-04-19T09:36:10.000000+00:00 app[api]: Build succeeded
2019-04-19T09:36:19.429154+00:00 app[web.1]: ----1----
2019-04-19T09:36:19.429219+00:00 app[web.1]: {
2019-04-19T09:36:19.429222+00:00 app[web.1]: "events": [
2019-04-19T09:36:19.429224+00:00 app[web.1]: {
2019-04-19T09:36:19.429227+00:00 app[web.1]: "replyToken": "00000000000000000000000000000000",
2019-04-19T09:36:19.429230+00:00 app[web.1]: "type": "message",
2019-04-19T09:36:19.429232+00:00 app[web.1]: "timestamp": 1555666578762,
2019-04-19T09:36:19.429234+00:00 app[web.1]: "source": {
2019-04-19T09:36:19.429235+00:00 app[web.1]: "type": "user",
2019-04-19T09:36:19.429237+00:00 app[web.1]: "userId": "Udeadbeefdeadbeefdeadbeefdeadbeef"
2019-04-19T09:36:19.429238+00:00 app[web.1]: },
2019-04-19T09:36:19.429240+00:00 app[web.1]: "message": {
2019-04-19T09:36:19.429241+00:00 app[web.1]: "id": "100001",
2019-04-19T09:36:19.429243+00:00 app[web.1]: "type": "text",
2019-04-19T09:36:19.429245+00:00 app[web.1]: "text": "Hello, world"
2019-04-19T09:36:19.429246+00:00 app[web.1]: }
2019-04-19T09:36:19.429248+00:00 app[web.1]: },
2019-04-19T09:36:19.429249+00:00 app[web.1]: {
2019-04-19T09:36:19.429251+00:00 app[web.1]: "replyToken": "ffffffffffffffffffffffffffffffff",
2019-04-19T09:36:19.429252+00:00 app[web.1]: "type": "message",
2019-04-19T09:36:19.429254+00:00 app[web.1]: "timestamp": 1555666578762,
2019-04-19T09:36:19.429255+00:00 app[web.1]: "source": {
2019-04-19T09:36:19.429257+00:00 app[web.1]: "type": "user",
2019-04-19T09:36:19.429258+00:00 app[web.1]: "userId": "Udeadbeefdeadbeefdeadbeefdeadbeef"
2019-04-19T09:36:19.429260+00:00 app[web.1]: },
2019-04-19T09:36:19.429262+00:00 app[web.1]: "message": {
2019-04-19T09:36:19.429263+00:00 app[web.1]: "id": "100002",
2019-04-19T09:36:19.429283+00:00 app[web.1]: "type": "sticker",
2019-04-19T09:36:19.429285+00:00 app[web.1]: "packageId": "1",
2019-04-19T09:36:19.429286+00:00 app[web.1]: "stickerId": "1"
2019-04-19T09:36:19.429288+00:00 app[web.1]: }
2019-04-19T09:36:19.429289+00:00 app[web.1]: }
2019-04-19T09:36:19.429291+00:00 app[web.1]: ]
2019-04-19T09:36:19.429292+00:00 app[web.1]: }
2019-04-19T09:36:19.429336+00:00 app[web.1]:
2019-04-19T09:36:19.429402+00:00 app[web.1]: ----2----

ちなみに、正常にオウム返しされるパターンと見比べてみて、

2019-04-19T09:36:19.939930+00:00 app[web.1]: linebot.exceptions.LineBotApiError: LineBotApiError: status_code=400, error_response={"details": [], "message": "Invalid reply token"}

このエラー内容から、LineBotApi内で、"replyToken": "00000000000000000000000000000000"はエラーとするロジックが入っているのではないかと予想した。

#余談
今回は、想定通り実装しているのに無効なHTTPステータスコードが返ってくる件を想定して書いたが、
本当にエラーを起こしていて、うまくいっていない人もいると思う。
私もある程度はまったので、記録に残しておこうと思う。

• 環境変数エラー

一部のオウム返し紹介記事ではherokuの環境変数を使用している。
その環境変数の設定がうまくいっていないケース。

2019-04-19T09:52:12.590781+00:00 app[web.1]: File "main.py", line 17, in <module>
2019-04-19T09:52:12.590867+00:00 app[web.1]: YOUR_CHANNEL_ACCESS_TOKEN = os.environ["YOUR_CHANNEL_ACCESS_TOKEN_TYPEMISS"]
2019-04-19T09:52:12.590871+00:00 app[web.1]: File "/app/.heroku/python/lib/python3.7/os.py", line 678, in __getitem__
2019-04-19T09:52:12.591158+00:00 app[web.1]: raise KeyError(key) from None
2019-04-19T09:52:12.591181+00:00 app[web.1]: KeyError: 'YOUR_CHANNEL_ACCESS_TOKEN_TYPEMISS'
2019-04-19T09:52:06.475889+00:00 app[api]: Deploy xxxxxxxx by user [e-mail]
2019-04-19T09:52:16.000000+00:00 app[api]: Build succeeded

上記はわかりやすく、TYPEMISSと変えてみたが、環境変数のキーワードが違っているケースと、
定義した変数名と使用している変数名が違っているケースといろいろあるので、
いっそ、この辺りは、ハードコーディングで通るかどうか試してしまうのが良いと思う。

• SyntaxError: invalid syntax

==で比較するところを=として代入になってたとか。
意外とBuild succeededになるから困る。

• インポートエラー

2019-04-19T09:57:49.322170+00:00 app[web.1]: NameError: name 'os' is not defined

うっかり消した。

• SSLの問題

なんか、SSL対応してないとダメとか何とかで、OpenSSLを入れた。
私はここではまらなかったけど、世の中にははまってる人もいたので。

• Webhook URLのアプリ名を間違えてる。

手入力する要素は一通り失敗したかも。

そんなところかな。

#雑感
今回は、割と一通り初めて触ったものが多く、
pythonの問題なのか、LINEの問題なのか、herokuの問題なのか、
どこで問題が起きてるのかわからーんと禿げそうになってた。

用語がわからないと質問もできないし、一体自分がどこまでできていて何ができていないのか・・・。

いろんなところで質問に対する回答がついていないものとか見かけたけど、
そのできているっていうのは何をもって確信しているのとか、
何がしたいのとかというのがあり、
だから回答がつかないんだろうなぁと。
回答がつかないときは、自分で追加調査記録をどんどん投げていくと、ああいうのは回答がつきやすくなるのかなぁ。