search

matrix-org / matrix-appservice-discord

A bridge between Matrix and Discord.
Apache License 2.0
785 stars 148 forks source link

Bridge crashes with M_UNKNOWN_TOKEN error #873

Open tux93 opened 1 year ago

tux93 commented 1 year ago

I have been using the bridge with only small issues (#839) for a while now but since last night the bridge crashes with this Error:

Dec 31 16:07:04 node[6186]: Dec-31 16:07:04.273 [bot-sdkMatrixHttpClient] error: [ '(REQ-11)', { errcode: 'M_UNKNOWN_TOKEN', error: 'Unknown token' } ]
Dec 31 16:07:04 node[6186]: matrix-appservice-discord/node_modules/matrix-bot-sdk/src/http.ts:110
Dec 31 16:07:04 node[6186]:         throw new MatrixError(errBody, response.statusCode);
Dec 31 16:07:04 node[6186]:               ^
Dec 31 16:07:04 node[6186]: Error: M_UNKNOWN_TOKEN: Unknown token
Dec 31 16:07:04 node[6186]:     at doHttpRequest (matrix-appservice-discord/node_modules/matrix-bot-sdk/src/http.ts:110:15)
Dec 31 16:07:04 node[6186]:     at processTicksAndRejections (node:internal/process/task_queues:96:5)
Dec 31 16:07:04 node[6186]:     at MatrixClient.descriptor.value (matrix-appservice-discord/node_modules/matrix-bot-sdk/src/metrics/decorators.ts:28:32)
Dec 31 16:07:04 node[6186]:     at MatrixClient.descriptor.value (matrix-appservice-discord/node_modules/matrix-bot-sdk/src/metrics/decorators.ts:28:32)
Dec 31 16:07:04 node[6186]:     at Intent.refreshJoinedRooms (matrix-appservice-discord/node_modules/matrix-bot-sdk/src/appservice/Intent.ts:296:33)
Dec 31 16:07:04 node[6186]:     at Intent.descriptor.value (matrix-appservice-discord/node_modules/matrix-bot-sdk/src/metrics/decorators.ts:83:32)
Dec 31 16:07:04 node[6186]:     at Appservice.processMembershipEvent (matrix-appservice-discord/node_modules/matrix-bot-sdk/src/appservice/Appservice.ts:616:9)
Dec 31 16:07:04 node[6186]:     at matrix-appservice-discord/node_modules/matrix-bot-sdk/src/appservice/Appservice.ts:841:21
Dec 31 16:07:04 matrix-dendrite-monolith-server[6158]: time="2022-12-31T15:07:04.391476516Z" level=error msg="Unable to send transaction to appservice, backing off for 2s" appservice=discord-bridge error="Put \"http://localhost:9005/transactions/1672457772054065971?access_token=[REDACTED]\": EOF"
tux93 commented 1 year ago

Going deeper into the logs it seems this is where it crashed for the first time, since then it keeps crashing as soon as a new message appears on the Matrix side

Dec 31 04:32:43 node[1279]: Dec-31 04:32:43.845 [bot-sdkMatrixHttpClient] error: [
Dec 31 04:32:43 node[1279]:   '(REQ-2909)',
Dec 31 04:32:43 node[1279]:   Error: Parse Error: Invalid header value char
Dec 31 04:32:43 node[1279]:       at TLSSocket.socketOnData (node:_http_client:534:22)
Dec 31 04:32:43 node[1279]:       at TLSSocket.emit (node:events:513:28)
Dec 31 04:32:43 node[1279]:       at addChunk (node:internal/streams/readable:315:12)
Dec 31 04:32:43 node[1279]:       at readableAddChunk (node:internal/streams/readable:289:9)
Dec 31 04:32:43 node[1279]:       at TLSSocket.Readable.push (node:internal/streams/readable:228:10)
Dec 31 04:32:43 node[1279]:       at TLSWrap.onStreamRead (node:internal/stream_base_commons:190:23) {
Dec 31 04:32:43 node[1279]:     bytesParsed: 627,
Dec 31 04:32:43 node[1279]:     code: 'HPE_INVALID_HEADER_TOKEN',
Dec 31 04:32:43 node[1279]:     reason: 'Invalid header value char',
Dec 31 04:32:43 node[1279]:     rawPacket: <Buffer 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d 0a 53 65 72 76 65 72 3a 20 6e 67 69 6e 78 2f 31 2e 32 31 2e 35 0d 0a 44 61 74 65 3a 20 53 61 74 2c 20 ... 895 more bytes>
Dec 31 04:32:43 node[1279]:   }
Dec 31 04:32:43 node[1279]: ]
Dec 31 04:32:43 node[1279]: Dec-31 04:32:43.846 [UserSync] error: Failed to update user's profile Error: Parse Error: Invalid header value char
Dec 31 04:32:43 node[1279]:     at TLSSocket.socketOnData (node:_http_client:534:22)
Dec 31 04:32:43 node[1279]:     at TLSSocket.emit (node:events:513:28)
Dec 31 04:32:43 node[1279]:     at addChunk (node:internal/streams/readable:315:12)
Dec 31 04:32:43 node[1279]:     at readableAddChunk (node:internal/streams/readable:289:9)
Dec 31 04:32:43 node[1279]:     at TLSSocket.Readable.push (node:internal/streams/readable:228:10)
Dec 31 04:32:43 node[1279]:     at TLSWrap.onStreamRead (node:internal/stream_base_commons:190:23) {
Dec 31 04:32:43 node[1279]:   bytesParsed: 627,
Dec 31 04:32:43 node[1279]:   code: 'HPE_INVALID_HEADER_TOKEN',
Dec 31 04:32:43 node[1279]:   reason: 'Invalid header value char',
Dec 31 04:32:43 node[1279]:   rawPacket: <Buffer 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d 0a 53 65 72 76 65 72 3a 20 6e 67 69 6e 78 2f 31 2e 32 31 2e 35 0d 0a 44 61 74 65 3a 20 53 61 74 2c 20 ... 895 more bytes>
Dec 31 04:32:43 node[1279]: }
Dec 31 04:32:44 matrix-dendrite-monolith-server[16924]: time="2022-12-31T03:32:44.122720206Z" level=error msg="Failed to leave room" error="user \"@_discord_[REDACTED]:squirrel.rocks\" is not a member of room \"![REDACTED]:squirrel.rocks\"" room_id="![REDACTED]:squirrel.rocks" user_id="@_discord_[REDACTED]:squirrel.rocks"
Dec 31 04:32:44 matrix-dendrite-monolith-server[16924]: time="2022-12-31T03:32:44.125313658Z" level=error msg="Failed to leave room" error="user \"@_discord_[REDACTED]:squirrel.rocks\" is not a member of room \"![REDACTED]:squirrel.rocks\"" room_id="![REDACTED]" user_id="@_discord_[REDACTED]:squirrel.rocks"
Dec 31 04:32:44 node[1279]: Dec-31 04:32:44.145 [bot-sdkMatrixHttpClient] error: [
Dec 31 04:32:44 node[1279]:   '(REQ-2913)',
Dec 31 04:32:44 node[1279]:   {
Dec 31 04:32:44 node[1279]:     errcode: 'M_UNKNOWN',
Dec 31 04:32:44 node[1279]:     error: 'user "@_discord_[REDACTED]:squirrel.rocks" is not a member of room "![REDACTED]:squirrel.rocks"'
Dec 31 04:32:44 node[1279]:   }
Dec 31 04:32:44 node[1279]: ]
Dec 31 04:32:44 node[1279]: Dec-31 04:32:44.148 [bot-sdkMatrixHttpClient] error: [
Dec 31 04:32:44 node[1279]:   '(REQ-2912)',
Dec 31 04:32:44 node[1279]:   {
Dec 31 04:32:44 node[1279]:     errcode: 'M_UNKNOWN',
Dec 31 04:32:44 node[1279]:     error: 'user "@_discord_[REDACTED]:squirrel.rocks" is not a member of room "![REDACTED]:squirrel.rocks"'
Dec 31 04:32:44 node[1279]:   }
Dec 31 04:32:44 node[1279]: ]
Dec 31 04:34:49 node[1279]: Dec-31 04:34:49.448 [bot-sdkMatrixHttpClient] error: [
Dec 31 04:34:49 node[1279]:   '(REQ-2914)',
Dec 31 04:34:49 node[1279]:   Error: Parse Error: Invalid header value char
Dec 31 04:34:49 node[1279]:       at TLSSocket.socketOnData (node:_http_client:534:22)
Dec 31 04:34:49 node[1279]:       at TLSSocket.emit (node:events:513:28)
Dec 31 04:34:49 node[1279]:       at addChunk (node:internal/streams/readable:315:12)
Dec 31 04:34:49 node[1279]:       at readableAddChunk (node:internal/streams/readable:289:9)
Dec 31 04:34:49 node[1279]:       at TLSSocket.Readable.push (node:internal/streams/readable:228:10)
Dec 31 04:34:49 node[1279]:       at TLSWrap.onStreamRead (node:internal/stream_base_commons:190:23) {
Dec 31 04:34:49 node[1279]:     bytesParsed: 627,
Dec 31 04:34:49 node[1279]:     code: 'HPE_INVALID_HEADER_TOKEN',
Dec 31 04:34:49 node[1279]:     reason: 'Invalid header value char',
Dec 31 04:34:49 node[1279]:     rawPacket: <Buffer 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d 0a 53 65 72 76 65 72 3a 20 6e 67 69 6e 78 2f 31 2e 32 31 2e 35 0d 0a 44 61 74 65 3a 20 53 61 74 2c 20 ... 895 more bytes>
Dec 31 04:34:49 node[1279]:   }
Dec 31 04:34:49 node[1279]: ]
Dec 31 04:34:49 node[1279]: Dec-31 04:34:49.451 [UserSync] error: Failed to update user's profile Error: Parse Error: Invalid header value char
Dec 31 04:34:49 node[1279]:     at TLSSocket.socketOnData (node:_http_client:534:22)
Dec 31 04:34:49 node[1279]:     at TLSSocket.emit (node:events:513:28)
Dec 31 04:34:49 node[1279]:     at addChunk (node:internal/streams/readable:315:12)
Dec 31 04:34:49 node[1279]:     at readableAddChunk (node:internal/streams/readable:289:9)
Dec 31 04:34:49 node[1279]:     at TLSSocket.Readable.push (node:internal/streams/readable:228:10)
Dec 31 04:34:49 node[1279]:     at TLSWrap.onStreamRead (node:internal/stream_base_commons:190:23) {
Dec 31 04:34:49 node[1279]:   bytesParsed: 627,
Dec 31 04:34:49 node[1279]:   code: 'HPE_INVALID_HEADER_TOKEN',
Dec 31 04:34:49 node[1279]:   reason: 'Invalid header value char',
Dec 31 04:34:49 node[1279]:   rawPacket: <Buffer 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d 0a 53 65 72 76 65 72 3a 20 6e 67 69 6e 78 2f 31 2e 32 31 2e 35 0d 0a 44 61 74 65 3a 20 53 61 74 2c 20 ... 895 more bytes>
Dec 31 04:34:49 node[1279]: }
Dec 31 04:34:49 matrix-dendrite-monolith-server[16924]: time="2022-12-31T03:34:49.713582327Z" level=error msg="Failed to leave room" error="user \"@_discord_[REDACTED]:squirrel.rocks\" is not a member of room \"![REDACTED]:squirrel.rocks\"" room_id="![REDACTED]:squirrel.rocks" user_id="@_discord_[REDACTED]:squirrel.rocks"
Dec 31 04:34:49 matrix-dendrite-monolith-server[16924]: time="2022-12-31T03:34:49.717456755Z" level=error msg="Failed to leave room" error="user \"@_discord_[REDACTED]:squirrel.rocks\" is not a member of room \"![REDACTED]:squirrel.rocks\"" room_id="![REDACTED]:squirrel.rocks" user_id="@_discord_[REDACTED]:squirrel.rocks"
Dec 31 04:34:49 node[1279]: Dec-31 04:34:49.737 [bot-sdkMatrixHttpClient] error: [
Dec 31 04:34:49 node[1279]:   '(REQ-2918)',
Dec 31 04:34:49 node[1279]:   {
Dec 31 04:34:49 node[1279]:     errcode: 'M_UNKNOWN',
Dec 31 04:34:49 node[1279]:     error: 'user "@_discord_[REDACTED]:squirrel.rocks" is not a member of room "![REDACTED]:squirrel.rocks"'
Dec 31 04:34:49 node[1279]:   }
Dec 31 04:34:49 node[1279]: ]
Dec 31 04:34:49 node[1279]: Dec-31 04:34:49.740 [bot-sdkMatrixHttpClient] error: [
Dec 31 04:34:49 node[1279]:   '(REQ-2917)',
Dec 31 04:34:49 node[1279]:   {
Dec 31 04:34:49 node[1279]:     errcode: 'M_UNKNOWN',
Dec 31 04:34:49 node[1279]:     error: 'user "@_discord_[REDACTED]:squirrel.rocks" is not a member of room "![REDACTED]:squirrel.rocks"'
Dec 31 04:34:49 node[1279]:   }
Dec 31 04:34:49 node[1279]: ]
Dec 31 04:36:15 node[1279]: Dec-31 04:36:15.247 [bot-sdkMatrixHttpClient] error: [
Dec 31 04:36:15 node[1279]:   '(REQ-2923)',
Dec 31 04:36:15 node[1279]:   { errcode: 'M_UNKNOWN_TOKEN', error: 'Unknown token' }
Dec 31 04:36:15 node[1279]: ]
Dec 31 04:36:15 node[1279]: matrix-appservice-discord/node_modules/matrix-bot-sdk/src/http.ts:110
Dec 31 04:36:15 node[1279]:         throw new MatrixError(errBody, response.statusCode);
Dec 31 04:36:15 node[1279]:               ^
Dec 31 04:36:15 node[1279]: Error: M_UNKNOWN_TOKEN: Unknown token
Dec 31 04:36:15 node[1279]:     at doHttpRequest (matrix-appservice-discord/node_modules/matrix-bot-sdk/src/http.ts:110:15)
Dec 31 04:36:15 node[1279]:     at runMicrotasks (<anonymous>)
Dec 31 04:36:15 node[1279]:     at processTicksAndRejections (node:internal/process/task_queues:96:5)
Dec 31 04:36:15 node[1279]:     at MatrixClient.descriptor.value (matrix-appservice-discord/node_modules/matrix-bot-sdk/src/metrics/decorators.ts:28:32)
Dec 31 04:36:15 node[1279]:     at MatrixClient.descriptor.value (matrix-appservice-discord/node_modules/matrix-bot-sdk/src/metrics/decorators.ts:28:32)
Dec 31 04:36:15 node[1279]:     at Intent.refreshJoinedRooms (matrix-appservice-discord/node_modules/matrix-bot-sdk/src/appservice/Intent.ts:296:33)
Dec 31 04:36:15 node[1279]:     at Intent.descriptor.value (matrix-appservice-discord/node_modules/matrix-bot-sdk/src/metrics/decorators.ts:83:32)
Dec 31 04:36:15 node[1279]:     at Appservice.processMembershipEvent (matrix-appservice-discord/node_modules/matrix-bot-sdk/src/appservice/Appservice.ts:616:9)
Dec 31 04:36:15 node[1279]:     at matrix-appservice-discord/node_modules/matrix-bot-sdk/src/appservice/Appservice.ts:841:21
Dec 31 04:36:15 matrix-dendrite-monolith-server[16924]: time="2022-12-31T03:36:15.416123236Z" level=error msg="Unable to send transaction to appservice, backing off for 2s" appservice=discord-bridge error="Put \"http://localhost:9005/transactions/1672457772054065971?access_token=[REDACTED]\": EOF"
Dec 31 04:36:15 systemd[1168]: matrix-discord.service: Main process exited, code=exited, status=1/FAILURE
Dec 31 04:36:15 systemd[1168]: matrix-discord.service: Failed with result 'exit-code'.
jaller94 commented 1 year ago

Are you sure that the home server has the registration file of your Discord appservice?

In the registration file you'll find as_token which both the home server and the bridge need to know. These string tokens need to match.

tux93 commented 1 year ago

Yes, both are using the same registration.yaml; and as I said it was working before and started crashing with this error overnight.

tux93 commented 1 year ago

Had another poke at it today and checked debug.log of the bridge, it seems to be an endless loop of this:

Jan-7 14:23:19.042 [DiscordStore] info: Starting DB Init
Jan-7 14:23:19.048 [DiscordStore] info: connString present in config, using postgres
Jan-7 14:23:19.049 [Postgres] info: Opening postgresql:///discord?host=/var/run/postgresql&user=discord&password=[REDACTED]
Jan-7 14:23:19.096 [DiscordStore] info: Database schema version is 12, latest version is 12
Jan-7 14:23:19.098 [DiscordStore] info: Updated database to the latest schema
Jan-7 14:23:19.887 [ClientFactory] info: Waiting for shardReady signal
Jan-7 14:23:20.056 [ClientFactory] info: Got shardReady signal
Jan-7 14:23:20.064 [DiscordBot] info: Discord bot client logged in.
Jan-7 14:23:20.065 [DiscordAS] info: Discordbot started successfully
Jan-7 14:23:20.072 [DiscordAS] info: Started listening on port 9005
Jan-7 14:24:05.453 [bot-sdkAppservice] info: [ 'Processing transaction 1672457772054065971' ]
Jan-7 14:24:05.456 [bot-sdkAppservice] info: [ 'Processing event of type m.room.member' ]
Jan-7 14:24:05.488 [MatrixEventProcessor] info: Skipping event due to age 640197954 > 900000
Jan-7 14:24:05.640 [bot-sdkMatrixHttpClient] error: [ '(REQ-1)', { errcode: 'M_UNKNOWN_TOKEN', error: 'Unknown token' } ]

It is the same transaction ID every time, it is skipped every time, the bridge crashes every time.

I wanted to try unbridging and starting over to see if that would at least work around this, but the bridge also no longer reacts to commands.

Please let me know where else I might find more info that could help you with analysing this.

tux93 commented 1 year ago

I ended up completely resetting the bridge by clearing out the discord database, regenerating the registration and setting up the bridges from scratch, for now it is working again.

I did save a dump of the database in the broken state and a copy of the registration in case you feel like trying to investigate further, otherwise feel free to close the issue for the time being.