Having trouble with logging

Moving a discussion about logging from anther tread here as logging is a separate topic.

I am trying to understand how to get my node.warn messages and any error messages that show up in the side bar to log to a file for later analysis. This is being done on a Raspberry Pi running headless with Node-Red running as a service.
This is what I have in my settings.js file now:

     logging: {
        // Only console logging is currently supported
        console: {
            level: "trace",
            metrics: true,
            audit: false
        }

After modifying the file and restarting node red via `node-red-start' command, I get this at the console:

~/.node-red $ node-red-start

Start Node-RED

Once Node-RED has started, point a browser at http://192.168.2.247:1880
On Pi Node-RED works better with the Firefox or Chrome browser

Use   node-red-stop                          to stop Node-RED
Use   node-red-start                         to start Node-RED again
Use   node-red-log                           to view the recent log output
Use   sudo systemctl enable nodered.service  to autostart Node-RED at every boot
Use   sudo systemctl disable nodered.service to disable autostart on boot

To find more nodes and example flows - go to http://flows.nodered.org

Starting as a systemd service.
28 Oct 14:48:21 - [info]
Welcome to Node-RED
===================
28 Oct 14:48:21 - [info] Node-RED version: v3.0.2
28 Oct 14:48:21 - [info] Node.js  version: v14.20.1
28 Oct 14:48:21 - [info] Linux 5.15.65-v7+ arm LE
28 Oct 14:48:24 - [info] Loading palette nodes
28 Oct 14:48:26 - [debug] Module: @yadomi/node-red-contrib-philipshue-events 1.5.1 /home/pi/.node-red/node_modules/@yadomi/node-red-contrib-philipshue-events
28 Oct 14:48:26 - [debug] Module: node-red-contrib-average 0.1.7 /home/pi/.node-red/node_modules/node-red-contrib-average
28 Oct 14:48:26 - [debug] Module: node-red-contrib-comfort 1.2.0 /home/pi/.node-red/node_modules/node-red-contrib-comfort
28 Oct 14:48:26 - [debug] Module: node-red-contrib-date 0.0.2 /home/pi/.node-red/node_modules/node-red-contrib-date
28 Oct 14:48:26 - [debug] Module: node-red-contrib-fs 1.4.1 /home/pi/.node-red/node_modules/node-red-contrib-fs
28 Oct 14:48:26 - [debug] Module: node-red-contrib-fs-ops 1.6.0 /home/pi/.node-red/node_modules/node-red-contrib-fs-ops
28 Oct 14:48:26 - [debug] Module: node-red-contrib-ftp-download 1.0.4 /home/pi/.node-red/node_modules/node-red-contrib-ftp-download
28 Oct 14:48:26 - [debug] Module: node-red-contrib-google-sheets 0.1.0 /home/pi/.node-red/node_modules/node-red-contrib-google-sheets
28 Oct 14:48:26 - [debug] Module: node-red-contrib-hs100 1.0.2 /home/pi/.node-red/node_modules/node-red-contrib-hs100
28 Oct 14:48:26 - [debug] Module: node-red-contrib-lftp 0.3.0 /home/pi/.node-red/node_modules/node-red-contrib-lftp
28 Oct 14:48:26 - [debug] Module: node-red-contrib-moment 4.0.0 /home/pi/.node-red/node_modules/node-red-contrib-moment
28 Oct 14:48:26 - [debug] Module: node-red-contrib-moving-average 1.3.0 /home/pi/.node-red/node_modules/node-red-contrib-moving-average
28 Oct 14:48:26 - [debug] Module: node-red-contrib-openaq 0.0.5 /home/pi/.node-red/node_modules/node-red-contrib-openaq
28 Oct 14:48:26 - [debug] Module: node-red-contrib-play-audio 2.5.0 /home/pi/.node-red/node_modules/node-red-contrib-play-audio
28 Oct 14:48:26 - [debug] Module: node-red-contrib-polymer 0.0.22 /home/pi/.node-red/node_modules/node-red-contrib-polymer
28 Oct 14:48:26 - [debug] Module: node-red-contrib-semaphore 1.0.1 /home/pi/.node-red/node_modules/node-red-contrib-semaphore
28 Oct 14:48:26 - [debug] Module: node-red-contrib-smb 1.2.0 /home/pi/.node-red/node_modules/node-red-contrib-smb
28 Oct 14:48:26 - [debug] Module: node-red-contrib-tplink 1.0.0 /home/pi/.node-red/node_modules/node-red-contrib-tplink
28 Oct 14:48:26 - [debug] Module: node-red-contrib-tplink-iot 0.1.8 /home/pi/.node-red/node_modules/node-red-contrib-tplink-iot
28 Oct 14:48:26 - [debug] Module: node-red-contrib-ui-artless-gauge 0.3.11 /home/pi/.node-red/node_modules/node-red-contrib-ui-artless-gauge
28 Oct 14:48:26 - [debug] Module: node-red-contrib-ui-led 0.4.9 /home/pi/.node-red/node_modules/node-red-contrib-ui-led
28 Oct 14:48:26 - [debug] Module: node-red-contrib-unit-converter 0.0.2 /home/pi/.node-red/node_modules/node-red-contrib-unit-converter
28 Oct 14:48:26 - [debug] Module: node-red-contrib-viseo-google-authentication 0.1.1 /home/pi/.node-red/node_modules/node-red-contrib-viseo-google-authentication
28 Oct 14:48:26 - [debug] Module: node-red-contrib-viseo-google-spreadsheet 0.5.1 /home/pi/.node-red/node_modules/node-red-contrib-viseo-google-spreadsheet
28 Oct 14:48:26 - [debug] Module: node-red-contrib-wellness 0.0.10 /home/pi/.node-red/node_modules/node-red-contrib-wellness
28 Oct 14:48:26 - [debug] Module: node-red-dashboard 2.28.2 /home/pi/.node-red/node_modules/node-red-dashboard
28 Oct 14:48:26 - [debug] Module: node-red-hxtx-ftp 0.0.14 /home/pi/.node-red/node_modules/node-red-hxtx-ftp
28 Oct 14:48:26 - [debug] Module: node-red-node-pi-gpio 1.2.3 /home/pi/.node-red/node_modules/node-red-node-pi-gpio
28 Oct 14:48:26 - [debug] Module: node-red-node-ping 0.3.1 /home/pi/.node-red/node_modules/node-red-node-ping
28 Oct 14:48:26 - [debug] Module: node-red-node-pushover 0.0.24 /home/pi/.node-red/node_modules/node-red-node-pushover
28 Oct 14:48:26 - [debug] Module: node-red-node-random 0.4.0 /home/pi/.node-red/node_modules/node-red-node-random
28 Oct 14:48:26 - [debug] Module: node-red-node-serialport 0.14.1 /home/pi/.node-red/node_modules/node-red-node-serialport
28 Oct 14:48:26 - [debug] Module: node-red-node-smooth 0.1.2 /home/pi/.node-red/node_modules/node-red-node-smooth
28 Oct 14:48:26 - [debug] Module: node-red-node-ui-lineargauge 0.3.6 /home/pi/.node-red/node_modules/node-red-node-ui-lineargauge
/bin/sh: 1: /home/pi/.node-red/node_modules/node-red-node-pi-gpio/testgpio.py: not found

I created a function node with just a node.warn() statement, connected an inject node into that and tried injecting a message 10 times then used node-red-log to see if anything got logged.

~/.node-red $ node-red-log


28 Oct 14:48:26 - [debug] Module: node-red-contrib-moment 4.0.0 /home/pi/.node-red/node_modules/node-red-contrib-moment
28 Oct 14:48:26 - [debug] Module: node-red-contrib-moving-average 1.3.0 /home/pi/.node-red/node_modules/node-red-contrib-moving-average
28 Oct 14:48:26 - [debug] Module: node-red-contrib-openaq 0.0.5 /home/pi/.node-red/node_modules/node-red-contrib-openaq
28 Oct 14:48:26 - [debug] Module: node-red-contrib-play-audio 2.5.0 /home/pi/.node-red/node_modules/node-red-contrib-play-audio
28 Oct 14:48:26 - [debug] Module: node-red-contrib-polymer 0.0.22 /home/pi/.node-red/node_modules/node-red-contrib-polymer
28 Oct 14:48:26 - [debug] Module: node-red-contrib-semaphore 1.0.1 /home/pi/.node-red/node_modules/node-red-contrib-semaphore
28 Oct 14:48:26 - [debug] Module: node-red-contrib-smb 1.2.0 /home/pi/.node-red/node_modules/node-red-contrib-smb
28 Oct 14:48:26 - [debug] Module: node-red-contrib-tplink 1.0.0 /home/pi/.node-red/node_modules/node-red-contrib-tplink
28 Oct 14:48:26 - [debug] Module: node-red-contrib-tplink-iot 0.1.8 /home/pi/.node-red/node_modules/node-red-contrib-tplink-iot
28 Oct 14:48:26 - [debug] Module: node-red-contrib-ui-artless-gauge 0.3.11 /home/pi/.node-red/node_modules/node-red-contrib-ui-artless-gauge
28 Oct 14:48:26 - [debug] Module: node-red-contrib-ui-led 0.4.9 /home/pi/.node-red/node_modules/node-red-contrib-ui-led
28 Oct 14:48:26 - [debug] Module: node-red-contrib-unit-converter 0.0.2 /home/pi/.node-red/node_modules/node-red-contrib-unit-converter
28 Oct 14:48:26 - [debug] Module: node-red-contrib-viseo-google-authentication 0.1.1 /home/pi/.node-red/node_modules/node-red-contrib-viseo-google-authentication
28 Oct 14:48:26 - [debug] Module: node-red-contrib-viseo-google-spreadsheet 0.5.1 /home/pi/.node-red/node_modules/node-red-contrib-viseo-google-spreadsheet
28 Oct 14:48:26 - [debug] Module: node-red-contrib-wellness 0.0.10 /home/pi/.node-red/node_modules/node-red-contrib-wellness
28 Oct 14:48:26 - [debug] Module: node-red-dashboard 2.28.2 /home/pi/.node-red/node_modules/node-red-dashboard
28 Oct 14:48:26 - [debug] Module: node-red-hxtx-ftp 0.0.14 /home/pi/.node-red/node_modules/node-red-hxtx-ftp
28 Oct 14:48:26 - [debug] Module: node-red-node-pi-gpio 1.2.3 /home/pi/.node-red/node_modules/node-red-node-pi-gpio
28 Oct 14:48:26 - [debug] Module: node-red-node-ping 0.3.1 /home/pi/.node-red/node_modules/node-red-node-ping
28 Oct 14:48:26 - [debug] Module: node-red-node-pushover 0.0.24 /home/pi/.node-red/node_modules/node-red-node-pushover
28 Oct 14:48:26 - [debug] Module: node-red-node-random 0.4.0 /home/pi/.node-red/node_modules/node-red-node-random
28 Oct 14:48:26 - [debug] Module: node-red-node-serialport 0.14.1 /home/pi/.node-red/node_modules/node-red-node-serialport
28 Oct 14:48:26 - [debug] Module: node-red-node-smooth 0.1.2 /home/pi/.node-red/node_modules/node-red-node-smooth
28 Oct 14:48:26 - [debug] Module: node-red-node-ui-lineargauge 0.3.6 /home/pi/.node-red/node_modules/node-red-node-ui-lineargauge
/bin/sh: 1: /home/pi/.node-red/node_modules/node-red-node-pi-gpio/testgpio.py: not found

I am trying to understand how I can record the warn and error messages from a flow I'm troubleshooting that is experiencing an intermittent problem. Because it's intermittent, being able to have logs is important for the troubleshooting process.

and your settings.js file is???????

Fixed the snippet, I inadvertently hit a key and you found my message while I was fixing things

1 Like

I just tried this in my function node:

node.warn("hi from node.warn")
node.log("hi from node.log")
return msg;

and in settings.js, I commented out metrics and audit so my log settings are:

         console: {
             /** Level of logging to be recorded. Options are:
              * fatal - only those errors which make the application unusable should be recorded
              * error - record errors which are deemed fatal for a particular request + fatal errors
              * warn - record problems which are non fatal + errors + fatal errors
              * info - record information about the general running of the application + warn + error + fatal errors
              * debug - record information which is more verbose than info + info + warn + error + fatal errors
              * trace - record very detailed logging + debug + info + warn + error + fatal errors
              * off - turn off all logging (doesn't affect metrics or audit)
              */
//             level: "info",
             level: "trace"
             /** Whether or not to include metric events in the log output */
//             metrics: false,
             /** Whether or not to include audit events in the log output */
//             audit: false
         }

and this shows up in the log starting NR with just 'node-red':

28 Oct 19:37:50 - [warn] [function:function 7] hi from node.warn
28 Oct 19:37:50 - [info] [function:function 7] hi from node.log

so I stoped and started node-red with 'node-red-start' and get this:

28 Oct 19:41:54 - [info] Started flows
28 Oct 19:41:54 - [info] [sqlitedb:b48607bf.623f88] opened /home/pi/databases/hvac4.db ok
28 Oct 19:41:54 - [info] [mqtt-broker:mqttpizw] Connected to broker: mqtt://192.168.48.70:1883
28 Oct 19:41:54 - [trace] comms.open U9SrUUNHtp8oqMskHLcwp5afGWE7GDNrr2VVADeYEXs=
28 Oct 19:41:55 - [trace] git["rev-list","HEAD","--count"]
28 Oct 19:41:55 - [trace] git["log","--format=sha: %H%nparents: %p%nrefs: %D%nauthor: %an%ndate: %ct%nsubject: %s%n-----","-n 20"]
28 Oct 19:41:55 - [trace] git["rev-list","HEAD","--count"]
28 Oct 19:41:56 - [trace] git["ls-files","--cached","--others","--exclude-standard"]
28 Oct 19:41:56 - [trace] git["status","--porcelain","-b"]
28 Oct 19:41:59 - [warn] [function:function 7] hi from node.warn
28 Oct 19:41:59 - [info] [function:function 7] hi from node.log

so I uncommented metrics and audits and I still see the outputs in the log.

It could be that it is there but too much other info is being dumped to the log so you miss it.

Sorry the video is a shaky phone video. I don't have proper screen capture set up right now. I figure a quick video will illustrate what I'm doing and perhaps that will reveal what is is I have wrong.

/bin/sh: 1: /home/pi/.node-red/node_modules/node-red-node-pi-gpio/testgpio.py: not found

Does node-red crash and restart after this line ?

No, it seems to run fine which is why I've ignored it. I figured it's related to Raspberry Pi GPIOs which I'm not using so I haven't bothered to try and resolve that error.

Another thing to try is to rename your .node-red directory temporarily. Then restart node red which will create a new directory with everything back at default settings. Then try node.warn() again.

Unfortunately starting with a default settings.js didn't work unless logging is impacted by adding an extra context store.

Could it be a version thing? I'm running on a Raspberry Pi which has some special consideration and needs special install scripts. The documentation mentions some considerations for the Pi's limited RAM. Is there a way to check if there is some deeper configuration that was modified to accommodate the idiosyncrasies of either the Raspberry Pi platform or its custom distro?

I didn't say to do that, I said to rename the .node-red directory so you start from scratch.

If it still doesn't work show us the startup log when you start node red after renaming .node-red