logIO - logging on steroids

Hello!

Preface

In the beginning of the year I decided to broaden my knowledge in ELK stack, thus I set up a local ElasticSearch and Kibana and then I needed some data ... lots of it.
Instead of using numerous meaningless data sets I though about leveraging my Node-Red instance and all the running flows inside it that produce thousands of messages per day. Should be enough to get me going.

And as we know how changing the light bulb leads to fixing everything else, ELK will wait and my first custom Node-Red node logIO is almost ready for release.

I'll appreciate if you take a look, maybe even test it if fits in your flows and give me some pointers or ideas before I make 1.0.0 release.

I'd aso like to thank everyone here, this forum was super helpful during development and I took some inspirations not only from official nodes but also nodes you built and shared here.

logIO

As the name suggests, logIO node logs INPUT and OUTPUT messages from nodes. Contrary to other nodes out there, you don't have to wire each and every node you want to log directly to logIO, but you can use it similar to core catch or status components. Of course you can use it also as core debug component with additional improvement here too.

Log outputs:
logIO currently supports following log outputs (multiple can be selected):

  • Node-Red debugger panel
  • System console (supports: colored output based on log level, json output, utc/local timestamps, additional meta data)
  • File (supports file rotation, compression and deletion of old logs, json output, utc/local timestamps, additional meta data)
  • ElasticSearch (sends logs directly to elasticsearch - tested with ES version > 8, supports: utc/local timestamps, additional meta data, custom index definition)

Log modes
inline [default] mode
In this mode, logIO behaves similar to core debug node, where you can pipe other nodes into logIO and input messages will be logged.

BUT you will notice that in inline mode, logIO has also an output, thus you can include in in the middle of the flow. if so, logIO will automatically log every input and output message of all the components that come after it.

flow, select, all modes
In these modes, logIO behaves similar to core catch or status components, meaning you don't have to wire other components into it, but it will still log input and output messages of all, current flow or selected nodes.

Controlling the node logging
By default, logIO will log messages of all connected or selected nodes from deploy onward.

You can disable this behavior by deselecting the Automatically start logging at startup and activate the logIO node through incoming message.

To activate logging, incoming message should have a _logIO_ object with key activate set to true:

{
  "payload" : "your payload",
  "topic": "your topic",
  "_logIO_" : { "activate": true }
}

To deactivate logging, incoming message should have a _logIO_ object with key activate set to false:

{
  "payload" : "your payload",
  "topic": "your topic",
  "_logIO_" : { "activate": false }
}

You can also toggle the logging through components button same as in core debug component.
Have in mind that those two actions are not the same and for example if you activated the logIO through incoming message but logIO is deactivated in editor, logging will still be paused.

Logging status and mode are also displayed in status of the component for easier visualization.

:pushpin: If logging is deactivated and logIO is in inline mode, logIO will act as a pass through component. It will not produce any logs, just pass the message onward as is.

Log levels: [error, warn, info, debug]

Default log level is set to debug.

If message doesn't have its own logLevel, it will be assigned one as defined in logIO and always logged. In this case logIO doesn't act as a filter, but only attaches the selected logLevel to the log entry.

Of course more common case is that you want to log you messages based on severity, so if the message contains _logIO_ object with key logLevel set to one of allowed levels, that one will be used for:

  1. displaying that log level in log entry
  2. omitting the message from logs, if current message logLevel priority is lower than logIO log level priority

e.g: logIO log level is set to warn

This message will be logged.

{
  "payload" : "your payload",
  "topic": "your topic",
  "_logIO_" : { "logLevel": "error" }
}

This message will be logged.

{
  "payload" : "your payload",
  "topic": "your topic",
  "_logIO_" : { "logLevel": "warn" }
}

This message will be logged with warn logLevel (same as logIO defined log level)

{
  "payload" : "your payload",
  "topic": "your topic",
}

This message will NOT be logged.

