Improved logging

README.md

@@ -104,6 +104,7 @@ mqttBroker | URL of the MQTT Broker, eg. mqtt://localhost
 mqttUsername | Username of the MQTT broker
 mqttPassword | Password of the MQTT broker
 includeRoomsAsLights | Adds all rooms as lights, making it possible to turn on/off lights by room instead. Setting this to false will ignore all rooms. *Added in v. 5*.
+logLevel | Minimim log level. Supported values are `error`, `warn`, `info`, `debug`, `verbose`, `silly` with increasing amount of logging. Do not log more than `info` for production purposes.
 connectionTimeout | Number of seconds to wait when scanning and connecting. Might need to be tweaked on platforms other than RPi 4. Defaults to: 2 seconds.
 writeQueueWaitTime | Wait time between message sent to Plejd over BLE, defaults to 400. If that doesn't work, try changing the value higher in steps of 50.
 
@@ -128,6 +129,57 @@ https://www.home-assistant.io/integrations/google_assistant/
 Check this out for more information on how you can get your Plejd lights controlled using HomeKit:
 https://www.home-assistant.io/integrations/homekit/
 
+## Logs
+Logs are color coded and can be accessed on the Log tab of the addon. If you set log level to debug, verbose or silly you will generate a lot of log output
+that will quickly scroll out of view. Logs can be exported through Docker that hosts all Home Assistant addons. To do that:
+* SSH or console access the HA installation
+* Identify the docker container name using `docker container ls` (NAMES column). Example name used `addon_local_plejd`
+* tail logs: `tail -f addon_local_plejd`
+* tail logs, strip color coding and save to file `docker logs -f addon_local_plejd | sed 's/\x1b\[[0-9;]*m//g' > /config/plejd.log`  (output file might need to be adjusted)
+
+### View logs in VS Code addon
+Logs extracted as above can easily be viewed in the VS Code Home Assistant addon, which will default to using the excellent `Log File Highlighter` extension to parse the file.
+Out of the box you can for example view elapsed time by selecting multiple lines and keeping an eye in the status bar. If you're feeling fancy you can get back the removed color information by adding something like below to the the `settings.json` configuration of VS Code.
+
+```JSON
+{
+  ... other settings,
+  "logFileHighlighter.customPatterns": [
+    {
+        "pattern": "ERR",
+        "foreground": "#af1f1f",
+        "fontStyle": "bold",
+    },
+    {
+        "pattern": "WRN",
+        "foreground": "#af6f00",
+        "fontStyle": "bold",
+    },
+    {
+      "pattern": "INF",
+      "foreground": "#44d",
+      "fontStyle": "bold"
+    },
+    {
+      "pattern": "VRB",
+      "foreground": "#4a4",
+    },
+    {
+      "pattern": "DBG",
+      "foreground": "#4a4",
+    },
+    {
+      "pattern": "SIL",
+      "foreground": "#999"
+    },
+    {
+      "pattern": "\\[.*\\]",
+      "foreground": "#666"
+    }
+  ]  
+}
+```
+
 ## Changelog
 *v 0.4.5*:
 * FIX: Resolved a Docker build error

plejd/Configuration.js

@@ -0,0 +1,15 @@
+const fs = require('fs');
+
+class Configuration {
+    static _config = null;
+
+    static getConfiguration() {
+        if (!Configuration._config) {
+            const rawData = fs.readFileSync('/data/options.json');          
+            Configuration._config = JSON.parse(rawData);
+        } 
+        return Configuration._config;
+    }
+}
+
+module.exports = Configuration;

plejd/Dockerfile

@@ -8,11 +8,13 @@ SHELL ["/bin/bash", "-o", "pipefail", "-c"]
 
 # Copy data for add-on
 COPY ./api.js /plejd/
+COPY ./ble.bluez.js /plejd/
 COPY ./config.json /plejd/
+COPY ./Configuration.js /plejd/
+COPY ./Logger.js /plejd/
 COPY ./main.js /plejd/
 COPY ./mqtt.js /plejd/
 COPY ./package.json /plejd/
-COPY ./ble.bluez.js /plejd/
 COPY ./scene.manager.js /plejd/
 
 ARG BUILD_ARCH

plejd/Logger.js

