turt2live / matrix-bot-sdk

TypeScript/JavaScript SDK for Matrix bots
MIT License
194 stars 68 forks source link

No event when `sync` failed, Bot stuck on 'Expect String but received undefined' #346

Open liemlylac opened 11 months ago

liemlylac commented 11 months ago

Request related to a problem: Expect String but received undefined. I have a list of bot clients and want to stress test bot sends encrypted messages to e2ee rooms. When running a stress test using Postman by using 10 bots to send messages to 10 rooms. Virtual user: 100, ramp-up duration: 2 minutes, request duration: 5 minutes. The total requests for every bot is ~1,5K.

MatrixClientLite shows the error: Expect String but received Undefined. Tracking error I found this is an error from matrix-rust-sdk-crypto-nodejs when returning the empty request object (without txn_id will throw exception). Sometimes I get the error: Invalid access token passed. from MatrixHttpClient.

-> Maybe a lot of events fired and Bot's clients cannot sync up to date.

After restarting all bot clients, no error can be found. I can't find any event to handle on "sync" error to detect error caused and handle restarting bot or get a new access_token for the bot client.

The solution Could you please add code like this.emit('sync.error', e) on catch() when sync failed?

Alternatives solution A better way is to resolve the error Expect String but received Undefined. Does update matrix-rust-sdk-crypto-nodejs dependencies to 0.1.0-beta.11 will resolve it?

Additional context I using matrix-bot-sdk: v0.6.6. NodeJs: v16.x

sovdchains commented 9 months ago

I did not do any testing but encountered the same problem this morning with 0.7.0. The bot was down for an hour and spammed the log

Fri, 08 Dec 2023 08:39:24 GMT [ERROR] [MatrixClientLite] Error handling sync Error: Expect value to be String, but received Undefined
Fri, 08 Dec 2023 08:39:51 GMT [ERROR] [MatrixClientLite] Error handling sync Error: Expect value to be String, but received Undefined
Fri, 08 Dec 2023 08:39:51 GMT [INFO] [MatrixClientLite] Backing off for 11904.073501040042ms
Fri, 08 Dec 2023 08:40:03 GMT [ERROR] [MatrixClientLite] Error handling sync Error: Expect value to be String, but received Undefined
Fri, 08 Dec 2023 08:40:03 GMT [INFO] [MatrixClientLite] Backing off for 8221.935616793704ms
Fri, 08 Dec 2023 08:40:11 GMT [INFO] [MatrixClientLite] Backing off for 9502.840719659358ms
Fri, 08 Dec 2023 08:40:11 GMT [ERROR] [MatrixClientLite] Error handling sync Error: Expect value to be String, but received Undefined
Fri, 08 Dec 2023 08:40:51 GMT [ERROR] [MatrixClientLite] Error handling sync Error: Expect value to be String, but received Undefined
sovdchains commented 8 months ago

I got a little more context now from sending a message in this state:

Error: Expect value to be String, but received Undefined
    at RustEngine.actuallyProcessToDeviceRequest (/app/node_modules/matrix-bot-sdk/lib/e2ee/RustEngine.js:128:28)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async RustEngine.processToDeviceRequest (/app/node_modules/matrix-bot-sdk/lib/e2ee/RustEngine.js:124:9)
    at async RustEngine.runOnly (/app/node_modules/matrix-bot-sdk/lib/e2ee/RustEngine.js:41:21)
    at async RustEngine.run (/app/node_modules/matrix-bot-sdk/lib/e2ee/RustEngine.js:22:9)
    at async CryptoClient.encryptRoomEvent (/app/node_modules/matrix-bot-sdk/lib/e2ee/CryptoClient.js:184:9)
    at async BotClient.sendEvent (/app/node_modules/matrix-bot-sdk/lib/MatrixClient.js:1194:23)
    at async descriptor.value (/app/node_modules/matrix-bot-sdk/lib/metrics/decorators.js:19:32)
    at async descriptor.value (/app/node_modules/matrix-bot-sdk/lib/metrics/decorators.js:19:32)
    at async descriptor.value (/app/node_modules/matrix-bot-sdk/lib/metrics/decorators.js:19:32) {
  code: 'InvalidArg'
}

The only way to fix this is restarting the bot process and since there is no event on sync error I can't really bodge an automation either

stronk7 commented 6 months ago

Just to confirm that this has started to happen to me after updating to 0.7.1 few days ago (from 0.6.5).

For reference, it was reported earlier @ #256 (in case it helps, because it was fixed at some point - worked ok here from 0.6.3 to 0.6.5).

Ciao :-)