Shunshun94 / discord-bcdicebot

BCDice bot for Discord
GNU General Public License v3.0
20 stars 16 forks source link

ボットが応答しなくなる #24

Closed GenKuzumochi closed 2 years ago

GenKuzumochi commented 4 years ago

環境:

常駐は想定環境と異なるかもしれませんが、報告まで。

Linuxサーバー上でdiscord-bcdicebotを常駐させたいのですが、起動して暫く経つとボットが返事をしなくなります。詳細な時間は未計測ですが、一日に何度も発生する程度の頻度です。プロセスを再起動すれば直りますが、何もしなくても数十分後(こちらも条件不明)に突然復活し、まとめて反応があります。そして、またしばらくすると返事をしなくなります。

image

以下がその時のログです(タイムゾーンがずれていますが00:28分頃のものです,)(念の為IDの一部をXXXXにしてあります)。Sent heartbeatは反応しない間も続いています。

(前略)
15:23:34.054 [Timer-3] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sent heartbeat (interval: 41250)
15:24:15.304 [Timer-3] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sent heartbeat (interval: 41250)
15:24:56.555 [Timer-3] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sent heartbeat (interval: 41250)
15:25:37.804 [Timer-3] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sent heartbeat (interval: 41250)
15:26:19.054 [Timer-3] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sent heartbeat (interval: 41250)
15:27:00.304 [Timer-3] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sent heartbeat (interval: 41250)
15:27:41.554 [Timer-3] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sent heartbeat (interval: 41250)
15:28:22.804 [Timer-3] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sent heartbeat (interval: 41250)
Mar 07, 2020 3:28:32 PM org.apache.http.impl.execchain.RetryExec execute
INFO: I/O exception (java.net.SocketException) caught when processing request to {s}->https://www.taruki.com:443: Connection timed out (Read failed)
Mar 07, 2020 3:28:32 PM org.apache.http.impl.execchain.RetryExec execute
INFO: Retrying request to {s}->https://www.taruki.com:443
15:28:32.695 [pool-4-thread-1] DEBUG o.jboss.resteasy.resteasy_jaxrs.i18n - Interceptor Context: org.jboss.resteasy.core.interception.jaxrs.ClientReaderInterceptorContext,  Method : proceed
15:28:32.695 [pool-4-thread-1] DEBUG o.jboss.resteasy.resteasy_jaxrs.i18n - MessageBodyReader: org.jboss.resteasy.spi.ResteasyProviderFactory$SortedKey
15:28:32.695 [pool-4-thread-1] DEBUG o.jboss.resteasy.resteasy_jaxrs.i18n - MessageBodyReader: org.jboss.resteasy.plugins.providers.StringTextStar
15:28:32.695 [pool-4-thread-1] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Updating status (game: bcdice help とチャットに打ち込むとコマンドのヘルプを確認できます, idle: false)
15:28:32.695 [pool-4-thread-1] DEBUG d.b.j.utils.DiscordWebsocketAdapter - {
  "op": 3,
  "d": {
    "game": {
      "name": "bcdice help とチャットに打ち込むとコマンドのヘルプを確認できます",
      "type": 0
    },
    "afk": false,
    "status": "online",
    "since": null
  }
}
15:28:32.737 [pool-4-thread-1] DEBUG o.jboss.resteasy.resteasy_jaxrs.i18n - Interceptor Context: org.jboss.resteasy.core.interception.jaxrs.ClientReaderInterceptorContext,  Method : proceed
15:28:32.737 [pool-4-thread-1] DEBUG o.jboss.resteasy.resteasy_jaxrs.i18n - MessageBodyReader: org.jboss.resteasy.spi.ResteasyProviderFactory$SortedKey
15:28:32.737 [pool-4-thread-1] DEBUG o.jboss.resteasy.resteasy_jaxrs.i18n - MessageBodyReader: org.jboss.resteasy.plugins.providers.StringTextStar
15:28:32.737 [pool-4-thread-1] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Updating status (game: bcdice help とチャットに打ち込むとコマンドのヘルプを確認できます, idle: false)
15:28:32.737 [pool-4-thread-1] DEBUG d.b.j.utils.DiscordWebsocketAdapter - {
  "op": 3,
  "d": {
    "game": {
      "name": "bcdice help とチャットに打ち込むとコマンドのヘルプを確認できます",
      "type": 0
    },
    "afk": false,
    "status": "online",
    "since": null
  }
}
15:28:32.789 [pool-4-thread-1] DEBUG o.jboss.resteasy.resteasy_jaxrs.i18n - Interceptor Context: org.jboss.resteasy.core.interception.jaxrs.ClientReaderInterceptorContext,  Method : proceed
15:28:32.790 [pool-4-thread-1] DEBUG o.jboss.resteasy.resteasy_jaxrs.i18n - MessageBodyReader: org.jboss.resteasy.spi.ResteasyProviderFactory$SortedKey
15:28:32.790 [pool-4-thread-1] DEBUG o.jboss.resteasy.resteasy_jaxrs.i18n - MessageBodyReader: org.jboss.resteasy.plugins.providers.StringTextStar
15:28:32.790 [pool-4-thread-1] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Updating status (game: bcdice help とチャットに打ち込むとコマンドのヘルプを確認できます, idle: false)
15:28:32.790 [pool-4-thread-1] DEBUG d.b.j.utils.DiscordWebsocketAdapter - {
  "op": 3,
  "d": {
    "game": {
      "name": "bcdice help とチャットに打ち込むとコマンドのヘルプを確認できます",
      "type": 0
    },
    "afk": false,
    "status": "online",
    "since": null
  }
}
15:28:32.824 [pool-4-thread-1] DEBUG o.jboss.resteasy.resteasy_jaxrs.i18n - Interceptor Context: org.jboss.resteasy.core.interception.jaxrs.ClientReaderInterceptorContext,  Method : proceed
15:28:32.824 [pool-4-thread-1] DEBUG o.jboss.resteasy.resteasy_jaxrs.i18n - MessageBodyReader: org.jboss.resteasy.spi.ResteasyProviderFactory$SortedKey
15:28:32.824 [pool-4-thread-1] DEBUG o.jboss.resteasy.resteasy_jaxrs.i18n - MessageBodyReader: org.jboss.resteasy.plugins.providers.StringTextStar
15:28:32.824 [pool-4-thread-1] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Updating status (game: bcdice help とチャットに打ち込むとコマンドのヘルプを確認できます, idle: false)
15:28:32.824 [pool-4-thread-1] DEBUG d.b.j.utils.DiscordWebsocketAdapter - {
  "op": 3,
  "d": {
    "game": {
      "name": "bcdice help とチャットに打ち込むとコマンドのヘルプを確認できます",
      "type": 0
    },
    "afk": false,
    "status": "online",
    "since": null
  }
}
15:28:32.824 [pool-2-thread-2] DEBUG d.b.j.entities.impl.ImplChannel - Trying to send message in channel 一般 (id: 6851949719XXXXXXXX) (content: ">くずもち
DiceBot: (2D6) > 3[1,2] > 3", tts: false)
15:28:32.880 [pool-4-thread-1] DEBUG o.jboss.resteasy.resteasy_jaxrs.i18n - Interceptor Context: org.jboss.resteasy.core.interception.jaxrs.ClientReaderInterceptorContext,  Method : proceed
15:28:32.880 [pool-4-thread-1] DEBUG o.jboss.resteasy.resteasy_jaxrs.i18n - MessageBodyReader: org.jboss.resteasy.spi.ResteasyProviderFactory$SortedKey
15:28:32.880 [pool-4-thread-1] DEBUG o.jboss.resteasy.resteasy_jaxrs.i18n - MessageBodyReader: org.jboss.resteasy.plugins.providers.StringTextStar
15:28:32.880 [pool-4-thread-1] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Updating status (game: bcdice help とチャットに打ち込むとコマンドのヘルプを確認できます, idle: false)
(以下略)

また時折Websocketと切断されています。

15:10:22.788 [Timer-0] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sent heartbeat (interval: 41250)
15:10:23.395 [WritingThread] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Websocket closed! Trying to resume connection.
15:10:23.986 [ReadingThread] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sending resume packet
15:10:23.987 [ReadingThread] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Received HELLO packet
15:10:24.151 [ReadingThread] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Received RESUMED packet
15:10:24.152 [Timer-1] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sent heartbeat (interval: 41250)

#

15:24:09.151 [Timer-1] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sent heartbeat (interval: 41250)
15:24:09.310 [WritingThread] INFO  d.b.j.utils.DiscordWebsocketAdapter - Websocket closed with reason null and code 1001 by server!
15:24:09.663 [ReadingThread] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sending resume packet
15:24:09.664 [ReadingThread] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Received HELLO packet
15:24:09.837 [ReadingThread] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Received RESUMED packet
15:24:09.838 [Timer-2] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sent heartbeat (interval: 41250)

他のタイミングではBCDice-APIのサーバー接続のtimeout以外では、以下が一度だけ記録されていました。

15:28:33.107 [pool-4-thread-1] WARN  d.b.j.u.h.m.MessageCreateHandler - Uncaught exception in MessageCreateListener!
java.lang.NullPointerException: null
        at com.hiyoko.discord.bot.BCDice.BCDiceBot$1$1.onMessageCreate(BCDiceBot.java:52) ~[discord-bcdicebot.jar:na]
        at de.btobastian.javacord.utils.handler.message.MessageCreateHandler$1.run(MessageCreateHandler.java:66) ~[discord-bcdicebot.jar:na]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_242]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_242]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_242]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_242]
        at java.lang.Thread.run(Thread.java:748) [na:1.8.0_242]
