一个很奇怪的bug，nonebot2卡住 #129

anaivebird · 2020-12-31T16:46:47Z

描述问题：

运行了几周了都正常，刚才突然卡住
console上不动了,我加的log也不增加了
但是bot收到新消息，oicq还会显示新的消息（正常），nonebot2就没反应
OICQ那边没有也显示ws断开，说明还连着

我设置的以下日志卡住后都不动了：
logger.add("critical.log",
encoding="utf-8",
rotation="00:00",
diagnose=False,
level="CRITICAL",
format=default_format)

logger.add("info.log",
encoding="utf-8",
rotation="00:00",
diagnose=False,
level="INFO",
format=default_format)

重新启动nonebot，之前卡住累计的信息会一次性发出，
但过一会儿又卡住了，是什么原因呢。

/home/myuser/.pm2/logs/oicq-out.log last 15 lines:
0|oicq | [2021-01-01T01:08:47.174] [INFO] [BOT:2469785829] - recv from: [Group: xxxxx(657359249), Member: 匿名消息(80000000)] ？
0|oicq | [2021-01-01T01:08:49.896] [INFO] [BOT:2469785829] - recv from: [Group: xxxxx(657359249), Member: 匿名消息(80000000)] 你不是几个小时前发过了吗
0|oicq | [2021-01-01T01:09:22.385] [INFO] [BOT:2469785829] - recv from: [Group: xxxxx(657359249), Member: 匿名消息(80000000)] 噢
0|oicq | [2021-01-01T01:09:31.048] [INFO] [BOT:2469785829] - recv from: [Group: xxxxx(657359249), Member: 匿名消息(80000000)] 我脑瘫
0|oicq | [2021-01-01T01:10:02.100] [INFO] [BOT:2469785829] - recv from: [Group: xxxxx(657359249), Member: 匿名消息(80000000)] 九头驸马有点东西
0|oicq | [2021-01-01T01:11:43.683] [INFO] [BOT:2469785829] - recv from: [Group: xxxxx(657359249), Member: 匿名消息(80000000)] 马上上
0|oicq | [2021-01-01T01:12:43.710] [INFO] [BOT:2469785829] - recv from: [Group: xxxxx(657359249), Member: 匿名消息(80000000)] [CQ:reply,id=Jzeo7QTEtAAAAHGRZK0iDV/uBaEB]？
0|oicq | [2021-01-01T01:13:14.205] [INFO] [BOT:2469785829] - recv from: [Group: xxxxx(657359249), Member: 匿名消息(80000000)] 您是？
0|oicq | [2021-01-01T01:14:25.105] [INFO] [BOT:2469785829] - recv from: [Group: xxxxx(657359249), Member: 匿名消息(80000000)] [CQ:reply,id=Jzeo7QTEtAAAAHGWQVw3ml/uBosB]别管我，我脑瘫
0|oicq | [2021-01-01T01:14:49.301] [INFO] [BOT:2469785829] - recv from: [Group: xxxxx(657359249), Member: 匿名消息(80000000)] 警告，咱们还是接着聊吧
0|oicq | [2021-01-01T01:15:02.429] [INFO] [BOT:2469785829] - recv from: [Group: xxxxx(657359249), Member: 匿名消息(80000000)] 鼍龙怪有点东西
0|oicq | [2021-01-01T01:15:09.606] [INFO] [BOT:2469785829] - recv from: [Group: xxxxx(657359249), Member: 匿名消息(80000000)] bot好像关了
0|oicq | [2021-01-01T01:16:28.344] [INFO] [BOT:2469785829] - recv from: [Group: xxxxx(657359249), Member: 匿名消息(80000000)] 要不xdm众筹下把bot放服务器上跑？

看oicq日志最后一条的时间是最新的，而nonebot2就卡在卡住的时间之后就不动了

如何复现？
之前好的，现在就这样了，触发条件不明

环境信息：

OS: [Centos7]
Python Version: [3.8]
Nonebot Version: [2.0.0]

