Telegram bridged users that haven't been existed since before Libera.Chat was bridged are not idle-kicked

[Mikaela]

Describe the bug

Before I attempted to remedy this situation by hand, I saw these users on #feneas on irc.libera.chat:

2021-W33-3 00:38:53 +0300 -- [#feneas] Telegrambridgeb7 (~teleg_482@2001:470:69fc:105::b78c) H 0 (@telegrambot:feneas.org)
2021-W33-3 00:38:53 +0300 -- [#feneas] Akash[m]123 (~teleg_481@2001:470:69fc:105::b74c) H 0 (@telegram_582396714:feneas.org)
2021-W33-3 00:38:53 +0300 -- [#feneas] Fla[m] (~teleg_480@2001:470:69fc:105::b70d) H 0 (@telegram_1061398789:feneas.org)
2021-W33-3 00:38:53 +0300 -- [#feneas] DaySandBox[m] (~teleg_481@2001:470:69fc:105::b73a) H 0 (@telegram_400753764:feneas.org)
2021-W33-3 00:38:53 +0300 -- [#feneas] AmyCupcakesCupca (~teleg_482@2001:470:69fc:105::b756) H 0 (@telegram_59050198:feneas.org)
2021-W33-3 00:38:53 +0300 -- [#feneas] ChristerWarn[m] (~teleg_482@2001:470:69fc:105::b76a) H 0 (@telegram_681150630:feneas.org)
2021-W33-3 00:38:53 +0300 -- [#feneas] LiaizonWakest[m] (~teleg_481@2001:470:69fc:105::b741) H 0 (@telegram_472917187:feneas.org)
2021-W33-3 00:38:53 +0300 -- [#feneas] tulir[m] (~teleg_482@2001:470:69fc:105::b772) H 0 (@telegram_84359547:feneas.org)
2021-W33-3 00:38:53 +0300 -- [#feneas] adamadinfinitum[ (~teleg_482@2001:470:69fc:105::b75d) H 0 (@telegram_679079626:feneas.org)
2021-W33-3 00:38:53 +0300 -- [#feneas] FeneasMatrixbrid (~teleg_482@2001:470:69fc:105::b777) H 0 (@telegram_852776608:feneas.org)
2021-W33-3 00:38:53 +0300 -- [#feneas] ThiagoSkrnio[m] (~teleg_480@2001:470:69fc:105::b712) H 0 (@telegram_109162179:feneas.org)
2021-W33-3 00:38:53 +0300 -- [#feneas] TheFuzzStone[m]1 (~teleg_481@2001:470:69fc:105::b728) H 0 (@telegram_253373664:feneas.org)
2021-W33-3 00:38:53 +0300 -- [#feneas] IiroLaiho[m] (~teleg_482@2001:470:69fc:105::b784) H 0 (@telegram_962636207:feneas.org)
2021-W33-3 00:38:53 +0300 -- [#feneas] Mykhailo[m] (~teleg_481@2001:470:69fc:105::b732) H 0 (@telegram_360450337:feneas.org)
2021-W33-3 00:38:53 +0300 -- [#feneas] RickyJones[m] (~teleg_481@2001:470:69fc:105::b71d) H 0 (@telegram_1344516645:feneas.org)
2021-W33-3 00:38:53 +0300 -- [#feneas] Zulu[m] (~teleg_481@2001:470:69fc:105::b723) H 0 (@telegram_187150329:feneas.org)
2021-W33-3 00:38:53 +0300 -- [#feneas] JasonRobinson[m4 (~teleg_481@2001:470:69fc:105::b718) H 0 (@telegram_123038871:feneas.org)
2021-W33-3 00:38:53 +0300 -- [#feneas] MikaelaTG[m] (~teleg_481@2001:470:69fc:105::b745) H 0 (@telegram_575404822:feneas.org)

The bridge has not been seen since 2020-10-24 so they should neither be sending read-receipts or new messages so I imagine they should be subject to #1194

To Reproduce

Unknown.

Expected behavior

The Telegram users have been kicked the first time libera.chat idle kicker ran since bridging of #feneas.

Screenshots

N/A

Desktop (please complete the following information):

N/A

Smartphone (please complete the following information):

N/A

Additional context

• users actively reading messages should not be kicked for being idle #1194 (comment) says that only users sending read-receipts or otherwise being active should be unaffected.
• https://git.feneas.org/feneas/association/-/issues/150 - Feneas issue on making the Telegram bridge leave everywhere it used to be in. I regardless consider this as a bridge issue as if a malicious actor figures out how to consistently reproduce this issue, I think IRC operators (and bridge maintainers) are going to be unhappy about unused connections taking I-line slots.
• blog: matrix-appservice-irc ignoring dead state reset homeservers if appservice doesn't have power? What to not do with bridging? Mikaela/mikaela.github.io#242 as prior bullet points on dead homeserver and a state reset together causing idle connections never getting reaped and thus keeping hundreds of connection slots used to the old freenode.
• Blog: IRC / (stateful?) bridging etiquette? Mikaela/mikaela.github.io#241 (comment) another prior case of wondering why are the Telegram users mentioned above still present?

[morguldir]

It seems that the isUserOnline function in matrix-lastactive returns -1 if it can't figure it out the time since a user was active either through the stored method, presence or by being on the same home server.
https://github.com/Half-Shot/matrix-lastactive/blob/99e2ac9f20e9d3853c04e41e636732aacc6d5a51/src/lib.ts#L127

The last active time in matrix-lastactive is only updated by the bridge when:

Restoring the state from the DB, which is only updated in the other code below:

matrix-appservice-irc/src/bridge/IrcBridge.ts

Lines 592 to 599 in 1f4d0dc

	if (this.activityTracker) {
	log.info("Restoring last active times from DB");
	const users = await this.dataStore.getLastSeenTimeForUsers();
	for (const user of users) {
	this.activityTracker.setLastActiveTime(user.user_id, user.ts);
	}
	log.info(`Restored ${users.length} last active times from DB`);
	}

On an Ephemeral Event:

matrix-appservice-irc/src/bridge/IrcBridge.ts

Lines 981 to 988 in 1f4d0dc

	if (userIds) {
	for (const userId of userIds) {
	this.activityTracker.bumpLastActiveTime(userId);
	this.dataStore.updateLastSeenTimeForUser(userId).catch((ex) => {
	log.warn(`Failed to bump last active time for ${userId} in database`, ex);
	});
	}
	}

On a normal Event:

matrix-appservice-irc/src/bridge/IrcBridge.ts

Lines 994 to 1000 in 1f4d0dc

	if (event.sender && (this.activityTracker ||
	this.config.ircService.metrics?.userActivityThresholdHours !== undefined)) {
	updatePromise = this.dataStore.updateLastSeenTimeForUser(event.sender);
	if (this.activityTracker) {
	this.activityTracker.bumpLastActiveTime(event.sender);
	}
	}

Then these users will be selected as the last to get idle kicked every time, so it would seem that the kick limit just hasn't been high enough for it to kick those users yet. Also possible that it's being excluded by regex in this specific case, or the kicking just fails, but the theory above could still happen elsewhere, and it's probably not reasonable that these users will always be the last ones to be kicked anyway.

[Half-Shot]

Reading the code, it looks like we would be kicking them first? We always run with defaultOnline to false so users we don't have a last active time for are automatically treated as offline. I would have thought given the sort, algorithm, that an activity time of -1 would actually cause them to be selected first.

[morguldir]

This is the sorting that's used as far as i can tell

matrix-appservice-irc/src/bridge/IrcBridge.ts

Line 1500 in 1bbbbb6

const sortedByActiveTime = [...usersToActiveTime.entries()].sort((a, b) => b[1] - a[1]).map(user => user[0]);

Which would put -1 at the end of the list, users that are considered online aren't considered, but since the users in the issue never got kicked by the bridge, I assume the bridge never kicked all the users that were considered offline.

If the bridge ever kicked every offline user though, then it seems like the bug would be avoided, at least for that bridge instance.