Add trace logs for E2E tests (#1745)

* Add optional trace logs for E2E tests

* Fix paths

* changelog

* Always trace and always clear up before running

* Fix missing files

* Add logging to debug why we only have one trace file in artefacts

* Ensure tracing is only cleaned on startup

* Derace powerlevels test

* Review comments

* Fix message

* Reorder joins

* Update spec/e2e/setup.ts

Co-authored-by: Andrew Ferrazzutti <[email protected]>

---------

Co-authored-by: Andrew Ferrazzutti <[email protected]>

Author: Half-Shot

.github/workflows/e2e-test.yml

@@ -138,6 +138,12 @@ jobs:
           yarn --strict-semver --frozen-lockfile
           HOMERUNNER_SPAWN_HS_TIMEOUT_SECS=100 ../homerunner &
           bash -ic 'yarn test:e2e'
+      - name: Archive trace logs
+        if: always()
+        uses: actions/upload-artifact@v3
+        with:
+          name: e2e-traces
+          path:  matrix-appservice-irc/.e2e-traces/*
 
   integration-test-pool: 
     runs-on: ubuntu-latest
@@ -207,4 +213,10 @@ jobs:
           cd matrix-appservice-irc
           yarn --strict-semver --frozen-lockfile
           HOMERUNNER_SPAWN_HS_TIMEOUT_SECS=100 ../homerunner &
-          bash -ic 'yarn test:e2e'
+          bash -ic 'yarn test:e2e'
+      - name: Archive trace logs
+        if: always()
+        uses: actions/upload-artifact@v3
+        with:
+          name: e2e-traces-pool
+          path:  matrix-appservice-irc/.e2e-traces/*

changelog.d/1745.misc

@@ -0,0 +1 @@
+Add tracing for Matrix and IRC clients when running E2E tests.

spec/e2e/jest.config.js

@@ -14,4 +14,5 @@ module.exports = {
       },
     ],
   },
+  globalSetup: './setup.ts'
 };

spec/e2e/powerlevels.spec.ts

@@ -1,8 +1,7 @@
 /* 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";
+import { describe, it } from "@jest/globals";
 
 
 describe('Ensure powerlevels are appropriately applied', () => {
@@ -28,10 +27,18 @@ describe('Ensure powerlevels are appropriately applied', () => {
         // Create the channel
         await bob.join(channel);
 
+        const aliceJoin = bob.waitForEvent('join');
         const cRoomId = await testEnv.joinChannelHelper(alice, await testEnv.createAdminRoomHelper(alice), channel);
+        // Trigger a join on IRC.
+        await alice.sendText(cRoomId, 'Hello world!');
+        // Wait for alice to join.
+        await aliceJoin;
 
         // Now have charlie join and be opped.
+        const charlieJoin = bob.waitForEvent('join');
         await charlie.join(channel);
+        await charlieJoin;
+
         const operatorPL = testEnv.ircBridge.config.ircService.servers.localhost.modePowerMap!.o;
         const plEvent = alice.waitForPowerLevel(
             cRoomId, {
@@ -43,6 +50,9 @@ describe('Ensure powerlevels are appropriately applied', () => {
             }
         );
 
+        // Wait for charlie to join
+        await charlieJoin;
+
         await bob.send('MODE', channel, '+o', charlie.nick);
         await plEvent;
     });

spec/e2e/setup.ts

@@ -0,0 +1,8 @@
+import * as fs from "node:fs/promises";
+
+export default async function() {
+    console.log('Cleaning .e2e-traces')
+    await fs.rm('.e2e-traces', { recursive: true, force: true })
+    await fs.mkdir('.e2e-traces');
+}
+

spec/util/e2e-test.ts

@@ -7,7 +7,9 @@ import { IrcServer } from "../../src/irc/IrcServer";
 import { MatrixClient } from "matrix-bot-sdk";
 import { TestIrcServer } from "matrix-org-irc";
 import { IrcConnectionPool } from "../../src/pool-service/IrcConnectionPool";
-import dns from 'node:dns';
+import { expect } from "@jest/globals";
+import * as dns from 'node:dns';
+import { WriteStream, createWriteStream } from "node:fs";
 // Needed to make tests work on GitHub actions. Node 17+ defaults
 // to IPv6, and the homerunner domain resolves to IPv6, but the
 // runtime doesn't actually support IPv6 🤦
@@ -24,8 +26,11 @@ interface Opts {
     ircNicks?: string[];
     timeout?: number;
     config?: Partial<BridgeConfig>,
+    traceToFile?: boolean,
 }
 
+const traceFilePath = '.e2e-traces';
+
 export class E2ETestMatrixClient extends MatrixClient {
 
     public async waitForPowerLevel(
@@ -160,6 +165,11 @@ export class IrcBridgeE2ETest {
     }
 
     static async createTestEnv(opts: Opts = {}): Promise<IrcBridgeE2ETest> {
+        const testName = expect.getState().currentTestName?.replace(/[^a-zA-Z]/g, '-');
+        const tracePath = `${traceFilePath}/${testName}.log`;
+        console.log('Opening new trace file', tracePath);
+        const traceLog = createWriteStream(tracePath, 'utf-8');
+
         const workerID = parseInt(process.env.JEST_WORKER_ID ?? '0');
         const { matrixLocalparts, config } = opts;
         const ircTest = new TestIrcServer();
@@ -280,7 +290,7 @@ export class IrcBridgeE2ETest {
             }
             }),
         }, registration);
-        return new IrcBridgeE2ETest(homeserver, ircBridge, registration, postgresDb, ircTest, redisPool)
+        return new IrcBridgeE2ETest(homeserver, ircBridge, registration, postgresDb, ircTest, traceLog, redisPool)
     }
 
     private constructor(
@@ -289,7 +299,24 @@ export class IrcBridgeE2ETest {
         public readonly registration: AppServiceRegistration,
         readonly postgresDb: string,
         public readonly ircTest: TestIrcServer,
-        public readonly pool?: IrcConnectionPool) {
+        private traceLog: WriteStream,
+        public readonly pool?: IrcConnectionPool,
+    ) {
+        const startTime = Date.now();
+        for (const [clientId, client] of Object.entries(ircTest.clients)) {
+            client.on('raw', (msg) => {
+                traceLog.write(
+                    `${Date.now() - startTime}ms [IRC:${clientId}] ${JSON.stringify(msg)} \n`
+                );
+            })
+        }
+        for (const {client, userId} of Object.values(homeserver.users)) {
+            client.on('room.event', (roomId, eventData) => {
+                traceLog.write(
+                    `${Date.now() - startTime}ms [Matrix:${userId}] ${roomId} ${JSON.stringify(eventData)}\n`
+                );
+            })
+        }
     }
 
     public async recreateBridge() {
@@ -317,6 +344,9 @@ export class IrcBridgeE2ETest {
     }
 
     public async tearDown(): Promise<void> {
+        if (this.traceLog) {
+            this.traceLog.close();
+        }
         await Promise.allSettled([
             this.ircBridge?.kill(),
             this.ircTest.tearDown(),