Discordrb + Heroku Schedulerでのやらかしについて

はじめに

フィヨルドブートキャンプで学習しています@Maedaといいます。 現在自作サービスを作るプラクティスでDiscord Botの作成に取り組んでいます。

Discordrb + Heroku Schedulerを使用した際につまづいたことについて話していきたいと思います。

目次

現在作成しているもの

Discordサーバー内のテキストチャンネルからランダムに一つ選び毎朝アナウンスしてくれる、テキストチャンネル紹介botを作成しております。

ruby-jpではrubotyというSlack botが毎朝9時にサーバー内のチャンネルをランダムで一つ紹介してくれています。このDiscord版(フィヨルドブートキャンプのDiscordサーバー内で使用)を作成しています。

まだ作成は終わっていませんが、こんな風にDiscord botがチャンネル紹介をしてくれるイメージです↓

botが毎日決まった時間にチャンネル紹介するようにしたいな〜と思ったのが、Heroku Schedulerを導入した経緯になります。

はまったところについて

では早速、自分がはまったことについてです。

Heroku Schedulerを導入する上で、まず1時間に一回定期実行してくれるのかをテスト検証してみようと思い、毎時間30分(1:30→2:30→3:30...)になったらチャンネル紹介するコマンドを実行するというjobをHeroku Schedulerに登録しました。

その結果、3時間に1回しかbotがチャンネル紹介してくれないという問題が発生しました...

(下の画像のような感じで、3時間に1回しかbotがチャンネル紹介してくれない...)

なんでだろう...という状態だったので、一つ一つ原因を調査してみることにしました。

調査

調査をフィヨルドブートキャンプのメンターの方と一緒に行って頂きました。

まずは、きちんとデプロイやHeroku Schedulerの設定がうまくできているかを確認しました。

→ここはHerokuのドキュメント通りに行ったため、問題なさそうということになりました。

次に、設定したjobがきちんと実行されているかどうかを確認をするため、「ログを集める・読む」ということを行いました。

ログの情報から、実行されたプロセスがずっと残り続けている。ということがわかり、ここが怪しいのではないか?ということに。(本来であれば、Process exited with status 0State changed from up to completeというような感じで、プロセス自体が完了になっているはず!)

(実際のログ↓)

Mar 16 01:30:24 rocky-temple-69583 heroku/scheduler.6680 Starting process with command `bundle exec ruby bin/bot_run.rb`
Mar 16 01:30:24 rocky-temple-69583 heroku/scheduler.6680 State changed from starting to up
Mar 16 02:32:30 rocky-temple-69583 heroku/scheduler.6680 Cycling
Mar 16 02:32:30 rocky-temple-69583 heroku/scheduler.6680 State changed from up to complete
Mar 16 02:32:31 rocky-temple-69583 heroku/scheduler.6680 Stopping all processes with SIGTERM
Mar 16 02:32:31 rocky-temple-69583 heroku/scheduler.6680 Process exited with status 143
Mar 16 04:30:09 rocky-temple-69583 heroku/scheduler.1568 Starting process with command `bundle exec ruby bin/bot_run.rb`
Mar 16 04:30:10 rocky-temple-69583 heroku/scheduler.1568 State changed from starting to up
Mar 16 05:31:08 rocky-temple-69583 heroku/scheduler.1568 Cycling
Mar 16 05:31:08 rocky-temple-69583 heroku/scheduler.1568 State changed from up to complete
Mar 16 05:31:10 rocky-temple-69583 heroku/scheduler.1568 Stopping all processes with SIGTERM
Mar 16 05:31:10 rocky-temple-69583 heroku/scheduler.1568 Process exited with status 143
Mar 16 07:30:19 rocky-temple-69583 heroku/scheduler.6649 Starting process with command `bundle exec ruby bin/bot_run.rb`
Mar 16 07:30:19 rocky-temple-69583 heroku/scheduler.6649 State changed from starting to up
Mar 16 08:31:30 rocky-temple-69583 heroku/scheduler.6649 Cycling
Mar 16 08:31:30 rocky-temple-69583 heroku/scheduler.6649 State changed from up to complete
Mar 16 08:31:31 rocky-temple-69583 heroku/scheduler.6649 Stopping all processes with SIGTERM
Mar 16 08:31:31 rocky-temple-69583 heroku/scheduler.6649 Process exited with status 143

