koishijs / koishi

Cross-platform chatbot framework made with love
https://koishi.chat
MIT License
4.5k stars 247 forks source link

Bug: 后台 SQL 指令报错,无实际影响 #667

Closed H4M5TER closed 1 year ago

H4M5TER commented 2 years ago

Describe the bug

as is

Steps to reproduce

暂无

Expected behavior

Screenshots

[D] message [@Dave] Dave: .rd
[W] sqlite SQL > INSERT INTO `stats_daily` (`command`,`dialogue`,`botSend`,`botReceive`,`group`,`time`) VALUES ('{"roll":1}', '{}', '{}', '{"sandbox:sandbox":1}', '{}', 1651680000000)
roll triggered
[W] app SqliteError: UNIQUE constraint failed: stats_daily.time
        at SQLiteDriver._SQLiteDriver_exec (D:\Repositories\bot\node_modules\.pnpm\@cosmotype+driver-sqlite@1.0.6\node_modules\@cosmotype\driver-sqlite\lib\index.js:234:52)
        at SQLiteDriver._SQLiteDriver_create (D:\Repositories\bot\node_modules\.pnpm\@cosmotype+driver-sqlite@1.0.6\node_modules\@cosmotype\driver-sqlite\lib\index.js:253:91)
        at SQLiteDriver.upsert (D:\Repositories\bot\node_modules\.pnpm\@cosmotype+driver-sqlite@1.0.6\node_modules\@cosmotype\driver-sqlite\lib\index.js:225:98)
        at runMicrotasks (<anonymous>)
        at processTicksAndRejections (node:internal/process/task_queues:96:5)
        at DatabaseService.upsert (D:\Repositories\bot\node_modules\.pnpm\cosmotype@1.0.9\node_modules\cosmotype\src\driver.ts:158:5)
        at _StatisticsProvider._uploadDaily (D:\Repositories\bot\node_modules\.pnpm\@koishijs+plugin-status@5.3.6_thq7p7x4rcon2kqiwzn7fzmj6e\node_modules\@koishijs\plugin-status\src\stats.ts:155:5)
        at async Promise.all (index 0)
        at _StatisticsProvider.upload (D:\Repositories\bot\node_modules\.pnpm\@koishijs+plugin-status@5.3.6_thq7p7x4rcon2kqiwzn7fzmj6e\node_modules\@koishijs\plugin-status\src\stats.ts:205:7)
[I] app terminated by SIGINT
[W] sqlite SQL > INSERT INTO `stats_daily` (`command`,`dialogue`,`botSend`,`botReceive`,`group`,`time`) VALUES ('{"roll":9}', '{}', '{}', '{"sandbox:sandbox":9}', '{}', 1651680000000)
[W] app SqliteError: UNIQUE constraint failed: stats_daily.time
        at SQLiteDriver._SQLiteDriver_exec (D:\Repositories\bot\node_modules\.pnpm\@cosmotype+driver-sqlite@1.0.6\node_modules\@cosmotype\driver-sqlite\lib\index.js:234:52)
        at SQLiteDriver._SQLiteDriver_create (D:\Repositories\bot\node_modules\.pnpm\@cosmotype+driver-sqlite@1.0.6\node_modules\@cosmotype\driver-sqlite\lib\index.js:253:91)
        at SQLiteDriver.upsert (D:\Repositories\bot\node_modules\.pnpm\@cosmotype+driver-sqlite@1.0.6\node_modules\@cosmotype\driver-sqlite\lib\index.js:225:98)
        at runMicrotasks (<anonymous>)
        at processTicksAndRejections (node:internal/process/task_queues:96:5)
        at DatabaseService.upsert (D:\Repositories\bot\node_modules\.pnpm\cosmotype@1.0.9\node_modules\cosmotype\src\driver.ts:158:5)
        at _StatisticsProvider._uploadDaily (D:\Repositories\bot\node_modules\.pnpm\@koishijs+plugin-status@5.3.6_thq7p7x4rcon2kqiwzn7fzmj6e\node_modules\@koishijs\plugin-status\src\stats.ts:155:5)
        at async Promise.all (index 0)
        at _StatisticsProvider.upload (D:\Repositories\bot\node_modules\.pnpm\@koishijs+plugin-status@5.3.6_thq7p7x4rcon2kqiwzn7fzmj6e\node_modules\@koishijs\plugin-status\src\stats.ts:205:7)
        at async Promise.all (index 1)

