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

@@ -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);
             }

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);

src/logging/LogFilter.js

@@ -0,0 +1,97 @@
+/*
+Copyright 2020 Bruno Windels <bruno@windels.cloud>
+
+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);
+    }
+}

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;
     }

src/logging/LogLevel.js

@@ -1,25 +0,0 @@
-/*
-Copyright 2020 Bruno Windels <bruno@windels.cloud>
-
-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,
-}

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;