From 50e9583e0ff0928c7a386d455d49ca932376e0d4 Mon Sep 17 00:00:00 2001 From: Alex Mikhalev Date: Sat, 30 Sep 2017 11:04:25 -0600 Subject: [PATCH] Added good logging to client --- .vscode/tasks.json | 10 ++++ app/index.tsx | 2 +- common/logger.ts | 136 ++++++++++++++++++++++++++++++++++++++++++++- common/mqtt.ts | 29 +++++----- 4 files changed, 162 insertions(+), 15 deletions(-) diff --git a/.vscode/tasks.json b/.vscode/tasks.json index 246d755..4a8b52d 100644 --- a/.vscode/tasks.json +++ b/.vscode/tasks.json @@ -23,6 +23,16 @@ } ] } + }, + { + "type": "npm", + "script": "watch:server", + "problemMatcher": [] + }, + { + "type": "npm", + "script": "start:pretty", + "problemMatcher": [] } ] } \ No newline at end of file diff --git a/app/index.tsx b/app/index.tsx index 2ec112f..22f22a6 100644 --- a/app/index.tsx +++ b/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" })); diff --git a/common/logger.ts b/common/logger.ts index 9c1deb1..9392a03 100644 --- a/common/logger.ts +++ b/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; diff --git a/common/mqtt.ts b/common/mqtt.ts index 1404082..161a086 100644 --- a/common/mqtt.ts +++ b/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) {