Versions

win10 node16

dependencies:
@koishijs/cli 4.6.1                      @koishijs/plugin-database-sqlite 1.2.2   @koishijs/plugin-sandbox 1.1.0           koishi-plugin-duplicate-checker 1.1.1
@koishijs/plugin-adapter-discord 2.0.8   @koishijs/plugin-dataview 1.2.4          @koishijs/plugin-schedule 4.2.0          koishi-plugin-emojimix 1.0.2
@koishijs/plugin-adapter-onebot 4.2.1    @koishijs/plugin-feedback 1.1.0          @koishijs/plugin-status 5.3.6            koishi-plugin-hitokoto 2.1.1
@koishijs/plugin-adapter-telegram 2.2.3  @koishijs/plugin-insight 1.3.0           @koishijs/plugin-teach 3.2.0             koishi-plugin-image-search 4.0.6
@koishijs/plugin-broadcast 1.1.0         @koishijs/plugin-logger 1.2.2            @koishijs/plugin-verifier 1.0.2          koishi-plugin-influxdb 1.1.0
@koishijs/plugin-callme 1.1.0            @koishijs/plugin-manager 1.7.3           koishi 4.6.1                             koishi-plugin-music 2.0.2
@koishijs/plugin-chat 1.3.0              @koishijs/plugin-recall 1.1.0            koishi-plugin-changelog 1.1.4            koishi-plugin-qrcode 2.1.0
@koishijs/plugin-console 3.2.8           @koishijs/plugin-repeater 1.0.1          koishi-plugin-dice link:plugins/dice     koishi-plugin-youdao 2.0.1

我尽量在下次复现之前清理一下插件

Additional context

No response

H4M5TER commented 2 years ago

我翻了一下日志,这个问题(stats_daily)基本就是退出稳定触发,发消息偶尔触发 稍微再贴一点 今日:

[I] app terminated by SIGINT
[W] sqlite SQL > INSERT INTO `stats_daily` (`command`,`dialogue`,`botSend`,`botReceive`,`group`,`time`) VALUES ('{"roll":2}', '{}', '{}', '{"sandbox:sandbox":2}', '{}', 1651852800000)
[W] app SqliteError: UNIQUE constraint failed: stats_daily.time
        at SQLiteDriver._SQLiteDriver_exec (D:\Repositories\bot\node_modules\.pnpm\@cosmotype+driver-sqlite@1.0.6\node_modules\@cosmotype\driver-sqlite\lib\index.js:234:52)
        at SQLiteDriver._SQLiteDriver_create (D:\Repositories\bot\node_modules\.pnpm\@cosmotype+driver-sqlite@1.0.6\node_modules\@cosmotype\driver-sqlite\lib\index.js:253:91)
        at SQLiteDriver.upsert (D:\Repositories\bot\node_modules\.pnpm\@cosmotype+driver-sqlite@1.0.6\node_modules\@cosmotype\driver-sqlite\lib\index.js:225:98)
        at runMicrotasks (<anonymous>)
        at processTicksAndRejections (node:internal/process/task_queues:96:5)
        at DatabaseService.upsert (D:\Repositories\bot\node_modules\.pnpm\cosmotype@1.0.9\node_modules\cosmotype\src\driver.ts:158:5)
        at _StatisticsProvider._uploadDaily (D:\Repositories\bot\node_modules\.pnpm\@koishijs+plugin-status@5.3.6_ziv5zvceh4ouatmezgjbieoeae\node_modules\@koishijs\plugin-status\src\stats.ts:155:5)
        at async Promise.all (index 0)
        at _StatisticsProvider.upload (D:\Repositories\bot\node_modules\.pnpm\@koishijs+plugin-status@5.3.6_ziv5zvceh4ouatmezgjbieoeae\node_modules\@koishijs\plugin-status\src\stats.ts:205:7)
        at async Promise.all (index 1)
