Intent.sendEvent duplicates events on (unwarranted) retry

[f0x52]

I've observed this issue multiple times with matrix-appservice-irc now, where messages coming from IRC are duplicated in the room. From digging into the code, this is caused by the original PUT for a new event to Synapse timing out after 30 seconds, though still sent to the room eventually, and the bridge already retrying the PUT, with a new transaction id.
This results in two events with the same content, and origin_server_ts timestamps that are 30 seconds apart.

matrix-appservice-bridge/src/components/intent.ts

Lines 904 to 917 in 0998090

	protected async _joinGuard<T>(roomId: string, promiseFn: () => Promise<T>): Promise<T> {
	try {
	// await so we can handle the error
	return await promiseFn();
	}
	catch (err) {
	if (err instanceof MatrixError && err.errcode !== "M_FORBIDDEN") {
	// not a guardable error
	throw err;
	}
	await this._ensureJoined(roomId, true);
	return promiseFn();
	}
	}

Intent.sendEvent calls to _joinGuard to ensure users are joined to the room they are trying to send a message in.
This try/catch silently swallows any error that isn't an M_FORBIDDEN MatrixError, and re-calls the promiseFn after forcing the join.
This leads to a situation where an HTTP timeout on the original send, due to a slow homeserver, causes a forced re-join, and another event to be sent. And because the call to this.botSdkIntent.underlyingClient.sendEvent(roomId, type, content) (to matrix-bot-sdk/MatrixClient.sendEvent) always generates a new idempotency token, messages aren't deduplicated by the homeserver either.

DEBUG 18:03:26:931 [MatrixHttpClient] (REQ-76523) PUT http://10.0.1.1:8008/_matrix/client/v3/rooms/ROOM_ID/send/m.room.message/1734541406931__inc1
  18:04:26 synapse[3338985]: synapse.http.site: [PUT-1810986] Connection from client lost before response was sent
  18:04:27 synapse[3338985]: synapse.http.client: [PUT-1810986] Received response to POST synapse-replication://events/_synapse/replication/send_events/BgegMiMzTC: 200
  18:04:27 synapse[3338985]: synapse.http.server: [PUT-1810986] Not sending response to request <XForwardedForRequest at 0x7f368c309610 method='PUT' 
                               uri='/_matrix/client/v3/rooms/ROOM_ID/send/m.room.message/1734541406931__inc1?user_id=%40BRIDGE_USER%3Apixie.town'
                               clientproto='HTTP/1.1' site='15001'>, already disconnected.
  18:04:27 synapse[3338985]: synapse.access.http.15001: [PUT-1810986] 10.0.1.4 - 15001 - {@BRIDGE_USER:pixie.town} Processed request: 61.011sec/-1.010sec (0.008sec, 0.002sec) (0.003sec/1.089sec/9)
                               0B 200! "PUT /_matrix/client/v3/rooms/ROOM_ID/send/m.room.message/1734541406931__inc1?user_id=%40BRIDGE_USER%3Apixie.town HTTP/1.1" "-" [0 dbevts]
event 1, origin_server_ts 1734541406957 - 18:03:26

DEBUG 18:04:56:709 [MatrixHttpClient] (REQ-76554) PUT http://10.0.1.1:8008/_matrix/client/v3/rooms/ROOM_ID/send/m.room.message/1734541496709__inc2
  18:04:57 cosmos synapse[3338985]: synapse.http.client: [PUT-1811025] Received response to POST synapse-replication://events/_synapse/replication/send_events/uCtZbmEPTu: 200
  18:04:57 cosmos synapse[3338985]: synapse.access.http.15001: [PUT-1811025] 10.0.1.4 - 15001 - {@BRIDGE_USER:pixie.town} Processed request: 0.618sec/0.000sec (0.013sec, 0.002sec) (0.003sec/0.202sec/8) 59B 200 "PUT /_matrix/client/v3/rooms/ROOM_ID/send/m.room.message/1734541496709__inc2?user_id=%40BRIDGE_USER%3Apixie.town HTTP/1.1" "-" [4 dbevts]

event 2, origin_server_ts 1734541496737 - 18:04:56

Notably the first event is sent with txnId 1734541406931__inc1 and second with 1734541496709__inc2, which is the timestamp + the increasing requestId for the specific bridged user's MatrixClient instance.