(実際の画像↓)

そもそも、このサービスのやりたいこととしては「Discord Botが毎日1回サーバー内のテキストチャンネルをランダムに一つ紹介する。」それだけであるので、 本来であればプロセスが生き続けている事自体がおかしいことに気づきました。

そこで初めて、不必要にbotを稼働させてしまっていることに気づきました。。。(ログを見るまでは気づいてませんでした...)

コードを見てみると、自分が行いたいことは 「botがチャンネルにメッセージを送るようにする」という事であり、それはDiscordrb::API::Channel.create_message(...)で実現できているのにも関わらず、「botを継続的に稼働させるようにする」という行う必要のないDiscordrb::Bot.new(...).runまで行うようにコードを書いてしまっている事がわかりました。


参考

  • Discordrb::API::Channel.create_messageについて

https://drb.shardlab.dev/v3.4.0/Discordrb/API/Channel.html#create_message-class_method

  • Discordrb::Bot.new(...).runについて

https://drb.shardlab.dev/v3.4.0/Discordrb/Bot.html#run-instance_method


「不必要にbotを稼働させてしまっていた」ここが今回の一番のやらかしポイントでした。

この部分を修正しデプロイし直した結果、きちんとHeroku Schedulerが作動し、1時間毎にチャンネル紹介をしてくれるようになりました。

修正したPRです

github.com

なぜチャンネル紹介が3時間おきに行われたのか?について

Heroku Schedulerの話に戻りますが、1時間おきにHeroku Schedulerが実行されるようjobを設定しているのにも関わらず、3時間おきに実行されてしまうという問題がありました。

この件について調べてみたところ、Heroku Schedulerのログの中にあるサイクルがあることがわかりました。

(実際のログ↓)

# ---ここから
Mar 16 01:30:24 rocky-temple-69583 heroku/scheduler.6680 Starting process with command `bundle exec ruby bin/bot_run.rb`
Mar 16 01:30:24 rocky-temple-69583 heroku/scheduler.6680 State changed from starting to up
Mar 16 02:32:30 rocky-temple-69583 heroku/scheduler.6680 Cycling
Mar 16 02:32:30 rocky-temple-69583 heroku/scheduler.6680 State changed from up to complete
Mar 16 02:32:31 rocky-temple-69583 heroku/scheduler.6680 Stopping all processes with SIGTERM
Mar 16 02:32:31 rocky-temple-69583 heroku/scheduler.6680 Process exited with status 143
# ---ここまで

# ---ここから
Mar 16 04:30:09 rocky-temple-69583 heroku/scheduler.1568 Starting process with command `bundle exec ruby bin/bot_run.rb`
Mar 16 04:30:10 rocky-temple-69583 heroku/scheduler.1568 State changed from starting to up
Mar 16 05:31:08 rocky-temple-69583 heroku/scheduler.1568 Cycling
Mar 16 05:31:08 rocky-temple-69583 heroku/scheduler.1568 State changed from up to complete
Mar 16 05:31:10 rocky-temple-69583 heroku/scheduler.1568 Stopping all processes with SIGTERM
Mar 16 05:31:10 rocky-temple-69583 heroku/scheduler.1568 Process exited with status 143
# ---ここまで

# ---ここから
Mar 16 07:30:19 rocky-temple-69583 heroku/scheduler.6649 Starting process with command `bundle exec ruby bin/bot_run.rb`
Mar 16 07:30:19 rocky-temple-69583 heroku/scheduler.6649 State changed from starting to up
Mar 16 08:31:30 rocky-temple-69583 heroku/scheduler.6649 Cycling
Mar 16 08:31:30 rocky-temple-69583 heroku/scheduler.6649 State changed from up to complete
Mar 16 08:31:31 rocky-temple-69583 heroku/scheduler.6649 Stopping all processes with SIGTERM
Mar 16 08:31:31 rocky-temple-69583 heroku/scheduler.6649 Process exited with status 143
# ---ここまで
  1. Heroku Schedulerが起動し、bundle exec ruby bin/bot_run.rbが実行された結果ファイル内に記載されている、Discordrb::API::Channel.create_messageが実行されてチャンネル紹介が行われ、Discordrb::Bot.new(...).runが実行されてbotの稼働が始まる。

  2. 1時間後、Heroku Schedulerが起動するも、Cycling(再起動が実行)が行われ、まだ残っているプロセス(Discordrb::Bot.new(...).run)を強制終了させる。(jobに設定してあるbundle exec ruby bin/bot_run.rbは実行されていない)

  3. 1時間後、実行されるはずのHeroku Schedulerが起動されない。→1に戻る。

