Added good logging to client

.vscode/tasks.json

@@ -23,6 +23,16 @@
                     }
                 ]
             }
+        },
+        {
+            "type": "npm",
+            "script": "watch:server",
+            "problemMatcher": []
+        },
+        {
+            "type": "npm",
+            "script": "start:pretty",
+            "problemMatcher": []
         }
     ]
 }

app/index.tsx

@@ -4,7 +4,7 @@ import { AppContainer } from "react-hot-loader";
 
 import App from "@app/components/App";
 import { ProvideState, State } from "@app/state";
-import log, { setLogger } from "@common/log";
+import log, { setLogger } from "@common/logger";
 
 setLogger(log.child({ name: "sprinklers3/app" }));
 

common/logger.ts

@@ -1,6 +1,140 @@
 import * as pino from "pino";
 
-let logger: pino.Logger = pino();
+type Level = "default" | 60 | 50 | 40 | 30 | 20 | 10;
+
+const levels = {
+    default: "USERLVL",
+    60: "FATAL",
+    50: "ERROR",
+    40: "WARN",
+    30: "INFO",
+    20: "DEBUG",
+    10: "TRACE",
+};
+
+const levelColors = {
+    default: "text-decoration: underline; color: #000000;",
+    60: "text-decoration: underline; background-color: #FF0000;",
+    50: "text-decoration: underline; color: #FF0000;",
+    40: "text-decoration: underline; color: #FFFF00;",
+    30: "text-decoration: underline; color: #00FF00;",
+    20: "text-decoration: underline; color: #0000FF;",
+    10: "text-decoration: underline; color: #AAAAAA;",
+};
+
+interface ColoredString {
+    str: string;
+    args: any[];
+}
+
+function makeColored(str: string = ""): ColoredString {
+    return { str, args: [] };
+}
+
+function concatColored(...coloredStrings: ColoredString[]): ColoredString {
+    return coloredStrings.reduce((prev, cur) => ({
+        str: prev.str + cur.str,
+        args: prev.args.concat(cur.args),
+    }), makeColored());
+}
+
+const standardKeys = ["pid", "hostname", "name", "level", "time", "v", "source", "msg"];
+
+function formatter(value: any) {
+    let line = concatColored(
+        // makeColored(formatTime(value, " ")),
+        formatSource(value),
+        formatLevel(value),
+        makeColored(": "),
+    );
+
+    if (value.msg) {
+        line = concatColored(line, {
+            str: "%c" + value.msg, args: ["color: #00FFFF"],
+        });
+    }
+    let args = [line.str].concat(line.args);
+    if (value.type === "Error") {
+        args = args.concat([value.stack]);
+    } else {
+        args = args.concat([filter(value)]);
+    }
+    let fn;
+    if (value.level >= 50) {
+        fn = console.error;
+    } else if (value.level >= 40) {
+        fn = console.warn;
+    } else {
+        fn = console.log;
+    }
+    fn.apply(null, args);
+}
+
+function withSpaces(value: string): string {
+    const lines = value.split("\n");
+    for (let i = 1; i < lines.length; i++) {
+        lines[i] = "    " + lines[i];
+    }
+    return lines.join("\n");
+}
+
+function filter(value: any) {
+    const keys = Object.keys(value);
+    const result: any = {};
+
+    for (const key of keys) {
+        if (standardKeys.indexOf(key) < 0) {
+            result[key] = value[key];
+        }
+    }
+
+    return result;
+}
+
+function asISODate(time: string) {
+    return new Date(time).toISOString();
+}
+
+function formatTime(value: any, after?: string) {
+    after = after || "";
+    try {
+        if (!value || !value.time) {
+            return "";
+        } else {
+            return "[" + asISODate(value.time) + "]" + after;
+        }
+    } catch (_) {
+        return "";
+    }
+}
+
+function formatSource(value: any): { str: string, args: any[] } {
+    if (value.source) {
+        return { str: "%c(" + value.source + ") ", args: ["color: #FF00FF"] };
+    } else {
+        return { str: "", args: [] };
+    }
+}
+
+function formatLevel(value: any): ColoredString {
+    const level = value.level as Level;
+    if (levelColors.hasOwnProperty(level as string)) {
+        return {
+            str: "%c" + levels[level] + "%c",
+            args: [levelColors[level], ""],
+        };
+    } else {
+        return {
+            str: levels.default,
+            args: [levelColors.default],
+        };
+    }
+}
+
+let logger: pino.Logger = pino({
+    browser: { write: formatter },
+    level: "trace",
+});
 
 export function setLogger(newLogger: pino.Logger) {
     logger = newLogger;

common/mqtt.ts

@@ -1,5 +1,6 @@
 import * as mqtt from "../node_modules/mqtt";
 
+import logger from "./logger";
 import {
     Duration,
     ISprinklersApi,
@@ -14,6 +15,8 @@ import {
 } from "./sprinklers";
 import { checkedIndexOf } from "./utils";
 
+const log = logger.child({ source: "mqtt" });
+
 export class MqttApiClient implements ISprinklersApi {
     readonly mqttUri: string;
     client: mqtt.Client;
@@ -30,7 +33,7 @@ export class MqttApiClient implements ISprinklersApi {
 
     start() {
         const clientId = MqttApiClient.newClientId();
-        console.log("connecting to mqtt with client id %s", clientId);
+        log.info({ clientId }, "connecting to mqtt with client id");
         this.client = mqtt.connect(this.mqttUri, {
             clientId,
         });
@@ -38,11 +41,11 @@ export class MqttApiClient implements ISprinklersApi {
         this.client.on("offline", () => {
             this.connected = false;
         });
-        this.client.on("error", (e) => {
-            console.error("mqtt error: ", e);
+        this.client.on("error", (err) => {
+            log.error({ err }, "mqtt error");
         });
         this.client.on("connect", () => {
-            console.log("mqtt connected");
+            log.info("mqtt connected");
             this.connected = true;
             for (const prefix of Object.keys(this.devices)) {
                 const device = this.devices[prefix];
@@ -76,19 +79,19 @@ export class MqttApiClient implements ISprinklersApi {
     private onMessageArrived(topic: string, payload: Buffer, packet: mqtt.Packet) {
         try {
             this.processMessage(topic, payload, packet);
-        } catch (e) {
-            console.error("error while processing mqtt message", e);
+        } catch (err) {
+            log.error({ err }, "error while processing mqtt message");
         }
     }
 
     private processMessage(topic: string, payload: Buffer, packet: mqtt.Packet) {
-        console.log("message arrived: ", { topic, payload });
+        log.trace({ topic, payload }, "message arrived: ");
         const topicIdx = topic.indexOf("/"); // find the first /
         const prefix = topic.substr(0, topicIdx); // assume prefix does not contain a /
         const topicSuffix = topic.substr(topicIdx + 1);
         const device = this.devices[prefix];
         if (!device) {
-            console.warn(`received message for unknown device. prefix: ${prefix}`);
+            log.debug({ prefix }, "received message for unknown device");
             return;
         }
         device.onMessage(topicSuffix, payload);
@@ -143,7 +146,7 @@ class MqttSprinklersDevice extends SprinklersDevice {
         const payload = payloadBuf.toString("utf8");
         if (topic === "connected") {
             this.connected = (payload === "true");
-            // console.log(`MqttSprinklersDevice with prefix ${this.prefix}: ${this.connected}`)
+            log.trace(`MqttSprinklersDevice with prefix ${this.prefix}: ${this.connected}`);
             return;
         }
         let matches = topic.match(/^sections(?:\/(\d+)(?:\/?(.+))?)?$/);
@@ -151,7 +154,7 @@ class MqttSprinklersDevice extends SprinklersDevice {
             //noinspection JSUnusedLocalSymbols
             /* tslint:disable-next-line:no-unused-variable */
             const [_topic, secStr, subTopic] = matches;
-            // console.log(`section: ${secStr}, topic: ${subTopic}, payload: ${payload}`);
+            log.trace({ section: secStr, topic: subTopic, payload });
             if (!secStr) { // new number of sections
                 this.sections.length = Number(payload);
             } else {
@@ -169,7 +172,7 @@ class MqttSprinklersDevice extends SprinklersDevice {
             //noinspection JSUnusedLocalSymbols
             /* tslint:disable-next-line:no-unused-variable */
             const [_topic, progStr, subTopic] = matches;
-            // console.log(`program: ${progStr}, topic: ${subTopic}, payload: ${payload}`);
+            log.trace({ program: progStr, topic: subTopic, payload });
             if (!progStr) { // new number of programs
                 this.programs.length = Number(payload);
             } else {
@@ -192,7 +195,7 @@ class MqttSprinklersDevice extends SprinklersDevice {
             //noinspection JSUnusedLocalSymbols
             /* tslint:disable-next-line:no-unused-variable */
             const [_topic, respIdStr] = matches;
-            // console.log(`response: ${respIdStr}`);
+            log.trace({ response: respIdStr });
             const respId = parseInt(respIdStr, 10);
             const data = JSON.parse(payload) as IResponseData;
             const cb = this.responseCallbacks[respId];
@@ -201,7 +204,7 @@ class MqttSprinklersDevice extends SprinklersDevice {
             }
             return;
         }
-        console.warn(`MqttSprinklersDevice recieved invalid topic: ${topic}`);
+        log.warn({ topic }, "MqttSprinklersDevice recieved invalid message");
     }
 
     runSection(section: Section | number, duration: Duration) {