From 0fdc6b1c3ae8e41e372c89b3f666b8937428eff1 Mon Sep 17 00:00:00 2001 From: Bruno Windels <274386+bwindels@users.noreply.github.com> Date: Fri, 6 May 2022 15:54:45 +0200 Subject: [PATCH] log both to idb storage and console, include open items in export refactor logging api so a logger has multiple reporters, IDBLogPersister and/or ConsoleReporter. By default, we add the idb persister for production and both for dev You can also inject your own logger when creating the platform now. --- .../session/settings/SettingsViewModel.js | 3 +- src/lib.ts | 3 + .../{ConsoleLogger.ts => ConsoleReporter.ts} | 25 +-- .../{IDBLogger.ts => IDBLogPersister.ts} | 154 +++++++++++------- src/logging/LogItem.ts | 10 +- src/logging/{BaseLogger.ts => Logger.ts} | 38 +++-- src/logging/NullLogger.ts | 16 +- src/logging/types.ts | 19 ++- src/platform/web/Platform.js | 17 +- 9 files changed, 182 insertions(+), 103 deletions(-) rename src/logging/{ConsoleLogger.ts => ConsoleReporter.ts} (84%) rename src/logging/{IDBLogger.ts => IDBLogPersister.ts} (60%) rename src/logging/{BaseLogger.ts => Logger.ts} (83%) diff --git a/src/domain/session/settings/SettingsViewModel.js b/src/domain/session/settings/SettingsViewModel.js index 7464a659..e7990844 100644 --- a/src/domain/session/settings/SettingsViewModel.js +++ b/src/domain/session/settings/SettingsViewModel.js @@ -136,7 +136,8 @@ export class SettingsViewModel extends ViewModel { } async exportLogs() { - const logExport = await this.logger.export(); + const persister = this.logger.reporters.find(r => typeof r.export === "function"); + const logExport = await persister.export(); this.platform.saveFileAs(logExport.asBlob(), `hydrogen-logs-${this.platform.clock.now()}.json`); } diff --git a/src/lib.ts b/src/lib.ts index a49eacbc..0fc6f539 100644 --- a/src/lib.ts +++ b/src/lib.ts @@ -14,6 +14,9 @@ See the License for the specific language governing permissions and limitations under the License. */ +export {Logger} from "./logging/Logger"; +export {IDBLogPersister} from "./logging/IDBLogPersister"; +export {ConsoleReporter} from "./logging/ConsoleReporter"; export {Platform} from "./platform/web/Platform.js"; export {Client, LoadStatus} from "./matrix/Client.js"; export {RoomStatus} from "./matrix/room/common"; diff --git a/src/logging/ConsoleLogger.ts b/src/logging/ConsoleReporter.ts similarity index 84% rename from src/logging/ConsoleLogger.ts rename to src/logging/ConsoleReporter.ts index 7a3ae638..328b4c23 100644 --- a/src/logging/ConsoleLogger.ts +++ b/src/logging/ConsoleReporter.ts @@ -13,22 +13,27 @@ 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. */ -import {BaseLogger} from "./BaseLogger"; -import {LogItem} from "./LogItem"; -import type {ILogItem, LogItemValues, ILogExport} from "./types"; -export class ConsoleLogger extends BaseLogger { - _persistItem(item: LogItem): void { - printToConsole(item); +import type {ILogger, ILogItem, LogItemValues, ILogReporter} from "./types"; +import type {LogItem} from "./LogItem"; + +export class ConsoleReporter implements ILogReporter { + private logger?: ILogger; + + reportItem(item: ILogItem): void { + printToConsole(item as LogItem); } - async export(): Promise { - return undefined; + setLogger(logger: ILogger) { + this.logger = logger; } printOpenItems(): void { - for (const item of this._openItems) { - this._persistItem(item); + if (!this.logger) { + return; + } + for (const item of this.logger.getOpenRootItems()) { + this.reportItem(item); } } } diff --git a/src/logging/IDBLogger.ts b/src/logging/IDBLogPersister.ts similarity index 60% rename from src/logging/IDBLogger.ts rename to src/logging/IDBLogPersister.ts index ab9474b0..2199b1ff 100644 --- a/src/logging/IDBLogger.ts +++ b/src/logging/IDBLogPersister.ts @@ -22,36 +22,69 @@ import { iterateCursor, fetchResults, } from "../matrix/storage/idb/utils"; -import {BaseLogger} from "./BaseLogger"; import type {Interval} from "../platform/web/dom/Clock"; import type {Platform} from "../platform/web/Platform.js"; import type {BlobHandle} from "../platform/web/dom/BlobHandle.js"; -import type {ILogItem, ILogExport, ISerializedItem} from "./types"; -import type {LogFilter} from "./LogFilter"; +import type {ILogItem, ILogger, ILogReporter, ISerializedItem} from "./types"; +import {LogFilter} from "./LogFilter"; type QueuedItem = { json: string; id?: number; } -export class IDBLogger extends BaseLogger { - private readonly _name: string; - private readonly _limit: number; +type Options = { + name: string, + flushInterval?: number, + limit?: number, + platform: Platform, + serializedTransformer?: (item: ISerializedItem) => ISerializedItem +} + +export class IDBLogPersister implements ILogReporter { private readonly _flushInterval: Interval; private _queuedItems: QueuedItem[]; + private readonly options: Options; + private logger?: ILogger; - constructor(options: {name: string, flushInterval?: number, limit?: number, platform: Platform, serializedTransformer?: (item: ISerializedItem) => ISerializedItem}) { - super(options); - const {name, flushInterval = 60 * 1000, limit = 3000} = options; - this._name = name; - this._limit = limit; + constructor(options: Options) { + this.options = options; this._queuedItems = this._loadQueuedItems(); // TODO: also listen for unload just in case sync keeps on running after pagehide is fired? window.addEventListener("pagehide", this, false); - this._flushInterval = this._platform.clock.createInterval(() => this._tryFlush(), flushInterval); + this._flushInterval = this.options.platform.clock.createInterval( + () => this._tryFlush(), + this.options.flushInterval ?? 60 * 1000 + ); } - // TODO: move dispose to ILogger, listen to pagehide elsewhere and call dispose from there, which calls _finishAllAndFlush + setLogger(logger: ILogger): void { + this.logger = logger; + } + + reportItem(logItem: ILogItem, filter: LogFilter, forced: boolean): void { + const queuedItem = this.prepareItemForQueue(logItem, filter, forced); + if (queuedItem) { + this._queuedItems.push(queuedItem); + } + } + + async export(): Promise { + const db = await this._openDB(); + try { + const txn = db.transaction(["logs"], "readonly"); + const logs = txn.objectStore("logs"); + const storedItems: QueuedItem[] = await fetchResults(logs.openCursor(), () => false); + const openItems = this.getSerializedOpenItems(); + const allItems = storedItems.concat(this._queuedItems).concat(openItems); + return new IDBLogExport(allItems, this, this.options.platform); + } finally { + try { + db.close(); + } catch (e) {} + } + } + dispose(): void { window.removeEventListener("pagehide", this, false); this._flushInterval.dispose(); @@ -63,7 +96,7 @@ export class IDBLogger extends BaseLogger { } } - async _tryFlush(): Promise { + private async _tryFlush(): Promise { const db = await this._openDB(); try { const txn = db.transaction(["logs"], "readwrite"); @@ -73,9 +106,10 @@ export class IDBLogger extends BaseLogger { logs.add(i); } const itemCount = await reqAsPromise(logs.count()); - if (itemCount > this._limit) { + const limit = this.options.limit ?? 3000; + if (itemCount > limit) { // delete an extra 10% so we don't need to delete every time we flush - let deleteAmount = (itemCount - this._limit) + Math.round(0.1 * this._limit); + let deleteAmount = (itemCount - limit) + Math.round(0.1 * limit); await iterateCursor(logs.openCursor(), (_, __, cursor) => { cursor.delete(); deleteAmount -= 1; @@ -93,14 +127,16 @@ export class IDBLogger extends BaseLogger { } } - _finishAllAndFlush(): void { - this._finishOpenItems(); - this.log({l: "pagehide, closing logs", t: "navigation"}); + private _finishAllAndFlush(): void { + if (this.logger) { + this.logger.log({l: "pagehide, closing logs", t: "navigation"}); + this.logger.forceFinish(); + } this._persistQueuedItems(this._queuedItems); } - _loadQueuedItems(): QueuedItem[] { - const key = `${this._name}_queuedItems`; + private _loadQueuedItems(): QueuedItem[] { + const key = `${this.options.name}_queuedItems`; try { const json = window.localStorage.getItem(key); if (json) { @@ -113,44 +149,32 @@ export class IDBLogger extends BaseLogger { return []; } - _openDB(): Promise { - return openDatabase(this._name, db => db.createObjectStore("logs", {keyPath: "id", autoIncrement: true}), 1); + private _openDB(): Promise { + return openDatabase(this.options.name, db => db.createObjectStore("logs", {keyPath: "id", autoIncrement: true}), 1); } - - _persistItem(logItem: ILogItem, filter: LogFilter, forced: boolean): void { - const serializedItem = logItem.serialize(filter, undefined, forced); + + private prepareItemForQueue(logItem: ILogItem, filter: LogFilter, forced: boolean): QueuedItem | undefined { + let serializedItem = logItem.serialize(filter, undefined, forced); if (serializedItem) { - const transformedSerializedItem = this._serializedTransformer(serializedItem); - this._queuedItems.push({ - json: JSON.stringify(transformedSerializedItem) - }); + if (this.options.serializedTransformer) { + serializedItem = this.options.serializedTransformer(serializedItem); + } + return { + json: JSON.stringify(serializedItem) + }; } } - _persistQueuedItems(items: QueuedItem[]): void { + private _persistQueuedItems(items: QueuedItem[]): void { try { - window.localStorage.setItem(`${this._name}_queuedItems`, JSON.stringify(items)); + window.localStorage.setItem(`${this.options.name}_queuedItems`, JSON.stringify(items)); } catch (e) { console.error("Could not persist queued log items in localStorage, they will likely be lost", e); } } - async export(): Promise { - const db = await this._openDB(); - try { - const txn = db.transaction(["logs"], "readonly"); - const logs = txn.objectStore("logs"); - const storedItems: QueuedItem[] = await fetchResults(logs.openCursor(), () => false); - const allItems = storedItems.concat(this._queuedItems); - return new IDBLogExport(allItems, this, this._platform); - } finally { - try { - db.close(); - } catch (e) {} - } - } - - async _removeItems(items: QueuedItem[]): Promise { + /** @internal called by ILogExport.removeFromStore */ + async removeItems(items: QueuedItem[]): Promise { const db = await this._openDB(); try { const txn = db.transaction(["logs"], "readwrite"); @@ -173,14 +197,29 @@ export class IDBLogger extends BaseLogger { } catch (e) {} } } + + private getSerializedOpenItems(): QueuedItem[] { + const openItems: QueuedItem[] = []; + if (!this.logger) { + return openItems; + } + const filter = new LogFilter(); + for(const item of this.logger!.getOpenRootItems()) { + const openItem = this.prepareItemForQueue(item, filter, false); + if (openItem) { + openItems.push(openItem); + } + } + return openItems; + } } -class IDBLogExport implements ILogExport { +export class IDBLogExport { private readonly _items: QueuedItem[]; - private readonly _logger: IDBLogger; + private readonly _logger: IDBLogPersister; private readonly _platform: Platform; - constructor(items: QueuedItem[], logger: IDBLogger, platform: Platform) { + constructor(items: QueuedItem[], logger: IDBLogPersister, platform: Platform) { this._items = items; this._logger = logger; this._platform = platform; @@ -194,18 +233,23 @@ class IDBLogExport implements ILogExport { * @return {Promise} */ removeFromStore(): Promise { - return this._logger._removeItems(this._items); + return this._logger.removeItems(this._items); } asBlob(): BlobHandle { + const json = this.asJSON(); + const buffer: Uint8Array = this._platform.encoding.utf8.encode(json); + const blob: BlobHandle = this._platform.createBlob(buffer, "application/json"); + return blob; + } + + asJSON(): string { const log = { formatVersion: 1, appVersion: this._platform.updateService?.version, items: this._items.map(i => JSON.parse(i.json)) }; const json = JSON.stringify(log); - const buffer: Uint8Array = this._platform.encoding.utf8.encode(json); - const blob: BlobHandle = this._platform.createBlob(buffer, "application/json"); - return blob; + return json; } } diff --git a/src/logging/LogItem.ts b/src/logging/LogItem.ts index 216cc6bb..5aaabcc4 100644 --- a/src/logging/LogItem.ts +++ b/src/logging/LogItem.ts @@ -16,7 +16,7 @@ limitations under the License. */ import {LogLevel, LogFilter} from "./LogFilter"; -import type {BaseLogger} from "./BaseLogger"; +import type {Logger} from "./Logger"; import type {ISerializedItem, ILogItem, LogItemValues, LabelOrValues, FilterCreator, LogCallback} from "./types"; export class LogItem implements ILogItem { @@ -25,11 +25,11 @@ export class LogItem implements ILogItem { public error?: Error; public end?: number; private _values: LogItemValues; - protected _logger: BaseLogger; + protected _logger: Logger; private _filterCreator?: FilterCreator; private _children?: Array; - constructor(labelOrValues: LabelOrValues, logLevel: LogLevel, logger: BaseLogger, filterCreator?: FilterCreator) { + constructor(labelOrValues: LabelOrValues, logLevel: LogLevel, logger: Logger, filterCreator?: FilterCreator) { this._logger = logger; this.start = logger._now(); // (l)abel @@ -38,7 +38,7 @@ export class LogItem implements ILogItem { this._filterCreator = filterCreator; } - /** start a new root log item and run it detached mode, see BaseLogger.runDetached */ + /** start a new root log item and run it detached mode, see Logger.runDetached */ runDetached(labelOrValues: LabelOrValues, callback: LogCallback, logLevel?: LogLevel, filterCreator?: FilterCreator): ILogItem { return this._logger.runDetached(labelOrValues, callback, logLevel, filterCreator); } @@ -253,7 +253,7 @@ export class LogItem implements ILogItem { return item; } - get logger(): BaseLogger { + get logger(): Logger { return this._logger; } diff --git a/src/logging/BaseLogger.ts b/src/logging/Logger.ts similarity index 83% rename from src/logging/BaseLogger.ts rename to src/logging/Logger.ts index 21643c48..395181ef 100644 --- a/src/logging/BaseLogger.ts +++ b/src/logging/Logger.ts @@ -17,17 +17,17 @@ limitations under the License. import {LogItem} from "./LogItem"; import {LogLevel, LogFilter} from "./LogFilter"; -import type {ILogger, ILogExport, FilterCreator, LabelOrValues, LogCallback, ILogItem, ISerializedItem} from "./types"; +import type {ILogger, ILogReporter, FilterCreator, LabelOrValues, LogCallback, ILogItem, ISerializedItem} from "./types"; import type {Platform} from "../platform/web/Platform.js"; -export abstract class BaseLogger implements ILogger { +export class Logger implements ILogger { protected _openItems: Set = new Set(); protected _platform: Platform; protected _serializedTransformer: (item: ISerializedItem) => ISerializedItem; + public readonly reporters: ILogReporter[] = []; - constructor({platform, serializedTransformer = (item: ISerializedItem) => item}) { + constructor({platform}) { this._platform = platform; - this._serializedTransformer = serializedTransformer; } log(labelOrValues: LabelOrValues, logLevel: LogLevel = LogLevel.Info): void { @@ -79,10 +79,10 @@ export abstract class BaseLogger implements ILogger { return this._run(item, callback, logLevel, true, filterCreator); } - _run(item: LogItem, callback: LogCallback, logLevel: LogLevel, wantResult: true, filterCreator?: FilterCreator): T; + private _run(item: LogItem, callback: LogCallback, logLevel: LogLevel, wantResult: true, filterCreator?: FilterCreator): T; // we don't return if we don't throw, as we don't have anything to return when an error is caught but swallowed for the fire-and-forget case. - _run(item: LogItem, callback: LogCallback, logLevel: LogLevel, wantResult: false, filterCreator?: FilterCreator): void; - _run(item: LogItem, callback: LogCallback, logLevel: LogLevel, wantResult: boolean, filterCreator?: FilterCreator): T | void { + private _run(item: LogItem, callback: LogCallback, logLevel: LogLevel, wantResult: false, filterCreator?: FilterCreator): void; + private _run(item: LogItem, callback: LogCallback, logLevel: LogLevel, wantResult: boolean, filterCreator?: FilterCreator): T | void { this._openItems.add(item); const finishItem = () => { @@ -134,7 +134,16 @@ export abstract class BaseLogger implements ILogger { } } - _finishOpenItems() { + addReporter(reporter: ILogReporter): void { + reporter.setLogger(this); + this.reporters.push(reporter); + } + + getOpenRootItems(): Iterable { + return this._openItems; + } + + forceFinish() { for (const openItem of this._openItems) { openItem.forceFinish(); try { @@ -150,19 +159,24 @@ export abstract class BaseLogger implements ILogger { this._openItems.clear(); } - abstract _persistItem(item: LogItem, filter?: LogFilter, forced?: boolean): void; - - abstract export(): Promise; + /** @internal */ + _persistItem(item: LogItem, filter?: LogFilter, forced?: boolean): void { + for (var i = 0; i < this.reporters.length; i += 1) { + this.reporters[i].reportItem(item, filter, forced); + } + } // expose log level without needing get level(): typeof LogLevel { return LogLevel; } + /** @internal */ _now(): number { return this._platform.clock.now(); } + /** @internal */ _createRefId(): number { return Math.round(this._platform.random() * Number.MAX_SAFE_INTEGER); } @@ -171,7 +185,7 @@ export abstract class BaseLogger implements ILogger { class DeferredPersistRootLogItem extends LogItem { finish() { super.finish(); - (this._logger as BaseLogger)._persistItem(this, undefined, false); + (this._logger as Logger)._persistItem(this, undefined, false); } forceFinish() { diff --git a/src/logging/NullLogger.ts b/src/logging/NullLogger.ts index 835f7314..9e9b576b 100644 --- a/src/logging/NullLogger.ts +++ b/src/logging/NullLogger.ts @@ -14,7 +14,7 @@ See the License for the specific language governing permissions and limitations under the License. */ import {LogLevel} from "./LogFilter"; -import type {ILogger, ILogExport, ILogItem, LabelOrValues, LogCallback, LogItemValues} from "./types"; +import type {ILogger, ILogItem, LabelOrValues, LogCallback, LogItemValues} from "./types"; function noop (): void {} @@ -23,6 +23,14 @@ export class NullLogger implements ILogger { log(): void {} + addReporter() {} + + getOpenRootItems(): Iterable { + return []; + } + + forceFinish(): void {} + child(): ILogItem { return this.item; } @@ -43,11 +51,7 @@ export class NullLogger implements ILogger { new Promise(r => r(callback(this.item))).then(noop, noop); return this.item; } - - async export(): Promise { - return undefined; - } - + get level(): typeof LogLevel { return LogLevel; } diff --git a/src/logging/types.ts b/src/logging/types.ts index 2b1d305d..0ed3b0dc 100644 --- a/src/logging/types.ts +++ b/src/logging/types.ts @@ -16,7 +16,6 @@ limitations under the License. */ import {LogLevel, LogFilter} from "./LogFilter"; -import type {BaseLogger} from "./BaseLogger"; import type {BlobHandle} from "../platform/web/dom/BlobHandle.js"; export interface ISerializedItem { @@ -40,7 +39,7 @@ export interface ILogItem { readonly level: typeof LogLevel; readonly end?: number; readonly start?: number; - readonly values: LogItemValues; + readonly values: Readonly; wrap(labelOrValues: LabelOrValues, callback: LogCallback, logLevel?: LogLevel, filterCreator?: FilterCreator): T; /*** This is sort of low-level, you probably want to use wrap. If you do use it, it should only be called once. */ run(callback: LogCallback): T; @@ -74,14 +73,20 @@ export interface ILogger { wrapOrRun(item: ILogItem | undefined, labelOrValues: LabelOrValues, callback: LogCallback, logLevel?: LogLevel, filterCreator?: FilterCreator): T; runDetached(labelOrValues: LabelOrValues, callback: LogCallback, logLevel?: LogLevel, filterCreator?: FilterCreator): ILogItem; run(labelOrValues: LabelOrValues, callback: LogCallback, logLevel?: LogLevel, filterCreator?: FilterCreator): T; - export(): Promise; get level(): typeof LogLevel; + getOpenRootItems(): Iterable; + addReporter(reporter: ILogReporter): void; + get reporters(): ReadonlyArray; + /** + * force-finishes any open items and passes them to the reporter, with the forced flag set. + * Good think to do when the page is being closed to not lose any logs. + **/ + forceFinish(): void; } -export interface ILogExport { - get count(): number; - removeFromStore(): Promise; - asBlob(): BlobHandle; +export interface ILogReporter { + setLogger(logger: ILogger): void; + reportItem(item: ILogItem, filter?: LogFilter, forced?: boolean): void; } export type LogItemValues = { diff --git a/src/platform/web/Platform.js b/src/platform/web/Platform.js index 9a8a19c9..19eef367 100644 --- a/src/platform/web/Platform.js +++ b/src/platform/web/Platform.js @@ -21,8 +21,9 @@ import {SessionInfoStorage} from "../../matrix/sessioninfo/localstorage/SessionI import {SettingsStorage} from "./dom/SettingsStorage.js"; import {Encoding} from "./utils/Encoding.js"; import {OlmWorker} from "../../matrix/e2ee/OlmWorker.js"; -import {IDBLogger} from "../../logging/IDBLogger"; -import {ConsoleLogger} from "../../logging/ConsoleLogger"; +import {IDBLogPersister} from "../../logging/IDBLogPersister"; +import {ConsoleReporter} from "../../logging/ConsoleReporter"; +import {Logger} from "../../logging/Logger"; import {RootView} from "./ui/RootView.js"; import {Clock} from "./dom/Clock.js"; import {ServiceWorkerHandler} from "./dom/ServiceWorkerHandler.js"; @@ -128,7 +129,7 @@ function adaptUIOnVisualViewportResize(container) { } export class Platform { - constructor({ container, assetPaths, config, configURL, options = null, cryptoExtras = null }) { + constructor({ container, assetPaths, config, configURL, logger, options = null, cryptoExtras = null }) { this._container = container; this._assetPaths = assetPaths; this._config = config; @@ -137,7 +138,7 @@ export class Platform { this.clock = new Clock(); this.encoding = new Encoding(); this.random = Math.random; - this._createLogger(options?.development); + this.logger = logger ?? this._createLogger(options?.development); this.history = new History(); this.onlineStatus = new OnlineStatus(); this._serviceWorkerHandler = null; @@ -185,6 +186,7 @@ export class Platform { } _createLogger(isDevelopment) { + const logger = new Logger({platform: this}); // Make sure that loginToken does not end up in the logs const transformer = (item) => { if (item.e?.stack) { @@ -192,11 +194,12 @@ export class Platform { } return item; }; + const logPersister = new IDBLogPersister({name: "hydrogen_logs", platform: this, serializedTransformer: transformer}); + logger.addReporter(logPersister); if (isDevelopment) { - this.logger = new ConsoleLogger({platform: this}); - } else { - this.logger = new IDBLogger({name: "hydrogen_logs", platform: this, serializedTransformer: transformer}); + logger.addReporter(new ConsoleReporter()); } + return logger; } get updateService() {