Logging system refactor (#412)

* Port hookshot logger

* changelog

* fix func name

* Log line improvements

* tidy up

* fix mistaken typo

README.md

@@ -47,6 +47,11 @@ components you use, though some components depend upon other components.
 All components operate on data models defined in the bridge. You can directly
 construct components: the bridge exposes the class constructor.
 
+### `Bridge`
+The component which orchestrates other components: a "glue" component. Provides
+a way to start the bridge. This is the component most examples use. Has
+dependencies on most of the components listed above.
+
 ### `BridgeStore`
 Provides basic document store (key-value) CRUD operations.
 
@@ -92,51 +97,27 @@ A wrapper around the JS SDK `MatrixClient` designed for use by the application
 service *itself*. Contains helper methods to get all rooms the AS is in, how
 many virtual / real users are in each, etc.
 
-### `Bridge`
-The component which orchestrates other components: a "glue" component. Provides
-a way to start the bridge. This is the component most examples use. Has
-dependencies on most of the components listed above.
-
 ## `Logging`
-This component exposes access to the bridges log reporter. To use, you should
-install the optional packages `winston@3`, `winston-daily-rotate-file@2` and
-`chalk@2` to get nice formatted log lines, otherwise it will default to the JS
-console. To use the component, use `Logging.configure(configObject)` to setup
-the logger, which takes the following options:
-```javascript
-{
-    // A level to set the console reporter to.
-    console: "error|warn|info|debug|off",
 
-    // Format to append to log files.
-    fileDatePattern: "YYYY-MM-DD",
+This component exposes access to the bridges log reporter.
+To use the component, use `Logger.configure` to setup 
+the logger.
 
-    // Format of the timestamp in log files.
-    timestampFormat: "MMM-D HH:mm:ss.SSS",
+```js
+// Configure the logger by providing these options
+Logger.configure({ level: "info" });
 
-    // Log files to emit to, keyed of the minimum level they report.
-    // You can leave this out, or set it to false to disable files.
-    files: {
-        // File paths can be relative or absolute, the date is appended onto the end.
-        "abc.log" => "error|warn|info|debug|off",
-    },
+// In each module, instantiate the Logger class with a module name.
+const log = new Logger('MyModule');
 
-    // The maximum number of files per level before old files get cleaned
-    // up. Use 0 to disable.
-    maxFiles: 5,
-}
+// Then log away!
+log.info('Hello, this is a log from my module');
+log.debug('Some debug info');
+log.error('Oh no, something went wrong!', new Error('an error'));
 ```
 
-
 You **MUST** configure the logger before anything will be emitted to the console.
 
-You can then use `const log = Logging.Get(ModuleName)` to start logging to the reporter,
-using the `log.error`, `log.warn`, `log.info` or `log.debug` functions. Arguments to these functions will
-automatically be seralized if they aren't strings.
-
-NOTE: ``opts.controller.onLog`` will override this, but if not set then the logging
-transport is used.
-
 ## `RoomLinkValidator`
 This component validates if a room can be linked to a remote channel based on
 whether it conflicts with any rules given in a rule file. The filename is given

changelog.d/412.feature

@@ -0,0 +1,2 @@
+Port the Logger class from `matrix-hookshot` to this SDK, granting JSON logging support and less noisy logs.
+**Note**: This change is breaking. `Logging.get(...)` becomes `new Logger(...)` and `Logging.configure` becomes `Logger.configure`.

examples/encryption/yarn.lock

@@ -871,6 +871,13 @@ is-arrayish@^0.3.1:
   resolved "https://registry.yarnpkg.com/is-arrayish/-/is-arrayish-0.3.2.tgz#4574a2ae56f7ab206896fb431eaeed066fdf8f03"
   integrity sha512-eVRqCvVlZbuw3GrM63ovNSNAeA1K16kaR/LRY/92w0zxQ5/1YzwblUX652i4Xs9RwAGjW9d9y6X88t8OaAJfWQ==
 
+is-core-module@^2.8.1:
+  version "2.9.0"
+  resolved "https://registry.yarnpkg.com/is-core-module/-/is-core-module-2.9.0.tgz#e1c34429cd51c6dd9e09e0799e396e27b19a9c69"
+  integrity sha512-+5FPy5PnwmO3lvfMb0AsoPaBG+5KHUI0wYFXOtYPnVVVspTFUuMZNfNaNVRt3FZadstu2c8x23vykRW/NBoU6A==
+  dependencies:
+    has "^1.0.3"
+
 is-my-ip-valid@^1.0.0:
   version "1.0.1"
   resolved "https://registry.yarnpkg.com/is-my-ip-valid/-/is-my-ip-valid-1.0.1.tgz#f7220d1146257c98672e6fba097a9f3f2d348442"
@@ -1281,6 +1288,16 @@ parseurl@~1.3.3:
   resolved "https://registry.yarnpkg.com/parseurl/-/parseurl-1.3.3.tgz#9da19e7bee8d12dff0513ed5b76957793bc2e8d4"
   integrity sha512-CiyeOxFT/JZyN5m0z9PfXw4SCBJ6Sygz1Dpl0wqjlhDEGGBP1GnsUVEL0p63hoG1fcj3fHynXi9NYO4nWOL+qQ==
 
+path-is-absolute@^1.0.0:
+  version "1.0.1"
+  resolved "https://registry.yarnpkg.com/path-is-absolute/-/path-is-absolute-1.0.1.tgz#174b9268735534ffbc7ace6bf53a5a9e1b5c5f5f"
+  integrity sha1-F0uSaHNVNP+8es5r9TpanhtcX18=
+
+path-parse@^1.0.7:
+  version "1.0.7"
+  resolved "https://registry.yarnpkg.com/path-parse/-/path-parse-1.0.7.tgz#fbc114b60ca42b30d9daf5858e4bd68bbedb6735"
+  integrity sha512-LDJzPVEEEPR+y48z93A0Ed0yXb8pAByGWo/k5YYdYgpY2/2EsOsksJrq7lOHxryrVOn1ejG6oAp8ahvOIQD8sw==
+
 [email protected]:
   version "0.1.7"
   resolved "https://registry.yarnpkg.com/path-to-regexp/-/path-to-regexp-0.1.7.tgz#df604178005f522f15eb4490e7247a1bfaa67f8c"

spec/unit/logging.spec.ts

@@ -0,0 +1,86 @@
+import { Writable } from "stream";
+import { Logger, GlobalLogger } from "../../src/index";
+
+const tortureArgs: [unknown, ...unknown[]][] = [
+    ["test-msg"],
+    [Number.MAX_VALUE],
+    [false],
+    [Buffer.from('foo')],
+    [new Error('Test')],
+    [undefined],
+    [null],
+    [NaN],
+    [[]],
+    [() => { /*dummy*/}],
+    ["Foo", "test-msg"],
+    ["Foo", Number.MAX_VALUE],
+    ["Foo", false],
+    ["Foo", Buffer.from('foo')],
+    ["Foo", new Error('Test')],
+    ["Foo", undefined],
+    ["Foo", null],
+    ["Foo", NaN],
+    ["Foo", []],
+    ["Foo", () => { /*dummy*/}],
+]
+
+const MODULE_NAME = 'LogTesting';
+
+describe('Logger', () => {
+    describe('text logger torture test', () => {
+        // eslint-disable-next-line @typescript-eslint/no-explicit-any
+        let data: any;
+        const global = new GlobalLogger();
+        global.configureLogging({
+            json: false,
+            console: 'debug',
+        }, new Writable({
+            write(chunk, _encoding, callback) {
+                data = chunk.toString();
+                callback();
+            },
+        }));
+
+        const log = new Logger(MODULE_NAME, {}, global);
+        for (const args of tortureArgs) {
+            it(`handles logging '${args.map(t => typeof t).join(', ')}'`, () => {
+                for (const level of ['debug', 'info', 'warn', 'error']) {
+                    log[level as 'debug'|'info'|'warn'|'error'](args[0], ...args.slice(1));
+                    expect(data).toBeDefined();
+                    expect(data).toContain(level.toUpperCase());
+                    expect(data).toContain(MODULE_NAME);
+                }
+            })
+        }
+    });
+    describe('JSON logger torture test', () => {
+        // eslint-disable-next-line @typescript-eslint/no-explicit-any
+        let data: any;
+        const global = new GlobalLogger();
+        global.configureLogging({
+            json: true,
+            console: 'debug',
+        }, new Writable({
+            write(chunk, _encoding, callback) {
+                data = JSON.parse(chunk.toString());
+                callback();
+            },
+        }));
+
+        const log = new Logger(MODULE_NAME, {}, global);
+        for (const args of tortureArgs) {
+            it(`handles logging '${args.map(t => typeof t).join(', ')}'`, () => {
+                for (const level of ['debug', 'info', 'warn', 'error']) {
+                    log[level as 'debug'|'info'|'warn'|'error'](args[0], ...args.slice(1));
+                    expect(data.level).toEqual(level.toUpperCase());
+                    expect(data.module).toEqual(MODULE_NAME);
+                    expect(data.message).toBeDefined();
+                    expect(data.timestamp).toBeDefined();
+                    if (args.length > 1) {
+                        expect(data.args).toHaveSize(args.length-1);
+                    }
+                }
+            })
+        }
+    });
+});

src/bridge.ts

@@ -35,7 +35,7 @@ import { MembershipCache, UserMembership, UserProfile } from "./components/membe
 import { RoomLinkValidator, RoomLinkValidatorStatus, Rules } from "./components/room-link-validator"
 import { RoomUpgradeHandler, RoomUpgradeHandlerOpts } from "./components/room-upgrade-handler";
 import { EventQueue } from "./components/event-queue";
-import * as logging from "./components/logging";
+import { Logger } from ".";
 import { UserActivityTracker } from "./components/user-activity";
 import { Defer, defer as deferPromise } from "./utils/promiseutil";
 import { unstable } from "./errors";
@@ -53,7 +53,7 @@ import * as BotSDK from "matrix-bot-sdk";
 import { ActivityTracker, ActivityTrackerOpts } from "./components/activity-tracker";
 import { EncryptedIntent, EncryptedIntentOpts } from "./components/encrypted-intent";
 
-const log = logging.get("bridge");
+const log = new Logger("bridge");
 
 // The frequency at which we will check the list of accumulated Intent objects.
 const INTENT_CULL_CHECK_PERIOD_MS = 1000 * 60; // once per minute

src/components/activity-tracker.ts

@@ -1,6 +1,6 @@
 import { MatrixClient } from "matrix-bot-sdk";
-import * as logging from "./logging";
-const log = logging.get("ActivityTracker");
+import { Logger } from ".."
+const log = new Logger("ActivityTracker");
 
 export interface ActivityTrackerOpts {
     /**

src/components/bridge-blocker.ts

@@ -12,8 +12,8 @@ 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 * as logging from "./logging";
-const log = logging.get("BridgeBlocker");
+import { Logger } from "..";
+const log = new Logger("BridgeBlocker");
 
 /**
  * Monitor the active user limit (or any limit you desire),

src/components/bridge-info-state.ts

@@ -1,8 +1,8 @@
 import { Bridge } from "../bridge";
-import logger from "./logging";
+import { Logger } from "..";
 import PQueue from "p-queue";
 
-const log = logger.get("BridgeStateSyncer");
+const log = new Logger("BridgeStateSyncer");
 export interface MappingInfo {
     creator?: string;
     protocol: {

src/components/cli.ts

@@ -20,9 +20,9 @@ import * as yaml from "js-yaml";
 import nopt from "nopt";
 import { AppServiceOutput, AppServiceRegistration } from "matrix-appservice";
 import { ConfigValidator } from "./config-validator";
-import * as logging from "./logging";
+import { Logger } from "..";
 
-const log = logging.get("cli");
+const log = new Logger("cli");
 
 export interface CliOpts<ConfigType extends Record<string, unknown>> {
     /**

src/components/encrypted-intent.ts

@@ -1,12 +1,10 @@
-import { UserMembership } from "./membership-cache";
 import { APPSERVICE_LOGIN_TYPE, ClientEncryptionSession } from "./encryption";
-import Logging from "./logging";
-import { ReadStream } from "fs";
+import { Logger } from "..";
 import BotSdk, { MatrixClient } from "matrix-bot-sdk";
 import { FileUploadOpts, Intent, IntentOpts } from "./intent";
 import { WeakStateEvent } from "./event-types";
 
-const log = Logging.get("EncryptedIntent");
+const log = new Logger("EncryptedIntent");
 
 export interface EncryptedIntentOpts {
     sessionPromise: Promise<ClientEncryptionSession|null>;

src/components/encryption.ts

@@ -2,15 +2,15 @@ import { MembershipCache } from "./membership-cache";
 import { AppServiceBot } from "./app-service-bot";
 import { WeakEvent } from "./event-types";
 import { Intent } from "./intent";
-import Logging from "./logging";
+import { Logger } from "..";
 import { MatrixClient } from "matrix-bot-sdk";
 import LRU from "@alloc/quick-lru"
 
-const log = Logging.get("EncryptedEventBroker");
-
 export const APPSERVICE_LOGIN_TYPE = "m.login.application_service";
 const EVENT_CACHE_FOR_MS = 5 * 60000; // 5 minutes
 
+const log = new Logger('EncryptedEventBroker');
+
 interface PantalaimonWeakEvent extends WeakEvent {
     decrypted: true;
 }

src/components/intent.ts

@@ -19,12 +19,11 @@ import { defer } from "../utils/promiseutil";
 import { UserMembership } from "./membership-cache";
 import { unstable } from "../errors";
 import BridgeErrorReason = unstable.BridgeErrorReason;
-import Logging from "./logging";
-import { ReadStream } from "fs";
 import BotSdk, { MatrixClient, MatrixProfileInfo, PresenceState } from "matrix-bot-sdk";
 import { WeakStateEvent } from "./event-types";
+import { Logger } from '..';
 
-const log = Logging.get("Intent");
+const log = new Logger("Intent");
 export type IntentBackingStore = {
     getMembership: (roomId: string, userId: string) => UserMembership,
     getMemberProfile: (roomId: string, userid: string) => MatrixProfileInfo,