{
  "payload" : "your payload",
  "topic": "your topic",
  "_logIO_" : { "logLevel": "info" }
}

:question: Here I have a question, would it make more sense to put logLevel directly on message and not inside _logLevel_ key? What are you currently using - is there any convention?

{
  "payload" : "your payload",
  "topic": "your topic",
  "logLevel": "error" 
}

To install and try it out, search for @zigasebenik/node-red-log-io or install manually (as I don't know how long in takes to appear in Node-Red after submitting it).

npm install @zigasebenik/node-red-log-io

Github repo is here.

I have to polish the editor a bit and properly document everything in the following days based on potential upcoming changes. Nevertheless it's ready to test it out.

4 Likes

Hi, this looks like a great addition. thanks for your efforts. While i have not tried it out (yet) i did have a peek at the dependencies.

I noted that the @zigasebenik/node-red-log-io package depends on @zigasebenik/winston-daily-rotate-file which in turn depends on @zigasebenik/file-stream-rotator which has a dependency on moment. As I am sure you are aware, moment is pretty much dead in the water these days. However that is not my point, my point is that the @zigasebenik/node-red-log-io package itself already depends on dayjs (which is pretty much a recommended replacement for moment). Is there any reason the sub-dependency doesnt also use dayjs instead of moment?

Hi Steve, thanks for taking time to check and for your question.

I know about moment being deprecated for a while now thus we are switching to dayjs or other libraries whenever making something new. It's not even hard to refactor a project from moment to dayjs as APIs are basically the same.

Here in this case I was originally using following dependencies:
winston
winston-daily-rotate-file

Then I discovered a bug were if you are logging results to a file and that file gets deleted, new one is not created. It goes further than that, if inode of the file gets changed during save (some editors do that and it also might be OS dependent), logging to that file was also interrupted.

I inspected the dependencies of winston-daily-rotate-file and found a cause of the bug in one of it's dependencies file-stream-rotator.

Thus I created a fork of it fixing the bug (bug is already reported to original project, and in the future I plan to make a PR). But in the mean time I had to use my forks where bug seems to be fixed in my Node-Red plugin.

So to the answer about moment, as it's used in currently forked projects I don't plan to refactor those in order to replace it with dayjs. Hopefully though future PR will be accepted and I can switch logIO dependencies back to original ones. Although that will not resolve the moment library inclusion :slight_smile:

Nice. Thanks for contributing.

Personally, I would prefer the use of _logLevel as that is much less likely to cause a property clash.

Hi, thanks for your input. I formulated the question a bit odd and now not sure if we're aligned, so like this:

{
  "payload": ...,
  "_logLevel": "error"
}

or scoped inside _logIO_ key

{
  "payload": ...,
  "_logIO_": { "logLevel": "error" }
}

I have another question, is there a good or proper way to get all nodes connected to particular node? As now I can easily get nodes that come out of one node by following the wires (only out wires seem to be defined on node). To get all connected nodes that came into certain node would require some more loops over RED.nodes.eachNode.

Sorry, my bad for replying when I should have been working! :slight_smile:

Yes, _logIO or _logIO_ would be preferred I believe. With the level as a property.

1 Like

I figured it out with only 1 pass over RED.nodes.eachNode and then partial and selective passes over forward connection nodes - should be pretty efficient and is done only upon node deploy.

So now this enables me to do things a bit differently.

I got rid of logIOs output node (as it was a bit confusing tbh), so now inline mode behaves exactly the same as core debug node.

I introduced a new mode called wired and in this mode, all nodes that are in any way connected to logIO are being logged. Example included in 0.9.2 release.

Plus I added option to choose to log either only INPUT or both INPUT and OUTPUT messages.

1 Like

Hi @ziga - I'm using logIO set up as follows;

...and writing the results to a logfile.
However, the node also outputs the results to the debug panel, which I don't want.
Is there anyway we can disable logging to the debug panel, and just write the log to a file.

Under your Logger settings (called ping_results in your case) - click pencil and edit the configuration - there you can choose where to output logs from this logger.

Select the outputs you want from a list. Unselect Debugger panel to omit logs from NR debugger panel.

Doh! sorry, I don't now how I missed that :grimacing:
All good now.
Thanks

Hi, loving the progress.

I do have 2 feature requests that would make this even better.

  1. Add a meta (or logio) Symbol to the msg object so that I can inspect the msg to understand if it was an input or output msg. As it stands, I only know which is which by inspecting the messages header and the order of them.
  2. Add Mode "group". So that when it's placed in a group it logs all nodes in the group.

Clarification on point 1 (adding a symbol)
Adding meta data to the msg using a symbol means you dont risk overwriting any existing props (symbols are unique) e.g...

msg[Symbol('logio')] = { logId:  "1ae34509fe928", logName: "Log-io 1", type: "out", port: 1,  }

This means even if any node accidentally writes to msg.logio it wont be affected. More importantly, you can be safe in the knowledge you dont overwrite any important existing props in the msg

NOTE: there are 2 issues in Node-RED I just discovered. 1. Monaco is complaining about the use of symbols as indexes (everything still works by its not right!) . 2. Symbols are not displayed in the debug output (like they are in an IDE debugger like VSCode or DevTools) however, that wont stop you adding your own tracking symbols to the msg.

@steve-mcl Do symbols also stay attached when we fork a flow ( and clone a msg) ?

They do yes (ignore the red triangles - issue raised here: )

Here is a demo...

[{"id":"26eb128dd5f8f08f","type":"function","z":"218eb0e5cd8a4155","name":"Add a symbol (obj)","func":"\nmsg[Symbol('meta')] = { type: \"out\", port: 1,  }\n\n\nreturn msg;","outputs":1,"timeout":0,"noerr":1,"initialize":"","finalize":"","libs":[],"x":610,"y":360,"wires":[["85ac3b6d8f898b7e"]]},{"id":"9f8e05b96247f76d","type":"inject","z":"218eb0e5cd8a4155","name":"","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"","payloadType":"date","x":420,"y":360,"wires":[["26eb128dd5f8f08f"]]},{"id":"85ac3b6d8f898b7e","type":"function","z":"218eb0e5cd8a4155","name":"Add same name symbol (string)","func":"\nmsg[Symbol('meta')] = \"added by another node\"\n\nreturn msg;","outputs":1,"timeout":0,"noerr":1,"initialize":"","finalize":"","libs":[],"x":650,"y":420,"wires":[["aaec9ccb3b633316","6b4416b549369c24"]]},{"id":"aaec9ccb3b633316","type":"debug","z":"218eb0e5cd8a4155","name":"full msg","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":880,"y":420,"wires":[]},{"id":"6b4416b549369c24","type":"junction","z":"218eb0e5cd8a4155","x":420,"y":480,"wires":[["c029b11ef221f15b","7bf3dd2d37320bd2","4c19d96c1bb91be6"]]},{"id":"c029b11ef221f15b","type":"function","z":"218eb0e5cd8a4155","name":"enumerate symbols","func":"\nconst symbols = Object.getOwnPropertySymbols(msg)\nmsg.payload = { symbols: [] } \nsymbols.forEach(sym => {\n    msg.payload.symbols.push({\n        name: sym.description,\n        value: msg[sym]\n    })\n})\nreturn msg;","outputs":1,"timeout":0,"noerr":1,"initialize":"","finalize":"","libs":[],"x":670,"y":480,"wires":[["f7f3217c17ff24a0"]]},{"id":"7bf3dd2d37320bd2","type":"function","z":"218eb0e5cd8a4155","name":"enumerate symbols","func":"\nconst symbols = Object.getOwnPropertySymbols(msg)\nmsg.payload = { symbols: [] } \nsymbols.forEach(sym => {\n    msg.payload.symbols.push({\n        name: sym.description,\n        value: msg[sym]\n    })\n})\nreturn msg;","outputs":1,"timeout":0,"noerr":1,"initialize":"","finalize":"","libs":[],"x":670,"y":540,"wires":[["63015767bc55243c"]]},{"id":"4c19d96c1bb91be6","type":"function","z":"218eb0e5cd8a4155","name":"RED..clone","func":"\n\nreturn RED.util.cloneMessage(msg);;","outputs":1,"timeout":0,"noerr":0,"initialize":"","finalize":"","libs":[],"x":510,"y":620,"wires":[["dcfc4e95f350f5d5"]]},{"id":"f7f3217c17ff24a0","type":"debug","z":"218eb0e5cd8a4155","name":"","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"payload","targetType":"msg","statusVal":"","statusType":"auto","x":890,"y":480,"wires":[]},{"id":"63015767bc55243c","type":"debug","z":"218eb0e5cd8a4155","name":"","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"payload","targetType":"msg","statusVal":"","statusType":"auto","x":890,"y":540,"wires":[]},{"id":"dcfc4e95f350f5d5","type":"function","z":"218eb0e5cd8a4155","name":"enumerate symbols","func":"\nconst symbols = Object.getOwnPropertySymbols(msg)\nmsg.payload = { symbols: [] } \nsymbols.forEach(sym => {\n    msg.payload.symbols.push({\n        name: sym.description,\n        value: msg[sym]\n    })\n})\nreturn msg;","outputs":1,"timeout":0,"noerr":1,"initialize":"","finalize":"","libs":[],"x":690,"y":620,"wires":[["60d7d52e11151f3e"]]},{"id":"60d7d52e11151f3e","type":"debug","z":"218eb0e5cd8a4155","name":"","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"payload","targetType":"msg","statusVal":"","statusType":"auto","x":890,"y":620,"wires":[]}]

Hey @Steve-Mcl, regarding 1st request I was thinking on how to attach meta information in case logging to debugger panel but didn't come up with something reliable that would not involve attaching this information to message object. In all other outputs this is not a problem and this meta info can already be outputted, but with NR debugger I'd have to attach it to msg itself thus it was not supported. I'll look into this again. Your idea to use Symbols is good and I'll investigate on this, although I see you reported that keys represented by Symbols are not displayed in NR debugger.

2nd request is also a valid one but I see a bit of an overlap with wired mode. Would one tend to use nodes in a group that are not wired together? That would be the only difference between group and wired mode, so in group mode one logIO node would log I/O of every node in a group even if not wired together.

100%

For example, the catch & status nodes (which all support "group" mode) dont have input connections but are connected to the grouped nodes

Also, sometimes, you might have several related lines like this:

  • Group: Update page
    • timed inject (30 min) --> get ABC --> update page title
    • timed inject (10 min) --> get XYZ --> update page footer
    • timed inject (1 min) --> some-node-with-status --> update page body
    • status (all in group) --> function (parse status) --> switch (disconnected?) --> notify user

Makes sense. I'll add the 'group' mode.

1 Like

@Steve-Mcl would you expect that in group mode logIO logs I/O from nodes part of most inner group only or from all groups logIO is part of?

My 2 cents on this...

There is already group selection for status node. Don't know how far it applies inner/outer/outest.
Whatever it is, having the same behaviour would be good.

Group mode added in logIO version 1.3.0.

Regarding displaying meta information in debugger panel I'm still not sure how to do it.
I could attach it to a message obj to some prop, but that is only possible when whole message is displayed in a debugger panel.
But one can output an array or a primitive value to a debugger panel and in that case, meta data can't be attached to anything.

Sorry, haven't had a chance to try it out yet. Are you providing your own custom panel? If so, nothing stopping you either having the meta data in a tooltip (the Editor has jQueryUI so I think you have access to enhanced tooltips) or attached as a popup to an icon.