@@ -0,0 +1,115 @@
+const winston = require("winston");
+const { colorize, combine, label, printf, timestamp } = winston.format;
+
+const Configuration = require("./Configuration");
+
+const LEVELS = ["error", "warn", "info", "debug", "verbose", "silly"];
+
+const logFormat = printf(info => {
+    if(info.stack) {
+        return `${info.timestamp} ${info.level} [${info.label}] ${info.message}\n${info.stack}`;
+    }
+    return `${info.timestamp} ${info.level} [${info.label}] ${info.message}`;
+});
+
+/** Winston-based logger */
+class Logger {
+    constructor () {
+        throw new Error("Please call createLogger instead");
+    }
+
+    /** Created logger will follow Winston createLogger, but
+     *  - add module name to logger
+     *  - swap debug/verbose levels and omit http to mimic HA standard 
+     * Levels (in order): error, warn, info, debug, verbose, silly
+     * */
+    static getLogger(moduleName) {
+        const config = Configuration.getConfiguration();
+        const level = (config.logLevel && LEVELS.find(l => l.startsWith(config.logLevel[0].toLowerCase()))) || "info";
+
+        const logger = winston.createLogger({
+            format: combine(
+                winston.format(info => {
+                    switch (info.level) {
+                        case "warning":
+                            info.level = "WRN";
+                            break;
+                        case "verbose":
+                            info.level = "VRB";
+                            break;
+                        case "debug":
+                            info.level = "DBG";
+                            break;
+                        default:
+                            info.level = info.level.substring(0,3).toUpperCase()
+                    }
+
+                    return info;
+                })(),
+                timestamp({ format: 'YYYY-MM-DD HH:mm:ss' }),
+                label({ label: moduleName}),
+                colorize(),
+                logFormat,
+            ),
+            level: level,
+            levels: Logger.logLevels().levels,
+            transports: [
+                new winston.transports.Console(),
+            ]
+        });
+        winston.addColors(Logger.logLevels().colors);
+
+
+        if (moduleName === "plejd-main") {
+            logger.log(level, `Log level set to ${level}`);
+        }
+
+        return logger;
+    }
+
+
+    static logLevels() {
+        // Default (npm) levels
+        // levels = { 
+        //     error: 0, 
+        //     warn: 1, 
+        //     info: 2, 
+        //     http: 3,
+        //     verbose: 4, 
+        //     debug: 5, 
+        //     silly: 6 
+        // }
+        // colors = {
+        //     error: 'red',
+        //     warn: 'yellow',
+        //     info: 'green',
+        //     http: 'green',
+        //     verbose: 'cyan',
+        //     debug: 'blue',
+        //     silly: 'magenta'
+        //   };
+
+        // Mimic HA standard below
+        // Debug/verbose swapped compared to npm levels, http omitted
+        return {
+          levels: { 
+            error: 0, 
+            warn: 1, 
+            info: 2, 
+            debug: 3,
+            verbose: 4, 
+            silly: 6 
+          },
+          colors: {
+            error: 'red',
+            warn: 'yellow',
+            info: 'green',
+            debug: 'cyan',
+            verbose: 'blue',
+            silly: 'magenta'
+          }
+        };
+    }
+}
+
+module.exports = Logger;

plejd/api.js

@@ -1,26 +1,14 @@
 const axios = require('axios');
 const EventEmitter = require('events');
+const Logger = require('./Logger');
 
 API_APP_ID = 'zHtVqXt8k4yFyk2QGmgp48D9xZr2G94xWYnF4dak';
 API_BASE_URL = 'https://cloud.plejd.com/parse/';
 API_LOGIN_URL = 'login';
 API_SITE_LIST_URL = 'functions/getSiteList';
 API_SITE_DETAILS_URL = 'functions/getSiteById';
 
