Updated to latest MSR 21243 and no entities are being executed I Hubitat
-
The messages in the log you posted indicate that NODE_PATH is incorrectly set, so I now cannot be sure if we're back at your original problem because you have tried to run it from the command line and this log is from that, or if this log is from an attempted systemd startup, which makes no sense because the service file you published earlier sets the environment variable correctly.
I've given you everything you need to get going again. I'm not sure what else to do. You need to figure it out, though, because this is how this and all future builds will be working, and right now, you're the only person I know of that isn't running, so I'm assuming its a local configuration issue and not a package/software issue.
Can you stop any local startup, start again with systemd, and post the startup portion of the log file? I don't want to see the error message again, I need to see all the messages from a Reactor startup under systemd. That will start with the string
Reactor <version> starting on <nodejs version>and give me everything up toStartup complete.@toggledbits
I dont see the string reactor version starting on XXXX as you wrote.From the var/log syslog I get this after stopped and started reactor via systemctl restart reactor
Sep 6 20:58:49 raspberrypi systemd[1]: Started Multi System Reactor.
Sep 6 20:58:50 raspberrypi systemd[1]: reactor.service: Succeeded.
Sep 6 21:00:41 raspberrypi dbus-daemon[402]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.57' (uid=1000 pid=1071 comm="/usr/lib/chromium-browser/chromium-browser-v7 --fo")
Sep 6 21:00:41 raspberrypi systemd[1]: Starting Hostname Service...
Sep 6 21:00:41 raspberrypi dbus-daemon[402]: [system] Successfully activated service 'org.freedesktop.hostname1'
Sep 6 21:00:41 raspberrypi systemd[1]: Started Hostname Service. -
In
reactor.log -
In
reactor.log@toggledbits
hmmm nothing is being logged there after stop ,start. the log file has not been updated since I tried node app.js for a couple of hours ago -
OK. Post that startup, then. It will tell me a few things as well.
-
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?
-
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?
@toggledbits they that you refer to are there but nothing after I now stopped and started
-
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?
@toggledbits But if I no try to start via node app.js
I get in terminal windowpi@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:~ $ -
Well that's because you're not in the Reactor directory.
-
Well that's because you're not in the Reactor directory.
@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
-
Right. And we've covered that. If you run it from the command line, you need to use
NODE_PATH=$(pwd) node appDo that, and please post (a) the startup messages from
logs/reactor.logas specified in my previous post, and (b) the contents of/etc/systemd/system/reactor.serviceagain. -
Right. And we've covered that. If you run it from the command line, you need to use
NODE_PATH=$(pwd) node appDo that, and please post (a) the startup messages from
logs/reactor.logas specified in my previous post, and (b) the contents of/etc/systemd/system/reactor.serviceagain.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!
-
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.
-
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.
@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.targetReactor 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. -
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.logThen,
sudo systemctl daemon-reloadThen,
sudo systemctl restart reactorThen try to get into the Reactor UI. If you can't get into the UI, look at the
reactor.logfile 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. -
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.logThen,
sudo systemctl daemon-reloadThen,
sudo systemctl restart reactorThen try to get into the Reactor UI. If you can't get into the UI, look at the
reactor.logfile 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.@toggledbits Could not reach thrue UI .
The reactor.log file is no missing since the rm command.....
-
OK. Then
/var/log/syslogAnd 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?
-
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 -
I just noticed, the
ExecStartline 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 -pFix that. Then do:
sudo systemctl daemon-reload sudo systemctl restart reactor -
I just noticed, the
ExecStartline 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 -pFix that. Then do:
sudo systemctl daemon-reload sudo systemctl restart reactor@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. -
That's better. OK, no more command line. Do this as well:
sudo systemctl enable reactorThis 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.