anaivebird · 2020-12-31T17:58:09Z

找到错误的日志了：1|nonebot2 | ESC[33mESC[1mTraceback (most recent call last):ESC[0m
1|nonebot2 | File "", line 1, in
1|nonebot2 | File "/usr/local/python3/lib/python3.8/multiprocessing/spawn.py", line 116, in spawn_main
1|nonebot2 | exitcode = _main(fd, parent_sentinel)
1|nonebot2 | File "/usr/local/python3/lib/python3.8/multiprocessing/spawn.py", line 129, in _main
1|nonebot2 | return self._bootstrap(parent_sentinel)
1|nonebot2 | File "/usr/local/python3/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
1|nonebot2 | self.run()
1|nonebot2 | File "/usr/local/python3/lib/python3.8/multiprocessing/process.py", line 108, in run
1|nonebot2 | self.target(*self.args, **self.kwargs)
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/uvicorn/subprocess.py", line 62, in subprocess_started
1|nonebot2 | target(sockets=sockets)
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/uvicorn/main.py", line 390, in run
1|nonebot2 | loop.run_until_complete(self.serve(sockets=sockets))
1|nonebot2 | > File "/home/anelderly/.local/lib/python3.8/site-packages/nonebot/message.py", line 164, in run_matcher
1|nonebot2 | await matcher.run(bot, event, state)
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/nonebot/matcher.py", line 419, in run
1|nonebot2 | await handler(bot, event, self.state)
1|nonebot2 | File "ESC[32mmynbrobot/plugins/shutup/ESC[0mESC[32mESC[1m__init.pyESC[0m", line ESC[33m264ESC[0m, in ESC[35mhandle_first_receiveESC[0m
1|nonebot2 | ESC[35mESC[1mawaitESC[0m ESC[1mhurtHPandBanIfNeededESC[0mESC[1m(ESC[0mESC[1mbotESC[0mESC[1m,ESC[0m ESC[1msenderIdESC[0mESC[1m,ESC[0m ESC[34mESC[1m2ESC[0mESC[1m,ESC[0m ESC[36m'为实名、无效或bot启动后未说过话的用户'ESC[0mESC[1m)ESC[0m
1|nonebot2 | File "ESC[32mmynbrobot/plugins/shutup/ESC[0mESC[32mESC[1m__init.pyESC[0m", line ESC[33m115ESC[0m, in ESC[35mhurtHPandBanIfNeededESC[0m
1|nonebot2 | ESC[35mESC[1mawaitESC[0m ESC[1mbotESC[0mESC[35mESC[1m.ESC[0mESC[1msetGroupAnonymousBanESC[0mESC[1m(ESC[0mESC[1mgroup_idESC[0mESC[35mESC[1m=ESC[0mESC[1mshutup_group_idESC[0mESC[1m,ESC[0m ESC[1mflagESC[0mESC[35mESC[1m=ESC[0mESC[1mbannedUserFlagESC[0mESC[1m,ESC[0m ESC[1mdurationESC[0mESC[35mESC[1m=ESC[0mESC[1mban_durationESC[0mESC[1m)ESC[0m
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/nonebot/adapters/cqhttp/bot.py", line 342, in call_api
1|nonebot2 | await self.websocket.send({
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/nonebot/drivers/fastapi.py", line 256, in send
1|nonebot2 | await self.websocket.send({"type": "websocket.send", "text": text})
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/starlette/websockets.py", line 68, in send
1|nonebot2 | await self._send(message)
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 225, in asgi_send
1|nonebot2 | raise RuntimeError(msg % message_type)

yanyongyu · 2021-01-01T03:33:42Z

注意不要在handler中进行过于耗时同步操作，甚至阻塞或者死锁。耗时操作应使用异步或后台执行。

yanyongyu · 2021-01-01T03:36:04Z

|nonebot2 | raise RuntimeError(msg % message_type)

这里的报错是什么

bytemain · 2021-01-01T15:41:01Z

帮你处理一下

sed "s/ESC\[[0-9;]*m//g" 1.txt

结果：

1|nonebot2 | File "", line 1, in
1|nonebot2 | File "/usr/local/python3/lib/python3.8/multiprocessing/spawn.py", line 116, in spawn_main
1|nonebot2 | exitcode = _main(fd, parent_sentinel)
1|nonebot2 | File "/usr/local/python3/lib/python3.8/multiprocessing/spawn.py", line 129, in _main
1|nonebot2 | return self._bootstrap(parent_sentinel)
1|nonebot2 | File "/usr/local/python3/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
1|nonebot2 | self.run()
1|nonebot2 | File "/usr/local/python3/lib/python3.8/multiprocessing/process.py", line 108, in run
1|nonebot2 | self.target(*self.args, **self.kwargs)
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/uvicorn/subprocess.py", line 62, in subprocess_started
1|nonebot2 | target(sockets=sockets)
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/uvicorn/main.py", line 390, in run
1|nonebot2 | loop.run_until_complete(self.serve(sockets=sockets))
1|nonebot2 | > File "/home/anelderly/.local/lib/python3.8/site-packages/nonebot/message.py", line 164, in run_matcher
1|nonebot2 | await matcher.run(bot, event, state)
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/nonebot/matcher.py", line 419, in run
1|nonebot2 | await handler(bot, event, self.state)
1|nonebot2 | File "mynbrobot/plugins/shutup/__init.py", line 264, in handle_first_receive
1|nonebot2 | await hurtHPandBanIfNeeded(bot, senderId, 2, '为实名、无效或bot启动后未说过话的用户')
1|nonebot2 | File "mynbrobot/plugins/shutup/__init.py", line 115, in hurtHPandBanIfNeeded
1|nonebot2 | await bot.setGroupAnonymousBan(group_id=shutup_group_id, flag=bannedUserFlag, duration=ban_duration)
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/nonebot/adapters/cqhttp/bot.py", line 342, in call_api
1|nonebot2 | await self.websocket.send({
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/nonebot/drivers/fastapi.py", line 256, in send
1|nonebot2 | await self.websocket.send({"type": "websocket.send", "text": text})
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/starlette/websockets.py", line 68, in send
1|nonebot2 | await self._send(message)
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 225, in asgi_send
1|nonebot2 | raise RuntimeError(msg % message_type)

yanyongyu · 2021-01-02T04:30:28Z

await bot.setGroupAnonymousBan(group_id=shutup_group_id, flag=bannedUserFlag, duration=ban_duration)

cqhttp 似乎并没有这个驼峰API，只有蛇形命名的API

bytemain · 2021-01-02T06:46:54Z

pip list 给一下安装的 uvicorn 版本

这个报错看起来是从 uvicorn 里报出来的

anaivebird · 2021-01-02T12:25:51Z

pip list 给一下安装的 uvicorn 版本

这个报错看起来是从 uvicorn 里报出来的

uvicorn 0.11.8

anaivebird · 2021-01-02T12:26:29Z

await bot.setGroupAnonymousBan(group_id=shutup_group_id, flag=bannedUserFlag, duration=ban_duration)

cqhttp 似乎并没有这个驼峰API，只有蛇形命名的API

我调用的是OICQ的，它是驼峰的，是可以调用成功的，一天调用几千次都没问题，就是最近经常nonebot2卡住

bytemain · 2021-01-02T12:33:18Z

没有更多日志以及其他的 issue 反馈，需要更多信息

翻了一下 uvicorn 的更新记录，没发现有类似的问题。
不过建议更新下 uvicorn 的版本试试吧

bytemain · 2021-01-02T12:34:17Z

之前的报错也没贴全，希望能能多贴一点

anaivebird · 2021-01-02T12:36:42Z

之前的报错也没贴全，希望能能多贴一点

现在启动不了了，一直是这个问题，想问下我之前发的这个报错日志是从哪里看的
现在忘了从哪里找的，控制台输出卡死之后就没了，没有报错

1|nonebot2 | File "", line 1, in
1|nonebot2 | File "/usr/local/python3/lib/python3.8/multiprocessing/spawn.py", line 116, in spawn_main
1|nonebot2 | exitcode = _main(fd, parent_sentinel)
1|nonebot2 | File "/usr/local/python3/lib/python3.8/multiprocessing/spawn.py", line 129, in _main
1|nonebot2 | return self._bootstrap(parent_sentinel)
1|nonebot2 | File "/usr/local/python3/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
1|nonebot2 | self.run()
1|nonebot2 | File "/usr/local/python3/lib/python3.8/multiprocessing/process.py", line 108, in run
1|nonebot2 | self.target(*self.args, **self.kwargs)
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/uvicorn/subprocess.py", line 62, in subprocess_started
1|nonebot2 | target(sockets=sockets)
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/uvicorn/main.py", line 390, in run
1|nonebot2 | loop.run_until_complete(self.serve(sockets=sockets))
1|nonebot2 | > File "/home/anelderly/.local/lib/python3.8/site-packages/nonebot/message.py", line 164, in run_matcher
1|nonebot2 | await matcher.run(bot, event, state)
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/nonebot/matcher.py", line 419, in run
1|nonebot2 | await handler(bot, event, self.state)
1|nonebot2 | File "mynbrobot/plugins/shutup/__init.py", line 264, in handle_first_receive
1|nonebot2 | await hurtHPandBanIfNeeded(bot, senderId, 2, '为实名、无效或bot启动后未说过话的用户')
1|nonebot2 | File "mynbrobot/plugins/shutup/__init.py", line 115, in hurtHPandBanIfNeeded
1|nonebot2 | await bot.setGroupAnonymousBan(group_id=shutup_group_id, flag=bannedUserFlag, duration=ban_duration)
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/nonebot/adapters/cqhttp/bot.py", line 342, in call_api
1|nonebot2 | await self.websocket.send({
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/nonebot/drivers/fastapi.py", line 256, in send
1|nonebot2 | await self.websocket.send({"type": "websocket.send", "text": text})
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/starlette/websockets.py", line 68, in send
1|nonebot2 | await self._send(message)
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 225, in asgi_send
1|nonebot2 | raise RuntimeError(msg % message_type)

bytemain · 2021-01-02T12:40:11Z

是你说的这个文件吗？

anaivebird · 2021-01-02T12:40:20Z

谢谢大家了，没想到这么多人回复，我先升级uvicorn了，看看这两天会不会有问题

anaivebird · 2021-01-02T12:40:51Z

这个nonebot2-out.log就是运行nonebot2的shell上的输出，这里面bot卡住之后就没显示了，所以看不到报错

那天我猜就是在nonebot2-out.log上看到的这些报错，但这个是偶发的现象，我这里遇到的卡住，大多数都没有报错，直接卡住了，nonebot2-out.log的最后一行是正常的消息
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/starlette/websockets.py", line 68, in send
1|nonebot2 | await self._send(message)
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 225, in asgi_send
1|nonebot2 | raise RuntimeError(msg % message_type)

anaivebird · 2021-01-06T07:00:25Z

升级最新版uvicorn还是会卡住

yanyongyu · 2021-01-06T07:17:13Z

1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/starlette/websockets.py", line 68, in send
1|nonebot2 | await self._send(message)
1|nonebot2 | File "/home/anelderly/.local/lib/python3.8/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 225, in asgi_send
1|nonebot2 | raise RuntimeError(msg % message_type)

这里报错的信息是什么，应该在traceback上方

RuntimeError(msg % message_type)

anaivebird · 2021-01-06T07:27:45Z

我现在差不多知道了，pm2运行的时候，log里面不会显示python的一些runtime error
我的pm2配置如下，原因不明
{
name : "nonebot2",
cwd : "/home/anelderly/botStable/mynbrobot/",
script : "/home/anelderly/botStable/mynbrobot/bot.py",
interpreter: "python3",
}

anaivebird · 2021-01-06T07:59:18Z

不知道在handle_first_receive函数中，调用requests.get会不会导致这个问题，我怀疑是这个导致的，现在换成了http3.AsyncClient()

anaivebird · 2021-01-06T08:06:50Z

225, in asgi_send

RuntimeError Unexpected ASGI message 'websocket.send', after sending 'websocket.close'

anaivebird · 2021-01-09T18:00:02Z

这三天没出问题了，在handle_first_receive函数中，最好不要调用requests.get，我怀疑是这个导致的，现在换成了http3.AsyncClient()几天没卡住了

yanyongyu · 2021-01-10T02:32:20Z

那就先close了

bytemain · 2021-01-10T04:02:56Z

也许可以把这个issue 作为备注加到文档里？ @yanyongyu

yanyongyu · 2021-01-10T04:14:26Z

也许可以把这个issue 作为备注加到文档里？ @yanyongyu

文档里已经有提示了

anaivebird added the bug Something isn't working label Dec 31, 2020

yanyongyu removed the bug Something isn't working label Jan 2, 2021

yanyongyu closed this as completed Jan 10, 2021

mnixry added the question Further information is requested label Jan 28, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

一个很奇怪的bug，nonebot2卡住 #129

一个很奇怪的bug，nonebot2卡住 #129

anaivebird commented Dec 31, 2020 •

edited

anaivebird commented Dec 31, 2020 •

edited

yanyongyu commented Jan 1, 2021

yanyongyu commented Jan 1, 2021

bytemain commented Jan 1, 2021

yanyongyu commented Jan 2, 2021 •

edited

bytemain commented Jan 2, 2021

anaivebird commented Jan 2, 2021

anaivebird commented Jan 2, 2021

bytemain commented Jan 2, 2021

bytemain commented Jan 2, 2021

anaivebird commented Jan 2, 2021

bytemain commented Jan 2, 2021

anaivebird commented Jan 2, 2021

anaivebird commented Jan 2, 2021 •

edited

anaivebird commented Jan 6, 2021

yanyongyu commented Jan 6, 2021

anaivebird commented Jan 6, 2021

anaivebird commented Jan 6, 2021

anaivebird commented Jan 6, 2021

anaivebird commented Jan 9, 2021

yanyongyu commented Jan 10, 2021

bytemain commented Jan 10, 2021

yanyongyu commented Jan 10, 2021

一个很奇怪的bug，nonebot2卡住 #129

一个很奇怪的bug，nonebot2卡住 #129

Comments

anaivebird commented Dec 31, 2020 • edited

anaivebird commented Dec 31, 2020 • edited

yanyongyu commented Jan 1, 2021

yanyongyu commented Jan 1, 2021

bytemain commented Jan 1, 2021

yanyongyu commented Jan 2, 2021 • edited

bytemain commented Jan 2, 2021

anaivebird commented Jan 2, 2021

anaivebird commented Jan 2, 2021

bytemain commented Jan 2, 2021

bytemain commented Jan 2, 2021

anaivebird commented Jan 2, 2021

bytemain commented Jan 2, 2021

anaivebird commented Jan 2, 2021

anaivebird commented Jan 2, 2021 • edited

anaivebird commented Jan 6, 2021

yanyongyu commented Jan 6, 2021

anaivebird commented Jan 6, 2021

anaivebird commented Jan 6, 2021

anaivebird commented Jan 6, 2021

anaivebird commented Jan 9, 2021

yanyongyu commented Jan 10, 2021

bytemain commented Jan 10, 2021

yanyongyu commented Jan 10, 2021

anaivebird commented Dec 31, 2020 •

edited

anaivebird commented Dec 31, 2020 •

edited

yanyongyu commented Jan 2, 2021 •

edited

anaivebird commented Jan 2, 2021 •

edited