Implement custom logger to replace scribe.js.

* scribe.js is unmaintained and adds unnecessary complexity.

README.md

@@ -116,10 +116,8 @@ Dann die `config.json` anpassen nach belieben. Es gibt die folgenden Konfigurati
 
 * **`server.logging.enabled`** Ob geloggt werden soll (Achtung: `false` sorgt dafür, dass überhaupt kein Output mehr auf
   `stdout` oder in den Logs erscheint und überschreibt damit alle anderen Logging-Optionen!), z. B.: `false`
-* **`server.logging.directory`** Verzeichnis unter dem Log-Files abgelegt werden, z. B.: `"$FFFFNG_HOME/logs"`
 * **`server.logging.debug`** Gibt an, ob Debug-Output geloggt werden soll (Achtung, viel!), z. B.: `false`
 * **`server.logging.profile`** Gibt an, ob Profiling-Output geloggt werden soll (Achtung, viel!), z. B.: `false`
-* **`server.logging.logRequests`** Gib an, ob HTTP-Requests geloggt werden sollen (Achtung, Datenschutz!), z. B.: `false`
 
 * **`server.internal.active`** Gibt an, ob interne URLs, wie Admin-Panel und Logging-Interface, erreichbar sein sollen,
   z. B.: `true`

REFACTOR.md

@@ -9,7 +9,6 @@
 
 * Integrate typescript in the build and start migrating the server code.
 * Find a nice way to integrate typescript with grunt.
-* Replace logging framework.
 * Bluebird for promises?
 * Yarn instead of NPM?
 

admin/js/main.js

@@ -453,14 +453,6 @@ angular.module('ffffngAdmin').config(function(NgAdminConfigurationProvider, Rest
                     .menu(tasks)
                     .icon('<span class="fa fa-cog"></span>')
                 )
-                .addChild(nga
-                    .menu()
-                    .template(
-                        '<a href="' + pathPrefix + '/internal/logs" target="_blank">' +
-                        '<span class="fa fa-list"></span> Logs' +
-                        '</a>'
-                    )
-                )
     );
 
     admin.dashboard(nga.dashboard()

config.json.example

@@ -8,10 +8,8 @@
 
         "logging": {
             "enabled": true,
-            "directory": "/tmp/logs",
             "debug": false,
-            "profile": false,
+            "profile": false
-            "logRequests": false
         },
 
         "internal": {

package-lock.json

@@ -29,7 +29,6 @@
                 "nodemailer": "^6.7.2",
                 "nodemailer-html-to-text": "^3.2.0",
                 "request": "^2.88.2",
-                "scribe-js": "^2.0.4",
                 "serve-static": "^1.14.1",
                 "sparkson": "^1.3.6",
                 "sqlite": "^3.0.6"
@@ -3897,14 +3896,6 @@
             "integrity": "sha1-JtII6onje1y95gJQoV8DHBak1ms=",
             "dev": true
         },
-        "node_modules/callsite": {
-            "version": "1.0.0",
-            "resolved": "https://registry.npmjs.org/callsite/-/callsite-1.0.0.tgz",
-            "integrity": "sha1-KAOY5dZkvXQDi28JBRU+borxvCA=",
-            "engines": {
-                "node": "*"
-            }
-        },
         "node_modules/callsites": {
             "version": "3.1.0",
             "resolved": "https://registry.npmjs.org/callsites/-/callsites-3.1.0.tgz",
@@ -4305,14 +4296,6 @@
             "resolved": "https://registry.npmjs.org/color-name/-/color-name-1.1.3.tgz",
             "integrity": "sha1-p9BVi9icQveV3UIyj3QIMcpTvCU="
         },
-        "node_modules/colors": {
-            "version": "1.4.0",
-            "resolved": "https://registry.npmjs.org/colors/-/colors-1.4.0.tgz",
-            "integrity": "sha512-a+UqTh4kgZg/SlGvfbzDHpgRu7AAQOmmqRHJnxhRZICKFUT91brVhNNt58CMWU9PsBbv3PDCZUHbVxuDiH2mtA==",
-            "engines": {
-                "node": ">=0.1.90"
-            }
-        },
         "node_modules/combined-stream": {
             "version": "1.0.8",
             "resolved": "https://registry.npmjs.org/combined-stream/-/combined-stream-1.0.8.tgz",
@@ -15819,19 +15802,6 @@
                 "node": ">=10"
             }
         },
