[WIP] Unified winston-based logging module (PR to branch) #47

ahochsteger · 2020-12-02T22:47:21Z

This PR is a draft to unify the logging across zwavejs2mqtt using winston and is continued in #67.

It provides the following changes:

A simple, central logging module (lib/logging.js)
Module-based default loggers
Example of a pre-configured module logger (for ZwaveClient.js) to show how special logging requirements for a certain module can be implemented (if required in the future)
An example usage of the logging module (in lib/ZwaveClient.js)

Usage:

const logger = require('./logger.js').module('ZWC')
logger.info("Some log message")

Conditions & Requirements:

Logging changes in the existing codebase:

The following files are affected and show the existing logging implementation that should be migrated to winston logging:

app.js (uses debug & morgan) ---> winston HTTP and APP modules
bin/www (uses debug) --> console
lib/debug.js (uses debug) ---> Will become logger.js
lib/Gateway.js (uses debug) ---> winston GATEWAY and (maybe) HASS modules
lib/jsonStore.js (uses debug) ---> winston STORE module (need to think about this, we could use console otherwise)
lib/MqttClient.js (uses debug) --> winston MQTT module
lib/ZwaveClient.js (uses debug) --> winston ZWAVE module

Next Steps:

Discuss the assumptions to turn them into solid conditions & requirements for the logging implementation
Adjust the example implementation to the agreed conditions & requirements
Rollout to the whole codebase

Foot notes:

If a more sophisticated logging/formatting is required then the logging extensions of node-zwave-js may be used instead.

Update forked repo

robertsLando

@ahochsteger The base is good. What is missing is a way to customize logger options like transports to use, enable/disable logs (silence transports). I would also provide a file transport, not by default but if it's requested in the options.

robertsLando · 2020-12-03T07:08:49Z

lib/ZwaveClient.js

      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)


Suggested change

logger.info('Driver already connected to', this.cfg.port)

logger.info(`Driver already connected to ${this.cfg.port}`)

I would convert all this loggers that are using commas , to use the template ``

robertsLando · 2020-12-03T07:09:11Z

lib/ZwaveClient.js

@@ -1897,7 +1904,7 @@ ZwaveClient.prototype.callApi = async function (apiName, ...args) {
    }
  }

-  debug(result.message, apiName, result.result || '')
+  logger.info(result.message, apiName, result.result || '')


Same as above

robertsLando · 2020-12-03T07:09:59Z

lib/logger.js

