ZWaveJSController - Warning/Error Traceback - Registering action set volume for Aeotec Siren 6 (ZW164)

[toggledbits]

Wait, I'm really confused, you said "nothing is being logged there after stop ,start". Then where did the stuff you posted here come from?

[Matteburk]

@toggledbits they that you refer to are there but nothing after I now stopped and started

[Matteburk]

@toggledbits But if I no try to start via node app.js
I get in terminal window

pi@raspberrypi:~ $ node app.js
internal/modules/cjs/loader.js:883
throw err;
^

Error: Cannot find module '/home/pi/app.js'
at Function.Module._resolveFilename (internal/modules/cjs/loader.js:880:15)
at Function.Module._load (internal/modules/cjs/loader.js:725:27)
at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:72:12)
at internal/main/run_main_module.js:17:47 {
code: 'MODULE_NOT_FOUND',
requireStack: []
}
pi@raspberrypi:~ $

[toggledbits]

Well that's because you're not in the Reactor directory.

[Matteburk]

@toggledbits
Gaaah..... im tired and beginner.....Sorry....

ok so this I no get when I run node app.js

2021-09-06T19:59:36.893Z Rule:5:980:Rule.js Rule#rule-kmst5xze._evaluate() mutex acquired, evaluating
2021-09-06T19:59:36.894Z Rule:5:984:Rule.js Rule#rule-kmst5xze update rate is 1/min limit 60/min
2021-09-06T19:59:36.895Z Rule:5:904:Rule.js Rule#rule-kmst5xze evaluateExpressions() with 0 expressions
2021-09-06T19:59:36.897Z Rule:CRIT Error: Cannot find module 'common/util'
Require stack:

• /home/pi/reactor/server/lib/Engine.js
• /home/pi/reactor/server/lib/httpapi.js
• /home/pi/reactor/app.js
  Error: Cannot find module 'common/util'
  Require stack:
• /home/pi/reactor/server/lib/Engine.js
• /home/pi/reactor/server/lib/httpapi.js
• /home/pi/reactor/app.js
  at Function.Module._resolveFilename (internal/modules/cjs/loader.js:880:15)
  at Function.Module._load (internal/modules/cjs/loader.js:725:27)
  at Module.require (internal/modules/cjs/loader.js:952:19)
  at require (internal/modules/cjs/helpers.js:88:18)
  at Engine._get_lexp_extensions (/home/pi/reactor/server/lib/Engine.js:862:25)
  at Rule.evaluateExpressions (/home/pi/reactor/server/lib/Rule.js:904:330)
  at Rule._evaluate (/home/pi/reactor/server/lib/Rule.js:994:344)
  at processTicksAndRejections (internal/process/task_queues.js:93:5)
  at async /home/pi/reactor/server/lib/Rule.js:963:17

[toggledbits]

Right. And we've covered that. If you run it from the command line, you need to use

    NODE_PATH=$(pwd) node app

Do that, and please post (a) the startup messages from logs/reactor.log as specified in my previous post, and (b) the contents of /etc/systemd/system/reactor.service again.

[Matteburk]

@toggledbits

We have a winner!

I did
cd reactor
NODE_PATH=$(pwd) node app ( this line I totally missed)

and my house lit up like a Christmas trea!

Thank you for your patience with me Patrick!

[toggledbits]

No, we're not done. That's not the way to run Reactor. You need to be running it under systemd. Please provide the information above as requested.

[Matteburk]

@toggledbits
hehe.... went exited

/etc/systemd/system/reactor.service......

[Unit]
Description=Multi System Reactor
After=network.target

[Service]
Type=simple
User=pi
WorkingDirectory=/home/pi/reactor
Environment=NODE_PATH=/home/pi/reactor
ExecStart=/home/pi/.local/lib/nodejs/node-v14.15.4-linux-armv7l/bin/node



Restart=on-failure
RestartSec=5s

[Install]
WantedBy=multi-user.target

Reactor log......