-        "node_modules/scribe-js": {
-            "version": "2.0.4",
-            "resolved": "https://registry.npmjs.org/scribe-js/-/scribe-js-2.0.4.tgz",
-            "integrity": "sha1-a1GbdVdqCXjCd/ghanRSVs/yTQs=",
-            "deprecated": "This package is no longer maintained. Please find an alternative solution. Sorry for inconvenience.",
-            "dependencies": {
-                "callsite": "^1.0.0",
-                "colors": "^1.0.0",
-                "express": "^4.0.0",
-                "mkdirp": "^0.5.0",
-                "moment": "^2.8.0"
-            }
-        },
         "node_modules/seek-bzip": {
             "version": "1.0.5",
             "resolved": "https://registry.npmjs.org/seek-bzip/-/seek-bzip-1.0.5.tgz",
@@ -21575,11 +21545,6 @@
             "integrity": "sha1-JtII6onje1y95gJQoV8DHBak1ms=",
             "dev": true
         },
-        "callsite": {
-            "version": "1.0.0",
-            "resolved": "https://registry.npmjs.org/callsite/-/callsite-1.0.0.tgz",
-            "integrity": "sha1-KAOY5dZkvXQDi28JBRU+borxvCA="
-        },
         "callsites": {
             "version": "3.1.0",
             "resolved": "https://registry.npmjs.org/callsites/-/callsites-3.1.0.tgz",
@@ -21904,11 +21869,6 @@
             "resolved": "https://registry.npmjs.org/color-name/-/color-name-1.1.3.tgz",
             "integrity": "sha1-p9BVi9icQveV3UIyj3QIMcpTvCU="
         },
-        "colors": {
-            "version": "1.4.0",
-            "resolved": "https://registry.npmjs.org/colors/-/colors-1.4.0.tgz",
-            "integrity": "sha512-a+UqTh4kgZg/SlGvfbzDHpgRu7AAQOmmqRHJnxhRZICKFUT91brVhNNt58CMWU9PsBbv3PDCZUHbVxuDiH2mtA=="
-        },
         "combined-stream": {
             "version": "1.0.8",
             "resolved": "https://registry.npmjs.org/combined-stream/-/combined-stream-1.0.8.tgz",
@@ -30830,18 +30790,6 @@
                 "xmlchars": "^2.2.0"
             }
         },
