Add a test for mode changes correctly applying to users. (#1732)

* Add powerlevel e2e test

* Log failures properly

* Log when we don't know a mode value

* Set sensible mode defaults

* Remove mistaken log line

* Remove consistent return lint rule

* changelog

* update changelog

* Improve userPrefixes check

* Catch failures to kill redis

* Don't call quit twice

* Remove duplicate test

* Fix unit test

* Disable passkey enc

* sneaky fix to stop logging pong timeouts erronously

* Remove comment

* Drop console line

* Review tweaks

* Fix changelog

* Add a loop to check all power levels

* Add ability to check for the right PL

* Don't wait for charlie's matrix membership

.eslintrc

@@ -19,7 +19,7 @@
   ],
   "rules": {
     "camelcase": 0, // Rule is bugged atm
-    "consistent-return": 2,
+    "consistent-return": 0,
     "curly": 1,
     "default-case": 2,
     "guard-for-in": 2,

changelog.d/1732.bugfix

@@ -0,0 +1 @@
+Fixes cases where powerlevel changes may not be correctly applied upon mode change.

spec/e2e/pooling.spec.ts

@@ -20,7 +20,7 @@ describeif('Connection pooling', () => {
             }
         });
         await testEnv.setUp();
-    })
+    });
 
     // Ensure we always tear down
     afterEach(() => {
@@ -72,48 +72,4 @@ describeif('Connection pooling', () => {
         bob.say(channel, "Hi alice!");
         await bobMsg;
     });
-
-    it('should be able to recover from legacy client state', async () => {
-        const channel = `#${TestIrcServer.generateUniqueNick("test")}`;
-
-        const { homeserver } = testEnv;
-        const alice = homeserver.users[0].client;
-        const { bob } = testEnv.ircTest.clients;
-
-        // Create the channel
-        await bob.join(channel);
-
-        const adminRoomId = await testEnv.createAdminRoomHelper(alice);
-        const cRoomId = await testEnv.joinChannelHelper(alice, adminRoomId, channel);
-
-        // And finally wait for bob to appear.
-        const bobUserId = `@irc_${bob.nick}:${homeserver.domain}`;
-        await alice.waitForRoomEvent(
-            {eventType: 'm.room.member', sender: bobUserId, stateKey: bobUserId, roomId: cRoomId}
-        );
-
-
-        // Send some messages
-        let aliceMsg = bob.waitForEvent('message', 10000);
-        let bobMsg = alice.waitForRoomEvent(
-            {eventType: 'm.room.message', sender: bobUserId, roomId: cRoomId}
-        );
-        alice.sendText(cRoomId, "Hello bob!");
-        await aliceMsg;
-        bob.say(channel, "Hi alice!");
-        await bobMsg;
-
-        // Now kill the bridge, do NOT kill the dependencies.
-        await testEnv.recreateBridge();
-        await testEnv.setUp();
-
-        aliceMsg = bob.waitForEvent('message', 10000);
-        bobMsg = alice.waitForRoomEvent(
-            {eventType: 'm.room.message', sender: bobUserId, roomId: cRoomId}
-        );
-        alice.sendText(cRoomId, "Hello bob!");
-        await aliceMsg;
-        bob.say(channel, "Hi alice!");
-        await bobMsg;
-    });
 });

spec/e2e/powerlevels.spec.ts

@@ -0,0 +1,49 @@
+/* eslint-disable @typescript-eslint/no-non-null-assertion */
+import { TestIrcServer } from "matrix-org-irc";
+import { IrcBridgeE2ETest } from "../util/e2e-test";
+import { describe, expect, it } from "@jest/globals";
+import { PowerLevelContent } from "matrix-appservice-bridge";
+
+
+describe('Ensure powerlevels are appropriately applied', () => {
+    let testEnv: IrcBridgeE2ETest;
+    beforeEach(async () => {
+        testEnv = await IrcBridgeE2ETest.createTestEnv({
+            matrixLocalparts: ['alice'],
+            ircNicks: ['bob', 'charlie'],
+        });
+        await testEnv.setUp();
+    });
+    afterEach(() => {
+        return testEnv?.tearDown();
+    });
+    it('should update powerlevel of IRC user when OPed by an IRC user', async () => {
+        const channel = `#${TestIrcServer.generateUniqueNick("test")}`;
+        const { homeserver } = testEnv;
+        const alice = homeserver.users[0].client;
+        const { bob, charlie } = testEnv.ircTest.clients;
+        const bobUserId = `@irc_${bob.nick}:${homeserver.domain}`;
+        const charlieUserId = `@irc_${charlie.nick}:${homeserver.domain}`;
+
+        // Create the channel
+        await bob.join(channel);
+
+        const cRoomId = await testEnv.joinChannelHelper(alice, await testEnv.createAdminRoomHelper(alice), channel);
+
+        // Now have charlie join and be opped.
+        await charlie.join(channel);
+        const operatorPL = testEnv.ircBridge.config.ircService.servers.localhost.modePowerMap!.o;
+        const plEvent = alice.waitForPowerLevel(
+            cRoomId, {
+                users: {
+                    [charlieUserId]: operatorPL,
+                    [testEnv.ircBridge.appServiceUserId]: 100,
+                    [bobUserId]: operatorPL,
+                },
+            }
+        );
+
+        await bob.send('MODE', channel, '+o', charlie.nick);
+        await plEvent;
+    });
+});