2021-09-06T20:07:08.063Z <app:null> Reactor "1.0.1-21243-ab6d917" starting on v14.15.4
2021-09-06T20:07:08.066Z <app:INFO> Process ID 3029; platform linux/arm #1408 SMP Mon Mar 22 12:49:24 GMT 2021; locale [ "sv-SE", "UTF-8" ]
2021-09-06T20:07:08.067Z <app:INFO> Basedir /home/pi/reactor; data in /home/pi/reactor/storage
2021-09-06T20:07:08.067Z <app:INFO> NODE_PATH /home/pi/reactor; module paths [ "/home/pi/reactor/node_modules", "/home/pi/node_modules", "/home/node_modules", "/node_modules" ]
2021-09-06T20:07:08.241Z <Plugin:null> Module Plugin v21173
2021-09-06T20:07:08.273Z <default:INFO> Module Entity v21177
2021-09-06T20:07:08.284Z <Controller:null> Module Controller v21226
2021-09-06T20:07:08.286Z <default:null> Module Structure v21229
2021-09-06T20:07:08.305Z <default:null> Module Ruleset v21096
2021-09-06T20:07:08.306Z <default:null> Module Rulesets v21096
2021-09-06T20:07:08.380Z <default:null> Module Rule v21224
2021-09-06T20:07:08.397Z <default:null> Module Engine v21213
2021-09-06T20:07:08.399Z <default:null> Module httpapi v21238
2021-09-06T20:07:08.406Z <default:null> Module httpproxy v21054
2021-09-06T20:07:08.450Z <default:null> Module wsapi v21196
2021-09-06T20:07:08.454Z <app:NOTICE> Starting Structure...
2021-09-06T20:07:08.463Z <Structure:INFO> Structure#1 starting controller interface vera (VeraController)
2021-09-06T20:07:08.473Z <Structure:INFO> Structure#1 starting controller interface hubitat (HubitatController)
2021-09-06T20:07:08.480Z <Structure:INFO> Structure#1 starting controller interface reactor_system (SystemController)
2021-09-06T20:07:08.622Z <default:null> Module VeraController v21236
2021-09-06T20:07:08.629Z <default:null> Module HubitatController v21243
2021-09-06T20:07:08.632Z <default:null> Module SystemController v21102
2021-09-06T20:07:08.642Z <VeraController:NOTICE> VeraController#vera starting
2021-09-06T20:07:08.765Z <VeraController:INFO> VeraController#vera loaded mapping ver 21236 rev 1 format 1 notice 
2021-09-06T20:07:08.767Z <VeraController:INFO> VeraController: deviceclass vera_system_object capability sys_system does not provide attribute state
2021-09-06T20:07:08.887Z <Controller:NOTICE> Controller SystemController#reactor_system is now online.
2021-09-06T20:07:09.035Z <app:INFO> Structure running; pausing for controllers' initial ready
2021-09-06T20:07:09.044Z <Controller:NOTICE> HubitatController#hubitat not ready; performing initial connect/query
2021-09-06T20:07:09.629Z <VeraController:NOTICE> Controller VeraController#vera is now online.
2021-09-06T20:07:10.118Z <Controller:ERR> HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T20:07:10.158Z <Controller:ERR> HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T20:07:10.274Z <Controller:ERR> HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T20:07:10.281Z <Controller:ERR> HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T20:07:10.287Z <Controller:ERR> HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T20:07:10.289Z <Controller:ERR> HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T20:07:10.318Z <Controller:ERR> HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T20:07:10.326Z <Controller:ERR> HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T20:07:10.331Z <Controller:ERR> HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T20:07:10.478Z <Controller:INFO> HubitatController#hubitat connecting to hub's eventsocket WebSocket API at ws://192.168.68.145/eventsocket
2021-09-06T20:07:10.484Z <Controller:NOTICE> Controller HubitatController#hubitat is now online.
2021-09-06T20:07:10.489Z <app:NOTICE> Starting Reaction Engine...
2021-09-06T20:07:10.491Z <Engine:INFO> Reaction Engine starting
2021-09-06T20:07:10.492Z <Engine:INFO> Checking rule sets...
2021-09-06T20:07:10.504Z <Engine:INFO> Checking rules...
2021-09-06T20:07:10.506Z <Engine:INFO> Data check complete; no corrections.

[toggledbits]

OK. Looks good.

First, make sure your command line Reactor is stopped. This is important, obviously, as the systemd Reactor will not start and keep trying to start if your command line Reactor is still running. Also, let's remove the existing Reactor log file:

    rm /home/pi/reactor/logs/reactor.log

Then, sudo systemctl daemon-reload

Then, sudo systemctl restart reactor

Then try to get into the Reactor UI. If you can't get into the UI, look at the reactor.log file for messages. In you still have the "common/util" exception, go up to the startup lines and look at what it reports for NODE_PATH and post that here.

[Matteburk]

@toggledbits Could not reach thrue UI .

The reactor.log file is no missing since the rm command.....

[toggledbits]

OK. Then /var/log/syslog

And tell me, how did you edit the service file? There are some excess blank lines in what you posted when I got it formatted as code on the forums... that's... odd... did you edit it on the system, or did you pull it up to a Mac or Windows, edit it, and then push it down? Or something else?

[Matteburk]

I edited them directly on the pie in the textfile.

this is what the var log file said:

