Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

启动MiraiCQ之后一段时间,会出现cpu占用率较高且日志空白无响应的问题 #18

Closed
byx2020 opened this issue Jul 12, 2022 · 10 comments
Labels
bug Something isn't working

Comments

@byx2020
Copy link

byx2020 commented Jul 12, 2022

此问题出现时的表现形式为,MiraiCQ不会收到和响应任何消息(go-cqhttp是一切正常的),打开MiraiCQ的详细设置界面,没有任何日志(如图三所示),界面一片空白(正常运行时会有很多日志),再打开任务管理器,可以看到MiraiCQ的前后台程序的cpu占用和内存占用都存在比较明显的异常(如图一和图二所示),通过手动重启MiraiCQ可以在短时间内恢复正常,但一般在几分钟后就又会出现此问题。
需要说明的一点是,此问题的具体出现时间应该是在最近三天内才开始出现的,之前我已经正常使用了MiraiCQ(2.3.8)将近一个月左右,都没有遇到过这个问题。
在问题发生后,我尝试通过将插件依次卸载后再启动MiraiCQ的方式来定位问题原因,最后发现将任何一个插件单独卸载都不会影响到问题的出现(总共就两个插件),所以应该不是插件的问题。
于是我尝试删掉MiraiCQ和go-cqhttp的所有数据和缓存文件,再重新启动MiraiCQ和go-cqhttp,但在运行一段时间后,问题还是出现了。
然后我看到MiraiCQ的日志都是空白,开始怀疑是不是由于MiraiCQ和go-cqhttp之间的通信连接断开导致的,于是去把go-cqhttp配置项里面的心跳频率从默认的1秒5次改成了1秒50次(如图四所示),改了之后,好像确实有了一点点效果,原来在启动MiraiCQ几分钟后就会出现卡死日志空白的问题,现在需要几十分钟才会出现了,但是问题还是没有得到解决。
一时间我也想不到其他解决问题的思路了,所以不得不再来打扰一下开发者大佬,有没有什么解决这个问题的办法或方案,可以让我去尝试一下。

以下为插件运行环境信息:
服务器配置:4C4G
操作系统:Windows Server 2012 R2 DataCenter 64bitCN
go-cqhttp版本:1.0.0-rc3
MiraiCQ版本:2.3.8
其他说明:如果大佬需要更多信息或协助,也可以让我进行提供

图片说明:由于最近qq经常封号,所以我给机器人准备了两个号,各自运行一部分的功能,降低由于发消息太多被qq屏蔽的概率,因此是同时运行的两个MiraiCQ,机器人一个号一个MiraiCQ,本次问题是两个MiraiCQ同时出现的。
image
image
image
image

@super1207
Copy link
Owner

感觉很奇怪...那个心跳理论上没用,建议关闭。
按如下方法测试下:
1:不要使用那个界面日志。
2:试试两个MiraiCQ是不是总是同时卡死。
3:看看卡死前收到了什么消息,在log文件夹里面应该可以看到。
4:开一个无插件的MiraiCQ做对照。
5:试试action里面最新的版本https://github.com/super1207/MiraiCQ/actions

@byx2020
Copy link
Author

byx2020 commented Jul 13, 2022

感觉很奇怪...那个心跳理论上没用,建议关闭。 按如下方法测试下: 1:不要使用那个界面日志。 2:试试两个MiraiCQ是不是总是同时卡死。 3:看看卡死前收到了什么消息,在log文件夹里面应该可以看到。 4:开一个无插件的MiraiCQ做对照。 5:试试action里面最新的版本https://github.com/super1207/MiraiCQ/actions

@super1207 好的,在收到你这条回复之后,我将两个MiraiCQ均替换为了action里面最新的版本,同时清空了log文件夹,然后启动了两个MiraiCQ并运行,之后过了大概十分钟左右,两个MiraiCQ同时卡死(基本上每次两个MiraiCQ都是同时卡死的),问题复现,然后我将两个MiraiCQ关闭,分别压缩了两个MiraiCQ的log文件夹,将其放到了附件里面,我自己看不太懂日志,可能需要麻烦大佬你这边帮忙看一下,关于你说的第4点,我会进行测试对照的,不过这可能需要一些时间,晚一点我会再反馈结果的。
log-0.zip
log-4.zip