spec/unit/pool-service/IrcClientRedisState.ts

@@ -55,7 +55,8 @@ describe("IrcClientRedisState", () => {
     it("should be able to create a fresh state", async () => {
         const state = await IrcClientRedisState.create(
             fakeRedis(),
-            userId
+            userId,
+            true
         );
         expect(state.loggedIn).toBeFalse();
         expect(state.registered).toBeFalse();
@@ -64,7 +65,8 @@ describe("IrcClientRedisState", () => {
     it("should be able to load existing state", async () => {
         const state = await IrcClientRedisState.create(
             fakeRedis(JSON.stringify(EXISTING_STATE)),
-            userId
+            userId,
+            false
         );
         expect(state.loggedIn).toBeTrue();
         expect(state.registered).toBeTrue();
@@ -101,7 +103,10 @@ describe("IrcClientRedisState", () => {
         }
         const state = await IrcClientRedisState.create(
             fakeRedis(JSON.stringify(existingState)),
-            userId
+            userId,
+            false
         );
+        expect(state.chans.get('#matrix-bridge-test')?.users instanceof Map);
+        expect(state.chans.get('#halfy-plumbs')?.users instanceof Map);
     })
 });

spec/util/e2e-test.ts

@@ -1,4 +1,4 @@
-import { AppServiceRegistration } from "matrix-appservice-bridge";
+import { AppServiceRegistration, PowerLevelContent } from "matrix-appservice-bridge";
 import { BridgeConfig } from "../../src/config/BridgeConfig";
 import { Client as PgClient } from "pg";
 import { ComplementHomeServer, createHS, destroyHS } from "./homerunner";
@@ -29,12 +29,50 @@ interface Opts {
 
 export class E2ETestMatrixClient extends MatrixClient {
 
-    public async waitForRoomEvent(
+    public async waitForPowerLevel(
+        roomId: string, expected: Partial<PowerLevelContent>,
+    ): Promise<{roomId: string, data: {
+        sender: string, type: string, state_key?: string, content: PowerLevelContent, event_id: string,
+    }}> {
+        return this.waitForEvent('room.event', (eventRoomId: string, eventData: {
+            sender: string, type: string, content: Record<string, unknown>, event_id: string, state_key: string,
+        }) => {
+            if (eventRoomId !== roomId) {
+                return undefined;
+            }
+
+            if (eventData.type !== "m.room.power_levels") {
+                return undefined;
+            }
+
+            if (eventData.state_key !== "") {
+                return undefined;
+            }
+
+            // Check only the keys we care about
+            for (const [key, value] of Object.entries(expected)) {
+                console.log(key, value, "---", eventData.content[key]);
+                if (JSON.stringify(eventData.content[key], undefined, 0) !== JSON.stringify(value, undefined, 0)) {
+                    return undefined;
+                }
+            }
+
+            console.info(
+                // eslint-disable-next-line max-len
+                `${eventRoomId} ${eventData.event_id} ${eventData.sender}`
+            );
+            return {roomId: eventRoomId, data: eventData};
+        }, `Timed out waiting for powerlevel from in ${roomId}`)
+    }
+
+    public async waitForRoomEvent<T extends object = Record<string, unknown>>(
         opts: {eventType: string, sender: string, roomId?: string, stateKey?: string}
-    ): Promise<{roomId: string, data: unknown}> {
+    ): Promise<{roomId: string, data: {
+        sender: string, type: string, state_key?: string, content: T, event_id: string,
+    }}> {
         const {eventType, sender, roomId, stateKey} = opts;
         return this.waitForEvent('room.event', (eventRoomId: string, eventData: {
-            sender: string, type: string, state_key?: string, content: {body?: string}, event_id: string,
+            sender: string, type: string, state_key?: string, content: T, event_id: string,
         }) => {
             if (eventData.sender !== sender) {
                 return undefined;
@@ -48,9 +86,10 @@ export class E2ETestMatrixClient extends MatrixClient {
             if (stateKey !== undefined && eventData.state_key !== stateKey) {
                 return undefined;
             }
+            const body = 'body' in eventData.content && eventData.content.body;
             console.info(
                 // eslint-disable-next-line max-len
-                `${eventRoomId} ${eventData.event_id} ${eventData.type} ${eventData.sender} ${eventData.state_key ?? eventData.content?.body ?? ''}`
+                `${eventRoomId} ${eventData.event_id} ${eventData.type} ${eventData.sender} ${eventData.state_key ?? body ?? ''}`
             );
             return {roomId: eventRoomId, data: eventData};
         }, `Timed out waiting for ${eventType} from ${sender} in ${roomId || "any room"}`)
@@ -170,6 +209,9 @@ export class IrcBridgeE2ETest {
                 connectionString: `${process.env.IRCBRIDGE_TEST_PGURL}/${postgresDb}`,
             },
             ircService: {
+                ircHandler: {
+                    powerLevelGracePeriodMs: 0,
+                },
                 servers: {
                     localhost: {
                         ...IrcServer.DEFAULT_CONFIG,

src/bridge/IrcHandler.ts

@@ -906,14 +906,14 @@ export class IrcHandler {
      * @return {Promise} which is resolved/rejected when the request finishes.
      */
     public async onMode(req: BridgeRequest, server: IrcServer, channel: string, by: string,
-                        mode: string, enabled: boolean, arg: string|null) {
+                        mode: string, enabled: boolean, arg: string|null): Promise<BridgeRequestErr|undefined> {
         this.incrementMetric("mode");
         req.log.info(
             "onMode(%s) in %s by %s (arg=%s)",
             (enabled ? ("+" + mode) : ("-" + mode)),
             channel, by, arg
         );
-        await this.roomAccessSyncer.onMode(req, server, channel, by, mode, enabled, arg);
+        return this.roomAccessSyncer.onMode(req, server, channel, by, mode, enabled, arg);
     }
 
     /**

src/bridge/RoomAccessSyncer.ts

@@ -1,6 +1,6 @@
 import { getLogger } from "../logging";
 import { IrcBridge } from "./IrcBridge";
-import { BridgeRequest } from "../models/BridgeRequest";
+import { BridgeRequest, BridgeRequestErr } from "../models/BridgeRequest";
 import { IrcServer } from "../irc/IrcServer";
 import { MatrixRoom, PowerLevelContent } from "matrix-appservice-bridge";
 import { BridgedClientStatus } from "../irc/BridgedClient";
@@ -50,8 +50,7 @@ export class RoomAccessSyncer {
     constructor(private ircBridge: IrcBridge) { }
 
     get powerLevelGracePeriod() {
-        const configPeriod = this.ircBridge.config.ircService.ircHandler?.powerLevelGracePeriodMs;
-        return configPeriod === undefined ? DEFAULT_POWER_LEVEL_GRACE_MS : configPeriod;
+        return this.ircBridge.config.ircService.ircHandler?.powerLevelGracePeriodMs ?? DEFAULT_POWER_LEVEL_GRACE_MS;
     }
 
     /**
@@ -202,7 +201,7 @@ export class RoomAccessSyncer {
      * @param {string|null} arg This is usually the affected user, if applicable.
      */
     public async onMode(req: BridgeRequest, server: IrcServer, channel: string, by: string,
-                        mode: string, enabled: boolean, arg: string|null) {
+                        mode: string, enabled: boolean, arg: string|null): Promise<BridgeRequestErr|undefined> {
         if (PRIVATE_MODES.includes(mode)) {
             await this.onPrivateMode(req, server, channel, mode, enabled);
             return;
@@ -215,7 +214,8 @@ export class RoomAccessSyncer {
 
         // Bridge usermodes to power levels
         const modeToPower = server.getModePowerMap();
-        if (!Object.keys(modeToPower).includes(mode)) {
+        if (mode in modeToPower === false) {
+            req.log.debug(`Mode '${mode}' is not known`);
             // Not an operator power mode
             return;
         }
@@ -226,7 +226,7 @@ export class RoomAccessSyncer {
         );
         if (matrixRooms.length === 0) {
             req.log.info("No mapped matrix rooms for IRC channel %s", channel);
-            return;
+            return BridgeRequestErr.ERR_NOT_MAPPED;
         }
 
         // Work out what power levels to give
@@ -243,12 +243,17 @@ export class RoomAccessSyncer {
             userId = bridgedClient.userId;
             if (bridgedClient.status !== BridgedClientStatus.CONNECTED) {
                 req.log.info(`Bridged client for ${nick} has no IRC client.`);
-                return;
+                return BridgeRequestErr.ERR_DROPPED;
             }
-            const userPrefixes = bridgedClient.chanData(channel)?.users.get(nick);
-            if (!userPrefixes) {
-                req.log.error(`No channel data for ${channel}/${nick}`);
-                return;
+            const chanData = bridgedClient.chanData(channel);
+            if (!chanData) {
+                req.log.error(`No channel data for ${channel}`);
+                return BridgeRequestErr.ERR_DROPPED;
+            }
+            const userPrefixes = chanData.users.get(nick);
+            if (userPrefixes === undefined) {
+                req.log.error(`No channel data for ${channel}/${nick}. Is the user still joined to the channel?`);
+                return BridgeRequestErr.ERR_DROPPED;
             }
             userPrefixes.split('').forEach(
                 prefix => {
@@ -266,7 +271,8 @@ export class RoomAccessSyncer {
 
         if (userId === null) {
             // Probably the BridgeBot or a user we don't know about, drop it.
-            return;
+            req.log.info('Could not determine userId for mode, ignoring');
+            return BridgeRequestErr.ERR_DROPPED;
         }
 
         // By default, unset the user's power level. This will be treated
@@ -283,8 +289,10 @@ export class RoomAccessSyncer {
             `${enabled ? level : 0} to ${userId}`
         );
 
+        let failureCause: Error|undefined;
         for (const room of matrixRooms) {
-            const powerLevelMap = await (this.getCurrentPowerlevels(room.getId())) || {};
+            const roomId = room.getId();
+            const powerLevelMap = await (this.getCurrentPowerlevels(roomId)) || {};
             const users = (powerLevelMap.users || {}) as {[userId: string]: number};
 
             // If the user's present PL is equal to the level,
@@ -310,9 +318,20 @@ export class RoomAccessSyncer {
                 // set of modes.
                 level = 0;
             }
-            this.setPowerLevel(room.getId(), userId, level, req);
+            try {
+                req.log.info(`Granting PL${level} to ${userId} in ${roomId}`);
+                await this.setPowerLevel(roomId, userId, level, req);
+            }
+            catch (ex) {
+                req.log.warn(`Failed to grant PL in ${roomId}`, ex);
+                failureCause = ex;
+            }
+        }
+        if (failureCause) {
+            // There *can* be multiple failures, but just use the first one.
+            // We still log all failures above.
+            throw new Error('Failed to update PL in some rooms', { cause: failureCause });
         }
-
     }
     /**
      * Called when an IRC server responds to a mode request.

src/irc/BridgedClient.ts

@@ -808,7 +808,6 @@ export class BridgedClient extends EventEmitter {
                                 identResolver: () => void) {
         // If this state has carried over from a previous connection, pull in any channels.
         [...connInst.client.chans.keys()].forEach(k => this.chanList.add(k));
-        console.log('Adding existing channels', this.chanList.entries());
         // listen for a connect event which is done when the TCP connection is
         // established and set ident info (this is different to the connect() callback
         // in node-irc which actually fires on a registered event..)

src/irc/IrcServer.ts

@@ -709,6 +709,10 @@ export class IrcServer {
                 joinChannelsIfNoUsers: true,
                 enabled: true
             },
+            modePowerMap: {
+                o: 50,
+                v: 1,
+            },
             privateMessages: {
                 enabled: true,
                 exclude: [],

src/pool-service/IrcConnectionPool.ts

@@ -188,8 +188,8 @@ export class IrcConnectionPool {
             if (data.includes('PING')) {
                 const msg = parseMessage(data.toString('utf-8'), false);
                 if (msg.command === 'PING') {
-                    log.warn(`Sending PONG for ${clientId}, since the bridge didn't respond fast enough.`);
                     this.connectionPongTimeouts.set(clientId, setTimeout(() => {
+                        log.warn(`Sending PONG for ${clientId}, since the bridge didn't respond fast enough.`);
                         connection.write('PONG ' + msg.args[0] + "\r\n");
                     }, TIME_TO_WAIT_BEFORE_PONG));
                 }