-        "scribe-js": {
-            "version": "2.0.4",
-            "resolved": "https://registry.npmjs.org/scribe-js/-/scribe-js-2.0.4.tgz",
-            "integrity": "sha1-a1GbdVdqCXjCd/ghanRSVs/yTQs=",
-            "requires": {
-                "callsite": "^1.0.0",
-                "colors": "^1.0.0",
-                "express": "^4.0.0",
-                "mkdirp": "^0.5.0",
-                "moment": "^2.8.0"
-            }
-        },
         "seek-bzip": {
             "version": "1.0.5",
             "resolved": "https://registry.npmjs.org/seek-bzip/-/seek-bzip-1.0.5.tgz",

package.json

@@ -49,7 +49,6 @@
         "nodemailer": "^6.7.2",
         "nodemailer-html-to-text": "^3.2.0",
         "request": "^2.88.2",
-        "scribe-js": "^2.0.4",
         "serve-static": "^1.14.1",
         "sparkson": "^1.3.6",
         "sqlite": "^3.0.6"

server/__mocks__/logger.ts

@@ -1,6 +1,5 @@
-import {Logger, TaggedLogger} from "../types";
+import {Logger, TaggedLogger, LogLevel} from '../types';
-
+import {ActivatableLogger} from '../logger';
-type LogLevel = 'debug' | 'info' | 'warn' | 'error' | 'profile';
 
 export type MockLogMessages = any[][];
 type TaggedLogMessages = {
@@ -8,7 +7,7 @@ type TaggedLogMessages = {
     logs: {[key: string]: MockLogMessages}
 }
 
-export class MockLogger implements Logger {
+export class MockLogger implements ActivatableLogger {
     private taggedLogMessages: TaggedLogMessages = MockLogger.emptyTaggedLogMessages();
 
     constructor() {}
@@ -37,7 +36,7 @@ export class MockLogger implements Logger {
         return taggedLogMessages.logs[level] || [];
     }
 
-    init(): void {}
+    init(...args: any[]): void {}
 
     private doLog(taggedLogMessages: TaggedLogMessages, level: LogLevel, tags: string[], args: any[]): void {
         if (tags.length > 0) {
@@ -55,17 +54,27 @@ export class MockLogger implements Logger {
         }
     }
 
-    private log(level: LogLevel, tags: string[], args: any[]): void {
-        this.doLog(this.taggedLogMessages, level, tags, args);
-    }
-
     tag(...tags: string[]): TaggedLogger {
+        const logger: MockLogger = this;
         return {
-            debug: (...args: any[]): void => this.log('debug', tags, args),
+            log(level: LogLevel, ...args: any[]): void {
-            info: (...args: any[]): void => this.log('info', tags, args),
+                logger.doLog(logger.taggedLogMessages, level, tags, args);
-            warn: (...args: any[]): void => this.log('warn', tags, args),
+            },
-            error: (...args: any[]): void => this.log('error', tags, args),
+            debug(...args: any[]): void {
-            profile: (...args: any[]): void => this.log('profile', tags, args),
+                this.log('debug', ...args);
+            },
+            info(...args: any[]): void {
+                this.log('info', ...args);
+            },
+            warn(...args: any[]): void {
+                this.log('warn', ...args);
+            },
+            error(...args: any[]): void {
+                this.log('error', ...args);
+            },
+            profile(...args: any[]): void {
+                this.log('profile', ...args);
+            },
         }
     }
 }

server/logger.test.ts

@@ -0,0 +1,190 @@
+import {LogLevel, LogLevels, isLogLevel} from "./types";
+import {ActivatableLoggerImpl} from "./logger";
+import _ from "lodash";
+
+class TestableLogger extends ActivatableLoggerImpl {
+    private logs: any[][] = [];
+
+    constructor(enabled?: boolean) {
+        super();
+        this.init(
+            enabled === false ? false : true, // default is true
+            (...args: any[]): void => this.doLog(...args)
+        );
+    }
+
+    doLog(...args: any[]): void {
+        this.logs.push(args);
+    }
+
+    getLogs(): any[][] {
+        return this.logs;
+    }
+}
+
+type ParsedLogEntry = {
+    level: LogLevel,
+    tags: string[],
+    message: string,
+    args: any[],
+};
+
+function parseLogEntry(logEntry: any[]): ParsedLogEntry {
+    if (!logEntry.length) {
+        throw new Error(
+            `Empty log entry. Should always start with log message: ${logEntry}`
+        );
+    }
+    
+    const logMessage = logEntry[0];
+    if (typeof logMessage !== "string") {
+        throw new Error(
+            `Expected log entry to start with string, but got: ${logMessage}`
+        );
+    } 
+
+    const regexp = /^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2} ([A-Z]+) - (\[[^\]]*\])? *(.*)$/;
+    const groups = logMessage.match(regexp);
+    if (groups === null || groups.length < 4) {
+        throw new Error(
+            `Malformed log message.\n\nExpected format: ${regexp}.\nGot: ${logMessage}`
+        );
+    }
+
+    const level = groups[1].toLowerCase();
+    if (!isLogLevel(level)) {
+        throw new Error(
+            `Unknown log level "${level}" in log message: ${logMessage}`
+        );
+    }
+
+    const tagsStr = groups[2].substring(1, groups[2].length - 1);
+    const tags = tagsStr ? _.split(tagsStr, ", ") : [];
+    const message = groups[3];
+    const args = logEntry.slice(1);
+
+    return {
+        level: level as LogLevel,
+        tags, 
+        message,
+        args,
+    };
+}
+
+function parseLogs(logs: any[][]): ParsedLogEntry[] {
+    const parsedLogs: ParsedLogEntry[] = [];
+    for (const logEntry of logs) {
+        parsedLogs.push(parseLogEntry(logEntry));
+    }
+    return parsedLogs;
+}
+
+for (const level of LogLevels) {
+    test(`should log single untagged ${level} message without parameters`, () => {
+        // given
+        const logger = new TestableLogger();
+
+        // when
+        logger.tag()[level]("message");
+
+        // then
+        expect(parseLogs(logger.getLogs())).toEqual([{
+            level,
+            tags: [],
+            message: "message",
+            args: [],
+        }]);
+    });
+
+    test(`should log single tagged ${level} message without parameters`, () => {
+        // given
+        const logger = new TestableLogger();
+
+        // when
+        logger.tag("tag1", "tag2")[level]("message");
+
+        // then
+        expect(parseLogs(logger.getLogs())).toEqual([{
+            level,
+            tags: ["tag1", "tag2"],
+            message: "message",
+            args: [],
+        }]);
+    });
+
+    test(`should log single tagged ${level} message with parameters`, () => {
+        // given
+        const logger = new TestableLogger();
+
+        // when
+        logger.tag("tag1", "tag2")[level]("message", 1, {}, [false]);
+
+        // then
+        expect(parseLogs(logger.getLogs())).toEqual([{
+            level,
+            tags: ["tag1", "tag2"],
+            message: "message",
+            args: [1, {}, [false]],
+        }]);
+    });
+
+    test(`should escape tags for ${level} message without parameters`, () => {
+        // given
+        const logger = new TestableLogger();
+
+        // when
+        logger.tag("%s", "%d", "%f", "%o", "%")[level]("message");
+
+        // then
+        expect(parseLogs(logger.getLogs())).toEqual([{
+            level,
+            tags: ["%%s", "%%d", "%%f", "%%o", "%%"],
+            message: "message",
+            args: [],
+        }]);
+    });
+
+    test(`should not escape ${level} message itself`, () => {
+        // given
+        const logger = new TestableLogger();
+
+        // when
+        logger.tag("tag")[level]("%s %d %f %o %%");
+
+        // then
+        expect(parseLogs(logger.getLogs())).toEqual([{
+            level,
+            tags: ["tag"],
+            message: "%s %d %f %o %%",
+            args: [],
+        }]);
+    }); 
+
+    test(`should not escape ${level} message arguments`, () => {
+        // given
+        const logger = new TestableLogger();
+
+        // when
+        logger.tag("tag")[level]("message", 1, "%s", "%d", "%f", "%o", "%");
+
+        // then
+        expect(parseLogs(logger.getLogs())).toEqual([{
+            level,
+            tags: ["tag"],
+            message: "message",
+            args: [1, "%s", "%d", "%f", "%o", "%"],
+        }]);
+    }); 
+
+    test(`should not log ${level} message on disabled logger`, () => {
+        // given
+        const logger = new TestableLogger(false);
+
+        // when
+        logger.tag("tag")[level]("message");
+
+        // then
+        expect(parseLogs(logger.getLogs())).toEqual([]);
+    }); 
+}
+

server/logger.ts

@@ -1,104 +1,71 @@
-import {Logger, TaggedLogger} from "./types";
+import {Logger, TaggedLogger, LogLevel} from './types';
+import moment from 'moment';
+import _ from 'lodash';
 
-function procConsole() {
+export type LoggingFunction = (...args: any[]) => void;
-    // @ts-ignore
-    return process.console;
-}
 
 const noopTaggedLogger: TaggedLogger = {
-    debug(...args: any): void {},
+    log(level: LogLevel, ...args: any[]): void {},
-    info(...args: any): void {},
+    debug(...args: any[]): void {},
-    warn(...args: any): void {},
+    info(...args: any[]): void {},
-    error(...args: any): void {},
+    warn(...args: any[]): void {},
-    profile(...args: any): void {},
+    error(...args: any[]): void {},
+    profile(...args: any[]): void {},
 };
 
-class ActivatableLogger implements Logger {
+export interface ActivatableLogger extends Logger {
+    init(enabled: boolean, loggingFunction?: LoggingFunction): void;
+}
+
+export class ActivatableLoggerImpl implements ActivatableLogger {
     private enabled: boolean = false;
+    private loggingFunction: LoggingFunction = console.info;
 
-    init(): void {
+    init(enabled: boolean, loggingFunction?: LoggingFunction): void {
-        const app = require('./app').app;
         const config = require('./config').config;
-
-        const enabled = config.server.logging.enabled;
         this.enabled = enabled;
-
+        this.loggingFunction = loggingFunction || console.info;
-        // Hack to allow proper logging of Error.
-        Object.defineProperty(Error.prototype, 'message', {
-            configurable: true,
-            enumerable: true
-        });
-        Object.defineProperty(Error.prototype, 'stack', {
-            configurable: true,
-            enumerable: true
-        });
-
-        const scribe = require('scribe-js')({
-            rootPath: config.server.logging.directory,
-        });
-
-        function addLogger(name: string, color: string, active: boolean) {
-            if (enabled && active) {
-                procConsole().addLogger(name, color, {
-                    logInConsole: false
-                });
-            } else {
-                // @ts-ignore
-                procConsole()[name] = function () {
-                    this._reset(); // forget tags, etc. for this logging event
-                };
-            }
     }
 
-        addLogger('debug', 'grey', config.server.logging.debug);
+    tag(...tags: string[]): TaggedLogger {
-        addLogger('profile', 'blue', config.server.logging.profile);
-
-        if (enabled && config.server.logging.logRequests) {
-            app.use(scribe.express.logger());
-        }
-        if (config.server.internal.active) {
-            const prefix = config.server.rootPath === '/' ? '' : config.server.rootPath;
-            app.use(prefix + '/internal/logs', scribe.webPanel());
-        }
-
-        // Hack to allow correct logging of node.js Error objects.
-        // See: https://github.com/bluejamesbond/Scribe.js/issues/70
-        Object.defineProperty(Error.prototype, 'toJSON', {
-            configurable: true,
-            value: function () {
-                const alt: {[key: string]: any} = {};
-                const storeKey = (key: string)  => {
-                    alt[key] = this[key];
-                };
-                Object.getOwnPropertyNames(this).forEach(storeKey, this);
-                return alt;
-            }
-        });
-
-        // @ts-ignore
-        for (const key of Object.keys(procConsole())) {
-            // @ts-ignore
-            module.exports[key] = enabled ? procConsole()[key] : (...args: any) => {};
-        }
-    }
-
-    tag(...tags: any): TaggedLogger {
         if (this.enabled) {
+            const loggingFunction = this.loggingFunction;
             return {
-                debug(...args: any): void {
+                log(level: LogLevel, ...args: any[]): void {
-                    procConsole().tag(...tags).debug(...args);
+                    const timeStr = moment().format('YYYY-MM-DD HH:mm:ss');
+                    const levelStr = level.toUpperCase();
+                    const tagsStr = tags ? '[' + _.join(tags, ', ') + ']' : '';
+                    const messagePrefix = `${timeStr} ${levelStr} - ${tagsStr}`;
+
+                    // Make sure to only replace %s, etc. in real log message
+                    // but not in tags.
+                    const escapedMessagePrefix = messagePrefix.replace(/%/g, '%%');
+                    
+                    let message = '';
+                    if (args && _.isString(args[0])) {
+                        message = args[0];
+                        args.shift();
+                    }
+
+                    const logStr = message
+                        ? `${escapedMessagePrefix} ${message}`
+                        : escapedMessagePrefix;
+                    loggingFunction(logStr, ...args);
                 },
-                info(...args: any): void {
+                debug(...args: any[]): void {
-                    procConsole().tag(...tags).info(...args);
+                    this.log('debug', ...args);
                 },
-                warn(...args: any): void {
+                info(...args: any[]): void {
-                    procConsole().tag(...tags).warn(...args);
+                    this.log('info', ...args);
                 },
-                error(...args: any): void {
+                warn(...args: any[]): void {
-                    procConsole().tag(...tags).error(...args);
+                    this.log('warn', ...args);
                 },
-                profile(...args: any): void {
+                error(...args: any[]): void {
-                    procConsole().tag(...tags).profile(...args);
+                    this.log('error', ...args);
+                },
+                profile(...args: any[]): void {
+                    this.log('profile', ...args);
                 },
             }
         } else {
@@ -107,4 +74,4 @@ class ActivatableLogger implements Logger {
     }
 }
 
-export default new ActivatableLogger() as Logger;
+export default new ActivatableLoggerImpl() as ActivatableLogger;

server/main.ts

@@ -7,7 +7,7 @@ import * as router from "./router"
 import * as app from "./app"
 
 app.init();
-Logger.init();
+Logger.init(config.server.logging.enabled);
 Logger.tag('main', 'startup').info('Server starting up...');
 
 async function main() {

server/types/config.ts

@@ -7,10 +7,8 @@ export type Version = string;
 export class LoggingConfig {
     constructor(
         @Field("enabled") public enabled: boolean,
-        @Field("directory") public directory: string,
         @Field("debug") public debug: boolean,
         @Field("profile") public profile: boolean,
-        @Field("logRequests") public logRequests: boolean,
     ) {}
 }
 

server/types/logger.ts

@@ -1,4 +1,20 @@
+export type LogLevel = 'debug' | 'info' | 'warn' | 'error' | 'profile';
+export const LogLevels: LogLevel[] = ['debug', 'info', 'warn', 'error', 'profile'];
+
+export function isLogLevel(arg: any): arg is LogLevel {
+    if (typeof arg !== "string") {
+        return false;
+    }
+    for (const level of LogLevels) {
+        if (level === arg) {
+            return true;
+        }
+    }
+    return false;
+}
+
 export interface TaggedLogger {
+    log(level: LogLevel, ...args: any[]): void;
     debug(...args: any[]): void;
     info(...args: any[]): void;
     warn(...args: any[]): void;
@@ -7,6 +23,5 @@ export interface TaggedLogger {
 }
 
 export interface Logger {
-    init(): void;
     tag(...tags: string[]): TaggedLogger;
 }