From 0658d56658f678e5b7e926ef5f3e80b9cb0ee29b Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Wed, 2 Dec 2020 23:33:59 +0100 Subject: [PATCH 01/37] refactor: Add loging module based on winston --- lib/ZwaveClient.js | 201 ++++++++++++++++++++++----------------------- lib/logger.js | 43 ++++++++++ package.json | 1 + 3 files changed, 143 insertions(+), 102 deletions(-) create mode 100644 lib/logger.js diff --git a/lib/ZwaveClient.js b/lib/ZwaveClient.js index b472dca20b0..08889f4cf23 100644 --- a/lib/ZwaveClient.js +++ b/lib/ZwaveClient.js @@ -17,6 +17,7 @@ const { socketEvents } = reqlib('/lib/SocketManager.js') const store = reqlib('config/store.js') const storeDir = utils.joinPath(true, reqlib('config/app.js').storeDir) const debug = reqlib('/lib/debug')('Zwave') +const logger = require('./logger.js').module('ZWC') const inherits = require('util').inherits debug.color = 4 @@ -38,7 +39,7 @@ const eventEmitter = { /** * The constructor */ -function ZwaveClient (config, socket) { +function ZwaveClient(config, socket) { if (!(this instanceof ZwaveClient)) { return new ZwaveClient(config) } @@ -78,7 +79,7 @@ inherits(ZwaveClient, EventEmitter) // ---------- DRIVER EVENTS ------------------------------------- -function driverReady () { +function driverReady() { /* Now the controller interview is complete. This means we know which nodes are included in the network, but they might not be ready yet. @@ -89,7 +90,7 @@ function driverReady () { this.status = ZWAVE_STATUS.driverReady this.driverReady = true - debug('Zwave driver is ready') + logger.info('Zwave driver is ready') updateControllerStatus.call(this, 'Driver ready') @@ -123,10 +124,10 @@ function driverReady () { this.error = false - debug('Scanning network with homeid:', homeHex) + logger.info('Scanning network with homeid:', homeHex) } -function driverError (error) { +function driverError(error) { this.error = 'Driver: ' + error.message this.status = ZWAVE_STATUS.driverFailed updateControllerStatus.call(this, this.error) @@ -134,7 +135,7 @@ function driverError (error) { this.emit('event', eventEmitter.driver, 'driver error', error) } -function scanComplete () { +function scanComplete() { this.scanComplete = true updateControllerStatus.call(this, 'Scan completed') @@ -143,7 +144,7 @@ function scanComplete () { this.status = ZWAVE_STATUS.scanDone const nodes = this.nodes.filter(n => !n.failed) - debug('Network scan complete. Found:', nodes.length, 'nodes') + logger.info('Network scan complete. Found:', nodes.length, 'nodes') this.emit('scanComplete') @@ -152,50 +153,50 @@ function scanComplete () { // ---------- CONTROLLER EVENTS ------------------------------- -function updateControllerStatus (status) { - debug(status) +function updateControllerStatus(status) { + logger.info(status) this.cntStatus = status this.sendToSocket(socketEvents.controller, status) } -function onInclusionStarted (secure) { +function onInclusionStarted(secure) { const message = `${secure ? 'Secure' : 'Non-secure'} inclusion started` updateControllerStatus.call(this, message) this.emit('event', eventEmitter.controller, 'inclusion started', secure) } -function onExclusionStarted () { +function onExclusionStarted() { const message = 'Exclusion started' updateControllerStatus.call(this, message) this.emit('event', eventEmitter.controller, 'exclusion started') } -function onInclusionStopped () { +function onInclusionStopped() { const message = 'Inclusion stopped' updateControllerStatus.call(this, message) this.emit('event', eventEmitter.controller, 'inclusion stopped') } -function onExclusionStopped () { +function onExclusionStopped() { const message = 'Exclusion stopped' updateControllerStatus.call(this, message) this.emit('event', eventEmitter.controller, 'exclusion stopped') } -function onInclusionFailed () { +function onInclusionFailed() { const message = 'Inclusion failed' updateControllerStatus.call(this, message) this.emit('event', eventEmitter.controller, 'inclusion failed') } -function onExclusionFailed () { +function onExclusionFailed() { const message = 'Exclusion failed' updateControllerStatus.call(this, message) this.emit('event', eventEmitter.controller, 'exclusion failed') } -function onNodeAdded (zwaveNode) { - debug(`Node ${zwaveNode.id}: added`) +function onNodeAdded(zwaveNode) { + logger.info(`Node ${zwaveNode.id}: added`) if (this.driverReady) { bindNodeEvents.call(this, zwaveNode) @@ -209,8 +210,8 @@ function onNodeAdded (zwaveNode) { ) } -function onNodeRemoved (zwaveNode) { - debug(`Node ${zwaveNode.id}: removed`) +function onNodeRemoved(zwaveNode) { + logger.info(`Node ${zwaveNode.id}: removed`) zwaveNode.removeAllListeners() this.emit( @@ -223,7 +224,7 @@ function onNodeRemoved (zwaveNode) { removeNode.call(this, zwaveNode.id) } -function onHealNetworkProgress (progress) { +function onHealNetworkProgress(progress) { const toHeal = [...progress.values()] const healedNodes = toHeal.filter(v => v !== 'pending') let message @@ -247,7 +248,7 @@ function onHealNetworkProgress (progress) { // ---------- NODE EVENTS ------------------------------------- // generic node status update -function onNodeStatus (zwaveNode) { +function onNodeStatus(zwaveNode) { const node = this.nodes[zwaveNode.id] if (node) { @@ -258,7 +259,7 @@ function onNodeStatus (zwaveNode) { } } -function onNodeReady (zwaveNode) { +function onNodeReady(zwaveNode) { const node = this.nodes[zwaveNode.id] // node ready event has been already tiggered by this node @@ -286,7 +287,7 @@ function onNodeReady (zwaveNode) { this.emit('event', eventEmitter.node, 'node ready', this.nodes[zwaveNode.id]) - debug( + logger.info( 'Node %d ready: %s - %s (%s)', node.id, node.manufacturer, @@ -296,7 +297,7 @@ function onNodeReady (zwaveNode) { } // when this event is triggered all node values and metadata are updated -function onNodeInterviewCompleted (zwaveNode) { +function onNodeInterviewCompleted(zwaveNode) { const node = this.nodes[zwaveNode.id] node.interviewCompleted = true node.neighbors = zwaveNode.neighbors @@ -319,7 +320,7 @@ function onNodeInterviewCompleted (zwaveNode) { } } - debug(`Node ${zwaveNode.id}: interview completed, all values are updated`) + logger.info(`Node ${zwaveNode.id}: interview completed, all values are updated`) onNodeStatus.call(this, zwaveNode) @@ -331,10 +332,9 @@ function onNodeInterviewCompleted (zwaveNode) { ) } -function onNodeWakeUp (zwaveNode, oldStatus) { - debug( - `Node ${zwaveNode.id} is ${ - oldStatus === NodeStatus.Unknown ? '' : 'now ' +function onNodeWakeUp(zwaveNode, oldStatus) { + logger.info( + `Node ${zwaveNode.id} is ${oldStatus === NodeStatus.Unknown ? '' : 'now ' }awake` ) @@ -342,40 +342,38 @@ function onNodeWakeUp (zwaveNode, oldStatus) { this.emit('event', eventEmitter.node, 'node wakeup', this.nodes[zwaveNode.id]) } -function onNodeSleep (zwaveNode, oldStatus) { - debug( - `Node ${zwaveNode.id} is ${ - oldStatus === NodeStatus.Unknown ? '' : 'now ' +function onNodeSleep(zwaveNode, oldStatus) { + logger.info( + `Node ${zwaveNode.id} is ${oldStatus === NodeStatus.Unknown ? '' : 'now ' }asleep` ) onNodeStatus.call(this, zwaveNode) this.emit('event', eventEmitter.node, 'node sleep', this.nodes[zwaveNode.id]) } -function onNodeAlive (zwaveNode, oldStatus) { +function onNodeAlive(zwaveNode, oldStatus) { onNodeStatus.call(this, zwaveNode) if (oldStatus === NodeStatus.Dead) { - debug(`Node ${zwaveNode.id}: has returned from the dead`) + logger.info(`Node ${zwaveNode.id}: has returned from the dead`) } else { - debug(`Node ${zwaveNode.id} is alive`) + logger.info(`Node ${zwaveNode.id} is alive`) } this.emit('event', eventEmitter.node, 'node alive', this.nodes[zwaveNode.id]) } -function onNodeDead (zwaveNode, oldStatus) { +function onNodeDead(zwaveNode, oldStatus) { onNodeStatus.call(this, zwaveNode) - debug( - `Node ${zwaveNode.id} is ${ - oldStatus === NodeStatus.Unknown ? '' : 'now ' + logger.info( + `Node ${zwaveNode.id} is ${oldStatus === NodeStatus.Unknown ? '' : 'now ' }dead` ) this.emit('event', eventEmitter.node, 'node dead', this.nodes[zwaveNode.id]) } -function onNodeValueAdded (zwaveNode, args) { - debug( +function onNodeValueAdded(zwaveNode, args) { + logger.info( `Node ${zwaveNode.id}: value added: ${getValueID(args)} =>`, args.newValue ) @@ -394,9 +392,9 @@ function onNodeValueAdded (zwaveNode, args) { ) } -function onNodeValueUpdated (zwaveNode, args) { +function onNodeValueUpdated(zwaveNode, args) { updateValue.call(this, zwaveNode, args) - debug( + logger.info( `Node ${zwaveNode.id}: value updated: ${getValueID(args)}`, args.prevValue, '=>', @@ -412,9 +410,9 @@ function onNodeValueUpdated (zwaveNode, args) { ) } -function onNodeValueRemoved (zwaveNode, args) { +function onNodeValueRemoved(zwaveNode, args) { removeValue.call(this, zwaveNode, args) - debug(`Node ${zwaveNode.id}: value removed: ${args}`) + logger.info(`Node ${zwaveNode.id}: value removed: ${args}`) this.emit( 'event', eventEmitter.node, @@ -424,9 +422,9 @@ function onNodeValueRemoved (zwaveNode, args) { ) } -function onNodeMetadataUpdated (zwaveNode, args) { +function onNodeMetadataUpdated(zwaveNode, args) { const valueId = initValue.call(this, zwaveNode, args, args.metadata) - debug(`Node ${valueId.nodeId}: metadata updated: ${getValueID(args)}`) + logger.info(`Node ${valueId.nodeId}: metadata updated: ${getValueID(args)}`) this.emit( 'event', eventEmitter.node, @@ -436,10 +434,9 @@ function onNodeMetadataUpdated (zwaveNode, args) { ) } -function onNodeNotification (zwaveNode, notificationLabel, parameters) { - debug( - `Node ${zwaveNode.id}: notification: ${notificationLabel} ${ - parameters ? 'with ' + parameters.toString() : '' +function onNodeNotification(zwaveNode, notificationLabel, parameters) { + logger.info( + `Node ${zwaveNode.id}: notification: ${notificationLabel} ${parameters ? 'with ' + parameters.toString() : '' }` ) this.emit('notification', zwaveNode, notificationLabel, parameters) @@ -453,7 +450,7 @@ function onNodeNotification (zwaveNode, notificationLabel, parameters) { ) } -function onNodeFirmwareUpdateProgress ( +function onNodeFirmwareUpdateProgress( zwaveNode, sentFragments, totalFragments @@ -473,7 +470,7 @@ function onNodeFirmwareUpdateProgress ( } // https://github.com/zwave-js/node-zwave-js/blob/cb35157da5e95f970447a67cbb2792e364b9d1e1/packages/zwave-js/src/lib/commandclass/FirmwareUpdateMetaDataCC.ts#L59 -function onNodeFirmwareUpdateFinished (zwaveNode, status, waitTime) { +function onNodeFirmwareUpdateFinished(zwaveNode, status, waitTime) { updateControllerStatus.call( this, `Node ${zwaveNode.id} firmware update FINISHED: Status ${status}, Time: ${waitTime}` @@ -491,7 +488,7 @@ function onNodeFirmwareUpdateFinished (zwaveNode, status, waitTime) { // ------- NODE METHODS ------------- -function bindNodeEvents (node) { +function bindNodeEvents(node) { // add a node to our nodes array addNode.call(this, node) @@ -512,8 +509,8 @@ function bindNodeEvents (node) { .on('firmware update finished', onNodeFirmwareUpdateFinished.bind(this)) } -function removeNode (nodeid) { - debug('Node removed', nodeid) +function removeNode(nodeid) { + logger.info('Node removed', nodeid) // don't use splice here, nodeid equals to the index in the array const node = this.nodes[nodeid] @@ -527,7 +524,7 @@ function removeNode (nodeid) { } // Triggered when a node is added but no informations are received yet -function addNode (zwaveNode) { +function addNode(zwaveNode) { const nodeId = zwaveNode.id this.nodes[nodeId] = { @@ -561,10 +558,10 @@ function addNode (zwaveNode) { onNodeStatus.call(this, zwaveNode) this.addEmptyNodes() - debug('Node added', nodeId) + logger.info('Node added', nodeId) } -function initNode (zwaveNode) { +function initNode(zwaveNode) { const nodeId = zwaveNode.id const node = this.nodes[nodeId] @@ -628,7 +625,7 @@ function initNode (zwaveNode) { this.getGroups(zwaveNode.id, true) } -function updateValueMetadata (zwaveNode, zwaveValue, zwaveValueMeta) { +function updateValueMetadata(zwaveNode, zwaveValue, zwaveValueMeta) { zwaveValue.nodeId = zwaveNode.id const valueId = { @@ -697,23 +694,23 @@ function updateValueMetadata (zwaveNode, zwaveValue, zwaveValueMeta) { * @param { ZWaveNode } zwaveNode * @param { ValueAddedArgs } valueAddedArgs https://github.com/zwave-js/node-zwave-js/blob/cb35157da5e95f970447a67cbb2792e364b9d1e1/packages/core/src/values/ValueDB.ts#L8 */ -function addValue (zwaveNode, zwaveValue) { +function addValue(zwaveNode, zwaveValue) { const node = this.nodes[zwaveNode.id] if (!node) { - debug('ValueAdded: no such node: ' + zwaveNode.id, 'error') + logger.info('ValueAdded: no such node: ' + zwaveNode.id, 'error') } else { const zwaveValueMeta = zwaveNode.getValueMetadata(zwaveValue) const valueId = initValue.call(this, zwaveNode, zwaveValue, zwaveValueMeta) - debug(`Node ${zwaveNode.id}: value added ${valueId.id} => ${valueId.value}`) + logger.info(`Node ${zwaveNode.id}: value added ${valueId.id} => ${valueId.value}`) this.emit('valueChanged', valueId, node) } } -function initValue (zwaveNode, zwaveValue, zwaveValueMeta) { +function initValue(zwaveNode, zwaveValue, zwaveValueMeta) { const node = this.nodes[zwaveNode.id] const valueId = updateValueMetadata.call( this, @@ -737,11 +734,11 @@ function initValue (zwaveNode, zwaveValue, zwaveValueMeta) { } // Triggered when a node is ready and a value changes -function updateValue (zwaveNode, args) { +function updateValue(zwaveNode, args) { const node = this.nodes[zwaveNode.id] if (!node) { - debug('valueChanged: no such node: ' + zwaveNode.id, 'error') + logger.info('valueChanged: no such node: ' + zwaveNode.id, 'error') } else { const valueId = node.values[getValueID(args)] @@ -754,7 +751,7 @@ function updateValue (zwaveNode, args) { } } -function removeValue (zwaveNode, args) { +function removeValue(zwaveNode, args) { const node = this.nodes[zwaveNode.id] const idString = getValueID(args) const toRemove = node ? node.values[idString] : null @@ -762,9 +759,9 @@ function removeValue (zwaveNode, args) { if (toRemove) { delete node.values[idString] this.sendToSocket(socketEvents.valueRemoved, toRemove) - debug('ValueRemoved: %s from node %d', idString, zwaveNode.id) + logger.info('ValueRemoved: %s from node %d', idString, zwaveNode.id) } else { - debug('ValueRemoved: no such node: ' + zwaveNode.id, 'error') + logger.info('ValueRemoved: no such node: ' + zwaveNode.id, 'error') } } @@ -776,7 +773,7 @@ function removeValue (zwaveNode, args) { * @param {Object} node Internal node object * @returns A string in the format `--` that unique identifhy a zwave device */ -function getDeviceID (node) { +function getDeviceID(node) { if (!node) return '' return `${parseInt(node.manufacturerId)}-${parseInt( @@ -784,11 +781,11 @@ function getDeviceID (node) { )}-${parseInt(node.productType)}` } -function isCurrentValue (valueId) { +function isCurrentValue(valueId) { return valueId.propertyName && /current/i.test(valueId.propertyName) } -function findTargetValue (zwaveValue, definedValueIds) { +function findTargetValue(zwaveValue, definedValueIds) { return definedValueIds.find( v => v.commandClass === zwaveValue.commandClass && @@ -805,7 +802,7 @@ function findTargetValue (zwaveValue, definedValueIds) { * @param {Boolean} nodeId Add node identifier * @returns The value id unique identifier */ -function getValueID (v, withNode) { +function getValueID(v, withNode) { return `${withNode ? v.nodeId + '-' : ''}${v.commandClass}-${v.endpoint || 0}-${v.property}${v.propertyKey !== undefined ? '-' + v.propertyKey : ''}` } @@ -816,7 +813,7 @@ function getValueID (v, withNode) { * context - what you want "this" to be. * params - array of parameters to pass to function. */ -function wrapFunction (fn, context, params) { +function wrapFunction(fn, context, params) { return function () { fn.apply(context, params) } @@ -828,7 +825,7 @@ function wrapFunction (fn, context, params) { * @param {*} obj The object to copy * @returns The copied object */ -function copy (obj) { +function copy(obj) { return JSON.parse(JSON.stringify(obj)) } @@ -930,9 +927,9 @@ ZwaveClient.prototype.heal = function () { try { this.beginHealingNetwork() - debug('Network auto heal started') + logger.info('Network auto heal started') } catch (error) { - debug('Error while doing scheduled network heal', error.message) + logger.error('Error while doing scheduled network heal', error.message) } // schedule next @@ -1086,7 +1083,7 @@ ZwaveClient.prototype.getGroups = async function ( try { groups = await this.driver.controller.getAssociationGroups(nodeId) } catch (error) { - debug(`Node ${nodeId} doesn't support groups associations`) + logger.warn(`Node ${nodeId} doesn't support groups associations`) // node doesn't support groups associations } for (const [groupIndex, group] of groups) { @@ -1124,11 +1121,11 @@ ZwaveClient.prototype.getAssociations = async function (nodeId, groupId) { groupId ) } catch (error) { - debug(`Node ${nodeId} doesn't support groups associations`) + logger.warn(`Node ${nodeId} doesn't support groups associations`) // node doesn't support groups associations } } else { - debug(`Node ${nodeId} not found when calling 'getAssociations'`) + logger.warn(`Node ${nodeId} not found when calling 'getAssociations'`) } return associations @@ -1152,21 +1149,21 @@ ZwaveClient.prototype.addAssociations = async function ( try { for (const a of associations) { if (this.driver.controller.isAssociationAllowed(nodeId, groupId, a)) { - debug( + logger.info( `Assocaitions: Adding Node ${a.nodeId} to Group ${groupId} of Node ${nodeId}` ) await this.driver.controller.addAssociations(nodeId, groupId, [a]) } else { - debug( + logger.warn( `Associations: Unable to add Node ${a.nodeId} to Group ${groupId} of Node ${nodeId}` ) } } } catch (error) { - debug(`Error while adding associations to ${nodeId}: ${error.message}`) + logger.warn(`Error while adding associations to ${nodeId}: ${error.message}`) } } else { - debug(`Node ${nodeId} not found when calling 'addAssociations'`) + logger.warn(`Node ${nodeId} not found when calling 'addAssociations'`) } } @@ -1186,7 +1183,7 @@ ZwaveClient.prototype.removeAssociations = async function ( if (zwaveNode) { try { - debug( + logger.info( `Assocaitions: Removing associations from Node ${nodeId} Group ${groupId}:`, associations ) @@ -1196,12 +1193,12 @@ ZwaveClient.prototype.removeAssociations = async function ( associations ) } catch (error) { - debug( + logger.warn( `Error while removing associations from ${nodeId}: ${error.message}` ) } } else { - debug(`Node ${nodeId} not found when calling 'removeAssociations'`) + logger.warn(`Node ${nodeId} not found when calling 'removeAssociations'`) } } @@ -1226,18 +1223,18 @@ ZwaveClient.prototype.removeAllAssociations = async function (nodeId) { groupId, associations ) - debug( + logger.info( `Assocaitions: Removed ${associations.length} associations from Node ${nodeId} group ${groupId}` ) } } } catch (error) { - debug( + logger.warn( `Error while removing all associations from ${nodeId}: ${error.message}` ) } } else { - debug(`Node ${nodeId} not found when calling 'removeAllAssociations'`) + logger.warn(`Node ${nodeId} not found when calling 'removeAllAssociations'`) } } @@ -1251,15 +1248,15 @@ ZwaveClient.prototype.removeNodeFromAllAssociations = async function (nodeId) { if (zwaveNode) { try { - debug(`Assocaitions: Removing Node ${nodeId} from all associations`) + logger.info(`Assocaitions: Removing Node ${nodeId} from all associations`) await this.driver.controller.removeNodeFromAllAssocations(nodeId) } catch (error) { - debug( + logger.warn( `Error while removing Node ${nodeId} from all associations: ${error.message}` ) } } else { - debug( + logger.warn( `Node ${nodeId} not found when calling 'removeNodeFromAllAssociations'` ) } @@ -1305,7 +1302,7 @@ ZwaveClient.prototype.connect = async function () { this.driver.once('driver ready', driverReady.bind(this)) this.driver.on('all nodes ready', scanComplete.bind(this)) - debug('Connecting to', this.cfg.port) + logger.info('Connecting to', this.cfg.port) try { await this.driver.start() @@ -1314,14 +1311,14 @@ ZwaveClient.prototype.connect = async function () { } catch (error) { // destroy diver instance when it fails this.driver.destroy().catch(err => { - debug('Error while destroing driver ' + err.message) + logger.error('Error while destroing driver ' + err.message) }) driverError.call(this, error) - debug('Retry connection in 3 seconds...') + logger.warn('Retry connection in 3 seconds...') this.reconnectTimeout = setTimeout(this.connect.bind(this), 3000) } } else { - debug('Driver already connected to', this.cfg.port) + logger.info('Driver already connected to', this.cfg.port) } } @@ -1698,7 +1695,7 @@ ZwaveClient.prototype.refreshInfo = async function (nodeId) { throw Error('Driver is closed') } -function guessFirmwareFormat (filename, firmware) { +function guessFirmwareFormat(filename, firmware) { if ( (filename.endsWith('.exe') || filename.endsWith('.ex_')) && firmware.includes(Buffer.from('Aeon Labs', 'utf8')) @@ -1878,7 +1875,7 @@ ZwaveClient.prototype.callApi = async function (apiName, ...args) { } } - debug(result.message, apiName, result.result || '') + logger.info(result.message, apiName, result.result || '') result.args = args @@ -1923,11 +1920,11 @@ ZwaveClient.prototype.writeValue = async function (valueId, value) { result = await this.getNode(valueId.nodeId).setValue(valueId, value) } } catch (error) { - debug(`Error while writing ${value} on ${valueId.id}: ${error.message}`) + logger.error(`Error while writing ${value} on ${valueId.id}: ${error.message}`) } // https://zwave-js.github.io/node-zwave-js/#/api/node?id=setvalue if (result === false) { - debug(`Unable to write ${value} on ${valueId.id}`) + logger.error(`Unable to write ${value} on ${valueId.id}`) } } } diff --git a/lib/logger.js b/lib/logger.js new file mode 100644 index 00000000000..3f3cf36e93f --- /dev/null +++ b/lib/logger.js @@ -0,0 +1,43 @@ +const winston = require('winston'); +const { createLogger, format, transports } = winston; +const { combine, timestamp, label, printf } = format; + +// Custom logging format +const customFormat = printf(({ level, message, label, timestamp }) => { + return `${timestamp} [${label || '-'}] ${level}: ${message}`; +}); + +// Custom combined logging format: +const customCombinedFormat = (module) => combine( + format.colorize({ all: true }), + label({ label: module }), + timestamp(), + customFormat +) + +// Custom transports: +const customTransports = () => [ + new transports.Console() +] + +// Container to provide different pre-configured loggers +const logContainer = new winston.Container() + +// Example: Pre-configured module logger with special properties +logContainer.add('ZWC', { + format: customCombinedFormat('ZWC'), + transports: customTransports() +}); + +// Default logger for modules: +logContainer.module = (module) => { + if (!logContainer.has(module)) { + logContainer.add(module, { + format: customCombinedFormat(module), + transports: customTransports() + }); + } + return logContainer.get(module); +} + +module.exports = logContainer diff --git a/package.json b/package.json index 4915b77928a..2ec529f6ccb 100644 --- a/package.json +++ b/package.json @@ -119,6 +119,7 @@ "vue-router": "^3.4.3", "vuetify": "^2.3.10", "vuex": "^3.5.1", + "winston": "^3.3.3", "zwave-js": "^5.5.0" }, "devDependencies": { From 8f43aa6d4e30f957ee713bac3406f27bf5aeb076 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Wed, 2 Dec 2020 23:49:09 +0100 Subject: [PATCH 02/37] style: Fix code style --- lib/ZwaveClient.js | 116 +++++++++++++++++++++++++-------------------- lib/logger.js | 35 +++++++------- 2 files changed, 81 insertions(+), 70 deletions(-) diff --git a/lib/ZwaveClient.js b/lib/ZwaveClient.js index 08889f4cf23..2584003363f 100644 --- a/lib/ZwaveClient.js +++ b/lib/ZwaveClient.js @@ -39,7 +39,7 @@ const eventEmitter = { /** * The constructor */ -function ZwaveClient(config, socket) { +function ZwaveClient (config, socket) { if (!(this instanceof ZwaveClient)) { return new ZwaveClient(config) } @@ -79,7 +79,7 @@ inherits(ZwaveClient, EventEmitter) // ---------- DRIVER EVENTS ------------------------------------- -function driverReady() { +function driverReady () { /* Now the controller interview is complete. This means we know which nodes are included in the network, but they might not be ready yet. @@ -127,7 +127,7 @@ function driverReady() { logger.info('Scanning network with homeid:', homeHex) } -function driverError(error) { +function driverError (error) { this.error = 'Driver: ' + error.message this.status = ZWAVE_STATUS.driverFailed updateControllerStatus.call(this, this.error) @@ -135,7 +135,7 @@ function driverError(error) { this.emit('event', eventEmitter.driver, 'driver error', error) } -function scanComplete() { +function scanComplete () { this.scanComplete = true updateControllerStatus.call(this, 'Scan completed') @@ -153,49 +153,49 @@ function scanComplete() { // ---------- CONTROLLER EVENTS ------------------------------- -function updateControllerStatus(status) { +function updateControllerStatus (status) { logger.info(status) this.cntStatus = status this.sendToSocket(socketEvents.controller, status) } -function onInclusionStarted(secure) { +function onInclusionStarted (secure) { const message = `${secure ? 'Secure' : 'Non-secure'} inclusion started` updateControllerStatus.call(this, message) this.emit('event', eventEmitter.controller, 'inclusion started', secure) } -function onExclusionStarted() { +function onExclusionStarted () { const message = 'Exclusion started' updateControllerStatus.call(this, message) this.emit('event', eventEmitter.controller, 'exclusion started') } -function onInclusionStopped() { +function onInclusionStopped () { const message = 'Inclusion stopped' updateControllerStatus.call(this, message) this.emit('event', eventEmitter.controller, 'inclusion stopped') } -function onExclusionStopped() { +function onExclusionStopped () { const message = 'Exclusion stopped' updateControllerStatus.call(this, message) this.emit('event', eventEmitter.controller, 'exclusion stopped') } -function onInclusionFailed() { +function onInclusionFailed () { const message = 'Inclusion failed' updateControllerStatus.call(this, message) this.emit('event', eventEmitter.controller, 'inclusion failed') } -function onExclusionFailed() { +function onExclusionFailed () { const message = 'Exclusion failed' updateControllerStatus.call(this, message) this.emit('event', eventEmitter.controller, 'exclusion failed') } -function onNodeAdded(zwaveNode) { +function onNodeAdded (zwaveNode) { logger.info(`Node ${zwaveNode.id}: added`) if (this.driverReady) { @@ -210,7 +210,7 @@ function onNodeAdded(zwaveNode) { ) } -function onNodeRemoved(zwaveNode) { +function onNodeRemoved (zwaveNode) { logger.info(`Node ${zwaveNode.id}: removed`) zwaveNode.removeAllListeners() @@ -224,7 +224,7 @@ function onNodeRemoved(zwaveNode) { removeNode.call(this, zwaveNode.id) } -function onHealNetworkProgress(progress) { +function onHealNetworkProgress (progress) { const toHeal = [...progress.values()] const healedNodes = toHeal.filter(v => v !== 'pending') let message @@ -248,7 +248,7 @@ function onHealNetworkProgress(progress) { // ---------- NODE EVENTS ------------------------------------- // generic node status update -function onNodeStatus(zwaveNode) { +function onNodeStatus (zwaveNode) { const node = this.nodes[zwaveNode.id] if (node) { @@ -259,7 +259,7 @@ function onNodeStatus(zwaveNode) { } } -function onNodeReady(zwaveNode) { +function onNodeReady (zwaveNode) { const node = this.nodes[zwaveNode.id] // node ready event has been already tiggered by this node @@ -297,7 +297,7 @@ function onNodeReady(zwaveNode) { } // when this event is triggered all node values and metadata are updated -function onNodeInterviewCompleted(zwaveNode) { +function onNodeInterviewCompleted (zwaveNode) { const node = this.nodes[zwaveNode.id] node.interviewCompleted = true node.neighbors = zwaveNode.neighbors @@ -320,7 +320,9 @@ function onNodeInterviewCompleted(zwaveNode) { } } - logger.info(`Node ${zwaveNode.id}: interview completed, all values are updated`) + logger.info( + `Node ${zwaveNode.id}: interview completed, all values are updated` + ) onNodeStatus.call(this, zwaveNode) @@ -332,9 +334,10 @@ function onNodeInterviewCompleted(zwaveNode) { ) } -function onNodeWakeUp(zwaveNode, oldStatus) { +function onNodeWakeUp (zwaveNode, oldStatus) { logger.info( - `Node ${zwaveNode.id} is ${oldStatus === NodeStatus.Unknown ? '' : 'now ' + `Node ${zwaveNode.id} is ${ + oldStatus === NodeStatus.Unknown ? '' : 'now ' }awake` ) @@ -342,16 +345,17 @@ function onNodeWakeUp(zwaveNode, oldStatus) { this.emit('event', eventEmitter.node, 'node wakeup', this.nodes[zwaveNode.id]) } -function onNodeSleep(zwaveNode, oldStatus) { +function onNodeSleep (zwaveNode, oldStatus) { logger.info( - `Node ${zwaveNode.id} is ${oldStatus === NodeStatus.Unknown ? '' : 'now ' + `Node ${zwaveNode.id} is ${ + oldStatus === NodeStatus.Unknown ? '' : 'now ' }asleep` ) onNodeStatus.call(this, zwaveNode) this.emit('event', eventEmitter.node, 'node sleep', this.nodes[zwaveNode.id]) } -function onNodeAlive(zwaveNode, oldStatus) { +function onNodeAlive (zwaveNode, oldStatus) { onNodeStatus.call(this, zwaveNode) if (oldStatus === NodeStatus.Dead) { logger.info(`Node ${zwaveNode.id}: has returned from the dead`) @@ -362,17 +366,18 @@ function onNodeAlive(zwaveNode, oldStatus) { this.emit('event', eventEmitter.node, 'node alive', this.nodes[zwaveNode.id]) } -function onNodeDead(zwaveNode, oldStatus) { +function onNodeDead (zwaveNode, oldStatus) { onNodeStatus.call(this, zwaveNode) logger.info( - `Node ${zwaveNode.id} is ${oldStatus === NodeStatus.Unknown ? '' : 'now ' + `Node ${zwaveNode.id} is ${ + oldStatus === NodeStatus.Unknown ? '' : 'now ' }dead` ) this.emit('event', eventEmitter.node, 'node dead', this.nodes[zwaveNode.id]) } -function onNodeValueAdded(zwaveNode, args) { +function onNodeValueAdded (zwaveNode, args) { logger.info( `Node ${zwaveNode.id}: value added: ${getValueID(args)} =>`, args.newValue @@ -392,7 +397,7 @@ function onNodeValueAdded(zwaveNode, args) { ) } -function onNodeValueUpdated(zwaveNode, args) { +function onNodeValueUpdated (zwaveNode, args) { updateValue.call(this, zwaveNode, args) logger.info( `Node ${zwaveNode.id}: value updated: ${getValueID(args)}`, @@ -410,7 +415,7 @@ function onNodeValueUpdated(zwaveNode, args) { ) } -function onNodeValueRemoved(zwaveNode, args) { +function onNodeValueRemoved (zwaveNode, args) { removeValue.call(this, zwaveNode, args) logger.info(`Node ${zwaveNode.id}: value removed: ${args}`) this.emit( @@ -422,7 +427,7 @@ function onNodeValueRemoved(zwaveNode, args) { ) } -function onNodeMetadataUpdated(zwaveNode, args) { +function onNodeMetadataUpdated (zwaveNode, args) { const valueId = initValue.call(this, zwaveNode, args, args.metadata) logger.info(`Node ${valueId.nodeId}: metadata updated: ${getValueID(args)}`) this.emit( @@ -434,9 +439,10 @@ function onNodeMetadataUpdated(zwaveNode, args) { ) } -function onNodeNotification(zwaveNode, notificationLabel, parameters) { +function onNodeNotification (zwaveNode, notificationLabel, parameters) { logger.info( - `Node ${zwaveNode.id}: notification: ${notificationLabel} ${parameters ? 'with ' + parameters.toString() : '' + `Node ${zwaveNode.id}: notification: ${notificationLabel} ${ + parameters ? 'with ' + parameters.toString() : '' }` ) this.emit('notification', zwaveNode, notificationLabel, parameters) @@ -450,7 +456,7 @@ function onNodeNotification(zwaveNode, notificationLabel, parameters) { ) } -function onNodeFirmwareUpdateProgress( +function onNodeFirmwareUpdateProgress ( zwaveNode, sentFragments, totalFragments @@ -470,7 +476,7 @@ function onNodeFirmwareUpdateProgress( } // https://github.com/zwave-js/node-zwave-js/blob/cb35157da5e95f970447a67cbb2792e364b9d1e1/packages/zwave-js/src/lib/commandclass/FirmwareUpdateMetaDataCC.ts#L59 -function onNodeFirmwareUpdateFinished(zwaveNode, status, waitTime) { +function onNodeFirmwareUpdateFinished (zwaveNode, status, waitTime) { updateControllerStatus.call( this, `Node ${zwaveNode.id} firmware update FINISHED: Status ${status}, Time: ${waitTime}` @@ -488,7 +494,7 @@ function onNodeFirmwareUpdateFinished(zwaveNode, status, waitTime) { // ------- NODE METHODS ------------- -function bindNodeEvents(node) { +function bindNodeEvents (node) { // add a node to our nodes array addNode.call(this, node) @@ -509,7 +515,7 @@ function bindNodeEvents(node) { .on('firmware update finished', onNodeFirmwareUpdateFinished.bind(this)) } -function removeNode(nodeid) { +function removeNode (nodeid) { logger.info('Node removed', nodeid) // don't use splice here, nodeid equals to the index in the array @@ -524,7 +530,7 @@ function removeNode(nodeid) { } // Triggered when a node is added but no informations are received yet -function addNode(zwaveNode) { +function addNode (zwaveNode) { const nodeId = zwaveNode.id this.nodes[nodeId] = { @@ -561,7 +567,7 @@ function addNode(zwaveNode) { logger.info('Node added', nodeId) } -function initNode(zwaveNode) { +function initNode (zwaveNode) { const nodeId = zwaveNode.id const node = this.nodes[nodeId] @@ -625,7 +631,7 @@ function initNode(zwaveNode) { this.getGroups(zwaveNode.id, true) } -function updateValueMetadata(zwaveNode, zwaveValue, zwaveValueMeta) { +function updateValueMetadata (zwaveNode, zwaveValue, zwaveValueMeta) { zwaveValue.nodeId = zwaveNode.id const valueId = { @@ -694,7 +700,7 @@ function updateValueMetadata(zwaveNode, zwaveValue, zwaveValueMeta) { * @param { ZWaveNode } zwaveNode * @param { ValueAddedArgs } valueAddedArgs https://github.com/zwave-js/node-zwave-js/blob/cb35157da5e95f970447a67cbb2792e364b9d1e1/packages/core/src/values/ValueDB.ts#L8 */ -function addValue(zwaveNode, zwaveValue) { +function addValue (zwaveNode, zwaveValue) { const node = this.nodes[zwaveNode.id] if (!node) { @@ -704,13 +710,15 @@ function addValue(zwaveNode, zwaveValue) { const valueId = initValue.call(this, zwaveNode, zwaveValue, zwaveValueMeta) - logger.info(`Node ${zwaveNode.id}: value added ${valueId.id} => ${valueId.value}`) + logger.info( + `Node ${zwaveNode.id}: value added ${valueId.id} => ${valueId.value}` + ) this.emit('valueChanged', valueId, node) } } -function initValue(zwaveNode, zwaveValue, zwaveValueMeta) { +function initValue (zwaveNode, zwaveValue, zwaveValueMeta) { const node = this.nodes[zwaveNode.id] const valueId = updateValueMetadata.call( this, @@ -734,7 +742,7 @@ function initValue(zwaveNode, zwaveValue, zwaveValueMeta) { } // Triggered when a node is ready and a value changes -function updateValue(zwaveNode, args) { +function updateValue (zwaveNode, args) { const node = this.nodes[zwaveNode.id] if (!node) { @@ -751,7 +759,7 @@ function updateValue(zwaveNode, args) { } } -function removeValue(zwaveNode, args) { +function removeValue (zwaveNode, args) { const node = this.nodes[zwaveNode.id] const idString = getValueID(args) const toRemove = node ? node.values[idString] : null @@ -773,7 +781,7 @@ function removeValue(zwaveNode, args) { * @param {Object} node Internal node object * @returns A string in the format `--` that unique identifhy a zwave device */ -function getDeviceID(node) { +function getDeviceID (node) { if (!node) return '' return `${parseInt(node.manufacturerId)}-${parseInt( @@ -781,11 +789,11 @@ function getDeviceID(node) { )}-${parseInt(node.productType)}` } -function isCurrentValue(valueId) { +function isCurrentValue (valueId) { return valueId.propertyName && /current/i.test(valueId.propertyName) } -function findTargetValue(zwaveValue, definedValueIds) { +function findTargetValue (zwaveValue, definedValueIds) { return definedValueIds.find( v => v.commandClass === zwaveValue.commandClass && @@ -802,7 +810,7 @@ function findTargetValue(zwaveValue, definedValueIds) { * @param {Boolean} nodeId Add node identifier * @returns The value id unique identifier */ -function getValueID(v, withNode) { +function getValueID (v, withNode) { return `${withNode ? v.nodeId + '-' : ''}${v.commandClass}-${v.endpoint || 0}-${v.property}${v.propertyKey !== undefined ? '-' + v.propertyKey : ''}` } @@ -813,7 +821,7 @@ function getValueID(v, withNode) { * context - what you want "this" to be. * params - array of parameters to pass to function. */ -function wrapFunction(fn, context, params) { +function wrapFunction (fn, context, params) { return function () { fn.apply(context, params) } @@ -825,7 +833,7 @@ function wrapFunction(fn, context, params) { * @param {*} obj The object to copy * @returns The copied object */ -function copy(obj) { +function copy (obj) { return JSON.parse(JSON.stringify(obj)) } @@ -1160,7 +1168,9 @@ ZwaveClient.prototype.addAssociations = async function ( } } } catch (error) { - logger.warn(`Error while adding associations to ${nodeId}: ${error.message}`) + logger.warn( + `Error while adding associations to ${nodeId}: ${error.message}` + ) } } else { logger.warn(`Node ${nodeId} not found when calling 'addAssociations'`) @@ -1695,7 +1705,7 @@ ZwaveClient.prototype.refreshInfo = async function (nodeId) { throw Error('Driver is closed') } -function guessFirmwareFormat(filename, firmware) { +function guessFirmwareFormat (filename, firmware) { if ( (filename.endsWith('.exe') || filename.endsWith('.ex_')) && firmware.includes(Buffer.from('Aeon Labs', 'utf8')) @@ -1920,7 +1930,9 @@ ZwaveClient.prototype.writeValue = async function (valueId, value) { result = await this.getNode(valueId.nodeId).setValue(valueId, value) } } catch (error) { - logger.error(`Error while writing ${value} on ${valueId.id}: ${error.message}`) + logger.error( + `Error while writing ${value} on ${valueId.id}: ${error.message}` + ) } // https://zwave-js.github.io/node-zwave-js/#/api/node?id=setvalue if (result === false) { diff --git a/lib/logger.js b/lib/logger.js index 3f3cf36e93f..297bca9eb28 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -1,24 +1,23 @@ -const winston = require('winston'); -const { createLogger, format, transports } = winston; -const { combine, timestamp, label, printf } = format; +const winston = require('winston') +const { createLogger, format, transports } = winston +const { combine, timestamp, label, printf } = format // Custom logging format const customFormat = printf(({ level, message, label, timestamp }) => { - return `${timestamp} [${label || '-'}] ${level}: ${message}`; -}); + return `${timestamp} [${label || '-'}] ${level}: ${message}` +}) // Custom combined logging format: -const customCombinedFormat = (module) => combine( - format.colorize({ all: true }), - label({ label: module }), - timestamp(), - customFormat -) +const customCombinedFormat = module => + combine( + format.colorize({ all: true }), + label({ label: module }), + timestamp(), + customFormat + ) // Custom transports: -const customTransports = () => [ - new transports.Console() -] +const customTransports = () => [new transports.Console()] // Container to provide different pre-configured loggers const logContainer = new winston.Container() @@ -27,17 +26,17 @@ const logContainer = new winston.Container() logContainer.add('ZWC', { format: customCombinedFormat('ZWC'), transports: customTransports() -}); +}) // Default logger for modules: -logContainer.module = (module) => { +logContainer.module = module => { if (!logContainer.has(module)) { logContainer.add(module, { format: customCombinedFormat(module), transports: customTransports() - }); + }) } - return logContainer.get(module); + return logContainer.get(module) } module.exports = logContainer From cda66b902812a993430f57f716078727227ef8a8 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Fri, 11 Dec 2020 10:38:45 +0100 Subject: [PATCH 03/37] fix: Removed unused createLogger --- lib/logger.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/logger.js b/lib/logger.js index 297bca9eb28..716828c2fe2 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -1,5 +1,5 @@ const winston = require('winston') -const { createLogger, format, transports } = winston +const { format, transports } = winston const { combine, timestamp, label, printf } = format // Custom logging format From de189703e4c9b9ecd681699cc46cba0ce5159023 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Fri, 11 Dec 2020 16:10:42 +0100 Subject: [PATCH 04/37] refactor(logger): Improved logger setup * Use setup() instead of module() * Allow config to be passed into setup() * Add `enable` config setting * Add `level` config setting * Add `logTofile` config setting * Add `filename` config setting * Adjust formatting to requirements --- lib/ZwaveClient.js | 2 +- lib/logger.js | 84 +++++++++++++++++++++++++++++++++------------- 2 files changed, 62 insertions(+), 24 deletions(-) diff --git a/lib/ZwaveClient.js b/lib/ZwaveClient.js index 2584003363f..3d7e634f3eb 100644 --- a/lib/ZwaveClient.js +++ b/lib/ZwaveClient.js @@ -17,7 +17,7 @@ const { socketEvents } = reqlib('/lib/SocketManager.js') const store = reqlib('config/store.js') const storeDir = utils.joinPath(true, reqlib('config/app.js').storeDir) const debug = reqlib('/lib/debug')('Zwave') -const logger = require('./logger.js').module('ZWC') +const logger = require('./logger.js').setup('zwc') const inherits = require('util').inherits debug.color = 4 diff --git a/lib/logger.js b/lib/logger.js index 716828c2fe2..e01813f55c5 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -2,41 +2,79 @@ const winston = require('winston') const { format, transports } = winston const { combine, timestamp, label, printf } = format -// Custom logging format -const customFormat = printf(({ level, message, label, timestamp }) => { - return `${timestamp} [${label || '-'}] ${level}: ${message}` +// Usage examples: +// Simple logger setup with module name and default config: +// const logger = require('./logger.js').setup('zwc') +// Logger setup with module name and specific config: +// const logger = require('./logger.js').setup('zwc', +// { enabled: true, level: 'info', logToFile: true, filename: "zwavejs2mqtt.log" } +// ) + +// Make sure every config value is defined +const sanitizedConfig = (module, config) => { + config = config || {} + return { + module: module !== undefined ? module : '-', + enabled: config.enabled !== undefined ? config.enabled : true, + level: config.level !== undefined ? config.level : 'info', + logToFile: config.logToFile !== undefined ? config.logToFile : false, + filename: + config.filename !== undefined ? config.filename : 'zwavejs2mqtt.log' + } +} + +// Format loglevel upper-case: +const upperCaseLevel = format(info => { + info.level = info.level.toUpperCase() + return info }) // Custom combined logging format: -const customCombinedFormat = module => +const customFormat = config => combine( - format.colorize({ all: true }), - label({ label: module }), - timestamp(), - customFormat + timestamp({ format: 'YYYY-MM-DD HH:mm:ss.SSS' }), + upperCaseLevel(), + label({ label: config.module.toUpperCase() }), + printf(({ level, message, label, timestamp }) => { + return `${timestamp} ${level} ${label || '-'}: ${message}` + }) ) // Custom transports: -const customTransports = () => [new transports.Console()] +const customTransports = config => { + const transportsList = [ + new transports.Console({ + format: format.colorize({ all: true }), + level: config.level + }) + ] + if (config.logToFile) { + transportsList.push( + new transports.File({ + format: customFormat(config), + filename: config.filename, + level: config.level + }) + ) + } + return transportsList +} -// Container to provide different pre-configured loggers +// Container for loggers of all modules: const logContainer = new winston.Container() -// Example: Pre-configured module logger with special properties -logContainer.add('ZWC', { - format: customCombinedFormat('ZWC'), - transports: customTransports() -}) - -// Default logger for modules: -logContainer.module = module => { - if (!logContainer.has(module)) { - logContainer.add(module, { - format: customCombinedFormat(module), - transports: customTransports() +// Setup logger for modules: +logContainer.setup = (module, config) => { + config = sanitizedConfig(module, config) + if (!logContainer.has(config.module)) { + logContainer.add(config.module, { + silent: !config.enabled, + level: config.level, + format: customFormat(config), + transports: customTransports(config) }) } - return logContainer.get(module) + return logContainer.get(config.module) } module.exports = logContainer From 20133dce4f92ce01e03ca8e1ee1ff63823cb5d0e Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Fri, 11 Dec 2020 16:30:12 +0100 Subject: [PATCH 05/37] fix: Use templates for logs in ZwaveClient.js --- lib/ZwaveClient.js | 35 +++++++++++++++-------------------- 1 file changed, 15 insertions(+), 20 deletions(-) diff --git a/lib/ZwaveClient.js b/lib/ZwaveClient.js index 3d7e634f3eb..4a1edefa2f9 100644 --- a/lib/ZwaveClient.js +++ b/lib/ZwaveClient.js @@ -16,12 +16,9 @@ const jsonStore = reqlib('/lib/jsonStore.js') const { socketEvents } = reqlib('/lib/SocketManager.js') const store = reqlib('config/store.js') const storeDir = utils.joinPath(true, reqlib('config/app.js').storeDir) -const debug = reqlib('/lib/debug')('Zwave') const logger = require('./logger.js').setup('zwc') const inherits = require('util').inherits -debug.color = 4 - const ZWAVE_STATUS = { connected: 'connected', driverReady: 'driver ready', @@ -124,7 +121,7 @@ function driverReady () { this.error = false - logger.info('Scanning network with homeid:', homeHex) + logger.info(`Scanning network with homeid: ${homeHex}`) } function driverError (error) { @@ -144,7 +141,7 @@ function scanComplete () { this.status = ZWAVE_STATUS.scanDone const nodes = this.nodes.filter(n => !n.failed) - logger.info('Network scan complete. Found:', nodes.length, 'nodes') + logger.info(`Network scan complete. Found: ${nodes.length} nodes`) this.emit('scanComplete') @@ -288,11 +285,9 @@ function onNodeReady (zwaveNode) { this.emit('event', eventEmitter.node, 'node ready', this.nodes[zwaveNode.id]) logger.info( - 'Node %d ready: %s - %s (%s)', - node.id, - node.manufacturer, - node.productLabel, - node.productDescription || 'Unknown' + `Node ${node.id} ready: ${node.manufacturer} - ${ + node.productLabel + } (${node.productDescription || 'Unknown'})` ) } @@ -516,7 +511,7 @@ function bindNodeEvents (node) { } function removeNode (nodeid) { - logger.info('Node removed', nodeid) + logger.info(`Node removed ${nodeid}`) // don't use splice here, nodeid equals to the index in the array const node = this.nodes[nodeid] @@ -564,7 +559,7 @@ function addNode (zwaveNode) { onNodeStatus.call(this, zwaveNode) this.addEmptyNodes() - logger.info('Node added', nodeId) + logger.info(`Node added ${nodeId}`) } function initNode (zwaveNode) { @@ -704,7 +699,7 @@ function addValue (zwaveNode, zwaveValue) { const node = this.nodes[zwaveNode.id] if (!node) { - logger.info('ValueAdded: no such node: ' + zwaveNode.id, 'error') + logger.info(`ValueAdded: no such node: ${zwaveNode.id} error`) } else { const zwaveValueMeta = zwaveNode.getValueMetadata(zwaveValue) @@ -746,7 +741,7 @@ function updateValue (zwaveNode, args) { const node = this.nodes[zwaveNode.id] if (!node) { - logger.info('valueChanged: no such node: ' + zwaveNode.id, 'error') + logger.info(`valueChanged: no such node: ${zwaveNode.id} error`) } else { const valueId = node.values[getValueID(args)] @@ -767,9 +762,9 @@ function removeValue (zwaveNode, args) { if (toRemove) { delete node.values[idString] this.sendToSocket(socketEvents.valueRemoved, toRemove) - logger.info('ValueRemoved: %s from node %d', idString, zwaveNode.id) + logger.info(`ValueRemoved: ${idString} from node ${zwaveNode.id}`) } else { - logger.info('ValueRemoved: no such node: ' + zwaveNode.id, 'error') + logger.info(`ValueRemoved: no such node: ${zwaveNode.id} error`) } } @@ -937,7 +932,7 @@ ZwaveClient.prototype.heal = function () { this.beginHealingNetwork() logger.info('Network auto heal started') } catch (error) { - logger.error('Error while doing scheduled network heal', error.message) + logger.error(`Error while doing scheduled network heal ${error.message}`) } // schedule next @@ -1312,7 +1307,7 @@ ZwaveClient.prototype.connect = async function () { this.driver.once('driver ready', driverReady.bind(this)) this.driver.on('all nodes ready', scanComplete.bind(this)) - logger.info('Connecting to', this.cfg.port) + logger.info(`Connecting to ${this.cfg.port}`) try { await this.driver.start() @@ -1328,7 +1323,7 @@ ZwaveClient.prototype.connect = async function () { this.reconnectTimeout = setTimeout(this.connect.bind(this), 3000) } } else { - logger.info('Driver already connected to', this.cfg.port) + logger.info(`Driver already connected to ${this.cfg.port}`) } } @@ -1885,7 +1880,7 @@ ZwaveClient.prototype.callApi = async function (apiName, ...args) { } } - logger.info(result.message, apiName, result.result || '') + logger.info(`${result.message} ${apiName} ${result.result || ''}`) result.args = args From 0cde5bcffcb1550b53e4e0d06eb3a307ffde27c7 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Fri, 11 Dec 2020 16:33:31 +0100 Subject: [PATCH 06/37] fix: Fix module name "zwc" -> "zwave" --- lib/ZwaveClient.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/ZwaveClient.js b/lib/ZwaveClient.js index 4a1edefa2f9..3f5012440fe 100644 --- a/lib/ZwaveClient.js +++ b/lib/ZwaveClient.js @@ -16,7 +16,7 @@ const jsonStore = reqlib('/lib/jsonStore.js') const { socketEvents } = reqlib('/lib/SocketManager.js') const store = reqlib('config/store.js') const storeDir = utils.joinPath(true, reqlib('config/app.js').storeDir) -const logger = require('./logger.js').setup('zwc') +const logger = require('./logger.js').setup('zwave') const inherits = require('util').inherits const ZWAVE_STATUS = { From f797c1136fa8373c389f5898bf7b4c3d41d8c827 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Fri, 11 Dec 2020 16:52:30 +0100 Subject: [PATCH 07/37] feat: Add stack traces to log output * Added 3 example usages to ZwaveClient.js --- lib/ZwaveClient.js | 6 +++--- lib/logger.js | 3 ++- 2 files changed, 5 insertions(+), 4 deletions(-) diff --git a/lib/ZwaveClient.js b/lib/ZwaveClient.js index 3f5012440fe..fdd8e2f1435 100644 --- a/lib/ZwaveClient.js +++ b/lib/ZwaveClient.js @@ -932,7 +932,7 @@ ZwaveClient.prototype.heal = function () { this.beginHealingNetwork() logger.info('Network auto heal started') } catch (error) { - logger.error(`Error while doing scheduled network heal ${error.message}`) + logger.error(`Error while doing scheduled network heal ${error.message}`, error) } // schedule next @@ -1316,7 +1316,7 @@ ZwaveClient.prototype.connect = async function () { } catch (error) { // destroy diver instance when it fails this.driver.destroy().catch(err => { - logger.error('Error while destroing driver ' + err.message) + logger.error(`Error while destroing driver ${err.message}`, error) }) driverError.call(this, error) logger.warn('Retry connection in 3 seconds...') @@ -1926,7 +1926,7 @@ ZwaveClient.prototype.writeValue = async function (valueId, value) { } } catch (error) { logger.error( - `Error while writing ${value} on ${valueId.id}: ${error.message}` + `Error while writing ${value} on ${valueId.id}: ${error.message}`, error ) } // https://zwave-js.github.io/node-zwave-js/#/api/node?id=setvalue diff --git a/lib/logger.js b/lib/logger.js index e01813f55c5..b2d3a74c605 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -1,6 +1,6 @@ const winston = require('winston') const { format, transports } = winston -const { combine, timestamp, label, printf } = format +const { combine, timestamp, label, printf, errors } = format // Usage examples: // Simple logger setup with module name and default config: @@ -32,6 +32,7 @@ const upperCaseLevel = format(info => { // Custom combined logging format: const customFormat = config => combine( + errors({ stack: true }), timestamp({ format: 'YYYY-MM-DD HH:mm:ss.SSS' }), upperCaseLevel(), label({ label: config.module.toUpperCase() }), From 7c755bb7a7c9074ec3a88512b9fa47dd60d74bea Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Fri, 11 Dec 2020 16:55:12 +0100 Subject: [PATCH 08/37] fix: Code formatting --- lib/ZwaveClient.js | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/lib/ZwaveClient.js b/lib/ZwaveClient.js index fdd8e2f1435..4beeb0016b1 100644 --- a/lib/ZwaveClient.js +++ b/lib/ZwaveClient.js @@ -932,7 +932,10 @@ ZwaveClient.prototype.heal = function () { this.beginHealingNetwork() logger.info('Network auto heal started') } catch (error) { - logger.error(`Error while doing scheduled network heal ${error.message}`, error) + logger.error( + `Error while doing scheduled network heal ${error.message}`, + error + ) } // schedule next @@ -1926,7 +1929,8 @@ ZwaveClient.prototype.writeValue = async function (valueId, value) { } } catch (error) { logger.error( - `Error while writing ${value} on ${valueId.id}: ${error.message}`, error + `Error while writing ${value} on ${valueId.id}: ${error.message}`, + error ) } // https://zwave-js.github.io/node-zwave-js/#/api/node?id=setvalue From 5a3d085fd8a049fae48f63165af837a2bdfacff4 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Fri, 11 Dec 2020 19:20:10 +0100 Subject: [PATCH 09/37] feat: Enable logger runtime configuration * Use module() again for creating the logger * Add setup() method to the logger * Revert module name back to original value --- lib/ZwaveClient.js | 2 +- lib/logger.js | 40 ++++++++++++++++++++++++++++------------ 2 files changed, 29 insertions(+), 13 deletions(-) diff --git a/lib/ZwaveClient.js b/lib/ZwaveClient.js index 4beeb0016b1..d7b1045113f 100644 --- a/lib/ZwaveClient.js +++ b/lib/ZwaveClient.js @@ -16,7 +16,7 @@ const jsonStore = reqlib('/lib/jsonStore.js') const { socketEvents } = reqlib('/lib/SocketManager.js') const store = reqlib('config/store.js') const storeDir = utils.joinPath(true, reqlib('config/app.js').storeDir) -const logger = require('./logger.js').setup('zwave') +const logger = require('./logger.js').module('Zwave') const inherits = require('util').inherits const ZWAVE_STATUS = { diff --git a/lib/logger.js b/lib/logger.js index b2d3a74c605..97ee700479b 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -4,11 +4,16 @@ const { combine, timestamp, label, printf, errors } = format // Usage examples: // Simple logger setup with module name and default config: -// const logger = require('./logger.js').setup('zwc') +// const logger = require('./logger.js').module('Zwave') // Logger setup with module name and specific config: -// const logger = require('./logger.js').setup('zwc', +// const logger = require('./logger.js').module('Zwave').setup( // { enabled: true, level: 'info', logToFile: true, filename: "zwavejs2mqtt.log" } // ) +// Change logger config during runtime: +// let logger = require('./logger.js').module('Zwave') +// log.info('This will be shown by default') +// logger = logger.setup({ level: 'warn' }) +// log.info('Now this won't be shown anymore') // Make sure every config value is defined const sanitizedConfig = (module, config) => { @@ -64,18 +69,29 @@ const customTransports = config => { // Container for loggers of all modules: const logContainer = new winston.Container() -// Setup logger for modules: -logContainer.setup = (module, config) => { +// Re-create a new module logger +const setupNewLogger = (module, container, config) => { config = sanitizedConfig(module, config) - if (!logContainer.has(config.module)) { - logContainer.add(config.module, { - silent: !config.enabled, - level: config.level, - format: customFormat(config), - transports: customTransports(config) - }) + if (container.has(module)) { + container.close(module) } - return logContainer.get(config.module) + const logger = container.add(module, { + silent: !config.enabled, + level: config.level, + format: customFormat(config), + transports: customTransports(config) + }) + + // Workaround to allow logger config changes during runtime: + logger.container = container + logger.setup = config => setupNewLogger(module, container, config) + + return logger +} + +// Get logger for module with default config: +logContainer.module = module => { + return setupNewLogger(module, logContainer, {}) } module.exports = logContainer From 6ce23e4b61e102e7919825582ae2c2c079453204 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Fri, 11 Dec 2020 20:49:56 +0100 Subject: [PATCH 10/37] docs: Add as contributor --- README.md | 1 + 1 file changed, 1 insertion(+) diff --git a/README.md b/README.md index 8dc529ad2bc..b082fdf0e05 100644 --- a/README.md +++ b/README.md @@ -824,6 +824,7 @@ Thanks to this people for help with issues tracking and contributions: - [**Jay**](https://github.com/jshridha) - [**Thiago Oliveira**](https://github.com/chilicheech) - [**Vassilis Aretakis**](https://github.com/billiaz) +- [**Andreas Hochsteger**](https://github.com/ahochsteger) ## :bowtie: Author From 9e29707316699d6a23c116ccac8212922bd8d4af Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Fri, 11 Dec 2020 21:54:24 +0100 Subject: [PATCH 11/37] refactor(app): Use logger module for app --- app.js | 30 ++++++++++++++++-------------- 1 file changed, 16 insertions(+), 14 deletions(-) diff --git a/app.js b/app.js index 691e9019699..e4d82415416 100644 --- a/app.js +++ b/app.js @@ -1,6 +1,6 @@ const express = require('express') const reqlib = require('app-root-path').require -const logger = require('morgan') +const morgan = require('morgan') const cookieParser = require('cookie-parser') const bodyParser = require('body-parser') const app = express() @@ -11,7 +11,7 @@ const ZWaveClient = reqlib('/lib/ZwaveClient') const MqttClient = reqlib('/lib/MqttClient') const Gateway = reqlib('/lib/Gateway') const store = reqlib('config/store.js') -const debug = reqlib('/lib/debug')('App') +const logger = reqlib('/lib/logger.js').module('App') const history = require('connect-history-api-fallback') const SocketManager = reqlib('/lib/SocketManager') const { inboundEvents, socketEvents } = reqlib('/lib/SocketManager.js') @@ -83,19 +83,21 @@ function printVersion () { } catch (error) { // git not installed } - debug(`Version: ${require('./package.json').version}${rev ? '.' + rev : ''}`) + logger.info( + `Version: ${require('./package.json').version}${rev ? '.' + rev : ''}` + ) } // ### EXPRESS SETUP printVersion() -debug('Application path:' + utils.getPath(true)) +logger.info('Application path:' + utils.getPath(true)) // view engine setup app.set('views', utils.joinPath(false, 'views')) app.set('view engine', 'ejs') -app.use(logger('dev', { stream: { write: msg => debug(msg.trimEnd()) } })) +app.use(morgan('dev', { stream: { write: msg => logger.info(msg.trimEnd()) } })) app.use(bodyParser.json({ limit: '50mb' })) app.use( bodyParser.urlencoded({ @@ -129,7 +131,7 @@ function setupSocket (server) { server.on('listening', function () { const addr = server.address() const bind = typeof addr === 'string' ? 'pipe ' + addr : 'port ' + addr.port - debug('Listening on', bind) + logger.info(`Listening on ${bind}`) }) socketManager.bindServer(server) @@ -146,7 +148,7 @@ function setupSocket (server) { }) socketManager.on(inboundEvents.zwave, async function (socket, data) { - debug('Zwave api call:', data.api, data.args) + logger.info(`Zwave api call: ${data.api} ${data.args}`) if (gw.zwave) { const result = await gw.zwave.callApi(data.api, ...data.args) result.api = data.api @@ -155,7 +157,7 @@ function setupSocket (server) { }) socketManager.on(inboundEvents.hass, async function (socket, data) { - debug('Hass api call:', data.apiName) + logger.info(`Hass api call: ${data.apiName}`) switch (data.apiName) { case 'delete': gw.publishDiscovery(data.device, data.nodeId, true, true) @@ -225,7 +227,7 @@ app.get('/api/settings', async function (req, res) { try { ports = await SerialPort.list() } catch (error) { - debug(error) + logger.error(error) } data.serial_ports = ports ? ports.map(p => p.path) : [] @@ -266,7 +268,7 @@ app.post('/api/importConfig', async function (req, res) { res.json({ success: true, message: 'Configuration imported successfully' }) } catch (error) { - debug(error.message) + logger.error(error.message) return res.json({ success: false, message: error.message }) } }) @@ -285,7 +287,7 @@ app.post('/api/settings', async function (req, res) { startGateway() res.json({ success: true, message: 'Configuration updated successfully' }) } catch (error) { - debug(error) + logger.error(error) res.json({ success: false, message: error.message }) } }) @@ -305,7 +307,7 @@ app.use(function (err, req, res) { res.locals.message = err.message res.locals.error = req.app.get('env') === 'development' ? err : {} - debug(`${req.method} ${req.url} ${err.status} - Error: ${err.message}`) + logger.error(`${req.method} ${req.url} ${err.status} - Error: ${err.message}`) // render the error page res.status(err.status || 500) @@ -315,10 +317,10 @@ app.use(function (err, req, res) { process.removeAllListeners('SIGINT') process.on('SIGINT', function () { - debug('Closing clients...') + logger.info('Closing clients...') gw.close() .catch(err => { - debug('Error while closing clients', err) + logger.error('Error while closing clients', err) }) .finally(() => { process.exit() From e8f7b998e5eb053768e79c1b380d038f4d99b650 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Fri, 11 Dec 2020 22:03:15 +0100 Subject: [PATCH 12/37] refactor(app): Use logger module for jsonStore --- lib/jsonStore.js | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/lib/jsonStore.js b/lib/jsonStore.js index 5070fe87f92..bdee5a597fe 100644 --- a/lib/jsonStore.js +++ b/lib/jsonStore.js @@ -5,11 +5,9 @@ const jsonfile = require('jsonfile'), reqlib = require('app-root-path').require, storeDir = reqlib('config/app.js').storeDir, Promise = require('bluebird'), - debug = reqlib('/lib/debug')('Store'), + logger = reqlib('/lib/logger.js').module('Store'), utils = reqlib('lib/utils.js') -debug.color = 3 - function getFile (config) { return new Promise((resolve, reject) => { jsonfile.readFile(utils.joinPath(true, storeDir, config.file), function ( @@ -20,7 +18,7 @@ function getFile (config) { reject(err) } else { if (err && err.code === 'ENOENT') { - debug(config.file, 'not found') + logger.warn(`${config.file} not found`) } if (!data) { data = config.default From f2fec1897754cc69d449a41a5bb8145f00df567b Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Fri, 11 Dec 2020 22:18:04 +0100 Subject: [PATCH 13/37] refactor(gateway): Use logger module for Gateway --- lib/Gateway.js | 52 +++++++++++++++++++++----------------------------- 1 file changed, 22 insertions(+), 30 deletions(-) diff --git a/lib/Gateway.js b/lib/Gateway.js index 9d1ea02496b..900f2287665 100755 --- a/lib/Gateway.js +++ b/lib/Gateway.js @@ -13,7 +13,7 @@ const { AlarmSensorType } = require('zwave-js') const { CommandClasses } = require('@zwave-js/core') const { socketEvents } = reqlib('/lib/SocketManager.js') const Constants = reqlib('/lib/Constants.js') -const debug = reqlib('/lib/debug')('Gateway') +const logger = reqlib('/lib/logger.js').module('Gateway') const inherits = require('util').inherits const hassCfg = reqlib('/hass/configurations.js') const hassDevices = reqlib('/hass/devices.js') @@ -26,8 +26,6 @@ const NODE_PREFIX = 'nodeID_' const CUSTOM_DEVICES = reqlib('config/app.js').storeDir + '/customDevices' let allDevices = hassDevices // will contain customDevices + hassDevices -debug.color = 2 - // watcher initiates a watch on a file. if this fails (e.g., because the file // doesn't exist), instead watch the directory. If the directory watch // triggers, cancel it and try to watch the file again. Meanwhile spam `fn()` @@ -82,7 +80,7 @@ const loadCustomDevices = () => { return } } catch (error) { - debug('failed to load ' + loaded + ':', error) + logger.error(`failed to load ${loaded}:`, error) return } @@ -94,15 +92,13 @@ const loadCustomDevices = () => { return } - debug('loading custom devices from', loaded) + logger.info(`loading custom devices from ${loaded}`) lastCustomDevicesLoad = sha allDevices = Object.assign({}, hassDevices, devices) - debug( - 'Loaded', - Object.keys(devices).length, - 'custom Hass devices configurations' + logger.info( + `Loaded ${Object.keys(devices).length} custom Hass devices configurations` ) } @@ -163,7 +159,7 @@ Gateway.prototype.start = async function () { // this is async but doesn't need to be awaited this.zwave.connect() } else { - debug('Zwave settings are not valid') + logger.error('Zwave settings are not valid') } } @@ -395,7 +391,7 @@ function onNodeStatus (node) { // } // } catch (error) { // const op = values[i].verifyChanges ? 'verify changes' : 'enable poll' - // debug('Error while call', op, error.message) + // logger.error(`Error while call ${op} ${error.message}`) // } // } // } @@ -425,7 +421,7 @@ function onBrokerStatus (online) { } function onHassStatus (online) { - debug('Home Assistant is ' + (online ? 'ONLINE' : 'OFFLINE')) + logger.info(`Home Assistant is ${online ? 'ONLINE' : 'OFFLINE'}`) if (online) { this.rediscoverAll() @@ -438,7 +434,7 @@ async function onApiRequest (topic, apiName, payload) { const result = await this.zwave.callApi(apiName, ...args) this.mqtt.publish(topic, result) } else { - debug('Requested Zwave api', apiName, "doesn't exist") + logger.error(`Requested Zwave api ${apiName} doesn't exist`) } } @@ -492,7 +488,7 @@ function evalFunction (code, valueId, value) { const parseFunc = new Function('value', code) result = parseFunc(value) } catch (error) { - debug('Error eval function of value ', valueId.id, error.message) + logger.error(`Error eval function of value ${valueId.id} ${error.message}`) } return result @@ -718,7 +714,9 @@ Gateway.prototype.parsePayload = function (payload, valueId, valueConf) { } } } catch (error) { - debug('Error while parsing payload', payload, 'for valueID', valueId) + logger.error( + `Error while parsing payload ${payload} for valueID ${valueId}` + ) } return payload @@ -730,7 +728,7 @@ Gateway.prototype.parsePayload = function (payload, valueId, valueConf) { Gateway.prototype.close = async function () { this.closed = true - debug('Closing Gateway...') + logger.info('Closing Gateway...') if (this.mqtt) { await this.mqtt.close() @@ -954,7 +952,7 @@ Gateway.prototype.publishDiscovery = function ( this.zwave.updateDevice(hassDevice, nodeId, deleteDevice) } } catch (error) { - debug('Error while publishing node %d: %s', nodeId, error.message) + logger.error(`Error while publishing node ${nodeId}: ${error.message}`) } } @@ -1146,11 +1144,8 @@ Gateway.prototype.discoverDevice = function (node, hassDevice) { } } } catch (error) { - debug( - 'Error while discovering device %s of node %d: %s', - hassID, - node.id, - error + logger.error( + `Error while discovering device ${hassID} of node ${node.id}: ${error}` ) } } @@ -1207,7 +1202,7 @@ Gateway.prototype.discoverClimates = function (node) { const temperatureId = temperatures[0] if (!temperatureId || !modeId) { - debug( + logger.warn( 'Unable to discover climate device, there is no valid temperature/thermostat mode valueIds' ) return @@ -1274,11 +1269,11 @@ Gateway.prototype.discoverClimates = function (node) { // discovered later when we call `discoverDevice` nodeDevices.push(config) - debug('New climate device discovered: ' + JSON.stringify(config)) + logger.info(`New climate device discovered: ${JSON.stringify(config)}`) allDevices[node.deviceId] = nodeDevices } catch (error) { - debug('Unable to discover climate device: ' + error.message) + logger.error(`Unable to discover climate device: ${error.message}`) } } @@ -1611,11 +1606,8 @@ Gateway.prototype.discoverValue = function (node, vId) { this.publishDiscovery(cfg, node.id) } catch (error) { - debug( - 'Error while discovering value %s of node %d: %s', - valueId.id, - node.id, - error.message + logger.error( + `Error while discovering value ${valueId.id} of node ${node.id}: ${error.message}` ) } } From fabcdafc8dd7e87ee23e9e990bf5b9795462e27c Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Fri, 11 Dec 2020 22:35:30 +0100 Subject: [PATCH 14/37] refactor(mqtt): Use logger module for MqttClient --- lib/MqttClient.js | 30 ++++++++++++++---------------- 1 file changed, 14 insertions(+), 16 deletions(-) diff --git a/lib/MqttClient.js b/lib/MqttClient.js index 492bb8b2fea..4c2e1094e2b 100644 --- a/lib/MqttClient.js +++ b/lib/MqttClient.js @@ -7,14 +7,12 @@ const reqlib = require('app-root-path').require, NeDBStore = require('mqtt-nedb-store'), EventEmitter = require('events'), storeDir = reqlib('config/app.js').storeDir, - debug = reqlib('/lib/debug')('Mqtt'), + logger = reqlib('/lib/logger.js').module('Mqtt'), url = require('native-url'), inherits = require('util').inherits const appVersion = reqlib('package.json').version -debug.color = 5 - const CLIENTS_PREFIX = '_CLIENTS' const EVENTS_PREFIX = '_EVENTS' @@ -47,7 +45,7 @@ function init (config) { this.toSubscribe = [] if (!config || config.disabled) { - debug('MQTT is disabled') + logger.info('MQTT is disabled') return } @@ -101,7 +99,7 @@ function init (config) { const serverUrl = `${protocol}://${parsed.hostname || config.host}:${ config.port }` - debug('Connecting to ' + serverUrl) + logger.info(`Connecting to ${serverUrl}`) const client = mqtt.connect(serverUrl, options) @@ -114,7 +112,7 @@ function init (config) { client.on('error', onError.bind(this)) client.on('offline', onOffline.bind(this)) } catch (e) { - debug('Error while connecting MQTT', e.message) + logger.error(`Error while connecting MQTT ${e.message}`) this.error = e.message } } @@ -123,7 +121,7 @@ function init (config) { * Function called when MQTT client connects */ function onConnect () { - debug('MQTT client connected') + logger.info('MQTT client connected') this.emit('connect') if (this.toSubscribe) { @@ -158,14 +156,14 @@ function onConnect () { * Function called when MQTT client reconnects */ function onReconnect () { - debug('MQTT client reconnecting') + logger.info('MQTT client reconnecting') } /** * Function called when MQTT client reconnects */ function onError (error) { - debug(error.message) + logger.info(error.message) this.error = error.message } @@ -173,7 +171,7 @@ function onError (error) { * Function called when MQTT client go offline */ function onOffline () { - debug('MQTT client offline') + logger.info('MQTT client offline') this.emit('brokerStatus', false) } @@ -181,14 +179,14 @@ function onOffline () { * Function called when MQTT client is closed */ function onClose () { - debug('MQTT client closed') + logger.info('MQTT client closed') } /** * Function called when an MQTT message is received */ function onMessageReceived (topic, payload) { - debug('Message received on', topic) + logger.info(`Message received on ${topic}`) if (topic === HASS_WILL) { this.emit('hassStatus', payload.toString().toLowerCase() === 'online') @@ -230,7 +228,7 @@ function onMessageReceived (topic, payload) { this.emit('apiCall', parts.join('/'), parts[3], payload) break default: - debug('Unknown action received', action, topic) + logger.warn(`Unknown action received ${action} ${topic}`) } } else { // It's a write request on zwave network @@ -322,7 +320,7 @@ MqttClient.prototype.publishVersion = function () { MqttClient.prototype.update = function (config) { this.close() - debug('Restarting Mqtt Client after update...') + logger.info('Restarting Mqtt Client after update...') init.call(this, config) } @@ -333,7 +331,7 @@ MqttClient.prototype.update = function (config) { MqttClient.prototype.subscribe = function (topic) { if (this.client && this.client.connected) { topic = this.config.prefix + '/' + topic + '/set' - debug('Subscribing to %s', topic) + logger.info(`Subscribing to ${topic}`) this.client.subscribe(topic) } else { this.toSubscribe.push(topic) @@ -354,7 +352,7 @@ MqttClient.prototype.publish = function (topic, data, options, prefix) { this.client.publish(topic, JSON.stringify(data), options, function (err) { if (err) { - debug('Error while publishing a value', err.message) + logger.error(`Error while publishing a value ${err.message}`) } }) } // end if client From c9b2f9689d635ca1cabf053746c31a52572f960b Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Fri, 11 Dec 2020 22:40:28 +0100 Subject: [PATCH 15/37] refactor(socket): Use logger module for SocketManager --- lib/SocketManager.js | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/lib/SocketManager.js b/lib/SocketManager.js index a97051a1d2d..b951657287a 100644 --- a/lib/SocketManager.js +++ b/lib/SocketManager.js @@ -3,9 +3,7 @@ const reqlib = require('app-root-path').require const inherits = require('util').inherits const EventEmitter = require('events') -const debug = reqlib('/lib/debug')('Socket') - -debug.color = 3 +const logger = reqlib('/lib/logger.js').module('Socket') // FIXME: this constants are duplicated on /src/plugins/socket.js. When converting this to ES6 module that can be removed // events from server ---> client @@ -59,7 +57,7 @@ SocketManager.prototype.bindServer = function (server) { * @param {Socket} socket */ function onConnection (socket) { - debug('New connection', socket.id) + logger.info(`New connection ${socket.id}`) // register inbound events from this socket for (const k in inboundEvents) { @@ -69,7 +67,7 @@ function onConnection (socket) { } socket.on('disconnect', function () { - debug('User disconnected', socket.id) + logger.info(`User disconnected ${socket.id}`) }) } @@ -81,7 +79,7 @@ function onConnection (socket) { * @param {any} args */ function emitEvent (eventName, socket, ...args) { - debug(`Event ${eventName} emitted to ${socket.id}`) + logger.info(`Event ${eventName} emitted to ${socket.id}`) this.emit(eventName, socket, ...args) } From 55109c5fadacce2069986f33f03c066159b3ef6a Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Fri, 11 Dec 2020 23:18:57 +0100 Subject: [PATCH 16/37] test: Add initial logger tests --- test/lib/logger.test.js | 26 ++++++++++++++++++++++++++ 1 file changed, 26 insertions(+) create mode 100644 test/lib/logger.test.js diff --git a/test/lib/logger.test.js b/test/lib/logger.test.js new file mode 100644 index 00000000000..4f952bf0ef5 --- /dev/null +++ b/test/lib/logger.test.js @@ -0,0 +1,26 @@ +const { assert } = require('chai') +const chai = require('chai') +const rewire = require('rewire') +chai.should() + +describe('#logger', () => { + const mod = rewire('../../lib/logger.js') + let logger + + it('has a module function', () => assert.isFunction(mod.module)) + + describe('#module', () => { + before(() => { + logger = mod.module('foo') + }) + it('should have a setup function', () => assert.isFunction(logger.setup)) + it('should have logging enabled', () => logger.silent.should.be.false) + it('should have log level info', () => logger.level.should.equal('info')) + }) + describe('#setup', () => { + before(() => { + logger = mod.module('foo').setup({ level: 'warn' }) + }) + it('should have log level warn', () => logger.level.should.equal('warn')) + }) +}) From e52d14e94a4bfb26c75966af4608ecd90aaf9b24 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Fri, 11 Dec 2020 23:21:35 +0100 Subject: [PATCH 17/37] cleanup: Remove obsolete debug.js --- lib/debug.js | 15 --------------- test/lib/debug.test.js | 30 ------------------------------ 2 files changed, 45 deletions(-) delete mode 100644 lib/debug.js delete mode 100644 test/lib/debug.test.js diff --git a/lib/debug.js b/lib/debug.js deleted file mode 100644 index b8c8c9479f3..00000000000 --- a/lib/debug.js +++ /dev/null @@ -1,15 +0,0 @@ -const log = require('debug') -let debug - -function init () { - if (!process.env.DEBUG) { - log.enable('z2m:*') - } - debug = log('z2m') - - debug.log = console.log.bind(console) -} -init() -module.exports = function (namespace) { - return debug.extend(namespace) -} diff --git a/test/lib/debug.test.js b/test/lib/debug.test.js deleted file mode 100644 index 8265ca58e6c..00000000000 --- a/test/lib/debug.test.js +++ /dev/null @@ -1,30 +0,0 @@ -const chai = require('chai') -const rewire = require('rewire') -chai.should() - -describe('#debug', () => { - const mod = rewire('../../lib/debug') - const fun = mod.__get__('init') - - it('returns debug extend', () => mod('foo').namespace.should.equal('z2m:foo')) - - describe('set process.env.DEBUG', () => { - before(() => { - mod.__get__('log').disable() - process.env.DEBUG = 'ff' - fun() - }) - it('should disable logging', () => - mod.__get__('log').enabled('z2m:aa').should.be.false) - }) - describe('unset process.env.DEBUG', () => { - before(() => { - mod.__get__('log').disable() - delete process.env.DEBUG - fun() - }) - it('should enable logging', () => { - return mod.__get__('log').enabled('z2m:aa').should.be.true - }) - }) -}) From acbcf59f4a9bc6c7113f54c6a16c29b6f579e4ba Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Sun, 13 Dec 2020 22:17:42 +0100 Subject: [PATCH 18/37] refactor(logger): Fully working logger + tests * Add automated tests for all functionality * Add setupAll() to change config for loggers of all modules * Code cleanup --- lib/logger.js | 73 +++++++++----------- test/lib/logger.test.js | 145 ++++++++++++++++++++++++++++++++++++---- 2 files changed, 163 insertions(+), 55 deletions(-) diff --git a/lib/logger.js b/lib/logger.js index 97ee700479b..500c284c3c9 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -1,19 +1,7 @@ const winston = require('winston') const { format, transports } = winston const { combine, timestamp, label, printf, errors } = format - -// Usage examples: -// Simple logger setup with module name and default config: -// const logger = require('./logger.js').module('Zwave') -// Logger setup with module name and specific config: -// const logger = require('./logger.js').module('Zwave').setup( -// { enabled: true, level: 'info', logToFile: true, filename: "zwavejs2mqtt.log" } -// ) -// Change logger config during runtime: -// let logger = require('./logger.js').module('Zwave') -// log.info('This will be shown by default') -// logger = logger.setup({ level: 'warn' }) -// log.info('Now this won't be shown anymore') +const loggerPrefix = 'zwavejs2mqtt.' // Make sure every config value is defined const sanitizedConfig = (module, config) => { @@ -28,22 +16,20 @@ const sanitizedConfig = (module, config) => { } } -// Format loglevel upper-case: -const upperCaseLevel = format(info => { - info.level = info.level.toUpperCase() - return info -}) - -// Custom combined logging format: +// Custom logging format: const customFormat = config => combine( errors({ stack: true }), timestamp({ format: 'YYYY-MM-DD HH:mm:ss.SSS' }), - upperCaseLevel(), + format(info => { + info.level = info.level.toUpperCase() + return info + })(), label({ label: config.module.toUpperCase() }), - printf(({ level, message, label, timestamp }) => { - return `${timestamp} ${level} ${label || '-'}: ${message}` - }) + printf( + info => + `${info.timestamp} ${info.level} ${info.label || '-'}: ${info.message}` + ) ) // Custom transports: @@ -66,32 +52,35 @@ const customTransports = config => { return transportsList } -// Container for loggers of all modules: -const logContainer = new winston.Container() - -// Re-create a new module logger -const setupNewLogger = (module, container, config) => { +// Helper function to setup a logger: +const setupLogger = (container, module, config) => { config = sanitizedConfig(module, config) - if (container.has(module)) { - container.close(module) - } - const logger = container.add(module, { + const logger = container.add(loggerPrefix + module) // NOTE: Winston automatically reuses an existing module logger + logger.configure({ silent: !config.enabled, level: config.level, format: customFormat(config), transports: customTransports(config) }) - - // Workaround to allow logger config changes during runtime: - logger.container = container - logger.setup = config => setupNewLogger(module, container, config) - + logger.module = module + logger.setup = cfg => + setupLogger(container, module, cfg) return logger } -// Get logger for module with default config: -logContainer.module = module => { - return setupNewLogger(module, logContainer, {}) +// Setup a logger for a certain module: +winston.loggers.module = (module) => { + return setupLogger(winston.loggers, module) +} + +// Setup loggers for all modules +winston.loggers.setupAll = config => { + for (const [key, logger] of winston.loggers.loggers) { + // Make sure, only winston loggers created from this logger module are modified: + if (key.startsWith(loggerPrefix)) { + logger.setup(config) + } + } } -module.exports = logContainer +module.exports = winston.loggers diff --git a/test/lib/logger.test.js b/test/lib/logger.test.js index 4f952bf0ef5..62eb3344b5e 100644 --- a/test/lib/logger.test.js +++ b/test/lib/logger.test.js @@ -1,26 +1,145 @@ const { assert } = require('chai') -const chai = require('chai') -const rewire = require('rewire') -chai.should() +const winston = require('winston') +const reqlib = require('app-root-path').require describe('#logger', () => { - const mod = rewire('../../lib/logger.js') - let logger + let logContainer + let logger1 + let logger2 - it('has a module function', () => assert.isFunction(mod.module)) + before(() => { + logContainer = reqlib('lib/logger.js') + }) + + it('has a module function', () => assert.isFunction(logContainer.module)) + it('has a configAllLoggers function', () => + assert.isFunction(logContainer.setupAll)) describe('#module', () => { before(() => { - logger = mod.module('foo') + logger1 = logContainer.module('foo') + }) + it('should set the module name', () => logger1.module.should.equal('foo')) + it('should have a cfg function', () => assert.isFunction(logger1.setup)) + it('should have logging enabled by default', () => + logger1.silent.should.be.false) + it('should have the default log level', () => + logger1.level.should.equal('info')) + it('should have a custom format', () => + logger1.format + .transform({ level: 'info', message: 'msg' }) + .label.should.be.equal('FOO')) + it('should have one transport only', () => + logger1.transports.length.should.be.equal(1)) + }) + + describe('#cfg (init)', () => { + before(() => { + logger1 = logContainer.module('bar') + logger2 = logger1.setup({ + enabled: false, + level: 'warn', + logToFile: true + }) }) - it('should have a setup function', () => assert.isFunction(logger.setup)) - it('should have logging enabled', () => logger.silent.should.be.false) - it('should have log level info', () => logger.level.should.equal('info')) + it('should return the same logger instance', () => + logger1.should.be.equal(logger2)) + it('should set the module name', () => logger1.module.should.equal('bar')) + it('should disable logging', () => logger1.silent.should.be.true) + it('should change the log level', () => logger1.level.should.equal('warn')) + it('should have 2 transports', () => + logger1.transports.length.should.be.equal(2)) + it('should have a custom format', () => + logger1.format + .transform({ level: 'info', message: 'msg' }) + .label.should.be.equal('BAR')) }) - describe('#setup', () => { + + describe('#setup (reconfig)', () => { before(() => { - logger = mod.module('foo').setup({ level: 'warn' }) + logger1 = logContainer + .module('mod') + .setup({ enabled: true, level: 'warn', logToFile: false }) + }) + it('should change the logger configuration', () => { + // Test pre-conditions: + logger1.module.should.equal('mod') + logger1.level.should.equal('warn') + logger1.format + .transform({ level: 'info', message: 'msg' }) + .label.should.be.equal('MOD') + logger1.transports.length.should.be.equal(1) + // Change logger configuration: + logger1.setup({ enabled: false, level: 'error', logToFile: true }) + // Test post-conditions: + logger1.module.should.equal('mod') + logger1.level.should.equal('error') + logger1.format + .transform({ level: 'info', message: 'msg' }) + .label.should.be.equal('MOD') + logger1.transports.length.should.be.equal(2) + }) + }) + + describe('#configAll', () => { + it('should change the logger config of all zwavejs2mqtt modules', () => { + logger1 = logContainer + .module('mod1') + .setup({ enabled: true, level: 'warn', logToFile: false }) + logger2 = logContainer + .module('mod2') + .setup({ enabled: true, level: 'warn', logToFile: false }) + // Test pre-conditions: + logger1.module.should.equal('mod1') + logger1.level.should.equal('warn') + logger1.format + .transform({ level: 'info', message: 'msg' }) + .label.should.be.equal('MOD1') + logger1.transports.length.should.be.equal(1) + logger2.module.should.equal('mod2') + logger2.level.should.equal('warn') + logger2.format + .transform({ level: 'info', message: 'msg' }) + .label.should.be.equal('MOD2') + logger2.transports.length.should.be.equal(1) + // Change logger configuration: + logContainer.setupAll({ + enabled: false, + level: 'error', + logToFile: true + }) + // Test post-conditions: + logger1.module.should.equal('mod1') + logger1.level.should.equal('error') + logger1.format + .transform({ level: 'info', message: 'msg' }) + .label.should.be.equal('MOD1') + logger1.transports.length.should.be.equal(2) + logger2.module.should.equal('mod2') + logger2.level.should.equal('error') + logger2.format + .transform({ level: 'info', message: 'msg' }) + .label.should.be.equal('MOD2') + logger2.transports.length.should.be.equal(2) + }) + it('should not change the logger config of non-zwavejs2mqtt loggers', () => { + logger1 = logContainer + .module('mod1') + .setup({ enabled: true, level: 'warn', logToFile: false }) + // Create a different winston logger: + logger2 = winston.loggers.add('somelogger') + logger2.level = 'warn' + // Test pre-conditions: + logger1.level.should.equal('warn') + // Change logger configuration: + logContainer.setupAll({ + enabled: false, + level: 'error', + logToFile: true + }) + // Test post-conditions: + logger1.level.should.equal('error') + logger2.level.should.equal('warn') }) - it('should have log level warn', () => logger.level.should.equal('warn')) }) }) From 6108516816c952dbd03ff712d32d0a14294f84f7 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Sun, 13 Dec 2020 22:28:54 +0100 Subject: [PATCH 19/37] fix: Code formatting --- lib/logger.js | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/lib/logger.js b/lib/logger.js index 500c284c3c9..7e0abbcc11f 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -63,13 +63,12 @@ const setupLogger = (container, module, config) => { transports: customTransports(config) }) logger.module = module - logger.setup = cfg => - setupLogger(container, module, cfg) + logger.setup = cfg => setupLogger(container, module, cfg) return logger } // Setup a logger for a certain module: -winston.loggers.module = (module) => { +winston.loggers.module = module => { return setupLogger(winston.loggers, module) } From 6dbedb06fbb2d7b783178777d34578b9fe4295f9 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Sun, 13 Dec 2020 23:32:54 +0100 Subject: [PATCH 20/37] feat: Dynamically setup winston logger in app.js --- app.js | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) diff --git a/app.js b/app.js index e4d82415416..0bca1c95ac8 100644 --- a/app.js +++ b/app.js @@ -11,7 +11,8 @@ const ZWaveClient = reqlib('/lib/ZwaveClient') const MqttClient = reqlib('/lib/MqttClient') const Gateway = reqlib('/lib/Gateway') const store = reqlib('config/store.js') -const logger = reqlib('/lib/logger.js').module('App') +const loggers = reqlib('/lib/logger.js') +const logger = loggers.module('App') const history = require('connect-history-api-fallback') const SocketManager = reqlib('/lib/SocketManager') const { inboundEvents, socketEvents } = reqlib('/lib/SocketManager.js') @@ -37,12 +38,21 @@ function start (server) { startGateway() } +function setupLogging (settings) { + loggers.setupAll({ + level: settings.zwave.logLevel, + logToFile: settings.zwave.logToFile + }) +} + function startGateway () { const settings = jsonStore.get(store.settings) let mqtt let zwave + setupLogging(settings) + if (settings.mqtt) { mqtt = new MqttClient(settings.mqtt) } @@ -283,6 +293,7 @@ app.post('/api/settings', async function (req, res) { } restarting = true await jsonStore.put(store.settings, req.body) + setupLogging(req.body) await gw.close() startGateway() res.json({ success: true, message: 'Configuration updated successfully' }) From b96f37332a1012e8767533adb1619aac23fccf55 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Mon, 14 Dec 2020 14:31:37 +0100 Subject: [PATCH 21/37] refactor(logging): Add error stack trace --- lib/Gateway.js | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/lib/Gateway.js b/lib/Gateway.js index 900f2287665..e5f073cb9d8 100755 --- a/lib/Gateway.js +++ b/lib/Gateway.js @@ -1145,7 +1145,8 @@ Gateway.prototype.discoverDevice = function (node, hassDevice) { } } catch (error) { logger.error( - `Error while discovering device ${hassID} of node ${node.id}: ${error}` + `Error while discovering device ${hassID} of node ${node.id}: ${error.message}`, + error ) } } @@ -1273,7 +1274,7 @@ Gateway.prototype.discoverClimates = function (node) { allDevices[node.deviceId] = nodeDevices } catch (error) { - logger.error(`Unable to discover climate device: ${error.message}`) + logger.error(`Unable to discover climate device: ${error.message}`, error) } } @@ -1607,7 +1608,8 @@ Gateway.prototype.discoverValue = function (node, vId) { this.publishDiscovery(cfg, node.id) } catch (error) { logger.error( - `Error while discovering value ${valueId.id} of node ${node.id}: ${error.message}` + `Error while discovering value ${valueId.id} of node ${node.id}: ${error.message}`, + error ) } } From 0317ad4ce33d00c70190f7fb519a3119dc0b61d6 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Tue, 15 Dec 2020 00:16:48 +0100 Subject: [PATCH 22/37] refactor: Move logging config to gateway section --- app.js | 5 +++-- src/components/Settings.vue | 36 +++++++++++++++++++++--------------- 2 files changed, 24 insertions(+), 17 deletions(-) diff --git a/app.js b/app.js index 0bca1c95ac8..943342cf85c 100644 --- a/app.js +++ b/app.js @@ -40,8 +40,9 @@ function start (server) { function setupLogging (settings) { loggers.setupAll({ - level: settings.zwave.logLevel, - logToFile: settings.zwave.logToFile + enabled: settings.gateway.logEnabled, + level: settings.gateway.logLevel, + logToFile: settings.gateway.logToFile }) } diff --git a/src/components/Settings.vue b/src/components/Settings.vue index f834f80ad7c..2488c0cd1c4 100644 --- a/src/components/Settings.vue +++ b/src/components/Settings.vue @@ -37,21 +37,6 @@ @click:append-outer="randomKey" > - - - - - - + + + + + + + Date: Tue, 15 Dec 2020 08:59:55 +0100 Subject: [PATCH 23/37] fix: Revert removal of zwave log settings --- src/components/Settings.vue | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/src/components/Settings.vue b/src/components/Settings.vue index 2488c0cd1c4..c68d22a561a 100644 --- a/src/components/Settings.vue +++ b/src/components/Settings.vue @@ -37,6 +37,21 @@ @click:append-outer="randomKey" > + + + + + + Date: Tue, 15 Dec 2020 12:15:20 +0100 Subject: [PATCH 24/37] fix: Show log settings only if logging is enabled --- src/components/Settings.vue | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/components/Settings.vue b/src/components/Settings.vue index c68d22a561a..cee72d3d2cd 100644 --- a/src/components/Settings.vue +++ b/src/components/Settings.vue @@ -328,6 +328,7 @@ v-model="gateway.logEnabled" > Date: Tue, 15 Dec 2020 12:57:31 +0100 Subject: [PATCH 25/37] fix: UI labels for gateway logging --- src/components/Settings.vue | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/components/Settings.vue b/src/components/Settings.vue index cee72d3d2cd..1d617793126 100644 --- a/src/components/Settings.vue +++ b/src/components/Settings.vue @@ -322,14 +322,14 @@ Date: Tue, 15 Dec 2020 13:51:17 +0100 Subject: [PATCH 26/37] feat: Add gateway logfile name to UI settings --- app.js | 3 ++- src/components/Settings.vue | 5 +++++ 2 files changed, 7 insertions(+), 1 deletion(-) diff --git a/app.js b/app.js index 943342cf85c..158eaab0ea2 100644 --- a/app.js +++ b/app.js @@ -42,7 +42,8 @@ function setupLogging (settings) { loggers.setupAll({ enabled: settings.gateway.logEnabled, level: settings.gateway.logLevel, - logToFile: settings.gateway.logToFile + logToFile: settings.gateway.logToFile, + filename: settings.gateway.logFilename }) } diff --git a/src/components/Settings.vue b/src/components/Settings.vue index 1d617793126..e7e8e4c91f5 100644 --- a/src/components/Settings.vue +++ b/src/components/Settings.vue @@ -342,6 +342,11 @@ v-model="gateway.logLevel" label="Log Level" > + From 8474ff3cd955724e5ec46f63fbd2cf663c960750 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Tue, 15 Dec 2020 14:20:00 +0100 Subject: [PATCH 27/37] fix: Log setting UI layout --- src/components/Settings.vue | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/src/components/Settings.vue b/src/components/Settings.vue index e7e8e4c91f5..4429cfc4bba 100644 --- a/src/components/Settings.vue +++ b/src/components/Settings.vue @@ -327,25 +327,25 @@ label="Log enabled" v-model="gateway.logEnabled" > - - - + + + From cceeb2f8603a2fcec6ca60595276d559e9380640 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Tue, 15 Dec 2020 14:23:50 +0100 Subject: [PATCH 28/37] fix: Remove useless logFilename setting --- src/components/Settings.vue | 11 ++--------- 1 file changed, 2 insertions(+), 9 deletions(-) diff --git a/src/components/Settings.vue b/src/components/Settings.vue index 4429cfc4bba..bdaad1bea9a 100644 --- a/src/components/Settings.vue +++ b/src/components/Settings.vue @@ -327,26 +327,19 @@ label="Log enabled" v-model="gateway.logEnabled" > + + - - - From 10c20ce94286ec85792205b9e3414cad0ce16fdd Mon Sep 17 00:00:00 2001 From: Daniel Lando Date: Tue, 15 Dec 2020 15:13:50 +0100 Subject: [PATCH 29/37] fix: pretty colors on console and use stderr for error logs --- lib/logger.js | 30 +++++++++++++++++++++--------- 1 file changed, 21 insertions(+), 9 deletions(-) diff --git a/lib/logger.js b/lib/logger.js index 7e0abbcc11f..cfad741ee04 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -1,8 +1,10 @@ const winston = require('winston') -const { format, transports } = winston -const { combine, timestamp, label, printf, errors } = format +const { format, transports, addColors } = winston +const { combine, timestamp, label, printf, errors, colorize } = format const loggerPrefix = 'zwavejs2mqtt.' +const colorizer = colorize() + // Make sure every config value is defined const sanitizedConfig = (module, config) => { config = config || {} @@ -16,8 +18,13 @@ const sanitizedConfig = (module, config) => { } } +addColors({ + time: 'grey', + module: 'bold' +}) + // Custom logging format: -const customFormat = config => +const customFormat = (config, useColors) => combine( errors({ stack: true }), timestamp({ format: 'YYYY-MM-DD HH:mm:ss.SSS' }), @@ -26,9 +33,14 @@ const customFormat = config => return info })(), label({ label: config.module.toUpperCase() }), + colorize({ level: useColors }), printf( - info => - `${info.timestamp} ${info.level} ${info.label || '-'}: ${info.message}` + (info) => { + info.timestamp = useColors ? colorizer.colorize('time', info.timestamp) : info.timestamp + info.label = useColors ? colorizer.colorize('module', info.label || '-') : info.label + + return `${info.timestamp} ${info.level} ${info.label}: ${info.message}` + } ) ) @@ -36,14 +48,15 @@ const customFormat = config => const customTransports = config => { const transportsList = [ new transports.Console({ - format: format.colorize({ all: true }), - level: config.level + format: customFormat(config, true), + level: config.level, + stderrLevels: ['error'] }) ] if (config.logToFile) { transportsList.push( new transports.File({ - format: customFormat(config), + format: customFormat(config, false), filename: config.filename, level: config.level }) @@ -59,7 +72,6 @@ const setupLogger = (container, module, config) => { logger.configure({ silent: !config.enabled, level: config.level, - format: customFormat(config), transports: customTransports(config) }) logger.module = module From 26888507b3d640ab1df0d8a7b9357ad51bbd12fd Mon Sep 17 00:00:00 2001 From: Daniel Lando Date: Tue, 15 Dec 2020 15:25:18 +0100 Subject: [PATCH 30/37] fix: store log file to store folder --- lib/logger.js | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/lib/logger.js b/lib/logger.js index cfad741ee04..e6676269935 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -2,8 +2,11 @@ const winston = require('winston') const { format, transports, addColors } = winston const { combine, timestamp, label, printf, errors, colorize } = format const loggerPrefix = 'zwavejs2mqtt.' +const utils = require('./utils') +const { storeDir } = require('../config/app.js') const colorizer = colorize() +const defaultLogFile = utils.joinPath(true, storeDir, 'zwavejs2mqtt.log') // Make sure every config value is defined const sanitizedConfig = (module, config) => { @@ -14,7 +17,7 @@ const sanitizedConfig = (module, config) => { level: config.level !== undefined ? config.level : 'info', logToFile: config.logToFile !== undefined ? config.logToFile : false, filename: - config.filename !== undefined ? config.filename : 'zwavejs2mqtt.log' + config.filename !== undefined ? config.filename : defaultLogFile } } From ebcf277250cab9d696cd2d802aa795a45916f1ae Mon Sep 17 00:00:00 2001 From: Daniel Lando Date: Tue, 15 Dec 2020 15:27:14 +0100 Subject: [PATCH 31/37] fix: lint issues --- lib/logger.js | 19 ++++++++++--------- 1 file changed, 10 insertions(+), 9 deletions(-) diff --git a/lib/logger.js b/lib/logger.js index e6676269935..a94e5267d6e 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -16,8 +16,7 @@ const sanitizedConfig = (module, config) => { enabled: config.enabled !== undefined ? config.enabled : true, level: config.level !== undefined ? config.level : 'info', logToFile: config.logToFile !== undefined ? config.logToFile : false, - filename: - config.filename !== undefined ? config.filename : defaultLogFile + filename: config.filename !== undefined ? config.filename : defaultLogFile } } @@ -37,14 +36,16 @@ const customFormat = (config, useColors) => })(), label({ label: config.module.toUpperCase() }), colorize({ level: useColors }), - printf( - (info) => { - info.timestamp = useColors ? colorizer.colorize('time', info.timestamp) : info.timestamp - info.label = useColors ? colorizer.colorize('module', info.label || '-') : info.label + printf(info => { + info.timestamp = useColors + ? colorizer.colorize('time', info.timestamp) + : info.timestamp + info.label = useColors + ? colorizer.colorize('module', info.label || '-') + : info.label - return `${info.timestamp} ${info.level} ${info.label}: ${info.message}` - } - ) + return `${info.timestamp} ${info.level} ${info.label}: ${info.message}` + }) ) // Custom transports: From 17310d643ce2153a65b55210d3e067bf749a5e36 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Wed, 16 Dec 2020 09:21:56 +0100 Subject: [PATCH 32/37] refactor: Simplify color handling + improve tests --- lib/logger.js | 29 ++++++-------- test/lib/logger.test.js | 87 +++++++++++++++++++++++------------------ 2 files changed, 63 insertions(+), 53 deletions(-) diff --git a/lib/logger.js b/lib/logger.js index a94e5267d6e..1152abb554e 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -26,7 +26,7 @@ addColors({ }) // Custom logging format: -const customFormat = (config, useColors) => +const customFormat = config => combine( errors({ stack: true }), timestamp({ format: 'YYYY-MM-DD HH:mm:ss.SSS' }), @@ -35,15 +35,10 @@ const customFormat = (config, useColors) => return info })(), label({ label: config.module.toUpperCase() }), - colorize({ level: useColors }), + colorize({ level: true }), printf(info => { - info.timestamp = useColors - ? colorizer.colorize('time', info.timestamp) - : info.timestamp - info.label = useColors - ? colorizer.colorize('module', info.label || '-') - : info.label - + info.timestamp = colorizer.colorize('time', info.timestamp) + info.label = colorizer.colorize('module', info.label || '-') return `${info.timestamp} ${info.level} ${info.label}: ${info.message}` }) ) @@ -52,7 +47,7 @@ const customFormat = (config, useColors) => const customTransports = config => { const transportsList = [ new transports.Console({ - format: customFormat(config, true), + format: customFormat(config), level: config.level, stderrLevels: ['error'] }) @@ -60,7 +55,7 @@ const customTransports = config => { if (config.logToFile) { transportsList.push( new transports.File({ - format: customFormat(config, false), + format: combine(customFormat(config), format.uncolorize()), filename: config.filename, level: config.level }) @@ -83,14 +78,16 @@ const setupLogger = (container, module, config) => { return logger } +const logContainer = new winston.Container() + // Setup a logger for a certain module: -winston.loggers.module = module => { - return setupLogger(winston.loggers, module) +logContainer.loggers.module = module => { + return setupLogger(logContainer, module) } // Setup loggers for all modules -winston.loggers.setupAll = config => { - for (const [key, logger] of winston.loggers.loggers) { +logContainer.loggers.setupAll = config => { + for (const [key, logger] of logContainer.loggers) { // Make sure, only winston loggers created from this logger module are modified: if (key.startsWith(loggerPrefix)) { logger.setup(config) @@ -98,4 +95,4 @@ winston.loggers.setupAll = config => { } } -module.exports = winston.loggers +module.exports = logContainer.loggers diff --git a/test/lib/logger.test.js b/test/lib/logger.test.js index 62eb3344b5e..ba9ed2cf0cf 100644 --- a/test/lib/logger.test.js +++ b/test/lib/logger.test.js @@ -1,21 +1,60 @@ const { assert } = require('chai') const winston = require('winston') const reqlib = require('app-root-path').require +const rewire = require('rewire') -describe('#logger', () => { - let logContainer +const logContainer = reqlib('lib/logger.js') +const logContainerRewired = rewire('../../lib/logger.js') + +function checkConfigDefaults (mod, cfg) { + const defaultLogFile = logContainerRewired.__get__('defaultLogFile') + cfg.module.should.equal(mod) + cfg.enabled.should.equal(true) + cfg.level.should.equal('info') + cfg.logToFile.should.equal(false) + cfg.filename.should.equal(defaultLogFile) +} + +describe('logger.js', () => { + const sanitizedConfig = logContainerRewired.__get__('sanitizedConfig') + const customTransports = logContainerRewired.__get__('customTransports') let logger1 let logger2 - before(() => { - logContainer = reqlib('lib/logger.js') + it('should have a module function', () => + assert.isFunction(logContainer.module)) + it('should have a configAllLoggers function', () => + assert.isFunction(logContainer.setupAll)) + + describe('sanitizedConfig()', () => { + it('should set undefined config object to defaults', () => { + const cfg = sanitizedConfig('-', undefined) + checkConfigDefaults('-', cfg) + }) + it('should set empty config object to defaults', () => { + const cfg = sanitizedConfig('-', {}) + checkConfigDefaults('-', cfg) + }) + }) + + describe('customFormat()', () => { + it('should uppercase the label', () => { + // TODO: Why does it fail with 'TypeError: colors[Colorizer.allColors[lookup]] is not a function'? + // const customFormat = logContainerRewired.__get__('customFormat') + // const fmt = customFormat(sanitizedConfig('foo', {})) + // fmt.transform({ module: 'foo', level: 'info', message: 'msg' }) + // .label.should.be.equal('FOO') + }) }) - it('has a module function', () => assert.isFunction(logContainer.module)) - it('has a configAllLoggers function', () => - assert.isFunction(logContainer.setupAll)) + describe('customTransports()', () => { + it('should have one transport by default', () => { + const transports = customTransports(sanitizedConfig('-', {})) + transports.length.should.equal(1) + }) + }) - describe('#module', () => { + describe('module()', () => { before(() => { logger1 = logContainer.module('foo') }) @@ -25,15 +64,11 @@ describe('#logger', () => { logger1.silent.should.be.false) it('should have the default log level', () => logger1.level.should.equal('info')) - it('should have a custom format', () => - logger1.format - .transform({ level: 'info', message: 'msg' }) - .label.should.be.equal('FOO')) it('should have one transport only', () => logger1.transports.length.should.be.equal(1)) }) - describe('#cfg (init)', () => { + describe('setup() (init)', () => { before(() => { logger1 = logContainer.module('bar') logger2 = logger1.setup({ @@ -49,13 +84,9 @@ describe('#logger', () => { it('should change the log level', () => logger1.level.should.equal('warn')) it('should have 2 transports', () => logger1.transports.length.should.be.equal(2)) - it('should have a custom format', () => - logger1.format - .transform({ level: 'info', message: 'msg' }) - .label.should.be.equal('BAR')) }) - describe('#setup (reconfig)', () => { + describe('setup() (reconfigure)', () => { before(() => { logger1 = logContainer .module('mod') @@ -65,23 +96,17 @@ describe('#logger', () => { // Test pre-conditions: logger1.module.should.equal('mod') logger1.level.should.equal('warn') - logger1.format - .transform({ level: 'info', message: 'msg' }) - .label.should.be.equal('MOD') logger1.transports.length.should.be.equal(1) // Change logger configuration: logger1.setup({ enabled: false, level: 'error', logToFile: true }) // Test post-conditions: logger1.module.should.equal('mod') logger1.level.should.equal('error') - logger1.format - .transform({ level: 'info', message: 'msg' }) - .label.should.be.equal('MOD') logger1.transports.length.should.be.equal(2) }) }) - describe('#configAll', () => { + describe('setupAll()', () => { it('should change the logger config of all zwavejs2mqtt modules', () => { logger1 = logContainer .module('mod1') @@ -92,15 +117,9 @@ describe('#logger', () => { // Test pre-conditions: logger1.module.should.equal('mod1') logger1.level.should.equal('warn') - logger1.format - .transform({ level: 'info', message: 'msg' }) - .label.should.be.equal('MOD1') logger1.transports.length.should.be.equal(1) logger2.module.should.equal('mod2') logger2.level.should.equal('warn') - logger2.format - .transform({ level: 'info', message: 'msg' }) - .label.should.be.equal('MOD2') logger2.transports.length.should.be.equal(1) // Change logger configuration: logContainer.setupAll({ @@ -111,15 +130,9 @@ describe('#logger', () => { // Test post-conditions: logger1.module.should.equal('mod1') logger1.level.should.equal('error') - logger1.format - .transform({ level: 'info', message: 'msg' }) - .label.should.be.equal('MOD1') logger1.transports.length.should.be.equal(2) logger2.module.should.equal('mod2') logger2.level.should.equal('error') - logger2.format - .transform({ level: 'info', message: 'msg' }) - .label.should.be.equal('MOD2') logger2.transports.length.should.be.equal(2) }) it('should not change the logger config of non-zwavejs2mqtt loggers', () => { From 0d5e90ff70d29d897992c070e75852533857e9ef Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Wed, 16 Dec 2020 09:39:21 +0100 Subject: [PATCH 33/37] test: Cleanup tests --- test/lib/logger.test.js | 14 ++++++-------- 1 file changed, 6 insertions(+), 8 deletions(-) diff --git a/test/lib/logger.test.js b/test/lib/logger.test.js index ba9ed2cf0cf..2509f0426c4 100644 --- a/test/lib/logger.test.js +++ b/test/lib/logger.test.js @@ -2,12 +2,10 @@ const { assert } = require('chai') const winston = require('winston') const reqlib = require('app-root-path').require const rewire = require('rewire') - -const logContainer = reqlib('lib/logger.js') -const logContainerRewired = rewire('../../lib/logger.js') +const logContainer = rewire('../../lib/logger.js') function checkConfigDefaults (mod, cfg) { - const defaultLogFile = logContainerRewired.__get__('defaultLogFile') + const defaultLogFile = logContainer.__get__('defaultLogFile') cfg.module.should.equal(mod) cfg.enabled.should.equal(true) cfg.level.should.equal('info') @@ -16,8 +14,8 @@ function checkConfigDefaults (mod, cfg) { } describe('logger.js', () => { - const sanitizedConfig = logContainerRewired.__get__('sanitizedConfig') - const customTransports = logContainerRewired.__get__('customTransports') + const sanitizedConfig = logContainer.__get__('sanitizedConfig') + const customTransports = logContainer.__get__('customTransports') let logger1 let logger2 @@ -40,9 +38,9 @@ describe('logger.js', () => { describe('customFormat()', () => { it('should uppercase the label', () => { // TODO: Why does it fail with 'TypeError: colors[Colorizer.allColors[lookup]] is not a function'? - // const customFormat = logContainerRewired.__get__('customFormat') + // const customFormat = logContainer.__get__('customFormat') // const fmt = customFormat(sanitizedConfig('foo', {})) - // fmt.transform({ module: 'foo', level: 'info', message: 'msg' }) + // fmt.transform({ level: 'info', message: 'msg' }) // .label.should.be.equal('FOO') }) }) From 92e07c7c05e084dd26cfa5d94ab86cf58eb7bfa9 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Wed, 16 Dec 2020 10:53:12 +0100 Subject: [PATCH 34/37] test: More cleanup --- test/lib/logger.test.js | 1 - 1 file changed, 1 deletion(-) diff --git a/test/lib/logger.test.js b/test/lib/logger.test.js index 2509f0426c4..d12fe613410 100644 --- a/test/lib/logger.test.js +++ b/test/lib/logger.test.js @@ -1,6 +1,5 @@ const { assert } = require('chai') const winston = require('winston') -const reqlib = require('app-root-path').require const rewire = require('rewire') const logContainer = rewire('../../lib/logger.js') From e1ea9c745c0cb234c4b6e3986fc41ccf926b8bc7 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Wed, 16 Dec 2020 16:55:49 +0100 Subject: [PATCH 35/37] refactor: Remove useless logger name prefix --- lib/logger.js | 12 ++++-------- 1 file changed, 4 insertions(+), 8 deletions(-) diff --git a/lib/logger.js b/lib/logger.js index 1152abb554e..ec87c6958ba 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -1,7 +1,6 @@ const winston = require('winston') const { format, transports, addColors } = winston const { combine, timestamp, label, printf, errors, colorize } = format -const loggerPrefix = 'zwavejs2mqtt.' const utils = require('./utils') const { storeDir } = require('../config/app.js') @@ -67,7 +66,7 @@ const customTransports = config => { // Helper function to setup a logger: const setupLogger = (container, module, config) => { config = sanitizedConfig(module, config) - const logger = container.add(loggerPrefix + module) // NOTE: Winston automatically reuses an existing module logger + const logger = container.add(module) // NOTE: Winston automatically reuses an existing module logger logger.configure({ silent: !config.enabled, level: config.level, @@ -87,12 +86,9 @@ logContainer.loggers.module = module => { // Setup loggers for all modules logContainer.loggers.setupAll = config => { - for (const [key, logger] of logContainer.loggers) { - // Make sure, only winston loggers created from this logger module are modified: - if (key.startsWith(loggerPrefix)) { - logger.setup(config) - } - } + logContainer.loggers.forEach(logger => { + logger.setup(config) + }) } module.exports = logContainer.loggers From 6fb35a97ddd3fea9f241e78de7f8c46408e44342 Mon Sep 17 00:00:00 2001 From: Andreas Hochsteger Date: Wed, 16 Dec 2020 16:59:36 +0100 Subject: [PATCH 36/37] refactor: Split logLevel + logToFile into separat v-flex Co-authored-by: Daniel Lando --- src/components/Settings.vue | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/components/Settings.vue b/src/components/Settings.vue index bdaad1bea9a..00e039ef0e3 100644 --- a/src/components/Settings.vue +++ b/src/components/Settings.vue @@ -334,6 +334,8 @@ v-model="gateway.logLevel" label="Log Level" > + + Date: Wed, 16 Dec 2020 17:05:14 +0100 Subject: [PATCH 37/37] style: Fix code style --- src/components/Settings.vue | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/components/Settings.vue b/src/components/Settings.vue index 00e039ef0e3..50101d08f49 100644 --- a/src/components/Settings.vue +++ b/src/components/Settings.vue @@ -334,8 +334,8 @@ v-model="gateway.logLevel" label="Log Level" > - - + +