Sep 6 22:17:23 raspberrypi dhcpcd[428]: wlan0: fe80::465:fde6:f33:2344 is reachable again
Sep 6 22:17:23 raspberrypi avahi-daemon[429]: Withdrawing address record for fe80::2598:15e9:620:fe7d on eth0.
Sep 6 22:17:26 raspberrypi dhcpcd[428]: eth0: leased 192.168.68.126 for 7200 seconds
Sep 6 22:17:26 raspberrypi avahi-daemon[429]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.68.126.
Sep 6 22:17:26 raspberrypi dhcpcd[428]: eth0: adding route to 192.168.68.0/24
Sep 6 22:17:26 raspberrypi dhcpcd[428]: eth0: adding default route via 192.168.68.1
Sep 6 22:17:26 raspberrypi avahi-daemon[429]: New relevant interface eth0.IPv4 for mDNS.
Sep 6 22:17:26 raspberrypi avahi-daemon[429]: Registering new address record for 192.168.68.126 on eth0.IPv4.
Sep 6 22:17:34 raspberrypi systemd[1]: systemd-fsckd.service: Succeeded.
Sep 6 22:50:34 raspberrypi systemd-timesyncd[339]: Synchronized to time server for the first time 178.16.128.13:123 (2.debian.pool.ntp.org).
Sep 6 22:50:41 raspberrypi systemd[1]: systemd-hostnamed.service: Succeeded.
Sep 6 22:53:32 raspberrypi dbus-daemon[626]: [session uid=1000 pid=626] Activating service name='ca.desrt.dconf' requested by ':1.28' (uid=1000 pid=1084 comm="mousepad /var/log/syslog ")
Sep 6 22:53:32 raspberrypi dbus-daemon[626]: [session uid=1000 pid=626] Successfully activated service 'ca.desrt.dconf'
Sep 6 22:54:50 raspberrypi dbus-daemon[418]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.51' (uid=1000 pid=1100 comm="/usr/lib/chromium-browser/chromium-browser-v7 --fo")
Sep 6 22:54:50 raspberrypi systemd[1]: Starting Hostname Service...
Sep 6 22:54:50 raspberrypi dbus-daemon[418]: [system] Successfully activated service 'org.freedesktop.hostname1'
Sep 6 22:54:50 raspberrypi systemd[1]: Started Hostname Service.
Sep 6 22:54:50 raspberrypi gvfsd[665]: mkdir failed on directory /var/cache/samba: Åtkomst nekas
Sep 6 22:54:50 raspberrypi gvfsd[665]: mkdir failed on directory /var/cache/samba: Åtkomst nekas
Sep 6 22:54:51 raspberrypi gvfsd[665]: mkdir failed on directory /var/cache/samba: Åtkomst nekas
Sep 6 22:54:51 raspberrypi gvfsd[665]: mkdir failed on directory /var/cache/samba: Åtkomst nekas
Sep 6 22:54:52 raspberrypi gvfsd[665]: mkdir failed on directory /var/cache/samba: Åtkomst nekas
Sep 6 22:54:52 raspberrypi gvfsd[665]: mkdir failed on directory /var/cache/samba: Åtkomst nekas
Sep 6 22:54:53 raspberrypi gvfsd[665]: mkdir failed on directory /var/cache/samba: Åtkomst nekas
Sep 6 22:54:53 raspberrypi gvfsd[665]: mkdir failed on directory /var/cache/samba: Åtkomst nekas
Sep 6 22:54:54 raspberrypi gvfsd[665]: mkdir failed on directory /var/cache/samba: Åtkomst nekas
Sep 6 22:54:54 raspberrypi gvfsd[665]: mkdir failed on directory /var/cache/samba: Åtkomst nekas
Sep 6 22:54:55 raspberrypi gvfsd[665]: mkdir failed on directory /var/cache/samba: Åtkomst nekas
Sep 6 22:54:55 raspberrypi gvfsd[665]: mkdir failed on directory /var/cache/samba: Åtkomst nekas

[toggledbits]

I just noticed, the ExecStart line in your edited service file is incomplete. It should read:

    ExecStart=/home/pi/.local/lib/nodejs/node-v14.15.4-linux-armv7l/bin/node app -p

Fix that. Then do:

    sudo systemctl daemon-reload
    sudo systemctl restart reactor

[Matteburk]

@toggledbits said in Updated to latest MSR 21243 and no entities are being executed I Hubitat:

ExecStart=/home/pi/.local/lib/nodejs/node-v14.15.4-linux-armv7l/bin/node app -p

Changed it and now i can reach msr thrue UI!

Here is the reactor.log

