From 13b1dcf78500081ff349a151e9e5ccb498e33593 Mon Sep 17 00:00:00 2001 From: David Baker Date: Mon, 16 Jan 2023 16:43:45 +0000 Subject: [PATCH 1/3] Mostly cosmetic fixes to rageshake * Remove duplicate copyright header * Remove ts-ignores by just using the objects directly rather than via event.target * Use error.message rather than errorCode which TS doesn't know about and may or may not exist. * Remove some unused things like the skip rageshake function and the option to init rageshakes without storage. * Turn single function with a boolean param to make it take two entirely separate code paths into two functions. --- src/settings/rageshake.ts | 113 +++++++++++++------------------------- 1 file changed, 39 insertions(+), 74 deletions(-) diff --git a/src/settings/rageshake.ts b/src/settings/rageshake.ts index 42441d1c..f83a205f 100644 --- a/src/settings/rageshake.ts +++ b/src/settings/rageshake.ts @@ -1,21 +1,4 @@ /* -Copyright 2022 New Vector Ltd - -Licensed under the Apache License, Version 2.0 (the "License"); -you may not use this file except in compliance with the License. -You may obtain a copy of the License at - -http://www.apache.org/licenses/LICENSE-2.0 - -Unless required by applicable law or agreed to in writing, software -distributed under the License is distributed on an "AS IS" BASIS, -WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -See the License for the specific language governing permissions and -limitations under the License. -*/ - -/* eslint-disable @typescript-eslint/ban-ts-comment */ -/* Copyright 2017 OpenMarket Ltd Copyright 2018 New Vector Ltd Copyright 2019 The New Vector Ltd @@ -99,13 +82,6 @@ export class ConsoleLogger { }); } - public bypassRageshake( - fnName: LogFunctionName, - ...args: (Error | DOMException | object | string)[] - ): void { - this.originalFunctions[fnName](...args); - } - public log( level: string, ...args: (Error | DOMException | object | string)[] @@ -140,20 +116,22 @@ export class ConsoleLogger { } /** - * Retrieve log lines to flush to disk. - * @param {boolean} keepLogs True to not delete logs after flushing. - * @return {string} \n delimited log lines to flush. + * Returns the log lines to flush to disk and empties the internal log buffer + * @return {string} \n delimited log lines */ - public flush(keepLogs?: boolean): string { - // The ConsoleLogger doesn't care how these end up on disk, it just - // flushes them to the caller. - if (keepLogs) { - return this.logs; - } + public popLogs(): string { const logsToFlush = this.logs; this.logs = ""; return logsToFlush; } + + /** + * Returns lines currently in the log buffer without removing them + * @return {string} \n delimited log lines + */ + public peekLogs(): string { + return this.logs; + } } // A class which stores log lines in an IndexedDB instance. @@ -174,30 +152,32 @@ export class IndexedDBLogStore { public connect(): Promise { const req = this.indexedDB.open("logs"); return new Promise((resolve, reject) => { - req.onsuccess = (event: Event) => { - // @ts-ignore - this.db = event.target.result; + req.onsuccess = () => { + this.db = req.result; // Periodically flush logs to local storage / indexeddb setInterval(this.flush.bind(this), FLUSH_RATE_MS); resolve(); }; req.onerror = (event) => { - const err = - // @ts-ignore - "Failed to open log database: " + event.target.error.name; + const err = "Failed to open log database: " + req.error.name; logger.error(err); reject(new Error(err)); }; // First time: Setup the object store req.onupgradeneeded = (event) => { - // @ts-ignore - const db = event.target.result; + const db = req.result; + // This is the log entries themselves. Each entry is a chunk of + // logs (ie multiple lines). 'id' is the instance ID (so logs with + // the same instance ID are all from the same session) and 'index' + // is a sequence number for the chunk. The log lines live in the + // 'lines' key, which is a chunk of many newline-separated log lines. const logObjStore = db.createObjectStore("logs", { keyPath: ["id", "index"], }); // Keys in the database look like: [ "instance-148938490", 0 ] + // (The instance ID plus the ID of each log chunk). // Later on we need to query everything based on an instance id. // In order to do this, we need to set up indexes "id". logObjStore.createIndex("id", "id", { unique: false }); @@ -206,6 +186,9 @@ export class IndexedDBLogStore { this.generateLogEntry(new Date() + " ::: Log database was created.") ); + // This records the last time each instance ID generated a log message, such + // that the logs from each session can be collated in the order they last logged + // something. const lastModifiedStore = db.createObjectStore("logslastmod", { keyPath: "id", }); @@ -258,7 +241,7 @@ export class IndexedDBLogStore { reject(new Error("No connected database")); return; } - const lines = this.logger.flush(); + const lines = this.logger.popLogs(); if (lines.length === 0) { resolve(); return; @@ -270,8 +253,7 @@ export class IndexedDBLogStore { }; txn.onerror = (event) => { logger.error("Failed to flush logs : ", event); - // @ts-ignore - reject(new Error("Failed to write logs: " + event.target.errorCode)); + reject(new Error("Failed to write logs: " + txn.error.message)); }; objStore.add(this.generateLogEntry(lines)); const lastModStore = txn.objectStore("logslastmod"); @@ -307,13 +289,11 @@ export class IndexedDBLogStore { .index("id") .openCursor(IDBKeyRange.only(id), "prev"); let lines = ""; - query.onerror = (event) => { - // @ts-ignore - reject(new Error("Query failed: " + event.target.errorCode)); + query.onerror = () => { + reject(new Error("Query failed: " + query.error.message)); }; - query.onsuccess = (event) => { - // @ts-ignore - const cursor = event.target.result; + query.onsuccess = () => { + const cursor = query.result; if (!cursor) { resolve(lines); return; // end of results @@ -355,9 +335,8 @@ export class IndexedDBLogStore { const o = txn.objectStore("logs"); // only load the key path, not the data which may be huge const query = o.index("id").openKeyCursor(IDBKeyRange.only(id)); - query.onsuccess = (event) => { - // @ts-ignore - const cursor = event.target.result; + query.onsuccess = () => { + const cursor = query.result; if (!cursor) { return; } @@ -367,12 +346,10 @@ export class IndexedDBLogStore { txn.oncomplete = () => { resolve(); }; - txn.onerror = (event) => { + txn.onerror = () => { reject( new Error( - "Failed to delete logs for " + - // @ts-ignore - `'${id}' : ${event.target.errorCode}` + "Failed to delete logs for " + `'${id}' : ${txn.error.message}` ) ); }; @@ -457,13 +434,11 @@ function selectQuery( return new Promise((resolve, reject) => { const results = []; query.onerror = (event) => { - // @ts-ignore - reject(new Error("Query failed: " + event.target.errorCode)); + reject(new Error("Query failed: " + query.error.message)); }; // collect results query.onsuccess = (event) => { - // @ts-ignore - const cursor = event.target.result; + const cursor = query.result; if (!cursor) { resolve(results); return; // end of results @@ -479,8 +454,6 @@ declare global { // eslint-disable-next-line no-var, camelcase var mx_rage_logger: ConsoleLogger; // eslint-disable-next-line no-var, camelcase - var mx_rage_initPromise: Promise; - // eslint-disable-next-line no-var, camelcase var mx_rage_initStoragePromise: Promise; } @@ -491,19 +464,11 @@ declare global { * be set up immediately for the logs. * @return {Promise} Resolves when set up. */ -export function init(setUpPersistence = true): Promise { - if (global.mx_rage_initPromise) { - return global.mx_rage_initPromise; - } +export function init(): Promise { global.mx_rage_logger = new ConsoleLogger(); global.mx_rage_logger.monkeyPatch(window.console); - if (setUpPersistence) { - return tryInitStorage(); - } - - global.mx_rage_initPromise = Promise.resolve(); - return global.mx_rage_initPromise; + return tryInitStorage(); } /** @@ -573,7 +538,7 @@ export async function getLogsForReport(): Promise { } else { return [ { - lines: global.mx_rage_logger.flush(true), + lines: global.mx_rage_logger.peekLogs(), id: "-", }, ]; From 860aff495858ac154ff4082290831beb741ef6f7 Mon Sep 17 00:00:00 2001 From: David Baker Date: Mon, 16 Jan 2023 17:27:49 +0000 Subject: [PATCH 2/3] Change rageshake persistence to throttled flushing Rather than every 30 seconds. This way we'll save logs for sessions lasting less than 30 seconds which we previously didn't. Also save on window unload just in case that doesn't catch everything. Plus remove some more unused params. --- package.json | 1 + src/settings/rageshake.ts | 65 ++++++++++++++++++++++++++++++--------- 2 files changed, 51 insertions(+), 15 deletions(-) diff --git a/package.json b/package.json index f7bbbb05..58001dba 100644 --- a/package.json +++ b/package.json @@ -45,6 +45,7 @@ "i18next": "^21.10.0", "i18next-browser-languagedetector": "^6.1.8", "i18next-http-backend": "^1.4.4", + "lodash": "^4.17.21", "matrix-js-sdk": "github:matrix-org/matrix-js-sdk#7b10fa367df357b51c2e78e220d39e5e7967f9e3", "matrix-widget-api": "^1.0.0", "mermaid": "^8.13.8", diff --git a/src/settings/rageshake.ts b/src/settings/rageshake.ts index f83a205f..268f2ac4 100644 --- a/src/settings/rageshake.ts +++ b/src/settings/rageshake.ts @@ -37,15 +37,23 @@ limitations under the License. // actually timestamps. We then purge the remaining logs. We also do this // purge on startup to prevent logs from accumulating. +import EventEmitter from "events"; +import { throttle } from "lodash"; import { logger } from "matrix-js-sdk/src/logger"; import { randomString } from "matrix-js-sdk/src/randomstring"; -// the frequency with which we flush to indexeddb -const FLUSH_RATE_MS = 30 * 1000; - // the length of log data we keep in indexeddb (and include in the reports) const MAX_LOG_SIZE = 1024 * 1024 * 5; // 5 MB +// Shortest amount of time between flushes. We are just appending to an +// IndexedDB table so we don't expect flushing to be that expensive, but +// we can batch the writes a little. +const MAX_FLUSH_INTERVAL = 2 * 1000; + +enum ConsoleLoggerEvent { + Log = "log", +} + type LogFunction = ( ...args: (Error | DOMException | object | string)[] ) => void; @@ -59,7 +67,7 @@ interface LogEntry { index?: number; } -export class ConsoleLogger { +export class ConsoleLogger extends EventEmitter { private logs = ""; private originalFunctions: { [key in LogFunctionName]?: LogFunction } = {}; @@ -113,6 +121,8 @@ export class ConsoleLogger { // Using + really is the quickest way in JS // http://jsperf.com/concat-vs-plus-vs-join this.logs += line; + + this.emit(ConsoleLoggerEvent.Log); } /** @@ -142,8 +152,14 @@ export class IndexedDBLogStore { private flushAgainPromise: Promise = null; private id: string; - constructor(private indexedDB: IDBFactory, private logger: ConsoleLogger) { + constructor( + private indexedDB: IDBFactory, + private loggerInstance: ConsoleLogger + ) { this.id = "instance-" + randomString(16); + + loggerInstance.on(ConsoleLoggerEvent.Log, this.onLoggerLog); + window.addEventListener("beforeunload", this.flush); } /** @@ -154,19 +170,18 @@ export class IndexedDBLogStore { return new Promise((resolve, reject) => { req.onsuccess = () => { this.db = req.result; - // Periodically flush logs to local storage / indexeddb - setInterval(this.flush.bind(this), FLUSH_RATE_MS); + resolve(); }; - req.onerror = (event) => { + req.onerror = () => { const err = "Failed to open log database: " + req.error.name; logger.error(err); reject(new Error(err)); }; // First time: Setup the object store - req.onupgradeneeded = (event) => { + req.onupgradeneeded = () => { const db = req.result; // This is the log entries themselves. Each entry is a chunk of // logs (ie multiple lines). 'id' is the instance ID (so logs with @@ -197,6 +212,26 @@ export class IndexedDBLogStore { }); } + private onLoggerLog = () => { + if (!this.db) return; + + this.throttledFlush(); + }; + + // Throttled function to flush logs. We use throttle rather + // than debounce as we want logs to be written regularly, otherwise + // if there's a constant stream of logging, we'd never write anything. + private throttledFlush = throttle( + () => { + this.flush(); + }, + MAX_FLUSH_INTERVAL, + { + leading: false, + trailing: true, + } + ); + /** * Flush logs to disk. * @@ -216,7 +251,7 @@ export class IndexedDBLogStore { * * @return {Promise} Resolved when the logs have been flushed. */ - public flush(): Promise { + public flush = (): Promise => { // check if a flush() operation is ongoing if (this.flushPromise) { if (this.flushAgainPromise) { @@ -241,14 +276,14 @@ export class IndexedDBLogStore { reject(new Error("No connected database")); return; } - const lines = this.logger.popLogs(); + const lines = this.loggerInstance.popLogs(); if (lines.length === 0) { resolve(); return; } const txn = this.db.transaction(["logs", "logslastmod"], "readwrite"); const objStore = txn.objectStore("logs"); - txn.oncomplete = (event) => { + txn.oncomplete = () => { resolve(); }; txn.onerror = (event) => { @@ -262,7 +297,7 @@ export class IndexedDBLogStore { this.flushPromise = null; }); return this.flushPromise; - } + }; /** * Consume the most recent logs and return them. Older logs which are not @@ -433,11 +468,11 @@ function selectQuery( const query = store.openCursor(keyRange); return new Promise((resolve, reject) => { const results = []; - query.onerror = (event) => { + query.onerror = () => { reject(new Error("Query failed: " + query.error.message)); }; // collect results - query.onsuccess = (event) => { + query.onsuccess = () => { const cursor = query.result; if (!cursor) { resolve(results); From e1c4042d15569c4ef05bffd1d7dea916ad506b46 Mon Sep 17 00:00:00 2001 From: David Baker Date: Tue, 17 Jan 2023 10:16:55 +0000 Subject: [PATCH 3/3] Add units to constant --- src/settings/rageshake.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/settings/rageshake.ts b/src/settings/rageshake.ts index 268f2ac4..446f0365 100644 --- a/src/settings/rageshake.ts +++ b/src/settings/rageshake.ts @@ -48,7 +48,7 @@ const MAX_LOG_SIZE = 1024 * 1024 * 5; // 5 MB // Shortest amount of time between flushes. We are just appending to an // IndexedDB table so we don't expect flushing to be that expensive, but // we can batch the writes a little. -const MAX_FLUSH_INTERVAL = 2 * 1000; +const MAX_FLUSH_INTERVAL_MS = 2 * 1000; enum ConsoleLoggerEvent { Log = "log", @@ -225,7 +225,7 @@ export class IndexedDBLogStore { () => { this.flush(); }, - MAX_FLUSH_INTERVAL, + MAX_FLUSH_INTERVAL_MS, { leading: false, trailing: true,