→ この1~3のサイクルが繰り返されて、3時間毎にチャンネル紹介がされていたということがわかりました。


色々調査しましたが結局のところ、

  • 2.で、Heroku Schedulerに設定したコマンドが実行されずに、プロセスを殺しただけで終了してしまっていること。
  • 2.で残っているプロセスを殺して終了した後、1時間後に実行されるはずのHeroku Schedulerが全く実行されていないこと。(その1時間後に再び定期実行されるようになる)

この2点に関してはなぜなのかわかりませんでした...

(わかる方がいらっしゃれば、コメントしてくださると幸いです。)


追記(3/30)

jnchitoさんからコメントいただきましたので、追記させて頂きます。

ここは僕もよくわからないのですが、Schedulerのドキュメントの「Long-running jobs」を読むと、そもそも「スケジューリング間隔をオーバーするような長時間のタスクはSchedulerを使うな」的なことが書いてあるので、あまり深追いしなくても良さそうな気がします。想定外の使い方をしてしまったので想定外の動きになった、ぐらいな結論でいいかもしれません。数秒〜数分で終わる適切なタスクを設定する上では、こういった問題は起きないはずなので。

https://devcenter.heroku.com/articles/scheduler#long-running-jobs

Heroku側も想定していない使い方をしてしまっていたので、どれだけ調べても推測でしかわからなそうということです。。。

そもそもの使い方がイレギュラーすぎると、原因も追いにくいということが分かりました😓

今回のまとめ

botを稼働させるという必要のないことをしてしまい、Heroku Schedulerが1時間後に次のコマンドを実行するときに前のプロセスが残り続けている。という問題が起きた結果、今回のような3時間に1回しか実行されないという問題に繋がってしまった。というのが今回の一連の流れです。

自分のやりたいこととしては、サーバー内のチャンネル情報を取得し、その情報をフォーマットし、その結果をbotに出力させる。ということなので、「スクリプトを実行する」ことで事足りるにも関わらず、使わなくてもいい機能であるDiscordrb::Bot.new(...).runを行ってしまっていた。ということが一番のやらかしポイントでした。 (Discordrb::Bot.new(...).runを行う必要があるのは、そのサーバー内にbotを常駐させて何かコマンドに対して反応させる必要がある時のような場合に行う)

学んだこと

  • Discord bot動作させる上で、 Discordrb::Bot.new(...).runを行うことが必要条件ではないことを学びました。(Discordrb::Bot.new(...).runbot稼働させる上で最低限必要なもの。)

  • Herokuのログを見るには、Papertrailというアドオンを入れておくと良い。

→ターミナルからもログはみれるが、Papertrailは検索機能がありとても使いやすかった。

→設定からTime zoneを日本時間に変更できる。(デフォルトではUTCで設定されているので、少し見づらい。)

  • 新しい技術(今回でいうとDiscordrbライブラリとHeroku)を使うときは、きちんとドキュメントを読むことが大事であると実感しました。きちんと理解しないまま使用すると、こんなこと間違えるわけない!!!という間違いを平気でしてしまうことがわかりました。

おわりに

最後まで読んでいただき、ありがとうございます。

この問題で1週間くらい悩まされたので、原因がわかったときは本当にスッキリしました! 一緒に調査して頂いた、フィヨルドブートキャンプのメンターの@cafedomancerさんありがとうございました!

また、今回このようにブログ記事にしたのも、 これまたフィヨルドブートキャンプのメンターである、伊藤淳一 (id:JunichiIto) さんにフィヨルドブートキャンプのDiscordサーバー内で自分(@Maeda)の調査方法(問題に対して「仮説」→「検証」を全然行えていなかった)が良くないとご指摘を受けたところから始まりました。(まだよくわかってない箇所がいくつかありますが...) 記事としてまとめるきっかけを頂き本当に感謝しております。

自分のようなことではまらない人が出ないことを祈っています!