编辑补充一下,刚刚我按大佬的建议把心跳关闭之后,发现问题的出现频率明显提升了很多,基本上是启动MiraiCQ后几分钟就卡死了,然后我测试了一下一次只启动一个MiraiCQ,问题仍然可以复现,所以应该也可以排除两个MiraiCQ互相干扰导致出现问题的因素了
image

@byx2020
Copy link
Author

byx2020 commented Jul 15, 2022

感觉很奇怪...那个心跳理论上没用,建议关闭。 按如下方法测试下: 1:不要使用那个界面日志。 2:试试两个MiraiCQ是不是总是同时卡死。 3:看看卡死前收到了什么消息,在log文件夹里面应该可以看到。 4:开一个无插件的MiraiCQ做对照。 5:试试action里面最新的版本https://github.com/super1207/MiraiCQ/actions

@super1207 后续测试结果反馈
把心跳关闭之后,我新建了一个文件夹,开了一个无插件的action最新版无插件MiraiCQ进行对照实验,不知道是不是巧合,在我启动无插件的MiraiCQ之后,之前两个很容易出问题的MiraiCQ感觉稳定了许多,不过过了十几个小时后,三个MiraiCQ(包括无插件的对照组)还是同时出现了cpu占用率上升且卡死的问题。
关于cpu占用率上升且卡死出现的规律,我稍微总结了一下:

  1. 如果有多个MiraiCQ在同时运行,那么根据目前观测到的结果,卡死这个问题总是在所有运行中的MiraiCQ上同时出现的。
  2. 但这并不意味着只运行单个MiraiCQ就不会出现问题,测试过单个MiraiCQ运行较长时间也会出现问题。
  3. 没有安装插件的MiraiCQ和安装了插件的MiraiCQ同时运行,问题仍然会同时出现,不知道是通过什么途径传导,导致无插件的MiraiCQ也会卡死。

@super1207
Copy link
Owner

@byx2020 好奇怪...我这边完全没法复现(一台win11的笔记本)
再做一个测试,开两个MiraiCQ,连不同的gocq(最好两个qq号的群不要有交集,如何需要的话,我可以提供qq号),看是不是同时卡住。

@byx2020
Copy link
Author

byx2020 commented Jul 15, 2022

@byx2020 好奇怪...我这边完全没法复现(一台win11的笔记本) 再做一个测试,开两个MiraiCQ,连不同的gocq(最好两个qq号的群不要有交集,如何需要的话,我可以提供qq号),看是不是同时卡住。

@super1207 好的,我会单开一个新的gocq+MiraiCQ并使用新qq来测试的,晚一点给你反馈结果。

我用的是腾讯云服务器,实际上这个问题我这边也是在这几天才突然出现,之前都很正常,印象中最近这段时间也没有做什么特别的操作,所以才一直找不到原因。
image

@byx2020
Copy link
Author

byx2020 commented Jul 16, 2022

@byx2020 好奇怪...我这边完全没法复现(一台win11的笔记本) 再做一个测试,开两个MiraiCQ,连不同的gocq(最好两个qq号的群不要有交集,如何需要的话,我可以提供qq号),看是不是同时卡住。

@super1207 出结果了,看起来好像真的和机器人接收到的消息有关,简单说明一下下图

  1. MiraiCQ0、MiraiCQ4安装了插件,MiraiCQ3、MiraiCQ5没有安装任何插件。
  2. MiraiCQ0、MiraiCQ3、MiraiCQ4分别连接的是三个不同的gcq,即不同的qq。
  3. 其中MiraiCQ0、MiraiCQ4、MiraiCQ5连接的qq加的群基本都是一样的,而MiraiCQ3加的群基本不与其他任何一个MiraiCQ相同。

将这四个MiraiCQ同时运行一段时间后,群相同的MiraiCQ0、MiraiCQ4、MiraiCQ5同时出现了问题,而群不同的MiraiCQ3没有受到影响,仍然可以正常运行。

image

如果有进一步的测试方案,可以提出让我这边继续进行。