2021-09-06T21:05:42.633Z app:null Reactor "1.0.1-21243-ab6d917" starting on v14.15.4
2021-09-06T21:05:42.636Z app:INFO Process ID 1780; platform linux/arm #1408 SMP Mon Mar 22 12:49:24 GMT 2021; locale [ "sv-SE", "UTF-8" ]
2021-09-06T21:05:42.637Z app:INFO Basedir /home/pi/reactor; data in /home/pi/reactor/storage
2021-09-06T21:05:42.637Z app:INFO NODE_PATH /home/pi/reactor; module paths [ "/home/pi/reactor/node_modules", "/home/pi/node_modules", "/home/node_modules", "/node_modules" ]
2021-09-06T21:05:42.781Z Plugin:null Module Plugin v21173
2021-09-06T21:05:42.797Z default:INFO Module Entity v21177
2021-09-06T21:05:42.805Z Controller:null Module Controller v21226
2021-09-06T21:05:42.806Z default:null Module Structure v21229
2021-09-06T21:05:42.822Z default:null Module Ruleset v21096
2021-09-06T21:05:42.823Z default:null Module Rulesets v21096
2021-09-06T21:05:42.869Z default:null Module Rule v21224
2021-09-06T21:05:42.880Z default:null Module Engine v21213
2021-09-06T21:05:42.881Z default:null Module httpapi v21238
2021-09-06T21:05:42.886Z default:null Module httpproxy v21054
2021-09-06T21:05:42.925Z default:null Module wsapi v21196
2021-09-06T21:05:42.928Z app:NOTICE Starting Structure...
2021-09-06T21:05:42.936Z Structure:INFO Structure#1 starting controller interface vera (VeraController)
2021-09-06T21:05:42.944Z Structure:INFO Structure#1 starting controller interface hubitat (HubitatController)
2021-09-06T21:05:42.947Z Structure:INFO Structure#1 starting controller interface reactor_system (SystemController)
2021-09-06T21:05:43.018Z default:null Module VeraController v21236
2021-09-06T21:05:43.026Z default:null Module HubitatController v21243
2021-09-06T21:05:43.029Z default:null Module SystemController v21102
2021-09-06T21:05:43.037Z VeraController:NOTICE VeraController#vera starting
2021-09-06T21:05:43.145Z VeraController:INFO VeraController#vera loaded mapping ver 21236 rev 1 format 1 notice
2021-09-06T21:05:43.148Z VeraController:INFO VeraController: deviceclass vera_system_object capability sys_system does not provide attribute state
2021-09-06T21:05:43.227Z Controller:NOTICE Controller SystemController#reactor_system is now online.
2021-09-06T21:05:43.339Z app:INFO Structure running; pausing for controllers' initial ready
2021-09-06T21:05:43.347Z Controller:NOTICE HubitatController#hubitat not ready; performing initial connect/query
2021-09-06T21:05:43.896Z VeraController:NOTICE Controller VeraController#vera is now online.
2021-09-06T21:05:45.291Z Controller:ERR HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T21:05:45.322Z Controller:ERR HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T21:05:45.383Z Controller:ERR HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T21:05:45.387Z Controller:ERR HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T21:05:45.391Z Controller:ERR HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T21:05:45.394Z Controller:ERR HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T21:05:45.409Z Controller:ERR HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T21:05:45.414Z Controller:ERR HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T21:05:45.418Z Controller:ERR HubitatController#hubitat mapped capability x_hubitat_healthcheck has no implementation
2021-09-06T21:05:45.510Z Controller:INFO HubitatController#hubitat connecting to hub's eventsocket WebSocket API at ws://192.168.68.145/eventsocket
2021-09-06T21:05:45.517Z Controller:NOTICE Controller HubitatController#hubitat is now online.
2021-09-06T21:05:45.522Z app:NOTICE Starting Reaction Engine...
2021-09-06T21:05:45.524Z Engine:INFO Reaction Engine starting
2021-09-06T21:05:45.525Z Engine:INFO Checking rule sets...
2021-09-06T21:05:45.542Z Engine:INFO Checking rules...
2021-09-06T21:05:45.544Z Engine:INFO Data check complete; no corrections.

[toggledbits]

That's better. OK, no more command line. Do this as well:

    sudo systemctl enable reactor

This will tell systemd to start Reactor at boot (which you should then test). If you have any other mechanism for starting Reactor at boot (e.g. modified .profile or bashrc files), then those will need to be removed/disabled.

[Matteburk]

ok... what does that line do?

got this
pi@raspberrypi:~ $ sudo systemctl enable reactor
Created symlink /etc/systemd/system/multi-user.target.wants/reactor.service \u2192 /etc/systemd/system/reactor.service.
pi@raspberrypi:~ $

[toggledbits]

@toggledbits said in Updated to latest MSR 21243 and no entities are being executed I Hubitat:

This will tell systemd to start Reactor at boot (which you should then test). If you have any other mechanism for starting Reactor at boot (e.g. modified .profile or bashrc files), then those will need to be removed/disabled.

[Matteburk]

@toggledbits
ok.... I cut the power and restarted the pie and msr got up by it self!!

Coool!

[toggledbits]

Noice! OK. You're on your way! NOW we're finished!