+const logContainer = new winston.Container()
+
+// Example: Pre-configured module logger with special properties
+logContainer.add('ZWC', {


What's ZWC ?

It's the short representation of "ZwaveClient" for shorter logging statements. It just shows that it may be different to the (possibly longer) filename.
It's also one of the assumptions we did not yet talk about and I'd like to get some feedback about what is expected.

I think zjs2m it's more generic (also the old z2m would be fine IMO) as we also have a zwave client module.

Modules are:

store: the json store module

app: everything that is in app.js

apis: to log api requests (will replace morgan)

zwave: zwave client

mqtt: mqtt client

ahochsteger · 2020-12-03T07:21:37Z

@ahochsteger The base is good. What is missing is a way to customize logger options like transports to use, enable/disable logs (silence transports). I would also provide a file transport, not by default but if it's requested in the options.

lib/logger.js would be the place where all logging customization can be done using the following 2 ways:

Set global customizations (see logContainer.module and customCombinedFormat and customTransports)
Set per-module customizations (see logContainer.add('ZWC', ...)

Or is there something else you'd expect?

robertsLando · 2020-12-03T07:28:10Z

@ahochsteger What I mean is:

When z2m starts we read settings.json where all settings are defined (gateway, zwave, mqtt). I would like to add to this settings logger options (maybe on gateway section):

logEnabled: enable/disable logs
logToFile: also log to file
logLevel: log level (error, warn, info, debug, ...)

Something like what I have done in this PR in zwave-js: zwave-js/node-zwave-js@5942fc8#diff-6f99af7443b72862fc7d1dce631cac3b76263260bdead8dfa2bbbfa062a38340R13

ahochsteger · 2020-12-03T07:41:55Z

@ahochsteger What I mean is:

When z2m starts we read settings.json where all settings are defined (gateway, zwave, mqtt). I would like to add to this settings logger options like:

enabled: enable/disable logs

logToFile: also log to file

@robertsLando I see what you mean.
What's the best way to get these settings into the logger.js?

I see the following options:

Directly read settings.js (bad option, is not the responsibility of logger.js to read this file)
Extend the constructor of MqttClient, ZWaveClient and Gateway to pass logging settings through which can be passed on to the logger
Anything else?

Assuming option 2, it could look like this:

const logger = require('./logger.js').module('<modname>')
...
logger.setup(<some logging settings>)
logger.info("Some log message")
...

The downside is, that you HAVE to call logger.setup in every file before using the logger.
On the upside you still have full control over logging within each module if you have a special usecase.

What do you think?

robertsLando · 2020-12-03T07:48:07Z

Extend the constructor of MqttClient, ZWaveClient and Gateway to pass logging settings through which can be passed on to the logger

There is no need to do this. The logger.setup function should be called only on Gateway and the logger options will be in config that is already passed to Gateway constructor. The logger setup is unique for all the application it's not specific for each module. By default the logger should be inited like it is now so the first logs in app.js will always appear

ahochsteger · 2020-12-04T07:06:01Z

Extend the constructor of MqttClient, ZWaveClient and Gateway to pass logging settings through which can be passed on to the logger

There is no need to do this. The logger.setup function should be called only on Gateway and the logger options will be in config that is already passed to Gateway constructor. The logger setup is unique for all the application it's not specific for each module. By default the logger should be inited like it is now so the first logs in app.js will always appear

What about the logging configuration of other modules (MqttClient, ZwaveClient, ...)? They need the config too.
I guess we should decide on the responsibilities for setting up the logger:

Responsibility of logger configuration:
a. The parent component knows how to fetch the logger configuration and passes it explicitly to the child component
b. The child component knows how to get the logger configuration (direct config access)
Responsibility of logger instantiation:
a. The parent instantiates the logger for the child component and passes it to the child component (dependency injection)
b. The child instantiates the logger and has control over it

So it comes down to the following architectural decisions:

If we want to ensure, logging of every component behaves the same and don't need flexibility on the module side we should go for 1a+2a
- Consequence: No control on the child component side which may be problematic, if we want to control integrated 3rd party modules/components that are used by child components, since there's no access to the logger config (just the pre-configured instance). So controlling the logging of 3rd party dependencies (possibly using other logger implementations) may not be possible.
If we want to make sure, we have a central logging configuration but want to keep the flexibility and control on the child component side we should go for 1a+2b
- Consequence: Each child component must instantiate the logger using the injected configuration itself. For 3rd party libs the config may be used to control their logging implementation.
If we want to have maximum control on the child component side we should go for 1b+2b
- Consequence: Each child component has a direct dependency logging configuration and instantiation. Unified behavior may not be easy to guarantee due to repeated code.

Since the current approach uses labels to tag logging events with the source module and the labels may have to be passed to the logger during instantiation time (at least I did not find a way to change it afterwards), I guess 1a+2b may be a good compromise. Maybe the suggestion to move the label to the info object may be a solution to make 1a+2a possible (see winstonjs/winston#736) if we really need this.

@robertsLando what's your thoughts on this?

ahochsteger · 2020-12-04T07:09:03Z

@robertsLando may you provide some feedback about the assumptions in the description so we can adjust them and move them to the section Agreed Conditions & Requirements? I'd like to do the code changes after this is done.

robertsLando · 2020-12-04T07:40:48Z

What about the logging configuration of other modules (MqttClient, ZwaveClient, ...)? They need the config too.
I guess we should decide on the responsibilities for setting up the logger

IMO this would become difficult to implement without so much benefits. If you are looking for zwave client logs you could easily get them by using grep for example or by doing a search in a log file. I would like to keep it as simple as possible (that's why I started with debug module at first). Also making all modules configurable means lot of options in user ui and I would like to avoid it too, more settings means also more possible user errors based on my experience.

Esentially there will be only 1 level of childs (modules) and this level will be:

store: the json store module
app: everything that is in app.js
apis: to log api requests (here we can replace morgan or pipe morgan stream to our logger)
zwave: zwave client (everything in ZwaveClient.js)
mqtt: mqtt client (everything in MqttClient.js)
gateway: the gateway logs (coming from Gateway.js)

In gateway we could think about having a custom logger for hass related stuff too. It could be a child of gateway or another module that extends the main z2m wiston container.

About assumptions:

Winston should be used the basis for unified logging

Yes

Modules are mapped to winston labels and logger categories

Not sure about what you mean here. In my idea there will be only one logger instance and more modules each module will share the same transports of the main instance. The output format w

All loggers should be defined on a central place (logger.js)

Yes

Modules/labels should be as short as possible (e.g. prefer ZWC to ZwaveClient)

I would use ZWAVE MQTT GATEWAY STORE HASS HTTP APP

Default loggers as well as special pre-configured loggers should be supported

What do you mean here?

Different log levels should be used to signal event severity (see https://github.com/winstonjs/winston#logging-levels)

Sure, in UI we the level input should be the same I'm using in zwave settings for zwave-js

A simple to use logging solution is required (unlike the more sophisticated solution of node-zwave-js)

Actually the logging solution is almost the same as node-zwave-js, it's not that difficult, zwave-js implementation just use some special formatting for logs but the main structure would be the same

Just a thought: I think that the STORE module will use the default logger as ATM store is used to read settings and we cannot configure the log before reading settings, we have to think about a way to fix this

ahochsteger · 2020-12-04T09:18:46Z

@robertsLando thanks for your feedback, I moved all agreed items to the other section - only two left.

Modules are mapped to winston labels and logger categories

Not sure about what you mean here. In my idea there will be only one logger instance and more modules each module will share the same transports of the main instance. The output format w

This is an implementation detail about how we map modules to winston elements:

I guess, you wanted to write some more about formatting, but your sentence seems to be not finished ...

Default loggers as well as special pre-configured loggers should be supported

What do you mean here?

It was my assumption that there may be modules that require very special logging configuration and we want to support that.
From your feedback concerning to be as simple as possible I assume that we may skip this requirement.

Different log levels should be used to signal event severity (see https://github.com/winstonjs/winston#logging-levels)

Sure, in UI we the level input should be the same I'm using in zwave settings for zwave-js

What do you mean with "level input" here?

A simple to use logging solution is required (unlike the more sophisticated solution of node-zwave-js)

Actually the logging solution is almost the same as node-zwave-js, it's not that difficult, zwave-js implementation just use some special formatting for logs but the main structure would be the same

I had the impression to be more sophisticated since there are a lot of logging classes and much improved colored formatting.
I'm not sure, if you'd like to support that for zwavejs2mqtt in the long run too.

Just a thought: I think that the STORE module will use the default logger as ATM store is used to read settings and we cannot configure the log before reading settings, we have to think about a way to fix this

Yes, that's a chicken/egg problem.
One way I see would be to store the logging configuration into its own file (e.g. logging.json) that is read during the bootstrapping before the store reads the setting.
But then we still would need the possibility to write the file using the store, but only if we want to persist changes to logging settings in the UI on the server-side to survive restarts.

robertsLando · 2020-12-04T10:19:02Z

I guess, you wanted to write some more about formatting, but your sentence seems to be not finished ...

Sorry didn't noticed that 😆 The output format could be like:

<time> <level>  <moduleName/label>: <logMessage>

The time format will be in 24h format
Level and module name should use upper cases

Example:

09:06:32.568 INFO APP: Zwave2MQTT Version 0.0.0

CATEGORIES: https://github.com/winstonjs/winston#working-with-multiple-loggers-in-winston

In my idea all loggers should use the same transports but they could use different formats, the base format is the one I showed you previously then we can customize the formats based on different modules needs. In a first step we could keep the format the same for all modules and then see how we could improve formats.

What do you mean with "level input" here?

Actually if you check the UI, settings page, zwave section, there is a select input for levels, we could use the same for the log levels of our logger settings

I had the impression to be more sophisticated since there are a lot of logging classes and much improved colored formatting.

Most of the complicated stuff there is the log formatting, what I would like to replicate here is the structure it uses (shared transports and module/labels)

One way I see would be to store the logging configuration into its own file (e.g. logging.json) that is read during the bootstrapping before the store reads the setting.

This could be a solution but IMO logging settings should be stored in settings.

But then we still would need the possibility to write the file using the store, but only if we want to persist changes to logging settings in the UI on the server-side to survive restarts.

Logging settings (like other settings) must be persistent.

robertsLando · 2020-12-04T13:20:18Z

@ahochsteger I have introduced the socket module here: #51

ahochsteger · 2020-12-04T15:21:20Z

@robertsLando thanks for the feedback - it's integrated into the list of requirements.

09:06:32.568 INFO APP: Zwave2MQTT Version 0.0.0

I'd miss the date here which is required if zwavejs2mqtt is running silently for a longer time and from time to time I'd like to review the logs for problems. Then it would be important to know on which day that was.

Optionally the timezone could be added too, but this is not that important IMO.
Maybe the time format is something we might let the user customize in the future?

robertsLando · 2020-12-04T15:52:14Z

I'd miss the date here which is required if zwavejs2mqtt is running silently for a longer time and from time to time I'd like to review the logs for problems. Then it would be important to know on which day that was.

Yep no problem we can add the date too :)

Maybe the time format is something we might let the user customize in the future?

Nope, I don't think so. Useless IMO

ahochsteger · 2020-12-11T08:32:17Z

@robertsLando, as you suggested on slack I'm about to move the commits & PR to a direct branch of this repo (winston-logging) so anyone is able to contribute.

robertsLando · 2020-12-11T09:06:37Z

@ahochsteger 👍

ahochsteger · 2020-12-11T09:36:30Z

@robertsLando, may you merge this into the new branch?
I'll then create a new PR and move the description to it.

ahochsteger · 2020-12-11T09:48:11Z

@robertsLando, nevermind, was able to do it myself :-).

ahochsteger · 2020-12-11T09:54:30Z

This PR is now continued in #67.

ahochsteger and others added 4 commits November 25, 2020 17:34

Merge pull request #1 from zwave-js/master

68c7516

Update forked repo

Merge remote-tracking branch 'upstream/master'

cbd7bd2

Merge remote-tracking branch 'upstream/master' into winston-logging

b9f409e

refactor: Add loging module based on winston

a2f426e

ahochsteger requested a review from robertsLando December 2, 2020 22:47

style: Fix code style

6d45630

ahochsteger changed the title ~~Unified winston-based logging module~~ [WIP] Unified winston-based logging module Dec 3, 2020

robertsLando requested changes Dec 3, 2020

View reviewed changes

larstobi mentioned this pull request Dec 10, 2020

[feat] Enable/disable logging to file without restarting network #64

Closed

Merge remote-tracking branch 'upstream/master' into winston-logging

91c37ae

ahochsteger changed the base branch from master to winston-logging December 11, 2020 09:32

ahochsteger changed the title ~~[WIP] Unified winston-based logging module~~ [WIP] Unified winston-based logging module (PR to branch) Dec 11, 2020

ahochsteger marked this pull request as ready for review December 11, 2020 09:34

fix: Removed unused createLogger

29e54a7

ahochsteger merged commit cda66b9 into zwave-js:winston-logging Dec 11, 2020

ahochsteger deleted the winston-logging branch December 11, 2020 09:47

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[WIP] Unified winston-based logging module (PR to branch) #47

[WIP] Unified winston-based logging module (PR to branch) #47

ahochsteger commented Dec 2, 2020 •

edited

Loading

robertsLando left a comment

robertsLando Dec 3, 2020

robertsLando Dec 3, 2020

robertsLando Dec 3, 2020

ahochsteger Dec 3, 2020

robertsLando Dec 3, 2020 •

edited

Loading

ahochsteger commented Dec 3, 2020

robertsLando commented Dec 3, 2020 •

edited

Loading

ahochsteger commented Dec 3, 2020

robertsLando commented Dec 3, 2020

ahochsteger commented Dec 4, 2020

ahochsteger commented Dec 4, 2020

robertsLando commented Dec 4, 2020 •

edited

Loading

ahochsteger commented Dec 4, 2020

robertsLando commented Dec 4, 2020 •

edited

Loading

robertsLando commented Dec 4, 2020

ahochsteger commented Dec 4, 2020

robertsLando commented Dec 4, 2020 •

edited

Loading

ahochsteger commented Dec 11, 2020

robertsLando commented Dec 11, 2020

ahochsteger commented Dec 11, 2020

ahochsteger commented Dec 11, 2020

ahochsteger commented Dec 11, 2020

	logger.info('Driver already connected to', this.cfg.port)
	logger.info(`Driver already connected to ${this.cfg.port}`)

[WIP] Unified winston-based logging module (PR to branch) #47

[WIP] Unified winston-based logging module (PR to branch) #47

Conversation

ahochsteger commented Dec 2, 2020 • edited Loading

robertsLando left a comment

Choose a reason for hiding this comment

robertsLando Dec 3, 2020

Choose a reason for hiding this comment

robertsLando Dec 3, 2020

Choose a reason for hiding this comment

robertsLando Dec 3, 2020

Choose a reason for hiding this comment

ahochsteger Dec 3, 2020

Choose a reason for hiding this comment

robertsLando Dec 3, 2020 • edited Loading

Choose a reason for hiding this comment

ahochsteger commented Dec 3, 2020

robertsLando commented Dec 3, 2020 • edited Loading

ahochsteger commented Dec 3, 2020

robertsLando commented Dec 3, 2020

ahochsteger commented Dec 4, 2020

ahochsteger commented Dec 4, 2020

robertsLando commented Dec 4, 2020 • edited Loading

ahochsteger commented Dec 4, 2020

robertsLando commented Dec 4, 2020 • edited Loading

robertsLando commented Dec 4, 2020

ahochsteger commented Dec 4, 2020

robertsLando commented Dec 4, 2020 • edited Loading

ahochsteger commented Dec 11, 2020

robertsLando commented Dec 11, 2020

ahochsteger commented Dec 11, 2020

ahochsteger commented Dec 11, 2020

ahochsteger commented Dec 11, 2020

ahochsteger commented Dec 2, 2020 •

edited

Loading

robertsLando Dec 3, 2020 •

edited

Loading

robertsLando commented Dec 3, 2020 •

edited

Loading

robertsLando commented Dec 4, 2020 •

edited

Loading

robertsLando commented Dec 4, 2020 •

edited

Loading

robertsLando commented Dec 4, 2020 •

edited

Loading