From 89599e9f870ee046f24a1a77264e31a3d004d244 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Thu, 11 Feb 2021 21:07:18 +0100 Subject: [PATCH 01/33] WIP --- src/domain/ViewModel.js | 19 ++-- src/logging/IDBLogger.js | 188 ++++++++++++++++++++++++++++++++ src/logging/LogItem.js | 94 ++++++++++++++++ src/logging/Logger.js | 51 +++++++++ src/matrix/storage/idb/utils.js | 2 +- 5 files changed, 343 insertions(+), 11 deletions(-) create mode 100644 src/logging/IDBLogger.js create mode 100644 src/logging/LogItem.js create mode 100644 src/logging/Logger.js diff --git a/src/domain/ViewModel.js b/src/domain/ViewModel.js index dd2d9819..f0588fc7 100644 --- a/src/domain/ViewModel.js +++ b/src/domain/ViewModel.js @@ -30,8 +30,8 @@ export class ViewModel extends EventEmitter { } childOptions(explicitOptions) { - const {navigation, urlCreator, platform} = this._options; - return Object.assign({navigation, urlCreator, platform}, explicitOptions); + const {navigation, urlCreator, platform, logger} = this._options; + return Object.assign({navigation, urlCreator, platform, logger}, explicitOptions); } // makes it easier to pass through dependencies of a sub-view model @@ -78,14 +78,9 @@ export class ViewModel extends EventEmitter { // we probably are, if we're using routing with a url, we could just refresh. i18n(parts, ...expr) { // just concat for now - let result = ""; - for (let i = 0; i < parts.length; ++i) { - result = result + parts[i]; - if (i < expr.length) { - result = result + expr[i]; - } - } - return result; + return parts.reduce((all, p, i) => { + return all + p + expr[i]; + }); } updateOptions(options) { @@ -108,6 +103,10 @@ export class ViewModel extends EventEmitter { return this._options.platform.clock; } + get logger() { + return this._options.logger; + } + /** * The url router, only meant to be used to create urls with from view models. * @return {URLRouter} diff --git a/src/logging/IDBLogger.js b/src/logging/IDBLogger.js new file mode 100644 index 00000000..1192f0b5 --- /dev/null +++ b/src/logging/IDBLogger.js @@ -0,0 +1,188 @@ +/* +Copyright 2020 Bruno Windels + +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. +*/ + +import {openDatabase, txnAsPromise, reqAsPromise, iterateCursor, fetchResults} from "../matrix/storage/idb/utils.js"; +import {LogItem} from "./LogItem.js"; + +class Logger { + constructor(clock) { + this._openItems = new Set(); + this._clock = clock; + } + + decend(label, callback, logLevel) { + const item = new LogItem(label, this, logLevel, this._clock); + + const failItem = (err) => { + item.catch(err); + finishItem(); + throw err; + }; + + const finishItem = () => { + item.finish(); + this._persistItem(item); + this._openItems.remove(item); + }; + + let result; + try { + result = callback(item); + if (result instanceof Promise) { + result = result.then(promiseResult => { + finishItem(); + return promiseResult; + }, failItem); + } + } catch (err) { + failItem(err); + } + } + + _persistItem(item) { + throw new Error("not implemented"); + } + + async extractItems() { + throw new Error("not implemented"); + } +} + +export function encodeUint64(n) { + const hex = n.toString(16); + return "0".repeat(16 - hex.length) + hex; +} + +export default class IDBLogger extends Logger { + constructor({name, clock, utf8, flushInterval = 2 * 60 * 1000, limit = 1000}) { + super(clock); + this._utf8 = utf8; + this._name = name; + this._limit = limit; + // does not get loaded from idb on startup as we only use it to + // differentiate between two items with the same start time + this._itemCounter = 0; + this._queuedItems = this._loadQueuedItems(); + window.addEventListener("pagehide", this, false); + this._flushInterval = this._clock.createInterval(() => this._tryFlush(), flushInterval); + } + + dispose() { + window.removeEventListener("pagehide", this, false); + this._flushInterval.dispose(); + } + + handleEvent(evt) { + if (evt.type === "pagehide") { + this._finishAllAndFlush(); + } + } + + async _tryFlush() { + const db = await this._openDB(); + try { + const txn = this.db.transaction(["logs"], "readwrite"); + const logs = txn.objectStore("logs"); + const amount = this._queuedItems.length; + for(const i of this._queuedItems) { + logs.add(i); + } + // trim logs if needed + const itemCount = await reqAsPromise(logs.count()); + if (itemCount > this._limit) { + let currentCount = itemCount; + await iterateCursor(logs.openCursor(), (_, __, cursor) => { + cursor.delete(); + currentCount -= 1; + return {done: currentCount <= this._limit}; + }); + } + await txnAsPromise(txn); + this._queuedItems.splice(0, amount); + } finally { + try { + db.close(); + } catch (e) {} + } + } + + _finishAllAndFlush() { + for (const openItem of this._openItems) { + openItem.finish(); + this._persistItem(openItem); + } + this._openItems.clear(); + this._persistQueuedItems(this._queuedItems); + } + + _loadQueuedItems() { + const key = `${this._name}_queuedItems`; + const json = window.localStorage.getItem(key); + if (json) { + window.localStorage.removeItem(key); + return JSON.parse(json); + } + return []; + } + + _openDB() { + return openDatabase(this._name, db => db.createObjectStore("logs", {keyPath: "id"}), 1); + } + + _persistItem(item) { + this._itemCounter += 1; + this._queuedItems.push({ + id: `${encodeUint64(item.start)}:${this._itemCounter}`, + // store as buffer so parsing overhead is lower + content: this._utf8.encode(JSON.stringify(item.serialize())) + }); + } + + _persistQueuedItems(items) { + window.localStorage.setItem(`${this._name}_queuedItems`, JSON.stringify(items)); + } + + // should we actually delete items and just not rely on trimming for it not to grow too large? + // just worried that people will create a file, not do anything with it, hit export logs again and then + // send a mostly empty file. we could just not delete but in _tryFlush (and perhaps make trimming delete a few more than needed to be below limit) + // how does eleweb handle this? + // + // both deletes and reads items from store + async extractItems() { + const db = this._openDB(); + try { + const queuedItems = this._queuedItems.slice(); + const txn = this.db.transaction(["logs"], "readwrite"); + const logs = txn.objectStore("logs"); + const items = await fetchResults(logs.openCursor(), () => false); + // we know we have read all the items as we're doing this in a txn + logs.clear(); + await txnAsPromise(txn); + // once the transaction is complete, remove the queued items + this._queuedItems.splice(0, queuedItems.length); + const sortedItems = items.concat(queuedItems).sort((a, b) => { + return a.id > b.id; + }).map(i => { + + }); + return sortedItems; + } finally { + try { + db.close(); + } catch (e) {} + } + } +} diff --git a/src/logging/LogItem.js b/src/logging/LogItem.js new file mode 100644 index 00000000..7136cf56 --- /dev/null +++ b/src/logging/LogItem.js @@ -0,0 +1,94 @@ +/* +Copyright 2020 Bruno Windels + +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. +*/ + +export class LogItem { + constructor(label, parent, logLevel, clock) { + this._clock = clock; + this._start = clock.now(); + this._end = null; + this._values = {label}; + this._parent = parent; + this._error = null; + this._children = []; + this._logLevel = logLevel; + } + + // should this handle errors in the same way as logger.descend/start? + descend(label, logLevel = this._logLevel) { + if (this._end !== null) { + throw new Error("can't descend on finished item"); + } + const item = new LogItem(label, logLevel); + this._children.push(item); + return item; + } + + set(key, value) { + if(typeof key === "object") { + const values = key; + Object.assign(this._values, values); + } else { + this._values[key] = value; + } + } + + // XXX: where will this be called? from wrapAsync? + finish() { + if (this._end === null) { + for(const c of this._children) { + c.finish(); + } + this._end = this._clock.now(); + if (this._parent) { + this._parent._closeChild(this); + } + } + } + + catch(err) { + this._error = err; + console.error(`log item ${this.values.label} failed: ${err.message}:\n${err.stack}`); + } + + serialize() { + let error; + if (this._error) { + error = { + message: this._error.message, + stack: this._error.stack, + }; + } + return { + start: this._start, + end: this._end, + values: this._values, + error, + children: this._children.map(c => c.serialize()), + logLevel: this._logLevel + }; + } + + async wrapAsync(fn) { + try { + const ret = await fn(this); + this.finish(); + return ret; + } catch (err) { + this.fail(err); + throw err; + } + } +} diff --git a/src/logging/Logger.js b/src/logging/Logger.js new file mode 100644 index 00000000..98654aad --- /dev/null +++ b/src/logging/Logger.js @@ -0,0 +1,51 @@ +/* +Copyright 2020 Bruno Windels + +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. +*/ + +import {LogItem} from "./LogItem.js"; + +export class Logger { + constructor(persister) { + this._openItems = []; + this._persister = persister; + this._closing = false; + } + + restore() { + const items = this._persister.loadTempItems(); + return this._persister.persistItems(items); + } + + start(label, logLevel) { + const item = new LogItem(label, logLevel, this); + this._openItems.push(item); + return item; + } + + _closeChild(item) { + if (!this._closing) { + this._persister.persistItems([item.serialize()]); + } + } + + close() { + this._closing = true; + for(const i of this._openItems) { + i.finish(); + } + this._closing = false; + this._persister.persistTempItems(this._openItems.map(i => i.serialize())); + } +} diff --git a/src/matrix/storage/idb/utils.js b/src/matrix/storage/idb/utils.js index 9d3a42d9..e06fa3a0 100644 --- a/src/matrix/storage/idb/utils.js +++ b/src/matrix/storage/idb/utils.js @@ -110,7 +110,7 @@ export function iterateCursor(cursorRequest, processValue) { needsSyncPromise && Promise._flush && Promise._flush(); return; // end of results } - const result = processValue(cursor.value, cursor.key); + const result = processValue(cursor.value, cursor.key, cursor); // TODO: don't use object for result and assume it's jumpTo when not === true/false or undefined const done = result?.done; const jumpTo = result?.jumpTo; From 91bd5f638c7da75882aba359f19ea8bc8ad7cb97 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Fri, 12 Feb 2021 13:04:05 +0100 Subject: [PATCH 02/33] finish logging api --- src/logging/BaseLogger.js | 60 ++++++++++++ src/logging/IDBLogger.js | 160 ++++++++++++++++---------------- src/logging/LogItem.js | 115 ++++++++++++++++------- src/logging/Logger.js | 51 ---------- src/matrix/storage/idb/utils.js | 6 ++ 5 files changed, 226 insertions(+), 166 deletions(-) create mode 100644 src/logging/BaseLogger.js delete mode 100644 src/logging/Logger.js diff --git a/src/logging/BaseLogger.js b/src/logging/BaseLogger.js new file mode 100644 index 00000000..64405279 --- /dev/null +++ b/src/logging/BaseLogger.js @@ -0,0 +1,60 @@ +/* +Copyright 2020 Bruno Windels + +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. +*/ + +import {LogItem} from "./LogItem.js"; + +export class BaseLogger { + constructor(platform) { + this._openItems = new Set(); + this._platform = platform; + } + + wrapLog(labelOrValues, callback, logLevel) { + const item = new LogItem(labelOrValues, logLevel, this._platform); + + const finishItem = () => { + this._persistItem(item); + this._openItems.remove(item); + }; + + try { + const result = item.run(callback); + if (result instanceof Promise) { + return result.then(promiseResult => { + finishItem(); + return promiseResult; + }, err => { + finishItem(); + throw err; + }); + } else { + finishItem(); + return result; + } + } catch (err) { + finishItem(); + throw err; + } + } + + _persistItem(item) { + throw new Error("not implemented"); + } + + async export() { + throw new Error("not implemented"); + } +} diff --git a/src/logging/IDBLogger.js b/src/logging/IDBLogger.js index 1192f0b5..672df9e7 100644 --- a/src/logging/IDBLogger.js +++ b/src/logging/IDBLogger.js @@ -14,68 +14,27 @@ See the License for the specific language governing permissions and limitations under the License. */ -import {openDatabase, txnAsPromise, reqAsPromise, iterateCursor, fetchResults} from "../matrix/storage/idb/utils.js"; -import {LogItem} from "./LogItem.js"; +import { + openDatabase, + txnAsPromise, + reqAsPromise, + iterateCursor, + fetchResults, + encodeUint64 +} from "../matrix/storage/idb/utils.js"; +import {BaseLogger} from "./BaseLogger.js"; -class Logger { - constructor(clock) { - this._openItems = new Set(); - this._clock = clock; - } - - decend(label, callback, logLevel) { - const item = new LogItem(label, this, logLevel, this._clock); - - const failItem = (err) => { - item.catch(err); - finishItem(); - throw err; - }; - - const finishItem = () => { - item.finish(); - this._persistItem(item); - this._openItems.remove(item); - }; - - let result; - try { - result = callback(item); - if (result instanceof Promise) { - result = result.then(promiseResult => { - finishItem(); - return promiseResult; - }, failItem); - } - } catch (err) { - failItem(err); - } - } - - _persistItem(item) { - throw new Error("not implemented"); - } - - async extractItems() { - throw new Error("not implemented"); - } -} - -export function encodeUint64(n) { - const hex = n.toString(16); - return "0".repeat(16 - hex.length) + hex; -} - -export default class IDBLogger extends Logger { - constructor({name, clock, utf8, flushInterval = 2 * 60 * 1000, limit = 1000}) { - super(clock); - this._utf8 = utf8; +export class IDBLogger extends BaseLogger { + constructor({name, platform, flushInterval = 2 * 60 * 1000, limit = 3000}) { + super(platform); this._name = name; this._limit = limit; // does not get loaded from idb on startup as we only use it to // differentiate between two items with the same start time this._itemCounter = 0; this._queuedItems = this._loadQueuedItems(); + // TODO: add dirty flag when calling descend + // TODO: also listen for unload just in case sync keeps on running after pagehide is fired? window.addEventListener("pagehide", this, false); this._flushInterval = this._clock.createInterval(() => this._tryFlush(), flushInterval); } @@ -100,6 +59,7 @@ export default class IDBLogger extends Logger { for(const i of this._queuedItems) { logs.add(i); } + // TODO: delete more than needed so we don't delete on every flush? // trim logs if needed const itemCount = await reqAsPromise(logs.count()); if (itemCount > this._limit) { @@ -130,11 +90,13 @@ export default class IDBLogger extends Logger { _loadQueuedItems() { const key = `${this._name}_queuedItems`; - const json = window.localStorage.getItem(key); - if (json) { - window.localStorage.removeItem(key); - return JSON.parse(json); - } + try { + const json = window.localStorage.getItem(key); + if (json) { + window.localStorage.removeItem(key); + return JSON.parse(json); + } + } catch (e) {} return []; } @@ -146,39 +108,49 @@ export default class IDBLogger extends Logger { this._itemCounter += 1; this._queuedItems.push({ id: `${encodeUint64(item.start)}:${this._itemCounter}`, - // store as buffer so parsing overhead is lower - content: this._utf8.encode(JSON.stringify(item.serialize())) + tree: item.serialize() }); } _persistQueuedItems(items) { - window.localStorage.setItem(`${this._name}_queuedItems`, JSON.stringify(items)); + try { + window.localStorage.setItem(`${this._name}_queuedItems`, JSON.stringify(items)); + } catch (e) { + console.warn("Could not persist queued log items in localStorage, they will likely be lost", e); + } } - // should we actually delete items and just not rely on trimming for it not to grow too large? - // just worried that people will create a file, not do anything with it, hit export logs again and then - // send a mostly empty file. we could just not delete but in _tryFlush (and perhaps make trimming delete a few more than needed to be below limit) - // how does eleweb handle this? - // - // both deletes and reads items from store - async extractItems() { + async export() { const db = this._openDB(); try { - const queuedItems = this._queuedItems.slice(); - const txn = this.db.transaction(["logs"], "readwrite"); + const txn = this.db.transaction(["logs"], "readonly"); const logs = txn.objectStore("logs"); const items = await fetchResults(logs.openCursor(), () => false); - // we know we have read all the items as we're doing this in a txn - logs.clear(); - await txnAsPromise(txn); - // once the transaction is complete, remove the queued items - this._queuedItems.splice(0, queuedItems.length); - const sortedItems = items.concat(queuedItems).sort((a, b) => { + const sortedItems = items.concat(this._queuedItems).sort((a, b) => { return a.id > b.id; - }).map(i => { - }); - return sortedItems; + return new IDBLogExport(sortedItems, this, this._platform); + } finally { + try { + db.close(); + } catch (e) {} + } + } + + async _removeItems(items) { + const db = this._openDB(); + try { + const txn = this.db.transaction(["logs"], "readwrite"); + const logs = txn.objectStore("logs"); + for (const item of items) { + const queuedIdx = this._queuedItems.findIndex(i => i.id === item.id); + if (queuedIdx === -1) { + logs.delete(item.id); + } else { + this._queuedItems.splice(queuedIdx, 1); + } + } + await txnAsPromise(txn); } finally { try { db.close(); @@ -186,3 +158,29 @@ export default class IDBLogger extends Logger { } } } + +class IDBLogExport { + constructor(items, logger, platform) { + this._items = items; + this._logger = logger; + this._platform = platform; + } + + /** + * @return {Promise} + */ + removeFromStore() { + return this._logger._removeItems(this._items); + } + + asBlob() { + const log = { + version: 1, + items: this._items + }; + const json = JSON.stringify(log); + const buffer = this._platform.utf8.encode(json); + const blob = this._platform.createBlob(buffer, "application/json"); + return blob; + } +} diff --git a/src/logging/LogItem.js b/src/logging/LogItem.js index 7136cf56..2d875fe2 100644 --- a/src/logging/LogItem.js +++ b/src/logging/LogItem.js @@ -15,25 +15,33 @@ limitations under the License. */ export class LogItem { - constructor(label, parent, logLevel, clock) { - this._clock = clock; - this._start = clock.now(); + constructor(labelOrValues, logLevel, platform) { + this._platform = platform; + this._start = platform.clock.now(); this._end = null; - this._values = {label}; - this._parent = parent; + this._values = typeof labelOrValues === "string" ? {label: labelOrValues} : labelOrValues; this._error = null; this._children = []; this._logLevel = logLevel; } - // should this handle errors in the same way as logger.descend/start? - descend(label, logLevel = this._logLevel) { - if (this._end !== null) { - throw new Error("can't descend on finished item"); - } - const item = new LogItem(label, logLevel); - this._children.push(item); - return item; + /** + * Creates a new child item and runs it in `callback`. + */ + wrap(labelOrValues, callback, logLevel = this._logLevel) { + const item = this._createChild(labelOrValues, logLevel); + return item.run(callback); + } + + /** + * Creates a new child item that finishes immediately + * and can hence not be modified anymore. + * + * Hence, the child item is not returned. + */ + log(labelOrValues, logLevel = this._logLevel) { + const item = this._createChild(labelOrValues, logLevel); + item.end = item.start; } set(key, value) { @@ -45,22 +53,9 @@ export class LogItem { } } - // XXX: where will this be called? from wrapAsync? - finish() { - if (this._end === null) { - for(const c of this._children) { - c.finish(); - } - this._end = this._clock.now(); - if (this._parent) { - this._parent._closeChild(this); - } - } - } - - catch(err) { - this._error = err; - console.error(`log item ${this.values.label} failed: ${err.message}:\n${err.stack}`); + anonymize(value) { + const buffer = this._platform.crypto.digest("SHA-256", value); + return this._platform.base64.encode(buffer); } serialize() { @@ -81,14 +76,66 @@ export class LogItem { }; } - async wrapAsync(fn) { + /** + * You probably want to use `wrap` instead of this. + * + * Runs a callback passing this log item, + * recording the timing and any error. + * + * callback can return a Promise. + * + * Can only be called once, and will throw after. + * + * @param {Function} callback [description] + * @return {[type]} [description] + */ + run(callback) { + if (this._end !== null) { + throw new Error("item is finished"); + } + let result; try { - const ret = await fn(this); - this.finish(); - return ret; + result = callback(this); + if (result instanceof Promise) { + return result.then(promiseResult => { + this._finish(); + return promiseResult; + }, err => { + this._catch(err); + this._finish(); + throw err; + }); + } else { + this._finish(); + return result; + } } catch (err) { - this.fail(err); + this._catch(err); + this._finish(); throw err; } } + + _catch(err) { + this._error = err; + console.error(`log item ${this.values.label} failed: ${err.message}:\n${err.stack}`); + } + + _createChild(labelOrValues, logLevel) { + if (this._end !== null) { + throw new Error("item is finished"); + } + const item = new LogItem(labelOrValues, logLevel, this._platform); + this._children.push(item); + return item; + } + + _finish() { + if (this._end === null) { + for(const c of this._children) { + c._finish(); + } + this._end = this._platform.clock.now(); + } + } } diff --git a/src/logging/Logger.js b/src/logging/Logger.js deleted file mode 100644 index 98654aad..00000000 --- a/src/logging/Logger.js +++ /dev/null @@ -1,51 +0,0 @@ -/* -Copyright 2020 Bruno Windels - -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. -*/ - -import {LogItem} from "./LogItem.js"; - -export class Logger { - constructor(persister) { - this._openItems = []; - this._persister = persister; - this._closing = false; - } - - restore() { - const items = this._persister.loadTempItems(); - return this._persister.persistItems(items); - } - - start(label, logLevel) { - const item = new LogItem(label, logLevel, this); - this._openItems.push(item); - return item; - } - - _closeChild(item) { - if (!this._closing) { - this._persister.persistItems([item.serialize()]); - } - } - - close() { - this._closing = true; - for(const i of this._openItems) { - i.finish(); - } - this._closing = false; - this._persister.persistTempItems(this._openItems.map(i => i.serialize())); - } -} diff --git a/src/matrix/storage/idb/utils.js b/src/matrix/storage/idb/utils.js index e06fa3a0..9fa8c55a 100644 --- a/src/matrix/storage/idb/utils.js +++ b/src/matrix/storage/idb/utils.js @@ -54,6 +54,12 @@ export function encodeUint32(n) { return "0".repeat(8 - hex.length) + hex; } +// used for logs where timestamp is part of key, which is larger than 32 bit +export function encodeUint64(n) { + const hex = n.toString(16); + return "0".repeat(16 - hex.length) + hex; +} + export function decodeUint32(str) { return parseInt(str, 16); } From 4c2abcf9c713951c7b3e0f613c092c908abcb1ed Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Fri, 12 Feb 2021 13:04:18 +0100 Subject: [PATCH 03/33] add logger to platform --- src/platform/web/Platform.js | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/platform/web/Platform.js b/src/platform/web/Platform.js index d2e532af..73dca9c2 100644 --- a/src/platform/web/Platform.js +++ b/src/platform/web/Platform.js @@ -21,6 +21,7 @@ import {SessionInfoStorage} from "../../matrix/sessioninfo/localstorage/SessionI import {SettingsStorage} from "./dom/SettingsStorage.js"; import {UTF8} from "./dom/UTF8.js"; import {OlmWorker} from "../../matrix/e2ee/OlmWorker.js"; +import {IDBLogger} from "../../logs/IDBLogger.js"; import {RootView} from "./ui/RootView.js"; import {Clock} from "./dom/Clock.js"; import {ServiceWorkerHandler} from "./dom/ServiceWorkerHandler.js"; @@ -85,6 +86,7 @@ export class Platform { this._paths = paths; this._container = container; this.utf8 = new UTF8(); + this.logger = new IDBLogger("hydrogen_logs", this); this.clock = new Clock(); this.history = new History(); this.onlineStatus = new OnlineStatus(); From 0763410aa1fd204f6b3d5cf61292c7afcc77f849 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Fri, 12 Feb 2021 14:05:51 +0100 Subject: [PATCH 04/33] filter output when serializing by loglevel --- src/logging/BaseLogger.js | 29 +++++++++++++++++--- src/logging/IDBLogger.js | 12 +++----- src/logging/LogItem.js | 58 ++++++++++++++++++++++++++++----------- src/logging/LogLevel.js | 25 +++++++++++++++++ 4 files changed, 96 insertions(+), 28 deletions(-) create mode 100644 src/logging/LogLevel.js diff --git a/src/logging/BaseLogger.js b/src/logging/BaseLogger.js index 64405279..772b2c62 100644 --- a/src/logging/BaseLogger.js +++ b/src/logging/BaseLogger.js @@ -15,18 +15,23 @@ limitations under the License. */ import {LogItem} from "./LogItem.js"; +import {LogLevel} from "./LogLevel.js"; export class BaseLogger { - constructor(platform) { + constructor(platform, baseLogLevel) { this._openItems = new Set(); this._platform = platform; + this._baseLogLevel = baseLogLevel; } - wrapLog(labelOrValues, callback, logLevel) { + wrapLog(labelOrValues, callback, logLevel = this._baseLogLevel) { const item = new LogItem(labelOrValues, logLevel, this._platform); const finishItem = () => { - this._persistItem(item); + const serialized = item.serialize(this._baseLogLevel); + if (serialized) { + this._persistItem(serialized); + } this._openItems.remove(item); }; @@ -50,11 +55,27 @@ export class BaseLogger { } } - _persistItem(item) { + _finishOpenItems() { + for (const openItem of this._openItems) { + openItem.finish(); + const serialized = openItem.serialize(this._baseLogLevel); + if (serialized) { + this._persistItem(serialized); + } + } + this._openItems.clear(); + } + + _persistItem() { throw new Error("not implemented"); } async export() { throw new Error("not implemented"); } + + // expose log level without needing + get level() { + return LogLevel; + } } diff --git a/src/logging/IDBLogger.js b/src/logging/IDBLogger.js index 672df9e7..c3a2ac1f 100644 --- a/src/logging/IDBLogger.js +++ b/src/logging/IDBLogger.js @@ -80,11 +80,7 @@ export class IDBLogger extends BaseLogger { } _finishAllAndFlush() { - for (const openItem of this._openItems) { - openItem.finish(); - this._persistItem(openItem); - } - this._openItems.clear(); + this._finishOpenItems(); this._persistQueuedItems(this._queuedItems); } @@ -104,11 +100,11 @@ export class IDBLogger extends BaseLogger { return openDatabase(this._name, db => db.createObjectStore("logs", {keyPath: "id"}), 1); } - _persistItem(item) { + _persistItem(serializedItem) { this._itemCounter += 1; this._queuedItems.push({ - id: `${encodeUint64(item.start)}:${this._itemCounter}`, - tree: item.serialize() + id: `${encodeUint64(serializedItem.start)}:${this._itemCounter}`, + tree: serializedItem }); } diff --git a/src/logging/LogItem.js b/src/logging/LogItem.js index 2d875fe2..7fb659ee 100644 --- a/src/logging/LogItem.js +++ b/src/logging/LogItem.js @@ -14,6 +14,8 @@ See the License for the specific language governing permissions and limitations under the License. */ +import {LogLevel} from "./LogLevel.js"; + export class LogItem { constructor(labelOrValues, logLevel, platform) { this._platform = platform; @@ -58,8 +60,22 @@ export class LogItem { return this._platform.base64.encode(buffer); } - serialize() { - let error; + serialize(logLevel) { + const children = this._children.reduce((array, c) => { + const s = c.serialize(logLevel); + if (s) { + array = array || []; + array.push(s); + } + return array; + }, null); + + // neither our children or us have a loglevel high enough, bail out. + if (!children && this._logLevel < logLevel) { + return null; + } + + let error = null; if (this._error) { error = { message: this._error.message, @@ -71,7 +87,7 @@ export class LogItem { end: this._end, values: this._values, error, - children: this._children.map(c => c.serialize()), + children, logLevel: this._logLevel }; } @@ -98,26 +114,45 @@ export class LogItem { result = callback(this); if (result instanceof Promise) { return result.then(promiseResult => { - this._finish(); + this.finish(); return promiseResult; }, err => { this._catch(err); - this._finish(); + this.finish(); throw err; }); } else { - this._finish(); + this.finish(); return result; } } catch (err) { this._catch(err); - this._finish(); + this.finish(); throw err; } } + /** + * finished the item, recording the end time. After finishing, an item can't be modified anymore as it will be persisted. + * @internal shouldn't typically be called by hand. allows to force finish if a promise is still running when closing the app + */ + finish() { + if (this._end === null) { + for(const c of this._children) { + c.finish(); + } + this._end = this._platform.clock.now(); + } + } + + // expose log level without needing + get level() { + return LogLevel; + } + _catch(err) { this._error = err; + this._logLevel = LogLevel.Error; console.error(`log item ${this.values.label} failed: ${err.message}:\n${err.stack}`); } @@ -129,13 +164,4 @@ export class LogItem { this._children.push(item); return item; } - - _finish() { - if (this._end === null) { - for(const c of this._children) { - c._finish(); - } - this._end = this._platform.clock.now(); - } - } } diff --git a/src/logging/LogLevel.js b/src/logging/LogLevel.js new file mode 100644 index 00000000..3580a5de --- /dev/null +++ b/src/logging/LogLevel.js @@ -0,0 +1,25 @@ +/* +Copyright 2020 Bruno Windels + +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. +*/ + +export const LogLevel = { + All: 1, + Debug: 2, + Info: 3, + Warn: 4, + Error: 5, + Fatal: 6, + Off: 7, +} From 2bb7b3b5985898cb81a65a1ffd6a46daa5d1bee1 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Fri, 12 Feb 2021 14:06:09 +0100 Subject: [PATCH 05/33] add null logger --- src/logging/NullLogger.js | 47 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 47 insertions(+) create mode 100644 src/logging/NullLogger.js diff --git a/src/logging/NullLogger.js b/src/logging/NullLogger.js new file mode 100644 index 00000000..b9803e55 --- /dev/null +++ b/src/logging/NullLogger.js @@ -0,0 +1,47 @@ +/* +Copyright 2020 Bruno Windels + +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. +*/ +import {LogLevel} from "./LogLevel.js"; + +export class NullLogger { + constructor() { + this._item = new NullLogItem(); + } + + wrapLog(_, callback) { + callback(this._item); + } + + async export() { + return null; + } + + get level() { + return LogLevel; + } +} + +class NullLogItem { + wrap(_, callback) { + callback(this); + } + log() {} + set() {} + anonymize() {} + + get level() { + return LogLevel; + } +} From bbab1e9ecc7c4cceede1d8e4f9026c68936bc404 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Fri, 12 Feb 2021 16:01:54 +0100 Subject: [PATCH 06/33] move base64/58 encoding into platform fixes https://github.com/vector-im/hydrogen-web/issues/99 --- src/matrix/Session.js | 7 ++++- src/matrix/e2ee/attachment.js | 21 ++++---------- src/matrix/e2ee/megolm/SessionBackup.js | 6 ++-- src/matrix/net/MediaRepository.js | 2 +- src/matrix/ssss/SecretStorage.js | 8 ++---- src/matrix/ssss/index.js | 2 +- src/matrix/ssss/passphrase.js | 5 ++-- src/matrix/ssss/recoveryKey.js | 5 ++-- src/platform/web/Platform.js | 4 +-- src/platform/web/dom/Crypto.js | 3 +- src/platform/web/utils/Base58.js | 27 ++++++++++++++++++ src/platform/web/utils/Base64.js | 37 +++++++++++++++++++++++++ src/platform/web/utils/Encoding.js | 27 ++++++++++++++++++ 13 files changed, 119 insertions(+), 35 deletions(-) create mode 100644 src/platform/web/utils/Base58.js create mode 100644 src/platform/web/utils/Base64.js create mode 100644 src/platform/web/utils/Encoding.js diff --git a/src/matrix/Session.js b/src/matrix/Session.js index 9952414c..17e4001f 100644 --- a/src/matrix/Session.js +++ b/src/matrix/Session.js @@ -207,7 +207,12 @@ export class Session { async _createSessionBackup(ssssKey, txn) { const secretStorage = new SecretStorage({key: ssssKey, platform: this._platform}); - this._sessionBackup = await SessionBackup.fromSecretStorage({olm: this._olm, secretStorage, hsApi: this._hsApi, txn}); + this._sessionBackup = await SessionBackup.fromSecretStorage({ + platform: this._platform, + olm: this._olm, secretStorage, + hsApi: this._hsApi, + txn + }); if (this._sessionBackup) { for (const room of this._rooms.values()) { if (room.isEncrypted) { diff --git a/src/matrix/e2ee/attachment.js b/src/matrix/e2ee/attachment.js index 3ead83eb..647cced8 100644 --- a/src/matrix/e2ee/attachment.js +++ b/src/matrix/e2ee/attachment.js @@ -14,8 +14,6 @@ See the License for the specific language governing permissions and limitations under the License. */ -import base64 from "../../../lib/base64-arraybuffer/index.js"; - /** * Decrypt an attachment. * @param {ArrayBuffer} ciphertextBuffer The encrypted attachment data buffer. @@ -25,12 +23,14 @@ import base64 from "../../../lib/base64-arraybuffer/index.js"; * @param {string} info.hashes.sha256 Base64 encoded SHA-256 hash of the ciphertext. * @return {Promise} A promise that resolves with an ArrayBuffer when the attachment is decrypted. */ -export async function decryptAttachment(crypto, ciphertextBuffer, info) { +export async function decryptAttachment(platform, ciphertextBuffer, info) { if (info === undefined || info.key === undefined || info.iv === undefined || info.hashes === undefined || info.hashes.sha256 === undefined) { throw new Error("Invalid info. Missing info.key, info.iv or info.hashes.sha256 key"); } + const {crypto} = platform; + const {base64} = platform.encoding; var ivArray = base64.decode(info.iv); // re-encode to not deal with padded vs unpadded var expectedSha256base64 = base64.encode(base64.decode(info.hashes.sha256)); @@ -59,6 +59,7 @@ export async function decryptAttachment(crypto, ciphertextBuffer, info) { export async function encryptAttachment(platform, blob) { const {crypto} = platform; + const {base64} = platform.encoding; const iv = await crypto.aes.generateIV(); const key = await crypto.aes.generateKey("jwk", 256); const buffer = await blob.readAsBuffer(); @@ -69,20 +70,10 @@ export async function encryptAttachment(platform, blob) { info: { v: "v2", key, - iv: encodeUnpaddedBase64(iv), + iv: base64.encodeUnpadded(iv), hashes: { - sha256: encodeUnpaddedBase64(digest) + sha256: base64.encodeUnpadded(digest) } } }; } - -function encodeUnpaddedBase64(buffer) { - const str = base64.encode(buffer); - const paddingIdx = str.indexOf("="); - if (paddingIdx !== -1) { - return str.substr(0, paddingIdx); - } else { - return str; - } -} diff --git a/src/matrix/e2ee/megolm/SessionBackup.js b/src/matrix/e2ee/megolm/SessionBackup.js index a5095311..e4c3788c 100644 --- a/src/matrix/e2ee/megolm/SessionBackup.js +++ b/src/matrix/e2ee/megolm/SessionBackup.js @@ -14,8 +14,6 @@ See the License for the specific language governing permissions and limitations under the License. */ -import base64 from "../../../../lib/base64-arraybuffer/index.js"; - export class SessionBackup { constructor({backupInfo, decryption, hsApi}) { this._backupInfo = backupInfo; @@ -41,10 +39,10 @@ export class SessionBackup { this._decryption.free(); } - static async fromSecretStorage({olm, secretStorage, hsApi, txn}) { + static async fromSecretStorage({platform, olm, secretStorage, hsApi, txn}) { const base64PrivateKey = await secretStorage.readSecret("m.megolm_backup.v1", txn); if (base64PrivateKey) { - const privateKey = new Uint8Array(base64.decode(base64PrivateKey)); + const privateKey = new Uint8Array(platform.encoding.base64.decode(base64PrivateKey)); const backupInfo = await hsApi.roomKeysVersion().response(); const expectedPubKey = backupInfo.auth_data.public_key; const decryption = new olm.PkDecryption(); diff --git a/src/matrix/net/MediaRepository.js b/src/matrix/net/MediaRepository.js index 7bd20cce..f7e47cfd 100644 --- a/src/matrix/net/MediaRepository.js +++ b/src/matrix/net/MediaRepository.js @@ -55,7 +55,7 @@ export class MediaRepository { async downloadEncryptedFile(fileEntry, cache = false) { const url = this.mxcUrl(fileEntry.url); const {body: encryptedBuffer} = await this._platform.request(url, {method: "GET", format: "buffer", cache}).response(); - const decryptedBuffer = await decryptAttachment(this._platform.crypto, encryptedBuffer, fileEntry); + const decryptedBuffer = await decryptAttachment(this._platform, encryptedBuffer, fileEntry); return this._platform.createBlob(decryptedBuffer, fileEntry.mimetype); } diff --git a/src/matrix/ssss/SecretStorage.js b/src/matrix/ssss/SecretStorage.js index 2b5a702f..04597084 100644 --- a/src/matrix/ssss/SecretStorage.js +++ b/src/matrix/ssss/SecretStorage.js @@ -14,8 +14,6 @@ See the License for the specific language governing permissions and limitations under the License. */ -import base64 from "../../../lib/base64-arraybuffer/index.js"; - export class SecretStorage { constructor({key, platform}) { this._key = key; @@ -40,17 +38,17 @@ export class SecretStorage { } async _decryptAESSecret(type, encryptedData) { + const {base64, utf8} = this._platform.encoding; // now derive the aes and mac key from the 4s key const hkdfKey = await this._platform.crypto.derive.hkdf( this._key.binaryKey, new Uint8Array(8).buffer, //zero salt - this._platform.utf8.encode(type), // info + utf8.encode(type), // info "SHA-256", 512 // 512 bits or 64 bytes ); const aesKey = hkdfKey.slice(0, 32); const hmacKey = hkdfKey.slice(32); - const ciphertextBytes = base64.decode(encryptedData.ciphertext); const isVerified = await this._platform.crypto.hmac.verify( @@ -67,6 +65,6 @@ export class SecretStorage { data: ciphertextBytes }); - return this._platform.utf8.decode(plaintextBytes); + return utf8.decode(plaintextBytes); } } diff --git a/src/matrix/ssss/index.js b/src/matrix/ssss/index.js index 1d8fea17..66ea3ea0 100644 --- a/src/matrix/ssss/index.js +++ b/src/matrix/ssss/index.js @@ -56,7 +56,7 @@ export async function keyFromCredential(type, credential, storage, platform, olm if (type === "phrase") { key = await keyFromPassphrase(keyDescription, credential, platform); } else if (type === "key") { - key = keyFromRecoveryKey(olm, keyDescription, credential); + key = keyFromRecoveryKey(keyDescription, credential, olm, platform); } else { throw new Error(`Invalid type: ${type}`); } diff --git a/src/matrix/ssss/passphrase.js b/src/matrix/ssss/passphrase.js index 828d15d9..681e4548 100644 --- a/src/matrix/ssss/passphrase.js +++ b/src/matrix/ssss/passphrase.js @@ -33,11 +33,12 @@ export async function keyFromPassphrase(keyDescription, passphrase, platform) { if (passphraseParams.algorithm !== "m.pbkdf2") { throw new Error(`Unsupported passphrase algorithm: ${passphraseParams.algorithm}`); } + const {utf8} = platform.encoding; const keyBits = await platform.crypto.derive.pbkdf2( - platform.utf8.encode(passphrase), + utf8.encode(passphrase), passphraseParams.iterations || DEFAULT_ITERATIONS, // salt is just a random string, not encoded in any way - platform.utf8.encode(passphraseParams.salt), + utf8.encode(passphraseParams.salt), "SHA-512", passphraseParams.bits || DEFAULT_BITSIZE); return new Key(keyDescription, keyBits); diff --git a/src/matrix/ssss/recoveryKey.js b/src/matrix/ssss/recoveryKey.js index 5d2b1d7a..bfe132a4 100644 --- a/src/matrix/ssss/recoveryKey.js +++ b/src/matrix/ssss/recoveryKey.js @@ -13,7 +13,6 @@ 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 bs58 from "../../../lib/bs58/index.js"; import {Key} from "./common.js"; const OLM_RECOVERY_KEY_PREFIX = [0x8B, 0x01]; @@ -24,8 +23,8 @@ const OLM_RECOVERY_KEY_PREFIX = [0x8B, 0x01]; * @param {string} recoveryKey * @return {Key} */ -export function keyFromRecoveryKey(olm, keyDescription, recoveryKey) { - const result = bs58.decode(recoveryKey.replace(/ /g, '')); +export function keyFromRecoveryKey(keyDescription, recoveryKey, olm, platform) { + const result = platform.encoding.base58.decode(recoveryKey.replace(/ /g, '')); let parity = 0; for (const b of result) { diff --git a/src/platform/web/Platform.js b/src/platform/web/Platform.js index 73dca9c2..e5300779 100644 --- a/src/platform/web/Platform.js +++ b/src/platform/web/Platform.js @@ -19,7 +19,7 @@ import {xhrRequest} from "./dom/request/xhr.js"; import {StorageFactory} from "../../matrix/storage/idb/StorageFactory.js"; import {SessionInfoStorage} from "../../matrix/sessioninfo/localstorage/SessionInfoStorage.js"; import {SettingsStorage} from "./dom/SettingsStorage.js"; -import {UTF8} from "./dom/UTF8.js"; +import {Encoding} from "./utils/Encoding.js"; import {OlmWorker} from "../../matrix/e2ee/OlmWorker.js"; import {IDBLogger} from "../../logs/IDBLogger.js"; import {RootView} from "./ui/RootView.js"; @@ -85,8 +85,8 @@ export class Platform { constructor(container, paths, cryptoExtras = null) { this._paths = paths; this._container = container; - this.utf8 = new UTF8(); this.logger = new IDBLogger("hydrogen_logs", this); + this.encoding = new Encoding(); this.clock = new Clock(); this.history = new History(); this.onlineStatus = new OnlineStatus(); diff --git a/src/platform/web/dom/Crypto.js b/src/platform/web/dom/Crypto.js index 2362ecda..b28897fa 100644 --- a/src/platform/web/dom/Crypto.js +++ b/src/platform/web/dom/Crypto.js @@ -14,6 +14,8 @@ See the License for the specific language governing permissions and limitations under the License. */ +import base64 from "../../../../lib/base64-arraybuffer/index.js"; + // turn IE11 result into promise function subtleCryptoResult(promiseOrOp, method) { if (promiseOrOp instanceof Promise) { @@ -302,7 +304,6 @@ function rawKeyToJwk(key) { }; } -import base64 from "../../../../lib/base64-arraybuffer/index.js"; class AESLegacyCrypto { constructor(aesjs, crypto) { diff --git a/src/platform/web/utils/Base58.js b/src/platform/web/utils/Base58.js new file mode 100644 index 00000000..ebe4a969 --- /dev/null +++ b/src/platform/web/utils/Base58.js @@ -0,0 +1,27 @@ +/* +Copyright 2020 The Matrix.org Foundation C.I.C. + +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. +*/ + +import bs58 from "../../../../lib/bs58/index.js"; + +export class Base58 { + encode(buffer) { + return bs58.encode(buffer); + } + + decode(str) { + return bs58.decode(str); + } +} diff --git a/src/platform/web/utils/Base64.js b/src/platform/web/utils/Base64.js new file mode 100644 index 00000000..6c114fe6 --- /dev/null +++ b/src/platform/web/utils/Base64.js @@ -0,0 +1,37 @@ +/* +Copyright 2020 The Matrix.org Foundation C.I.C. + +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. +*/ + +import base64 from "../../../../lib/base64-arraybuffer/index.js"; + +export class Base64 { + encodeUnpadded(buffer) { + const str = base64.encode(buffer); + const paddingIdx = str.indexOf("="); + if (paddingIdx !== -1) { + return str.substr(0, paddingIdx); + } else { + return str; + } + } + + encode(buffer) { + return base64.encode(buffer); + } + + decode(str) { + return base64.decode(str); + } +} diff --git a/src/platform/web/utils/Encoding.js b/src/platform/web/utils/Encoding.js new file mode 100644 index 00000000..5f7753e5 --- /dev/null +++ b/src/platform/web/utils/Encoding.js @@ -0,0 +1,27 @@ +/* +Copyright 2020 The Matrix.org Foundation C.I.C. + +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. +*/ + +import {UTF8} from "../dom/UTF8.js"; +import {Base64} from "./Base64.js"; +import {Base58} from "./Base58.js"; + +export class Encoding { + constructor() { + this.utf8 = new UTF8(); + this.base64 = new Base64(); + this.base58 = new Base58(); + } +} From c0a03858ebc14f98a8cd1ca19fd0b61d9fd5f563 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Fri, 12 Feb 2021 16:08:07 +0100 Subject: [PATCH 07/33] add option to anonymize logged values --- src/logging/BaseLogger.js | 7 ++++--- src/logging/IDBLogger.js | 7 ++++--- src/logging/LogItem.js | 15 ++++++++++----- 3 files changed, 18 insertions(+), 11 deletions(-) diff --git a/src/logging/BaseLogger.js b/src/logging/BaseLogger.js index 772b2c62..6b2f433a 100644 --- a/src/logging/BaseLogger.js +++ b/src/logging/BaseLogger.js @@ -18,14 +18,15 @@ import {LogItem} from "./LogItem.js"; import {LogLevel} from "./LogLevel.js"; export class BaseLogger { - constructor(platform, baseLogLevel) { + constructor({platform, baseLogLevel, anonymize}) { this._openItems = new Set(); this._platform = platform; + this._anonymize = anonymize; this._baseLogLevel = baseLogLevel; } wrapLog(labelOrValues, callback, logLevel = this._baseLogLevel) { - const item = new LogItem(labelOrValues, logLevel, this._platform); + const item = new LogItem(labelOrValues, logLevel, this._platform, this._anonymize); const finishItem = () => { const serialized = item.serialize(this._baseLogLevel); @@ -73,7 +74,7 @@ export class BaseLogger { async export() { throw new Error("not implemented"); } - + // expose log level without needing get level() { return LogLevel; diff --git a/src/logging/IDBLogger.js b/src/logging/IDBLogger.js index c3a2ac1f..4ea746ac 100644 --- a/src/logging/IDBLogger.js +++ b/src/logging/IDBLogger.js @@ -25,8 +25,9 @@ import { import {BaseLogger} from "./BaseLogger.js"; export class IDBLogger extends BaseLogger { - constructor({name, platform, flushInterval = 2 * 60 * 1000, limit = 3000}) { - super(platform); + constructor(options) { + super(options); + const {name, flushInterval = 2 * 60 * 1000, limit = 3000} = options; this._name = name; this._limit = limit; // does not get loaded from idb on startup as we only use it to @@ -175,7 +176,7 @@ class IDBLogExport { items: this._items }; const json = JSON.stringify(log); - const buffer = this._platform.utf8.encode(json); + const buffer = this._platform.encoding.utf8.encode(json); const blob = this._platform.createBlob(buffer, "application/json"); return blob; } diff --git a/src/logging/LogItem.js b/src/logging/LogItem.js index 7fb659ee..a63aacbb 100644 --- a/src/logging/LogItem.js +++ b/src/logging/LogItem.js @@ -17,8 +17,9 @@ limitations under the License. import {LogLevel} from "./LogLevel.js"; export class LogItem { - constructor(labelOrValues, logLevel, platform) { + constructor(labelOrValues, logLevel, platform, anonymize) { this._platform = platform; + this._anonymize = anonymize; this._start = platform.clock.now(); this._end = null; this._values = typeof labelOrValues === "string" ? {label: labelOrValues} : labelOrValues; @@ -56,8 +57,12 @@ export class LogItem { } anonymize(value) { - const buffer = this._platform.crypto.digest("SHA-256", value); - return this._platform.base64.encode(buffer); + if (this._anonymize) { + const buffer = this._platform.crypto.digest("SHA-256", value); + return this._platform.encoding.base64.encode(buffer); + } else { + return value; + } } serialize(logLevel) { @@ -144,7 +149,7 @@ export class LogItem { this._end = this._platform.clock.now(); } } - + // expose log level without needing get level() { return LogLevel; @@ -160,7 +165,7 @@ export class LogItem { if (this._end !== null) { throw new Error("item is finished"); } - const item = new LogItem(labelOrValues, logLevel, this._platform); + const item = new LogItem(labelOrValues, logLevel, this._platform, this._anonymize); this._children.push(item); return item; } From 89139bba30f7c742c61e6387a109893a7ad76931 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Fri, 12 Feb 2021 16:08:28 +0100 Subject: [PATCH 08/33] expose some meta data on a log export to show before submitting --- src/logging/IDBLogger.js | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/src/logging/IDBLogger.js b/src/logging/IDBLogger.js index 4ea746ac..155d186a 100644 --- a/src/logging/IDBLogger.js +++ b/src/logging/IDBLogger.js @@ -163,6 +163,24 @@ class IDBLogExport { this._platform = platform; } + get minTimestamp() { + if (!this._items.length) { + return 0; + } + return this._items[0].start; + } + + get maxTimestamp() { + if (!this._items.length) { + return 0; + } + return this._items[this._items.length - 1].end; + } + + get count() { + return this._items.length; + } + /** * @return {Promise} */ From f65db338cf78be83178e702196e7dcdce5006d0c Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Fri, 12 Feb 2021 18:05:39 +0100 Subject: [PATCH 09/33] make it work --- src/logging/IDBLogger.js | 12 ++++++------ src/logging/LogItem.js | 4 ++-- src/platform/web/Platform.js | 10 +++++----- 3 files changed, 13 insertions(+), 13 deletions(-) diff --git a/src/logging/IDBLogger.js b/src/logging/IDBLogger.js index 155d186a..40237399 100644 --- a/src/logging/IDBLogger.js +++ b/src/logging/IDBLogger.js @@ -37,7 +37,7 @@ export class IDBLogger extends BaseLogger { // TODO: add dirty flag when calling descend // TODO: also listen for unload just in case sync keeps on running after pagehide is fired? window.addEventListener("pagehide", this, false); - this._flushInterval = this._clock.createInterval(() => this._tryFlush(), flushInterval); + this._flushInterval = this._platform.clock.createInterval(() => this._tryFlush(), flushInterval); } dispose() { @@ -54,7 +54,7 @@ export class IDBLogger extends BaseLogger { async _tryFlush() { const db = await this._openDB(); try { - const txn = this.db.transaction(["logs"], "readwrite"); + const txn = db.transaction(["logs"], "readwrite"); const logs = txn.objectStore("logs"); const amount = this._queuedItems.length; for(const i of this._queuedItems) { @@ -118,9 +118,9 @@ export class IDBLogger extends BaseLogger { } async export() { - const db = this._openDB(); + const db = await this._openDB(); try { - const txn = this.db.transaction(["logs"], "readonly"); + const txn = db.transaction(["logs"], "readonly"); const logs = txn.objectStore("logs"); const items = await fetchResults(logs.openCursor(), () => false); const sortedItems = items.concat(this._queuedItems).sort((a, b) => { @@ -135,9 +135,9 @@ export class IDBLogger extends BaseLogger { } async _removeItems(items) { - const db = this._openDB(); + const db = await this._openDB(); try { - const txn = this.db.transaction(["logs"], "readwrite"); + const txn = db.transaction(["logs"], "readwrite"); const logs = txn.objectStore("logs"); for (const item of items) { const queuedIdx = this._queuedItems.findIndex(i => i.id === item.id); diff --git a/src/logging/LogItem.js b/src/logging/LogItem.js index a63aacbb..02a0b941 100644 --- a/src/logging/LogItem.js +++ b/src/logging/LogItem.js @@ -58,7 +58,7 @@ export class LogItem { anonymize(value) { if (this._anonymize) { - const buffer = this._platform.crypto.digest("SHA-256", value); + const buffer = this._platform.crypto.digest("SHA-256", this._platform.encoding.utf8.encode(value)); return this._platform.encoding.base64.encode(buffer); } else { return value; @@ -83,8 +83,8 @@ export class LogItem { let error = null; if (this._error) { error = { - message: this._error.message, stack: this._error.stack, + name: this._error.name }; } return { diff --git a/src/platform/web/Platform.js b/src/platform/web/Platform.js index e5300779..7bd81471 100644 --- a/src/platform/web/Platform.js +++ b/src/platform/web/Platform.js @@ -21,7 +21,7 @@ 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 "../../logs/IDBLogger.js"; +import {IDBLogger} from "../../logging/IDBLogger.js"; import {RootView} from "./ui/RootView.js"; import {Clock} from "./dom/Clock.js"; import {ServiceWorkerHandler} from "./dom/ServiceWorkerHandler.js"; @@ -85,9 +85,11 @@ export class Platform { constructor(container, paths, cryptoExtras = null) { this._paths = paths; this._container = container; - this.logger = new IDBLogger("hydrogen_logs", this); - this.encoding = new Encoding(); + this.settingsStorage = new SettingsStorage("hydrogen_setting_v1_"); this.clock = new Clock(); + this.encoding = new Encoding(); + this.random = Math.random; + this.logger = new IDBLogger({name: "hydrogen_logs", platform: this}); this.history = new History(); this.onlineStatus = new OnlineStatus(); this._serviceWorkerHandler = null; @@ -98,9 +100,7 @@ export class Platform { this.crypto = new Crypto(cryptoExtras); this.storageFactory = new StorageFactory(this._serviceWorkerHandler); this.sessionInfoStorage = new SessionInfoStorage("hydrogen_sessions_v1"); - this.settingsStorage = new SettingsStorage("hydrogen_setting_v1_"); this.estimateStorageUsage = estimateStorageUsage; - this.random = Math.random; if (typeof fetch === "function") { this.request = createFetchRequest(this.clock.createTimeout); } else { From e6c108c6e010c91d3b2d453516756d2fe3e7b005 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Fri, 12 Feb 2021 18:06:14 +0100 Subject: [PATCH 10/33] no need to copy it over in viewmodel --- src/domain/ViewModel.js | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/domain/ViewModel.js b/src/domain/ViewModel.js index f0588fc7..10fbf580 100644 --- a/src/domain/ViewModel.js +++ b/src/domain/ViewModel.js @@ -30,8 +30,8 @@ export class ViewModel extends EventEmitter { } childOptions(explicitOptions) { - const {navigation, urlCreator, platform, logger} = this._options; - return Object.assign({navigation, urlCreator, platform, logger}, explicitOptions); + const {navigation, urlCreator, platform} = this._options; + return Object.assign({navigation, urlCreator, platform}, explicitOptions); } // makes it easier to pass through dependencies of a sub-view model @@ -104,7 +104,7 @@ export class ViewModel extends EventEmitter { } get logger() { - return this._options.logger; + return this.platform.logger; } /** From a53c25d2ae9628f1ae36905625de659c27b2fb91 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Fri, 12 Feb 2021 18:35:33 +0100 Subject: [PATCH 11/33] support logging in hsApi --- src/logging/LogItem.js | 25 +++++++++++-------------- src/logging/NullLogger.js | 12 +++++++++++- src/matrix/net/HomeServerApi.js | 31 ++++++++++++++++++++++++++----- 3 files changed, 48 insertions(+), 20 deletions(-) diff --git a/src/logging/LogItem.js b/src/logging/LogItem.js index 02a0b941..ab51d220 100644 --- a/src/logging/LogItem.js +++ b/src/logging/LogItem.js @@ -32,7 +32,7 @@ export class LogItem { * Creates a new child item and runs it in `callback`. */ wrap(labelOrValues, callback, logLevel = this._logLevel) { - const item = this._createChild(labelOrValues, logLevel); + const item = this.child(labelOrValues, logLevel); return item.run(callback); } @@ -43,7 +43,7 @@ export class LogItem { * Hence, the child item is not returned. */ log(labelOrValues, logLevel = this._logLevel) { - const item = this._createChild(labelOrValues, logLevel); + const item = this.child(labelOrValues, logLevel); item.end = item.start; } @@ -105,14 +105,14 @@ export class LogItem { * * callback can return a Promise. * - * Can only be called once, and will throw after. + * Should only be called once. * * @param {Function} callback [description] * @return {[type]} [description] */ run(callback) { if (this._end !== null) { - throw new Error("item is finished"); + console.trace("log item is finished, additional logs will likely not be recorded"); } let result; try { @@ -122,18 +122,14 @@ export class LogItem { this.finish(); return promiseResult; }, err => { - this._catch(err); - this.finish(); - throw err; + throw this.catch(err); }); } else { this.finish(); return result; } } catch (err) { - this._catch(err); - this.finish(); - throw err; + throw this.catch(err); } } @@ -155,15 +151,16 @@ export class LogItem { return LogLevel; } - _catch(err) { + catch(err) { this._error = err; this._logLevel = LogLevel.Error; - console.error(`log item ${this.values.label} failed: ${err.message}:\n${err.stack}`); + this.finish(); + return err; } - _createChild(labelOrValues, logLevel) { + child(labelOrValues, logLevel) { if (this._end !== null) { - throw new Error("item is finished"); + console.trace("log item is finished, additional logs will likely not be recorded"); } const item = new LogItem(labelOrValues, logLevel, this._platform, this._anonymize); this._children.push(item); diff --git a/src/logging/NullLogger.js b/src/logging/NullLogger.js index b9803e55..1330ba23 100644 --- a/src/logging/NullLogger.js +++ b/src/logging/NullLogger.js @@ -20,7 +20,7 @@ export class NullLogger { this._item = new NullLogItem(); } - wrapLog(_, callback) { + run(_, callback) { callback(this._item); } @@ -44,4 +44,14 @@ class NullLogItem { get level() { return LogLevel; } + + catch(err) { + return err; + } + + child() { + return this; + } + + finish() {} } diff --git a/src/matrix/net/HomeServerApi.js b/src/matrix/net/HomeServerApi.js index 935c6889..fa560db6 100644 --- a/src/matrix/net/HomeServerApi.js +++ b/src/matrix/net/HomeServerApi.js @@ -19,24 +19,34 @@ import {HomeServerError, ConnectionError} from "../error.js"; import {encodeQueryParams} from "./common.js"; class RequestWrapper { - constructor(method, url, requestResult) { + constructor(method, url, requestResult, log) { + this._log = log; this._requestResult = requestResult; this._promise = requestResult.response().then(response => { + log?.set("status", response.status); // ok? if (response.status >= 200 && response.status < 300) { + log?.finish(); return response.body; } else { if (response.status >= 400 && !response.body?.errcode) { - throw new ConnectionError(`HTTP error status ${response.status} without errcode in body, assume this is a load balancer complaining the server is offline.`); + const err = new ConnectionError(`HTTP error status ${response.status} without errcode in body, assume this is a load balancer complaining the server is offline.`); + log?.catch(err); + throw err; } else { - throw new HomeServerError(method, url, response.body, response.status); + const err = new HomeServerError(method, url, response.body, response.status); + log?.catch(err); + throw err; } } }, err => { // if this._requestResult is still set, the abort error came not from calling abort here if (err.name === "AbortError" && this._requestResult) { - throw new Error(`Request ${method} ${url} was unexpectedly aborted, see #187.`); + const err = new Error(`Unexpectedly aborted, see #187.`); + log?.catch(err); + throw err; } else { + log?.catch(err); throw err; } }); @@ -44,6 +54,7 @@ class RequestWrapper { abort() { if (this._requestResult) { + this._log?.set("aborted", true); this._requestResult.abort(); // to mark that it was on purpose in above rejection handler this._requestResult = null; @@ -93,6 +104,15 @@ export class HomeServerApi { _baseRequest(method, url, queryParams, body, options, accessToken) { const queryString = encodeQueryParams(queryParams); url = `${url}?${queryString}`; + let log; + if (options?.log) { + const parent = options?.log; + log = parent.child({ + kind: "request", + url, + method, + }, parent.level.Info); + } let encodedBody; const headers = new Map(); if (accessToken) { @@ -105,6 +125,7 @@ export class HomeServerApi { headers.set("Content-Length", encoded.length); encodedBody = encoded.body; } + const requestResult = this._requestFn(url, { method, headers, @@ -114,7 +135,7 @@ export class HomeServerApi { format: "json" // response format }); - const wrapper = new RequestWrapper(method, url, requestResult); + const wrapper = new RequestWrapper(method, url, requestResult, log); if (this._reconnector) { wrapper.response().catch(err => { From 42780df94fadc8190665706c1ba58cf6049d11fb Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Fri, 12 Feb 2021 18:36:04 +0100 Subject: [PATCH 12/33] actually track log items, and correctly remove them --- src/logging/BaseLogger.js | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/logging/BaseLogger.js b/src/logging/BaseLogger.js index 6b2f433a..830cced0 100644 --- a/src/logging/BaseLogger.js +++ b/src/logging/BaseLogger.js @@ -27,13 +27,14 @@ export class BaseLogger { wrapLog(labelOrValues, callback, logLevel = this._baseLogLevel) { const item = new LogItem(labelOrValues, logLevel, this._platform, this._anonymize); + this._openItems.add(item); const finishItem = () => { const serialized = item.serialize(this._baseLogLevel); if (serialized) { this._persistItem(serialized); } - this._openItems.remove(item); + this._openItems.delete(item); }; try { From 1183305d717d7e0a8fa303a4d0d65690bfac5a11 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Fri, 12 Feb 2021 18:36:21 +0100 Subject: [PATCH 13/33] wrapLog => run is a better name --- src/logging/BaseLogger.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/logging/BaseLogger.js b/src/logging/BaseLogger.js index 830cced0..82524167 100644 --- a/src/logging/BaseLogger.js +++ b/src/logging/BaseLogger.js @@ -25,7 +25,7 @@ export class BaseLogger { this._baseLogLevel = baseLogLevel; } - wrapLog(labelOrValues, callback, logLevel = this._baseLogLevel) { + run(labelOrValues, callback, logLevel = this._baseLogLevel) { const item = new LogItem(labelOrValues, logLevel, this._platform, this._anonymize); this._openItems.add(item); From 07f8500d29b2f7f71f5848cfb5513a7cf6536692 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Fri, 12 Feb 2021 18:55:37 +0100 Subject: [PATCH 14/33] don't read from settings for now, as it is async --- src/logging/BaseLogger.js | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/src/logging/BaseLogger.js b/src/logging/BaseLogger.js index 82524167..aa55468a 100644 --- a/src/logging/BaseLogger.js +++ b/src/logging/BaseLogger.js @@ -18,11 +18,13 @@ import {LogItem} from "./LogItem.js"; import {LogLevel} from "./LogLevel.js"; export class BaseLogger { - constructor({platform, baseLogLevel, anonymize}) { + constructor({platform}) { this._openItems = new Set(); this._platform = platform; - this._anonymize = anonymize; - this._baseLogLevel = baseLogLevel; + this._anonymize = false; //await platform.settingsStorage.getBool("anonymize", false); + this._baseLogLevel = LogLevel.Info; //await platform.settingsStorage.getInt("baseLogLevel", LogLevel.Info); + } + } run(labelOrValues, callback, logLevel = this._baseLogLevel) { From 704708bd6ce54a63f256b38132fb041f1b255578 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Fri, 12 Feb 2021 18:56:26 +0100 Subject: [PATCH 15/33] add some logging to sync --- src/matrix/SessionContainer.js | 2 +- src/matrix/Sync.js | 26 +++++++++++++++----------- src/matrix/room/Room.js | 6 ++++-- 3 files changed, 20 insertions(+), 14 deletions(-) diff --git a/src/matrix/SessionContainer.js b/src/matrix/SessionContainer.js index 3945f2ef..ebb9e07e 100644 --- a/src/matrix/SessionContainer.js +++ b/src/matrix/SessionContainer.js @@ -184,7 +184,7 @@ export class SessionContainer { await this._session.createIdentity(); } - this._sync = new Sync({hsApi: this._requestScheduler.hsApi, storage: this._storage, session: this._session}); + this._sync = new Sync({hsApi: this._requestScheduler.hsApi, storage: this._storage, session: this._session, logger: this._platform.logger}); // notify sync and session when back online this._reconnectSubscription = this._reconnector.connectionStatus.subscribe(state => { if (state === ConnectionStatus.Online) { diff --git a/src/matrix/Sync.js b/src/matrix/Sync.js index 31daff88..24a19f07 100644 --- a/src/matrix/Sync.js +++ b/src/matrix/Sync.js @@ -56,8 +56,9 @@ function timelineIsEmpty(roomResponse) { * ``` */ export class Sync { - constructor({hsApi, session, storage}) { + constructor({hsApi, session, storage, logger}) { this._hsApi = hsApi; + this._logger = logger; this._session = session; this._storage = storage; this._currentRequest = null; @@ -108,7 +109,7 @@ export class Sync { // for us. We do that by calling it with a zero timeout until it // doesn't give us any more to_device messages. const timeout = this._status.get() === SyncStatus.Syncing ? INCREMENTAL_TIMEOUT : 0; - const syncResult = await this._syncRequest(syncToken, timeout); + const syncResult = await this._logger.run("sync", log => this._syncRequest(syncToken, timeout, log)); syncToken = syncResult.syncToken; roomStates = syncResult.roomStates; sessionChanges = syncResult.sessionChanges; @@ -169,28 +170,31 @@ export class Sync { await Promise.all(roomsPromises.concat(sessionPromise)); } - async _syncRequest(syncToken, timeout) { + async _syncRequest(syncToken, timeout, log) { let {syncFilterId} = this._session; if (typeof syncFilterId !== "string") { this._currentRequest = this._hsApi.createFilter(this._session.user.id, {room: {state: {lazy_load_members: true}}}); syncFilterId = (await this._currentRequest.response()).filter_id; } const totalRequestTimeout = timeout + (80 * 1000); // same as riot-web, don't get stuck on wedged long requests - this._currentRequest = this._hsApi.sync(syncToken, syncFilterId, timeout, {timeout: totalRequestTimeout}); + this._currentRequest = this._hsApi.sync(syncToken, syncFilterId, timeout, {timeout: totalRequestTimeout, log}); const response = await this._currentRequest.response(); const isInitialSync = !syncToken; syncToken = response.next_batch; + log.set("isInitialSync", isInitialSync); + log.set("syncToken", log.anonymize(syncToken)); + log.set("status", this._status.get()); + const roomStates = this._parseRoomsResponse(response.rooms, isInitialSync); - await this._prepareRooms(roomStates); + await log.wrap("prepare rooms", log => this._prepareRooms(roomStates, log)); let sessionChanges; const syncTxn = this._openSyncTxn(); try { - sessionChanges = await this._session.writeSync(response, syncFilterId, syncTxn); + sessionChanges = await log.wrap("session.writeSync", log => this._session.writeSync(response, syncFilterId, syncTxn, log)); await Promise.all(roomStates.map(async rs => { - console.log(` * applying sync response to room ${rs.room.id} ...`); - rs.changes = await rs.room.writeSync( - rs.roomResponse, isInitialSync, rs.preparation, syncTxn); + rs.changes = await log.wrap("room.writeSync", log => rs.room.writeSync( + rs.roomResponse, isInitialSync, rs.preparation, syncTxn, log)); })); } catch(err) { // avoid corrupting state by only @@ -232,10 +236,10 @@ export class Sync { ]); } - async _prepareRooms(roomStates) { + async _prepareRooms(roomStates, log) { const prepareTxn = this._openPrepareSyncTxn(); await Promise.all(roomStates.map(async rs => { - rs.preparation = await rs.room.prepareSync(rs.roomResponse, rs.membership, prepareTxn); + rs.preparation = await log.wrap("room.prepareSync", log => rs.room.prepareSync(rs.roomResponse, rs.membership, prepareTxn, log)); })); // This is needed for safari to not throw TransactionInactiveErrors on the syncTxn. See docs/INDEXEDDB.md await prepareTxn.complete(); diff --git a/src/matrix/room/Room.js b/src/matrix/room/Room.js index 4cf9106e..1e017cf9 100644 --- a/src/matrix/room/Room.js +++ b/src/matrix/room/Room.js @@ -175,7 +175,8 @@ export class Room extends EventEmitter { return request; } - async prepareSync(roomResponse, membership, txn) { + async prepareSync(roomResponse, membership, txn, log) { + log.set("roomId", this.id); const summaryChanges = this._summary.data.applySyncResponse(roomResponse, membership) let roomEncryption = this._roomEncryption; // encryption is enabled in this sync @@ -211,7 +212,8 @@ export class Room extends EventEmitter { } /** @package */ - async writeSync(roomResponse, isInitialSync, {summaryChanges, decryptChanges, roomEncryption}, txn) { + async writeSync(roomResponse, isInitialSync, {summaryChanges, decryptChanges, roomEncryption}, txn, log) { + log.set("roomId", this.id); const {entries, newLiveKey, memberChanges} = await this._syncWriter.writeSync(roomResponse, txn); if (decryptChanges) { From 510d5ab2cdba8a812e2bde097f013c7e80eaf55b Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Fri, 12 Feb 2021 19:08:13 +0100 Subject: [PATCH 16/33] add bool settings type --- src/platform/web/dom/SettingsStorage.js | 22 +++++++++++++++++++--- 1 file changed, 19 insertions(+), 3 deletions(-) diff --git a/src/platform/web/dom/SettingsStorage.js b/src/platform/web/dom/SettingsStorage.js index 0b3e81a8..4e4c18c7 100644 --- a/src/platform/web/dom/SettingsStorage.js +++ b/src/platform/web/dom/SettingsStorage.js @@ -20,18 +20,34 @@ export class SettingsStorage { } async setInt(key, value) { - window.localStorage.setItem(`${this._prefix}${key}`, value); + this._set(key, value); } - async getInt(key) { + async getInt(key, defaultValue = 0) { const value = window.localStorage.getItem(`${this._prefix}${key}`); if (typeof value === "string") { return parseInt(value, 10); } - return; + return defaultValue; + } + + async setBool(key, value) { + this._set(key, value); + } + + async getBool(key, defaultValue = false) { + const value = window.localStorage.getItem(`${this._prefix}${key}`); + if (typeof value === "string") { + return value === "true"; + } + return defaultValue; } async remove(key) { window.localStorage.removeItem(`${this._prefix}${key}`); } + + async _set(key, value) { + window.localStorage.setItem(`${this._prefix}${key}`, value); + } } From 78805f0a655053b58671e2c798f5b7a7797e94ce Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 16 Feb 2021 11:37:48 +0100 Subject: [PATCH 17/33] implement dynamic log filtering the logger does not have a base level any more, because there is no sensible place to configure this. instead, we allow to dynamically determine what should be logged after an operation finished by setting the threshold and default log level inspecting the finished log item. --- src/logging/BaseLogger.js | 17 +++++-- src/logging/IDBLogger.js | 9 ++-- src/logging/LogFilter.js | 97 +++++++++++++++++++++++++++++++++++++++ src/logging/LogItem.js | 59 +++++++++++++++--------- src/logging/LogLevel.js | 25 ---------- src/matrix/Sync.js | 12 ++++- 6 files changed, 162 insertions(+), 57 deletions(-) create mode 100644 src/logging/LogFilter.js delete mode 100644 src/logging/LogLevel.js diff --git a/src/logging/BaseLogger.js b/src/logging/BaseLogger.js index aa55468a..b8e6d4b4 100644 --- a/src/logging/BaseLogger.js +++ b/src/logging/BaseLogger.js @@ -15,24 +15,31 @@ limitations under the License. */ import {LogItem} from "./LogItem.js"; -import {LogLevel} from "./LogLevel.js"; +import {LogLevel} from "./LogFilter.js"; export class BaseLogger { constructor({platform}) { this._openItems = new Set(); this._platform = platform; this._anonymize = false; //await platform.settingsStorage.getBool("anonymize", false); - this._baseLogLevel = LogLevel.Info; //await platform.settingsStorage.getInt("baseLogLevel", LogLevel.Info); } + get anonymize() { + return this._anonymize; } - run(labelOrValues, callback, logLevel = this._baseLogLevel) { - const item = new LogItem(labelOrValues, logLevel, this._platform, this._anonymize); + set anonymize(value) { + this._anonymize = !!value; + this._platform.settingsStorage.setBool("anonymize", this._anonymize); + } + + run(labelOrValues, callback, logFilterDef) { + const item = new LogItem(labelOrValues, logFilterDef, this._platform, this._anonymize); this._openItems.add(item); const finishItem = () => { - const serialized = item.serialize(this._baseLogLevel); + const serialized = item.serialize(null); + console.log("serialized log item", item, serialized); if (serialized) { this._persistItem(serialized); } diff --git a/src/logging/IDBLogger.js b/src/logging/IDBLogger.js index 40237399..1ac09c74 100644 --- a/src/logging/IDBLogger.js +++ b/src/logging/IDBLogger.js @@ -27,7 +27,7 @@ import {BaseLogger} from "./BaseLogger.js"; export class IDBLogger extends BaseLogger { constructor(options) { super(options); - const {name, flushInterval = 2 * 60 * 1000, limit = 3000} = options; + const {name, flushInterval = 5 * 1000, limit = 3000} = options; this._name = name; this._limit = limit; // does not get loaded from idb on startup as we only use it to @@ -104,7 +104,7 @@ export class IDBLogger extends BaseLogger { _persistItem(serializedItem) { this._itemCounter += 1; this._queuedItems.push({ - id: `${encodeUint64(serializedItem.start)}:${this._itemCounter}`, + id: `${encodeUint64(serializedItem.s)}:${this._itemCounter}`, tree: serializedItem }); } @@ -122,8 +122,9 @@ export class IDBLogger extends BaseLogger { try { const txn = db.transaction(["logs"], "readonly"); const logs = txn.objectStore("logs"); - const items = await fetchResults(logs.openCursor(), () => false); - const sortedItems = items.concat(this._queuedItems).sort((a, b) => { + const storedItems = await fetchResults(logs.openCursor(), () => false); + const allItems = storedItems.concat(this._queuedItems); + const sortedItems = allItems.sort((a, b) => { return a.id > b.id; }); return new IDBLogExport(sortedItems, this, this._platform); diff --git a/src/logging/LogFilter.js b/src/logging/LogFilter.js new file mode 100644 index 00000000..aff753db --- /dev/null +++ b/src/logging/LogFilter.js @@ -0,0 +1,97 @@ +/* +Copyright 2020 Bruno Windels + +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. +*/ + +export const LogLevel = { + All: 1, + Debug: 2, + Info: 3, + Warn: 4, + Error: 5, + Fatal: 6, + Off: 7, +} + +export function wrapLogFilterSource(logFilterDef) { + if (typeof logFilterDef === "function") { + return new DeferredFilterCreator(logFilterDef); + } else if (typeof logFilterDef === "number") { + return new SimpleFilterCreator(logFilterDef); + } + return null; +} + +class LogFilter { + constructor(parentFilter) { + this._default = parentFilter ? parentFilter._default : null; + this._min = parentFilter ? parentFilter._min : null; + } + + /* methods to build the filter */ + min(logLevel) { + this._min = logLevel; + if (this._default === null) { + this._default = logLevel; + } + return this; + } + + default(logLevel) { + this._default = logLevel; + if (this._min === null) { + this._min = logLevel; + } + return this; + } + + /* methods to use the filter */ + /** determine log level for item */ + itemLevel(item) { + if (item._error) { + return LogLevel.Error; + } + return this._default; + } + + /** determines whether an item should be persisted */ + includeItem(item, logLevel, children) { + // neither our children or us have a loglevel high enough, bail out. + return logLevel >= this._min || children; + } +} + +/** + * Allows to determine the log level of an item after it has finished. + * So we can set the log level on the item duration for example. + */ +class DeferredFilterCreator { + constructor(fn) { + this._fn = fn; + } + + createFilter(item, parentFilter) { + return this._fn(new LogFilter(parentFilter), item); + } +} + +class SimpleFilterCreator { + constructor(logLevel) { + this._logLevel = logLevel; + } + + createFilter(item, parentFilter) { + return new LogFilter(parentFilter).default(this._logLevel); + } +} diff --git a/src/logging/LogItem.js b/src/logging/LogItem.js index ab51d220..95c0a93f 100644 --- a/src/logging/LogItem.js +++ b/src/logging/LogItem.js @@ -14,10 +14,10 @@ See the License for the specific language governing permissions and limitations under the License. */ -import {LogLevel} from "./LogLevel.js"; +import {LogLevel, wrapLogFilterSource} from "./LogFilter.js"; export class LogItem { - constructor(labelOrValues, logLevel, platform, anonymize) { + constructor(labelOrValues, logFilterDef, platform, anonymize) { this._platform = platform; this._anonymize = anonymize; this._start = platform.clock.now(); @@ -25,16 +25,24 @@ export class LogItem { this._values = typeof labelOrValues === "string" ? {label: labelOrValues} : labelOrValues; this._error = null; this._children = []; - this._logLevel = logLevel; + this._logFilterSource = wrapLogFilterSource(logFilterDef); } /** * Creates a new child item and runs it in `callback`. */ - wrap(labelOrValues, callback, logLevel = this._logLevel) { - const item = this.child(labelOrValues, logLevel); + wrap(labelOrValues, callback, logFilterDef = null) { + const item = this.child(labelOrValues, logFilterDef); return item.run(callback); } + + duration() { + if (this._end) { + return this._end - this._start; + } else { + return null; + } + } /** * Creates a new child item that finishes immediately @@ -42,8 +50,8 @@ export class LogItem { * * Hence, the child item is not returned. */ - log(labelOrValues, logLevel = this._logLevel) { - const item = this.child(labelOrValues, logLevel); + log(labelOrValues, logFilterDef = null) { + const item = this.child(labelOrValues, logFilterDef); item.end = item.start; } @@ -65,9 +73,12 @@ export class LogItem { } } - serialize(logLevel) { + serialize(parentFilter) { + const filter = this._logFilterSource ? this._logFilterSource.createFilter(this, parentFilter) : parentFilter; + const logLevel = filter.itemLevel(this); + console.log("logLevel for item", logLevel); const children = this._children.reduce((array, c) => { - const s = c.serialize(logLevel); + const s = c.serialize(filter); if (s) { array = array || []; array.push(s); @@ -75,8 +86,8 @@ export class LogItem { return array; }, null); - // neither our children or us have a loglevel high enough, bail out. - if (!children && this._logLevel < logLevel) { + if (!filter.includeItem(this, logLevel, children)) { + console.log("excluding log item", logLevel, children, this); return null; } @@ -87,14 +98,19 @@ export class LogItem { name: this._error.name }; } - return { - start: this._start, - end: this._end, - values: this._values, - error, - children, - logLevel: this._logLevel + const item = { + s: this._start, + e: this._end, + v: this._values, + l: logLevel }; + if (error) { + item.err = error; + } + if (children) { + item.c = children; + } + return item; } /** @@ -146,23 +162,22 @@ export class LogItem { } } - // expose log level without needing + // expose log level without needing import everywhere get level() { return LogLevel; } catch(err) { this._error = err; - this._logLevel = LogLevel.Error; this.finish(); return err; } - child(labelOrValues, logLevel) { + child(labelOrValues, logFilterDef = null) { if (this._end !== null) { console.trace("log item is finished, additional logs will likely not be recorded"); } - const item = new LogItem(labelOrValues, logLevel, this._platform, this._anonymize); + const item = new LogItem(labelOrValues, logFilterDef, this._platform, this._anonymize); this._children.push(item); return item; } diff --git a/src/logging/LogLevel.js b/src/logging/LogLevel.js deleted file mode 100644 index 3580a5de..00000000 --- a/src/logging/LogLevel.js +++ /dev/null @@ -1,25 +0,0 @@ -/* -Copyright 2020 Bruno Windels - -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. -*/ - -export const LogLevel = { - All: 1, - Debug: 2, - Info: 3, - Warn: 4, - Error: 5, - Fatal: 6, - Off: 7, -} diff --git a/src/matrix/Sync.js b/src/matrix/Sync.js index 24a19f07..8b59dfb7 100644 --- a/src/matrix/Sync.js +++ b/src/matrix/Sync.js @@ -109,7 +109,17 @@ export class Sync { // for us. We do that by calling it with a zero timeout until it // doesn't give us any more to_device messages. const timeout = this._status.get() === SyncStatus.Syncing ? INCREMENTAL_TIMEOUT : 0; - const syncResult = await this._logger.run("sync", log => this._syncRequest(syncToken, timeout, log)); + const syncResult = await this._logger.run("sync", + log => this._syncRequest(syncToken, timeout, log), + (filter, log) => { + if (log.duration >= 2000) { + return filter.min(log.level.Info).default(log.level.Warn); + } if (this._status.get() === SyncStatus.CatchupSync) { + return filter.min(log.level.Info).default(log.level.Info); + } else { + return filter.min(log.level.Error); + } + }); syncToken = syncResult.syncToken; roomStates = syncResult.roomStates; sessionChanges = syncResult.sessionChanges; From 4defbe13225a583f515d91eb07a8a55bde2bc9c6 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 16 Feb 2021 15:07:17 +0100 Subject: [PATCH 18/33] simplify log filtering, while also adding depth based filtering --- src/logging/BaseLogger.js | 16 ++++-- src/logging/LogFilter.js | 83 +++++++++--------------------- src/logging/LogItem.js | 103 +++++++++++++++++++++----------------- src/matrix/Sync.js | 12 ++--- 4 files changed, 97 insertions(+), 117 deletions(-) diff --git a/src/logging/BaseLogger.js b/src/logging/BaseLogger.js index b8e6d4b4..c2cd579f 100644 --- a/src/logging/BaseLogger.js +++ b/src/logging/BaseLogger.js @@ -15,7 +15,7 @@ limitations under the License. */ import {LogItem} from "./LogItem.js"; -import {LogLevel} from "./LogFilter.js"; +import {LogLevel, LogFilter} from "./LogFilter.js"; export class BaseLogger { constructor({platform}) { @@ -33,13 +33,19 @@ export class BaseLogger { this._platform.settingsStorage.setBool("anonymize", this._anonymize); } - run(labelOrValues, callback, logFilterDef) { - const item = new LogItem(labelOrValues, logFilterDef, this._platform, this._anonymize); + run(labelOrValues, callback, logLevel = LogLevel.Info, filterCreator = null) { + const item = new LogItem(labelOrValues, logLevel, null, this._platform, this._anonymize); this._openItems.add(item); const finishItem = () => { - const serialized = item.serialize(null); - console.log("serialized log item", item, serialized); + let filter = new LogFilter(); + if (filterCreator) { + filter = filterCreator(filter, this); + } else { + // if not filter is specified, filter out anything lower than the initial log level + filter = filter.minLevel(logLevel); + } + const serialized = item.serialize(filter, 0); if (serialized) { this._persistItem(serialized); } diff --git a/src/logging/LogFilter.js b/src/logging/LogFilter.js index aff753db..461a3e86 100644 --- a/src/logging/LogFilter.js +++ b/src/logging/LogFilter.js @@ -24,74 +24,37 @@ export const LogLevel = { Off: 7, } -export function wrapLogFilterSource(logFilterDef) { - if (typeof logFilterDef === "function") { - return new DeferredFilterCreator(logFilterDef); - } else if (typeof logFilterDef === "number") { - return new SimpleFilterCreator(logFilterDef); - } - return null; -} - -class LogFilter { +export class LogFilter { constructor(parentFilter) { - this._default = parentFilter ? parentFilter._default : null; - this._min = parentFilter ? parentFilter._min : null; + this._parentFilter = parentFilter; + this._min = null; + this._maxDepth = null; + } + + filter(item, children, depth) { + if (this._parentFilter) { + if (!this._parentFilter.filter(item, children, depth)) { + return false; + } + } + // neither our children or us have a loglevel high enough, filter out. + if (this._min !== null && children === null && item.logLevel < this._min) { + return false; + } if (this._maxDepth !== null && depth > this._maxDepth) { + return false; + } else { + return true; + } } /* methods to build the filter */ - min(logLevel) { + minLevel(logLevel) { this._min = logLevel; - if (this._default === null) { - this._default = logLevel; - } return this; } - default(logLevel) { - this._default = logLevel; - if (this._min === null) { - this._min = logLevel; - } + maxDepth(depth) { + this._maxDepth = depth; return this; } - - /* methods to use the filter */ - /** determine log level for item */ - itemLevel(item) { - if (item._error) { - return LogLevel.Error; - } - return this._default; - } - - /** determines whether an item should be persisted */ - includeItem(item, logLevel, children) { - // neither our children or us have a loglevel high enough, bail out. - return logLevel >= this._min || children; - } -} - -/** - * Allows to determine the log level of an item after it has finished. - * So we can set the log level on the item duration for example. - */ -class DeferredFilterCreator { - constructor(fn) { - this._fn = fn; - } - - createFilter(item, parentFilter) { - return this._fn(new LogFilter(parentFilter), item); - } -} - -class SimpleFilterCreator { - constructor(logLevel) { - this._logLevel = logLevel; - } - - createFilter(item, parentFilter) { - return new LogFilter(parentFilter).default(this._logLevel); - } } diff --git a/src/logging/LogItem.js b/src/logging/LogItem.js index 95c0a93f..72056f8b 100644 --- a/src/logging/LogItem.js +++ b/src/logging/LogItem.js @@ -14,29 +14,30 @@ See the License for the specific language governing permissions and limitations under the License. */ -import {LogLevel, wrapLogFilterSource} from "./LogFilter.js"; +import {LogLevel, LogFilter} from "./LogFilter.js"; export class LogItem { - constructor(labelOrValues, logFilterDef, platform, anonymize) { + constructor(labelOrValues, logLevel, filterCreator, platform, anonymize) { this._platform = platform; this._anonymize = anonymize; this._start = platform.clock.now(); this._end = null; - this._values = typeof labelOrValues === "string" ? {label: labelOrValues} : labelOrValues; - this._error = null; - this._children = []; - this._logFilterSource = wrapLogFilterSource(logFilterDef); + this._values = typeof labelOrValues === "string" ? {l: labelOrValues} : labelOrValues; + this.error = null; + this.logLevel = logLevel; + this._children = null; + this._filterCreator = filterCreator; } /** * Creates a new child item and runs it in `callback`. */ - wrap(labelOrValues, callback, logFilterDef = null) { - const item = this.child(labelOrValues, logFilterDef); + wrap(labelOrValues, callback, logLevel = LogLevel.Info, filterCreator = null) { + const item = this.child(labelOrValues, logLevel, filterCreator); return item.run(callback); } - duration() { + get duration() { if (this._end) { return this._end - this._start; } else { @@ -50,8 +51,8 @@ export class LogItem { * * Hence, the child item is not returned. */ - log(labelOrValues, logFilterDef = null) { - const item = this.child(labelOrValues, logFilterDef); + log(labelOrValues, logLevel = LogLevel.Info) { + const item = this.child(labelOrValues, logLevel, null); item.end = item.start; } @@ -73,41 +74,45 @@ export class LogItem { } } - serialize(parentFilter) { - const filter = this._logFilterSource ? this._logFilterSource.createFilter(this, parentFilter) : parentFilter; - const logLevel = filter.itemLevel(this); - console.log("logLevel for item", logLevel); - const children = this._children.reduce((array, c) => { - const s = c.serialize(filter); - if (s) { - array = array || []; - array.push(s); - } - return array; - }, null); - - if (!filter.includeItem(this, logLevel, children)) { - console.log("excluding log item", logLevel, children, this); + serialize(filter, depth) { + if (this._filterCreator) { + filter = this._filterCreator(new LogFilter(filter), this); + } + let children; + if (this._children !== null) { + children = this._children.reduce((array, c) => { + const s = c.serialize(filter, depth + 1); + if (s) { + if (array === null) { + array = []; + } + array.push(s); + } + return array; + }, null); + } + if (!filter.filter(this, children, depth)) { return null; } - - let error = null; - if (this._error) { - error = { - stack: this._error.stack, - name: this._error.name + const item = { + // (s)tart + s: this._start, + // (d)uration + d: this.duration, + // (v)alues + v: this._values, + // (l)evel + l: this.logLevel + }; + if (this.error) { + // (e)rror + item.e = { + stack: this.error.stack, + name: this.error.name }; } - const item = { - s: this._start, - e: this._end, - v: this._values, - l: logLevel - }; - if (error) { - item.err = error; - } if (children) { + // (c)hildren item.c = children; } return item; @@ -155,8 +160,10 @@ export class LogItem { */ finish() { if (this._end === null) { - for(const c of this._children) { - c.finish(); + if (this._children !== null) { + for(const c of this._children) { + c.finish(); + } } this._end = this._platform.clock.now(); } @@ -168,16 +175,20 @@ export class LogItem { } catch(err) { - this._error = err; + this.error = err; + this.logLevel = LogLevel.Error; this.finish(); return err; } - child(labelOrValues, logFilterDef = null) { + child(labelOrValues, logLevel, filterCreator) { if (this._end !== null) { console.trace("log item is finished, additional logs will likely not be recorded"); } - const item = new LogItem(labelOrValues, logFilterDef, this._platform, this._anonymize); + const item = new LogItem(labelOrValues, logLevel, filterCreator, this._platform, this._anonymize); + if (this._children === null) { + this._children = []; + } this._children.push(item); return item; } diff --git a/src/matrix/Sync.js b/src/matrix/Sync.js index 8b59dfb7..9d9e6904 100644 --- a/src/matrix/Sync.js +++ b/src/matrix/Sync.js @@ -111,13 +111,14 @@ export class Sync { const timeout = this._status.get() === SyncStatus.Syncing ? INCREMENTAL_TIMEOUT : 0; const syncResult = await this._logger.run("sync", log => this._syncRequest(syncToken, timeout, log), + this._logger.level.Info, (filter, log) => { - if (log.duration >= 2000) { - return filter.min(log.level.Info).default(log.level.Warn); - } if (this._status.get() === SyncStatus.CatchupSync) { - return filter.min(log.level.Info).default(log.level.Info); + if (log.duration >= 2000 || this._status.get() === SyncStatus.CatchupSync) { + return filter.minLevel(log.level.Info); + } else if (log.error) { + return filter.minLevel(log.level.Error); } else { - return filter.min(log.level.Error); + return filter.maxDepth(0); } }); syncToken = syncResult.syncToken; @@ -192,7 +193,6 @@ export class Sync { const isInitialSync = !syncToken; syncToken = response.next_batch; - log.set("isInitialSync", isInitialSync); log.set("syncToken", log.anonymize(syncToken)); log.set("status", this._status.get()); From 48569c28bc2e44433bd9b7ce048f473f63b24d44 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 16 Feb 2021 15:08:08 +0100 Subject: [PATCH 19/33] serialize logs as json --- src/logging/IDBLogger.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/logging/IDBLogger.js b/src/logging/IDBLogger.js index 1ac09c74..10e51f15 100644 --- a/src/logging/IDBLogger.js +++ b/src/logging/IDBLogger.js @@ -105,7 +105,7 @@ export class IDBLogger extends BaseLogger { this._itemCounter += 1; this._queuedItems.push({ id: `${encodeUint64(serializedItem.s)}:${this._itemCounter}`, - tree: serializedItem + json: JSON.stringify(serializedItem) }); } @@ -192,7 +192,7 @@ class IDBLogExport { asBlob() { const log = { version: 1, - items: this._items + items: this._items.map(i => JSON.parse(i.json)) }; const json = JSON.stringify(log); const buffer = this._platform.encoding.utf8.encode(json); From 7dc37078716c337fc079a63b00344570e7312ba4 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 16 Feb 2021 15:27:24 +0100 Subject: [PATCH 20/33] add button to export logs --- src/domain/session/settings/SettingsViewModel.js | 5 +++++ src/platform/web/ui/session/settings/SettingsView.js | 1 + 2 files changed, 6 insertions(+) diff --git a/src/domain/session/settings/SettingsViewModel.js b/src/domain/session/settings/SettingsViewModel.js index 2c072305..e682a0c8 100644 --- a/src/domain/session/settings/SettingsViewModel.js +++ b/src/domain/session/settings/SettingsViewModel.js @@ -110,5 +110,10 @@ export class SettingsViewModel extends ViewModel { return this.i18n`unknown`; } } + + async exportLogs() { + const logExport = await this.logger.export(); + this.platform.saveFileAs(logExport.asBlob(), "logs.json"); + } } diff --git a/src/platform/web/ui/session/settings/SettingsView.js b/src/platform/web/ui/session/settings/SettingsView.js index 0b8a4837..eca45806 100644 --- a/src/platform/web/ui/session/settings/SettingsView.js +++ b/src/platform/web/ui/session/settings/SettingsView.js @@ -51,6 +51,7 @@ export class SettingsView extends TemplateView { t.h3("Application"), row(vm.i18n`Version`, version), row(vm.i18n`Storage usage`, vm => `${vm.storageUsage} / ${vm.storageQuota}`), + row(vm.i18n`Export logs`, t.button({onClick: () => vm.exportLogs()}, "Export")), ]) ]); } From 5d67db0c5ee1c98975c4b9c2bee11ca336d3a485 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 16 Feb 2021 15:35:30 +0100 Subject: [PATCH 21/33] Fix NullLogger --- src/logging/NullLogger.js | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/logging/NullLogger.js b/src/logging/NullLogger.js index 1330ba23..3b9e4ca3 100644 --- a/src/logging/NullLogger.js +++ b/src/logging/NullLogger.js @@ -13,7 +13,7 @@ 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 {LogLevel} from "./LogLevel.js"; +import {LogLevel} from "./LogFilter.js"; export class NullLogger { constructor() { @@ -21,7 +21,7 @@ export class NullLogger { } run(_, callback) { - callback(this._item); + return callback(this._item); } async export() { @@ -35,7 +35,7 @@ export class NullLogger { class NullLogItem { wrap(_, callback) { - callback(this); + return callback(this); } log() {} set() {} From ee4a38257838572046687bd963b61bf38c7c3510 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 16 Feb 2021 15:38:43 +0100 Subject: [PATCH 22/33] revert this back --- src/domain/ViewModel.js | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/src/domain/ViewModel.js b/src/domain/ViewModel.js index 10fbf580..97a91700 100644 --- a/src/domain/ViewModel.js +++ b/src/domain/ViewModel.js @@ -78,9 +78,14 @@ export class ViewModel extends EventEmitter { // we probably are, if we're using routing with a url, we could just refresh. i18n(parts, ...expr) { // just concat for now - return parts.reduce((all, p, i) => { - return all + p + expr[i]; - }); + let result = ""; + for (let i = 0; i < parts.length; ++i) { + result = result + parts[i]; + if (i < expr.length) { + result = result + expr[i]; + } + } + return result; } updateOptions(options) { From e629a93edd74165290bd90811c2db1f18cabcfd0 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 16 Feb 2021 17:45:19 +0100 Subject: [PATCH 23/33] delete extra log items when over limit,to not have to delete every flush --- src/logging/IDBLogger.js | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/src/logging/IDBLogger.js b/src/logging/IDBLogger.js index 10e51f15..49c3e0a3 100644 --- a/src/logging/IDBLogger.js +++ b/src/logging/IDBLogger.js @@ -60,19 +60,20 @@ export class IDBLogger extends BaseLogger { for(const i of this._queuedItems) { logs.add(i); } - // TODO: delete more than needed so we don't delete on every flush? - // trim logs if needed const itemCount = await reqAsPromise(logs.count()); if (itemCount > this._limit) { - let currentCount = itemCount; + // 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); await iterateCursor(logs.openCursor(), (_, __, cursor) => { cursor.delete(); - currentCount -= 1; - return {done: currentCount <= this._limit}; + deleteAmount -= 1; + return {done: deleteAmount === 0}; }); } await txnAsPromise(txn); this._queuedItems.splice(0, amount); + } catch (err) { + console.warn("Could not flush logs", err); } finally { try { db.close(); From 1f91fa9a948b30009b0383d0cf6a0ef25f9bf89a Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 16 Feb 2021 17:45:47 +0100 Subject: [PATCH 24/33] final flush interval --- src/logging/IDBLogger.js | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/src/logging/IDBLogger.js b/src/logging/IDBLogger.js index 49c3e0a3..25566e9b 100644 --- a/src/logging/IDBLogger.js +++ b/src/logging/IDBLogger.js @@ -27,14 +27,13 @@ import {BaseLogger} from "./BaseLogger.js"; export class IDBLogger extends BaseLogger { constructor(options) { super(options); - const {name, flushInterval = 5 * 1000, limit = 3000} = options; + const {name, flushInterval = 60 * 1000, limit = 3000} = options; this._name = name; this._limit = limit; // does not get loaded from idb on startup as we only use it to // differentiate between two items with the same start time this._itemCounter = 0; this._queuedItems = this._loadQueuedItems(); - // TODO: add dirty flag when calling descend // 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); From 59928432df050210625ef2d1e74dd97d7941f383 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 16 Feb 2021 17:46:07 +0100 Subject: [PATCH 25/33] better logs filename --- src/domain/session/settings/SettingsViewModel.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/domain/session/settings/SettingsViewModel.js b/src/domain/session/settings/SettingsViewModel.js index e682a0c8..50aabd2c 100644 --- a/src/domain/session/settings/SettingsViewModel.js +++ b/src/domain/session/settings/SettingsViewModel.js @@ -113,7 +113,7 @@ export class SettingsViewModel extends ViewModel { async exportLogs() { const logExport = await this.logger.export(); - this.platform.saveFileAs(logExport.asBlob(), "logs.json"); + this.platform.saveFileAs(logExport.asBlob(), `hydrogen-logs-${this.platform.clock.now()}.json`); } } From 90cfcad5f16781fd80f0a968bd48ac146a2dda04 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 16 Feb 2021 18:25:52 +0100 Subject: [PATCH 26/33] add privacy notice in settings --- src/platform/web/ui/session/settings/SettingsView.js | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/platform/web/ui/session/settings/SettingsView.js b/src/platform/web/ui/session/settings/SettingsView.js index eca45806..84441cbb 100644 --- a/src/platform/web/ui/session/settings/SettingsView.js +++ b/src/platform/web/ui/session/settings/SettingsView.js @@ -51,7 +51,9 @@ export class SettingsView extends TemplateView { t.h3("Application"), row(vm.i18n`Version`, version), row(vm.i18n`Storage usage`, vm => `${vm.storageUsage} / ${vm.storageQuota}`), - row(vm.i18n`Export logs`, t.button({onClick: () => vm.exportLogs()}, "Export")), + row(vm.i18n`Debug logs`, t.button({onClick: () => vm.exportLogs()}, "Export")), + t.p(["Debug logs contain application usage data including your username, the IDs or aliases of the rooms or groups you have visited and the usernames of other users. They do not contain messages. For more information, review our ", + t.a({href: "https://element.io/privacy", target: "_blank", rel: "noopener"}, "privacy policy"), "."]), ]) ]); } From 338f628627fe83cbd5bd13ca1c857db76e1c9169 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 16 Feb 2021 18:29:42 +0100 Subject: [PATCH 27/33] remove option to anonymize --- src/logging/BaseLogger.js | 12 +----------- src/logging/LogItem.js | 20 +++++--------------- src/matrix/Sync.js | 2 +- 3 files changed, 7 insertions(+), 27 deletions(-) diff --git a/src/logging/BaseLogger.js b/src/logging/BaseLogger.js index c2cd579f..01e9899d 100644 --- a/src/logging/BaseLogger.js +++ b/src/logging/BaseLogger.js @@ -21,20 +21,10 @@ export class BaseLogger { constructor({platform}) { this._openItems = new Set(); this._platform = platform; - this._anonymize = false; //await platform.settingsStorage.getBool("anonymize", false); - } - - get anonymize() { - return this._anonymize; - } - - set anonymize(value) { - this._anonymize = !!value; - this._platform.settingsStorage.setBool("anonymize", this._anonymize); } run(labelOrValues, callback, logLevel = LogLevel.Info, filterCreator = null) { - const item = new LogItem(labelOrValues, logLevel, null, this._platform, this._anonymize); + const item = new LogItem(labelOrValues, logLevel, null, this._platform.clock); this._openItems.add(item); const finishItem = () => { diff --git a/src/logging/LogItem.js b/src/logging/LogItem.js index 72056f8b..0da040d5 100644 --- a/src/logging/LogItem.js +++ b/src/logging/LogItem.js @@ -17,10 +17,9 @@ limitations under the License. import {LogLevel, LogFilter} from "./LogFilter.js"; export class LogItem { - constructor(labelOrValues, logLevel, filterCreator, platform, anonymize) { - this._platform = platform; - this._anonymize = anonymize; - this._start = platform.clock.now(); + constructor(labelOrValues, logLevel, filterCreator, clock) { + this._clock = clock; + this._start = clock.now(); this._end = null; this._values = typeof labelOrValues === "string" ? {l: labelOrValues} : labelOrValues; this.error = null; @@ -65,15 +64,6 @@ export class LogItem { } } - anonymize(value) { - if (this._anonymize) { - const buffer = this._platform.crypto.digest("SHA-256", this._platform.encoding.utf8.encode(value)); - return this._platform.encoding.base64.encode(buffer); - } else { - return value; - } - } - serialize(filter, depth) { if (this._filterCreator) { filter = this._filterCreator(new LogFilter(filter), this); @@ -165,7 +155,7 @@ export class LogItem { c.finish(); } } - this._end = this._platform.clock.now(); + this._end = this._clock.now(); } } @@ -185,7 +175,7 @@ export class LogItem { if (this._end !== null) { console.trace("log item is finished, additional logs will likely not be recorded"); } - const item = new LogItem(labelOrValues, logLevel, filterCreator, this._platform, this._anonymize); + const item = new LogItem(labelOrValues, logLevel, filterCreator, this._clock); if (this._children === null) { this._children = []; } diff --git a/src/matrix/Sync.js b/src/matrix/Sync.js index 9d9e6904..454c7435 100644 --- a/src/matrix/Sync.js +++ b/src/matrix/Sync.js @@ -193,7 +193,7 @@ export class Sync { const isInitialSync = !syncToken; syncToken = response.next_batch; - log.set("syncToken", log.anonymize(syncToken)); + log.set("syncToken", syncToken); log.set("status", this._status.get()); const roomStates = this._parseRoomsResponse(response.rooms, isInitialSync); From 2dd8803efc9c2ab60b6d0061dfdda83c11646680 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 16 Feb 2021 18:30:23 +0100 Subject: [PATCH 28/33] better error handling if something goes wrong serializing log items --- src/logging/BaseLogger.js | 20 ++++++++++++++------ 1 file changed, 14 insertions(+), 6 deletions(-) diff --git a/src/logging/BaseLogger.js b/src/logging/BaseLogger.js index 01e9899d..abf330b3 100644 --- a/src/logging/BaseLogger.js +++ b/src/logging/BaseLogger.js @@ -35,9 +35,13 @@ export class BaseLogger { // if not filter is specified, filter out anything lower than the initial log level filter = filter.minLevel(logLevel); } - const serialized = item.serialize(filter, 0); - if (serialized) { - this._persistItem(serialized); + try { + const serialized = item.serialize(filter, 0); + if (serialized) { + this._persistItem(serialized); + } + } catch (err) { + console.warn("Could not serialize log item", err); } this._openItems.delete(item); }; @@ -65,9 +69,13 @@ export class BaseLogger { _finishOpenItems() { for (const openItem of this._openItems) { openItem.finish(); - const serialized = openItem.serialize(this._baseLogLevel); - if (serialized) { - this._persistItem(serialized); + try { + const serialized = openItem.serialize(this._baseLogLevel); + if (serialized) { + this._persistItem(serialized); + } + } catch (err) { + console.warn("Could not serialize log item", err); } } this._openItems.clear(); From c3637def2ecf4303212341446c17cc43fe8cb52b Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 16 Feb 2021 18:36:41 +0100 Subject: [PATCH 29/33] ensure any breakage does not disrupt logging --- src/logging/BaseLogger.js | 10 +++++++--- src/logging/IDBLogger.js | 4 ++-- src/logging/LogItem.js | 6 +++++- 3 files changed, 14 insertions(+), 6 deletions(-) diff --git a/src/logging/BaseLogger.js b/src/logging/BaseLogger.js index abf330b3..5791e14e 100644 --- a/src/logging/BaseLogger.js +++ b/src/logging/BaseLogger.js @@ -30,7 +30,11 @@ export class BaseLogger { const finishItem = () => { let filter = new LogFilter(); if (filterCreator) { - filter = filterCreator(filter, this); + try { + filter = filterCreator(filter, this); + } catch (err) { + console.error("Error while creating log filter", err); + } } else { // if not filter is specified, filter out anything lower than the initial log level filter = filter.minLevel(logLevel); @@ -41,7 +45,7 @@ export class BaseLogger { this._persistItem(serialized); } } catch (err) { - console.warn("Could not serialize log item", err); + console.error("Could not serialize log item", err); } this._openItems.delete(item); }; @@ -75,7 +79,7 @@ export class BaseLogger { this._persistItem(serialized); } } catch (err) { - console.warn("Could not serialize log item", err); + console.error("Could not serialize log item", err); } } this._openItems.clear(); diff --git a/src/logging/IDBLogger.js b/src/logging/IDBLogger.js index 25566e9b..0d644362 100644 --- a/src/logging/IDBLogger.js +++ b/src/logging/IDBLogger.js @@ -72,7 +72,7 @@ export class IDBLogger extends BaseLogger { await txnAsPromise(txn); this._queuedItems.splice(0, amount); } catch (err) { - console.warn("Could not flush logs", err); + console.error("Could not flush logs", err); } finally { try { db.close(); @@ -113,7 +113,7 @@ export class IDBLogger extends BaseLogger { try { window.localStorage.setItem(`${this._name}_queuedItems`, JSON.stringify(items)); } catch (e) { - console.warn("Could not persist queued log items in localStorage, they will likely be lost", e); + console.error("Could not persist queued log items in localStorage, they will likely be lost", e); } } diff --git a/src/logging/LogItem.js b/src/logging/LogItem.js index 0da040d5..8d9530b6 100644 --- a/src/logging/LogItem.js +++ b/src/logging/LogItem.js @@ -66,7 +66,11 @@ export class LogItem { serialize(filter, depth) { if (this._filterCreator) { - filter = this._filterCreator(new LogFilter(filter), this); + try { + filter = this._filterCreator(new LogFilter(filter), this); + } catch (err) { + console.error("Error creating log item", err); + } } let children; if (this._children !== null) { From b28eefb2db6444045b397dbf911258e68789021b Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 16 Feb 2021 19:53:37 +0100 Subject: [PATCH 30/33] do emergency serialization without log filter --- src/logging/BaseLogger.js | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/logging/BaseLogger.js b/src/logging/BaseLogger.js index 5791e14e..44410220 100644 --- a/src/logging/BaseLogger.js +++ b/src/logging/BaseLogger.js @@ -74,7 +74,10 @@ export class BaseLogger { for (const openItem of this._openItems) { openItem.finish(); try { - const serialized = openItem.serialize(this._baseLogLevel); + // for now, serialize with an all-permitting filter + // as the createFilter function would get a distorted image anyway + // about the duration of the item, etc ... + const serialized = openItem.serialize(new LogFilter(), 0); if (serialized) { this._persistItem(serialized); } From 0ccf735148214da0b88772da7adcbf6e8bebde6b Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 16 Feb 2021 19:57:45 +0100 Subject: [PATCH 31/33] console log when failing to restore queued items --- src/logging/IDBLogger.js | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/logging/IDBLogger.js b/src/logging/IDBLogger.js index 0d644362..4b6c937d 100644 --- a/src/logging/IDBLogger.js +++ b/src/logging/IDBLogger.js @@ -93,7 +93,9 @@ export class IDBLogger extends BaseLogger { window.localStorage.removeItem(key); return JSON.parse(json); } - } catch (e) {} + } catch (err) { + console.error("Could not load queued log items", err); + } return []; } From 630ac40f058b3e73f24d73749feeba68af4ee8f0 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 16 Feb 2021 20:00:08 +0100 Subject: [PATCH 32/33] this is broken now, but we're not using it anyway, so remove --- src/logging/IDBLogger.js | 16 +--------------- 1 file changed, 1 insertion(+), 15 deletions(-) diff --git a/src/logging/IDBLogger.js b/src/logging/IDBLogger.js index 4b6c937d..2f2be249 100644 --- a/src/logging/IDBLogger.js +++ b/src/logging/IDBLogger.js @@ -165,21 +165,7 @@ class IDBLogExport { this._logger = logger; this._platform = platform; } - - get minTimestamp() { - if (!this._items.length) { - return 0; - } - return this._items[0].start; - } - - get maxTimestamp() { - if (!this._items.length) { - return 0; - } - return this._items[this._items.length - 1].end; - } - + get count() { return this._items.length; } From 5bec4d5a72f30c4e961254f9cc06b4b3be8d3868 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 16 Feb 2021 20:05:33 +0100 Subject: [PATCH 33/33] comment --- src/logging/LogItem.js | 1 + 1 file changed, 1 insertion(+) diff --git a/src/logging/LogItem.js b/src/logging/LogItem.js index 8d9530b6..54eb51c2 100644 --- a/src/logging/LogItem.js +++ b/src/logging/LogItem.js @@ -21,6 +21,7 @@ export class LogItem { this._clock = clock; this._start = clock.now(); this._end = null; + // (l)abel this._values = typeof labelOrValues === "string" ? {l: labelOrValues} : labelOrValues; this.error = null; this.logLevel = logLevel;