15:28:33.146 [pool-4-thread-1] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Updating status (game: bcdice help とチャットに打ち込むとコマンドのヘルプを確認できます, idle: false)
15:28:33.146 [pool-4-thread-1] DEBUG d.b.j.utils.DiscordWebsocketAdapter - {
  "op": 3,
  "d": {
    "game": {
      "name": "bcdice help とチャットに打ち込むとコマンドのヘルプを確認できます",
      "type": 0
    },
    "afk": false,
    "status": "online",
    "since": null
  }
}
15:28:33.156 [pool-2-thread-2] DEBUG d.b.j.entities.impl.ImplChannel - Sent message in channel 一般 (id: 6851949719XXXXXXXX) (content: ">くずもち
DiceBot: (2D6) > 3[1,2] > 3", tts: false)
15:29:04.054 [Timer-3] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sent heartbeat (interval: 41250)
15:29:45.304 [Timer-3] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sent heartbeat (interval: 41250)
15:30:26.554 [Timer-3] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sent heartbeat (interval: 41250)
15:31:07.804 [Timer-3] DEBUG d.b.j.utils.DiscordWebsocketAdapter - Sent heartbeat (interval: 41250)
(以下略)
GenKuzumochi commented 4 years ago

v1.11を試してみました。しばらく使っているとなにかチャットするたびに以下のようなエラーがDiscordに出力されます。

[ERROR]RESTEASY004655: Unable to invoke request(https://www.taruki.com/bcdice-api/v1/diceroll?command=2d10&system=DiceBot)

また、反応が悪くなった際のログは以下です。単純に通信が多すぎてBCDice-apiの短期IPブロック等を食らってるだけな気がしてきました。


2020-04-03 16:28:22.396+0000 ERROR org.javacord.core.util.event.EventDispatcherBase Interrupted a a listener thread for くずもち's server,
because it was running over 120 seconds! This was most likely caused by a deadlock or very heavy computation/blocking operations in the listener thread. Make sure to not block listener threads! {shard=0}
16:28:22.397 [Javacord - Central ExecutorService - 3] DEBUG com.hiyoko.discord.bot.BCDice.BCDiceBot - ********** posts: https://discordapp.com/channels/********** /********** /********** 
Failed to request to https://www.taruki.com/bcdice-api/v1/diceroll?command=2d10&system=DiceBot, RESTEASY004655: Unable to invoke request, app will try 5
Failed to request to https://www.taruki.com/bcdice-api/v1/diceroll?command=2d10&system=DiceBot, RESTEASY004655: Unable to invoke request, app will try 4
Failed to request to https://www.taruki.com/bcdice-api/v1/diceroll?command=2d10&system=DiceBot, RESTEASY004655: Unable to invoke request, app will try 3
Failed to request to https://www.taruki.com/bcdice-api/v1/diceroll?command=2d10&system=DiceBot, RESTEASY004655: Unable to invoke request, app will try 2
Failed to request to https://www.taruki.com/bcdice-api/v1/diceroll?command=2d10&system=DiceBot, RESTEASY004655: Unable to invoke request, app will try 1
16:28:24.906 [Javacord - Central ExecutorService - 3] WARN com.hiyoko.discord.bot.BCDice.BCDiceBot - USERID: 538687904457949224 MESSAGE: 2$10
16:28:24.908 [Javacord - Central ExecutorService - 3] WARN com.hiyoko.discord.bot.BCDice.BCDiceBot - Failed to reply to user request
java.io.IOException: RESTEASY004655: Unable to invoke request(https://www.taruki.com/bcdice-api/v1/diceroll?command=2d10&system=DiceBot)
        at com.hiyoko.discord.bot.BCDice.DiceClient.BCDiceClient.getUrl(BCDiceClient.java:58)
        at com.hiyoko.discord.bot.BCDice.DiceClient.BCDiceClient.getUrl(BCDiceClient.java:66)
        at com.hiyoko.discord.bot.BCDice.DiceClient.BCDiceClient.getUrl(BCDiceClient.java:66)
        at com.hiyoko.discord.bot.BCDice.DiceClient.BCDiceClient.getUrl(BCDiceClient.java:66)
        at com.hiyoko.discord.bot.BCDice.DiceClient.BCDiceClient.getUrl(BCDiceClient.java:66)
        at com.hiyoko.discord.bot.BCDice.DiceClient.BCDiceClient.getUrl(BCDiceClient.java:66)
        at com.hiyoko.discord.bot.BCDice.DiceClient.BCDiceClient.getUrl(BCDiceClient.java:91)
        at com.hiyoko.discord.bot.BCDice.DiceClient.BCDiceClient.rollDice(BCDiceClient.java:120)
        at com.hiyoko.discord.bot.BCDice.DiceClient.BCDiceClient.rollDiceWithChannel(BCDiceClient.java:116)
        at com.hiyoko.discord.bot.BCDice.BCDiceCLI.roll(BCDiceCLI.java:124)
        at com.hiyoko.discord.bot.BCDice.BCDiceBot.lambda$null$1(BCDiceBot.java:60)
        at org.javacord.core.util.event.EventDispatcher.lambda$dispatchMessageCreateEvent$95(EventDispatcher.java:3413)
        at org.javacord.core.util.event.EventDispatcherBase.lambda$dispatchEvent$10(EventDispatcherBase.java:197)
        at org.javacord.core.util.event.EventDispatcherBase.lambda$checkRunningListenersAndStartIfPossible$18(EventDispatcherBase.java:265$
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Shunshun94 commented 4 years ago

ありがとうございます。

以下が出ている以上、おっしゃっている通りのように見えます。

16:28:22.397 [Javacord - Central ExecutorService - 3] DEBUG com.hiyoko.discord.bot.BCDice.BCDiceBot - ** posts: https://discordapp.com/channels/** /** /**

ダイスボットの prefixes を使えば絞れそうではあるのですが、
ちょっと難しそうなので考えてみます。
(BCDice のサーバで提案なさっていた方法を少し変えたものが現実的には見えます)

Shunshun94 commented 2 years ago

ダイスボットの prefixes を使えば絞れそうではあるのですが、 ちょっと難しそうなので考えてみます。

これについて 2.5.0 で入ったので閉じます