并附上在本次实验中未安装任何插件的MiraiCQ5的完整日志文件(MiraiCQ0、MiraiCQ4和MiraiCQ5的日志基本相同)。
main_daily_2022-07-16.txt
其中MiraiCQ5在卡死之前最后收到的最后三条消息为

[2022-07-16 15:36:23.487] [MiraiLog] [debug] [Center]:收到的消息:{"anonymous":null,"font":0,"group_id":1093094655,"message":[{"data":{"text":"?"},"type":"text"}],"message_id":-2141255263,"message_seq":1062848,"message_type":"group","post_type":"message","raw_message":"?","self_id":2709800974,"sender":{"age":0,"area":"","card":"","level":"","nickname":"金馆长","role":"member","sex":"unknown","title":"小丑巴伯","user_id":2134234676},"sub_type":"normal","time":1657956989,"user_id":2134234676}

[2022-07-16 15:36:23.963] [MiraiLog] [debug] [Center]:收到的消息:{"anonymous":null,"font":0,"group_id":590284615,"message":[{"data":{"text":"就是那个"},"type":"text"}],"message_id":-1755087382,"message_seq":601677,"message_type":"group","post_type":"message","raw_message":"就是那个","self_id":2709800974,"sender":{"age":0,"area":"","card":"永远的爱莉希雅","level":"","nickname":"??????????????????","role":"member","sex":"unknown","title":"","user_id":2598865133},"sub_type":"normal","time":1657956990,"user_id":2598865133}

[2022-07-16 15:36:24.880] [MiraiLog] [debug] [Center]:收到的消息:{"anonymous":null,"font":0,"group_id":671446182,"message":[{"data":{"text":"[CQ:emoji,id=128020]QQ:3020294538\n[CQ:emoji,id=128052]情侣/伴侣:无\n[CQ:emoji,id=128054]所在群号:671446182\n[CQ:emoji,id=128059]所在群名:<$?āD\u000E>金庸群侠传x交\n[CQ:emoji,id=128038]钱包余额:1001714849\n[CQ:emoji,id=128055]银行余额:0\n[CQ:emoji,id=128048]当前魅力:0\n[CQ:emoji,id=128053]累计签到:1次\n[CQ:emoji,id=128015]获得成就:无\n[CQ:emoji,id=128027]上次签到时间:2022-07-14"},"type":"text"}],"message_id":1356868282,"message_seq":110840,"message_type":"group","post_type":"message","raw_message":"[CQ:emoji,id=128020]QQ:3020294538\n[CQ:emoji,id=128052]情侣/伴侣:无\n[CQ:emoji,id=128054]所在群号:671446182\n[CQ:emoji,id=128059]所在群名:<$?āD\u000E>金庸群侠传x交\n[CQ:emoji,id=128038]钱包余额:1001714849\n[CQ:emoji,id=128055]银行余额:0\n[CQ:emoji,id=128048]当前魅力:0\n[CQ:emoji,id=128053]累计签到:1次\n[CQ:emoji,id=128015]获得成就:无\n[CQ:emoji,id=128027]上次签到时间:2022-07-14","self_id":2709800974,"sender":{"age":0,"area":"","card":"","level":"","nickname":"知命","role":"admin","sex":"unknown","title":"","user_id":702415372},"sub_type":"normal","time":1657956990,"user_id":702415372}

@super1207
Copy link
Owner

MiraiCQ的自身的Log不够详细,没法找出卡住的原因。用这个工具记录下MiraiCQ卡住前后的log
ob_log_helper.zip

@byx2020
Copy link
Author

byx2020 commented Jul 16, 2022

MiraiCQ的自身的Log不够详细,没法找出卡住的原因。用这个工具记录下MiraiCQ卡住前后的log ob_log_helper.zip

@super1207 行,已经挂着了

@super1207 super1207 added the bug Something isn't working label Jul 16, 2022
@super1207
Copy link
Owner

问题原因已经找到,原因是收到了含有'\0'的utf8字符串,导致MiraiCQ解析出错。
最新的action里面有已经规避这个bug的构建:https://github.com/super1207/MiraiCQ/actions
下个版本正式修复。

@super1207
Copy link
Owner

2.3.9 已修复

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

2 participants