终止批处理操作吗(Y/N)?

这个是刨出来之前的日志,当时还没 cosmotype

2022-04-27 20:15:58 [W] sqlite SQL > INSERT INTO `stats_daily` (`command`,`dialogue`,`botSend`,`botReceive`,`group`,`time`) VALUES ('{"roll":6}', '{}', '{"discord:censor":5}', '{"discord:censor":11}', '{"discord:censor":5}', 1650988800000)
2022-04-27 20:15:58 [W] sqlite SQL > INSERT INTO `stats_hourly` (`total`,`group`,`private`,`command`,`dialogue`,`time`) VALUES (5, 5, 0, 5, 0, 1651060800000)
2022-04-27 20:15:58 [W] sqlite SQL > INSERT INTO `stats_longterm` (`message`,`time`) VALUES (5, 1650988800000)
2022-04-27 20:15:58 [W] app SqliteError: UNIQUE constraint failed: stats_daily.time
                            at SQLiteDatabase.#exec (D:\bot\bot3\node_modules\@koishijs\plugin-database-sqlite\src\index.ts:184:43)
                            at SQLiteDatabase.#create (D:\bot\bot3\node_modules\@koishijs\plugin-database-sqlite\src\index.ts:257:12)
                            at SQLiteDatabase.upsert (D:\bot\bot3\node_modules\@koishijs\plugin-database-sqlite\src\index.ts:286:9)
                            at _StatisticsProvider._uploadDaily (D:\bot\bot3\node_modules\@koishijs\plugin-status\src\stats.ts:155:29)
                            at _StatisticsProvider.upload (D:\bot\bot3\node_modules\@koishijs\plugin-status\src\stats.ts:206:14)
                            at Session.<anonymous> (D:\bot\bot3\node_modules\@koishijs\plugin-status\src\stats.ts:109:14)
                            at App.serial (D:\bot\bot3\node_modules\@koishijs\core\src\context.ts:393:37)
                            at _Command._checkers (D:\bot\bot3\node_modules\@koishijs\core\src\command.ts:46:21)
                            at _Command.execute (D:\bot\bot3\node_modules\@koishijs\core\src\command.ts:236:38)
                            at null.<anonymous> (D:\bot\bot3\node_modules\@koishijs\core\src\session.ts:420:36)
H4M5TER commented 2 years ago

另外,我还在日志里刨出来了一个似乎和 teach 有关的 sqlerror,但是之后我就把 teach 关了,再之后 teach 就拆出来改名了。 基本形状如下,同一用户会多次触发,有需要我发 dialogue 现在仓库去