-const logInfo = true;     // Normal operations
-const logDebug = false;   // Chatty
-const logVerbose = false; // Very chatty
-
-const consoleLogger = (level) => (...msg) =>
-  console.log(new Date().toISOString().replace("T", " ").substring(0, 19) + "Z", level, "plejd-api", ...msg);
-
-const getLogger = (level, shouldLog) => (shouldLog ? consoleLogger(level) : () => {});
-
-const errLogger = getLogger("ERR", true);
-const infLogger = getLogger("INF", logInfo);
-const dbgLogger = getLogger("DBG", logDebug);
-const vrbLogger = getLogger("vrb", logVerbose);
-
+const logger = Logger.getLogger("plejd-api");
 
 class PlejdApi extends EventEmitter {
   constructor(siteName, username, password, includeRoomsAsLights) {
@@ -35,13 +23,9 @@ class PlejdApi extends EventEmitter {
     this.site = null;
   }
 
-  updateSettings(settings) {
-    logVerbose("Got new settings: ", settings);
-  }
-
   login() {
-    infLogger('login()');
-    infLogger('logging into ' + this.siteName);
+    logger.info('login()');
+    logger.info('logging into ' + this.siteName);
     const self = this;
 
     const instance = axios.create({
@@ -53,7 +37,7 @@ class PlejdApi extends EventEmitter {
     });
 
     return new Promise((resolve, reject) => {
-      dbgLogger('sending POST to ' + API_BASE_URL + API_LOGIN_URL);
+      logger.debug('sending POST to ' + API_BASE_URL + API_LOGIN_URL);
 
       instance.post(
         API_LOGIN_URL,
@@ -62,22 +46,22 @@ class PlejdApi extends EventEmitter {
           'password': this.password
         })
         .then((response) => {
-          infLogger('got session token response');
+          logger.info('got session token response');
           self.sessionToken = response.data.sessionToken;
 
           if (!self.sessionToken) {
-            errLogger('No session token received');
+            logger.error('No session token received');
             reject('no session token received.');
           }
 
           resolve();
         })
         .catch((error) => {
           if (error.response.status === 400) {
-            errLogger('Server returned status 400. probably invalid credentials, please verify.');
+            logger.error('Server returned status 400. probably invalid credentials, please verify.');
           }
           else {
-            errLogger('Unable to retrieve session token response: ' + error);
+            logger.error('Unable to retrieve session token response: ', error);
           }
 
           reject('unable to retrieve session token response: ' + error);
@@ -86,7 +70,7 @@ class PlejdApi extends EventEmitter {
   }
 
   getSites() {
-    infLogger('getSites()');
+    logger.info('Get all Plejd sites for account...');
     const self = this;
 
     const instance = axios.create({
@@ -99,30 +83,30 @@ class PlejdApi extends EventEmitter {
     });
 
     return new Promise((resolve, reject) => {
-      dbgLogger('sending POST to ' + API_BASE_URL + API_SITE_LIST_URL);
+      logger.debug('sending POST to ' + API_BASE_URL + API_SITE_LIST_URL);
 
       instance.post(API_SITE_LIST_URL)
         .then((response) => {
-          infLogger('got site list response');
+          logger.info('got site list response');
           const site = response.data.result.find(x => x.site.title == self.siteName);
 
           if (!site) {
-            errLogger('error: failed to find a site named ' + self.siteName);
+            logger.error('error: failed to find a site named ' + self.siteName);
             reject('failed to find a site named ' + self.siteName);
             return;
           }
 
           resolve(site);
         })
         .catch((error) => {
-          errLogger('error: unable to retrieve list of sites. error: ' + error);
+          logger.error('error: unable to retrieve list of sites. error: ', error);
           return reject('plejd-api: unable to retrieve list of sites. error: ' + error);
         });
     });
   }
 
   getSite(siteId) {
-    infLogger('getSite(...)');
+    logger.info(`Get site details...`);
     const self = this;
 
     const instance = axios.create({
@@ -135,14 +119,14 @@ class PlejdApi extends EventEmitter {
     });
 
     return new Promise((resolve, reject) => {
-      dbgLogger('sending POST to ' + API_BASE_URL + API_SITE_DETAILS_URL);
+      logger.debug('sending POST to ' + API_BASE_URL + API_SITE_DETAILS_URL);
 
       instance.post(API_SITE_DETAILS_URL, { siteId: siteId })
         .then((response) => {
-          infLogger('got site details response');
+          logger.info('got site details response');
           if (response.data.result.length === 0) {
             const msg = 'no site with ID ' + siteId + ' was found.';
-            errLogger('error: ' + msg);
+            logger.error('error: ' + msg);
             reject(msg);
             return;
           }
@@ -153,7 +137,7 @@ class PlejdApi extends EventEmitter {
           resolve(self.cryptoKey);
         })
         .catch((error) => {
-          errLogger('error: unable to retrieve the crypto key. error: ' + error);
+          logger.error('error: unable to retrieve the crypto key. error: ', error);
           return reject('plejd-api: unable to retrieve the crypto key. error: ' + error);
         });
     });
@@ -162,7 +146,7 @@ class PlejdApi extends EventEmitter {
   getDevices() {
     let devices = [];
 
-    vrbLogger(JSON.stringify(this.site));
+    logger.verbose(JSON.stringify(this.site));
 
     const roomDevices = {};
 
@@ -252,7 +236,7 @@ class PlejdApi extends EventEmitter {
     }
 
     if (this.includeRoomsAsLights) {
-      dbgLogger('includeRoomsAsLights is set to true, adding rooms too.');
+      logger.debug('includeRoomsAsLights is set to true, adding rooms too.');
       for (let i = 0; i < this.site.rooms.length; i++) {
         const room = this.site.rooms[i];
         const roomId = room.roomId;
@@ -268,7 +252,7 @@ class PlejdApi extends EventEmitter {
 
         devices.push(newDevice);
       }
-      dbgLogger('includeRoomsAsLights done.');
+      logger.debug('includeRoomsAsLights done.');
     }
 
     // add scenes as switches