2022-04-08 20:32:11 [D] message [@Dave] Dave: 1
2022-04-08 20:32:11 [W] sqlite SQL > SELECT * FROM `dialogue` WHERE (`flag` & 16 = 0 AND (',' || `guilds` || ',') LIKE '%,'sandbox:@Dave',%' OR `flag` & 16 = 16 AND NOT(((',' || `guilds` || ',') LIKE '%,'sandbox:@Dave',%'))) AND (`flag` & 2 = 2 AND '1' REGEXP `original` OR `flag` & 2 = 0 AND `question` = '1') AND (NOT(`predecessors`)) AND (((`endTime` - `startTime`) * (`startTime` - 1232) * (1232 - `endTime`)) >= 0)
2022-04-08 20:32:11 [W] session 1
                        SqliteError: near "sandbox": syntax error
                            at Database.prepare (G:\bot\bot3\node_modules\better-sqlite3\lib\methods\wrappers.js:5:21)
                            at SQLiteDatabase.#exec (G:\bot\bot3\node_modules\@koishijs\plugin-database-sqlite\lib\index.js:294:28)
                            at SQLiteDatabase.#get (G:\bot\bot3\node_modules\@koishijs\plugin-database-sqlite\lib\index.js:319:54)
                            at SQLiteDatabase.get (G:\bot\bot3\node_modules\@koishijs\plugin-database-sqlite\lib\index.js:233:48)
                            at Teach.get (G:\bot\bot3\node_modules\@koishijs\plugin-teach\lib\index.js:1012:49)
                            at triggerDialogue (G:\bot\bot3\node_modules\@koishijs\plugin-teach\lib\index.js:245:55)
                            at G:\bot\bot3\node_modules\@koishijs\plugin-teach\lib\index.js:331:12
                            at next (G:\bot\bot3\node_modules\@koishijs\core\lib\node.js:2797:69)
                        Middleware stack:
                          - G:\bot\bot3\plugins\dice\lib\roll.js:111:20
                          - G:\bot\bot3\node_modules\@koishijs\plugin-feedback\lib\index.js:81:14
                          - G:\bot\bot3\node_modules\@koishijs\core\lib\node.js:2589:26
                          - G:\bot\bot3\node_modules\@koishijs\core\lib\node.js:2311:14
                          - G:\bot\bot3\node_modules\@koishijs\core\lib\node.js:2769:12
H4M5TER commented 2 years ago

还有,挺奇怪的,我在日志里刨出来了之前用 level 的时候 chat 导致的 duplicate entry 错误 #621。 但是换成 sqlite 之后完全没有遇见,chat 是一直装着的。

2022-04-07 18:57:13 [D] message [私聊] 1
2022-04-07 19:09:23 [W] app DriverError: duplicate entry
                            at /home/ubuntu/bot3/node_modules/@koishijs/plugin-database-level/lib/node.js:236:15
                            at async Session._observeChannelLike (/home/ubuntu/bot3/node_modules/@koishijs/core/lib/node.js:1592:18)
                            at async Promise.all (index 0)
                            at async Session.observeChannel (/home/ubuntu/bot3/node_modules/@koishijs/core/lib/node.js:1607:40)
                            at async /home/ubuntu/bot3/node_modules/@koishijs/plugin-chat/lib/index.js:243:28
                            at async Promise.all (index 0)
                            at async _Context.parallel (/home/ubuntu/bot3/node_modules/@koishijs/core/lib/node.js:1001:5)
shigma commented 2 years ago

更新:问题我已复现但不稳定。之后会持续关注。

Anillc commented 1 year ago

Duplicate entry 的错误我有一个稳定的复现,机器人第一次收到某个频道或者某个用户的消息并且该消息是指令的话就会触发。

shigma commented 1 year ago

Duplicate entry 的错误我有一个稳定的复现,机器人第一次收到某个频道或者某个用户的消息并且该消息是指令的话就会触发。

是 sqlite 限定还是都有?

Anillc commented 1 year ago

Duplicate entry 的错误我有一个稳定的复现,机器人第一次收到某个频道或者某个用户的消息并且该消息是指令的话就会触发。

是 sqlite 限定还是都有?

我是 mysql

mksudo commented 1 year ago

我也遇到了这个问题,并且能够稳定复现。具体复现方法为在stats_daily表中已有一个当天记录的情况下,调用一个命令并重载status插件。问题出在@koishijs/plugin-status和数据库driver上。对于driver-sqlite来说,第338行upsert方法中的const row = results.find(row => keys.every(key => row[key] === item[key]))key = "time"时,由于row[key]item[key]都为Date对象,在对比时并不相等。 图片 可以看到当调用getTime再对比时结果才为true。因此upsert没有找到row并调用create方法,导致UNIQUE constraint failed错误。

shigma commented 1 year ago

@mksudo 你说的非常有道理!感谢你提供的信息和 PR!