As usual, you nailed it!

With a dimming.step of 0.03, it does a very nice gradation.

Many thanks

Loaded the new built and as expected, the dimming.up/down are working for all levels. I also noticed that the dimming.level reported are nicely round up to one digit after the "." except for 50% where it displays "0.51" (not really an isssue just reporting what I see)

However, the other issue mentionned my opening post (that got kind of forgotten) is still present. Here is the refference:

said in Gradually turn on lights.:

1- The "dimming.step" when changed does not stick after a dimming.up/down

In the "Entities" menu I set the attribute "dimming.step" to 0.05. Still in the etities menu, I then perform a "dimming.up" and can confirm that indeed the "dimming.level" went up by 0.05 however at the same time the dimming.step goes back to 0.1 (default). From that point, any subsequent "dimming.up" uses the default.

Again, this can wait until your next release if a fix is indeed needed.

@toggledbits Thank you for looking into this.

There is absolutely no rush on any of this on my side. When I read the post I really liked the approach you suggested and made a test rule to see how I could use it and got into some issues.

Since you took the time to make an interim built, I will take the time to test it and report back here with the result. This way, you will know the status when you return.

Thanks again

Hi,

The dimming.maximum/minimum are set to 1 and 0

@toggledbits said in Gradually turn on lights.:

Failing that, does the device itself have min/max set in its Z-Wave configuration?

Not sure exactely how to check this. The device is a Zooz ZEN 72. I look in the Z-Wave JS UI and could not find any parameter that would limit the dimming min/max.

I might be wrong here but it is my understanding that the Z-Wave JS UI sits between HA and the devices. Since the Z-Wave JS UI log shows that any level change request above 60 from MSR, stays at 60, it can only be coming from MSR or HA. In addition the dimming.set works without any issues.

Hi again, more accurate info for the "Perform dimming.up/down"

I have just made a test from the entity menu. Using the default dimming.step (0.1) I did the following starting with the dimmer off:

1- Perform dimming.up 10 times

This should have brought the dimmer to 100% but it did stop at 60% (0.59...)

2- Perform dimming.down 10 times

This should have brought the dimmer to 0% but it did stop at 50%

From 100%, I can only dimmed.down to 50%
from 0%, I can only dimmed.up to 60% (0.59)

The dimming.set "value" works all the time

Here is the log from Z-Wave JS for the 10x dimming.up followed by the 10x dimming.down test.

2025-07-07 23:32:00.315 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 0 => 10
2025-07-07 23:32:00.328 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 10 => 10
2025-07-07 23:32:03.828 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 10 => 20
2025-07-07 23:32:03.834 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 10 => 20
2025-07-07 23:32:03.854 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 20 => 20
2025-07-07 23:32:06.007 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 20 => 30
2025-07-07 23:32:06.014 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 20 => 30
2025-07-07 23:32:06.045 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 30 => 30
2025-07-07 23:32:08.149 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 30 => 40
2025-07-07 23:32:08.152 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 30 => 40
2025-07-07 23:32:08.165 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 40 => 40
2025-07-07 23:32:10.289 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 40 => 50
2025-07-07 23:32:10.295 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 40 => 50
2025-07-07 23:32:10.308 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:12.397 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 50 => 59
2025-07-07 23:32:12.401 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 59
2025-07-07 23:32:12.416 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 59 => 59
2025-07-07 23:32:14.848 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 59 => 59
2025-07-07 23:32:14.853 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 59 => 59
2025-07-07 23:32:14.866 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 59 => 59
2025-07-07 23:32:16.744 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 59 => 59
2025-07-07 23:32:16.749 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 59 => 59
2025-07-07 23:32:16.762 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 59 => 59
2025-07-07 23:32:18.651 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 59 => 59
2025-07-07 23:32:18.654 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 59 => 59
2025-07-07 23:32:18.665 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 59 => 59
2025-07-07 23:32:20.649 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 59 => 59
2025-07-07 23:32:20.652 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 59 => 59
2025-07-07 23:32:20.661 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 59 => 59
2025-07-07 23:32:22.864 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 59 => 50
2025-07-07 23:32:22.870 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 59 => 50
2025-07-07 23:32:22.881 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:26.963 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 50 => 50
2025-07-07 23:32:26.966 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:26.975 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:29.030 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 50 => 50
2025-07-07 23:32:29.035 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:29.052 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:31.234 DEBUG Z-WAVE: Polling value 49-0-Air temperature
2025-07-07 23:32:31.289 INFO Z-WAVE: [Node 036] Metadata updated: 49-0-Air temperature
2025-07-07 23:32:31.292 INFO Z-WAVE: [Node 036] Value updated: 49-0-Air temperature 24 => 24
2025-07-07 23:32:31.297 DEBUG Z-WAVE: 36-49-0-Air temperature will be polled in 60 seconds
2025-07-07 23:32:31.715 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 50 => 50
2025-07-07 23:32:31.718 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:31.727 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:34.557 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 50 => 50
2025-07-07 23:32:34.562 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:34.578 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:36.379 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 50 => 50
2025-07-07 23:32:36.384 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:36.398 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:38.130 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 50 => 50
2025-07-07 23:32:38.133 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:38.141 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:39.756 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 50 => 50
2025-07-07 23:32:39.759 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:39.767 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:41.731 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 50 => 50
2025-07-07 23:32:41.737 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:41.756 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:43.814 INFO Z-WAVE: [Node 005] Value updated: 38-0-targetValue 50 => 50
2025-07-07 23:32:43.819 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50
2025-07-07 23:32:43.828 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 50 => 50 ~~~

@gwp1 Here is the screen capture. It is basically a copy of what toggledbits provided. Keep in mind that it is working fine with the default dimming.step and if your dimmer is normally set to 100% before being turned off.

From the screen capture you can see that, in my case, the "Current value" is 0.59...This is as high as it will go if the previous state of the dimmer was 60%. This situation causes the while to repeat every 2 second indefinitely. I have to kill it in the "running reaction" status screen or to disable the rule.

@toggledbits I am having some difficulty implementing the suggested approach. In my case, what you suggested above worked but with some limitations. Maybe due to the fact that I am not using the Z-Wave controller but Z-Wave JS UI.

I have created the same rule as you suggested but to better understand what is happening I perform some test from the "Entities" menu.

1- The "dimming.step" when changed does not stick after a dimming.up/down

In the "Entities" menu I set the attribute "dimming.step" to 0.05. Still in the etities menu, I then perform a "dimming.up" and can confirm that indeed the "dimming.level" went up by 0.05 however at the same time the dimming.step goes back to 0.1 (default). From that point, any subsequent "dimming.up" uses the default.

2- The dimming.up does not exceed the previous level (This might be normal but a bit difficult to manage?)

If the dimming level was set to 60% and then turn off, performing a "dimming up" will not go beyond 60%. So implementing the rule as suggested, make an infinite while since .99 is never reached.

I tried this on 2 type of z-wave devices with the same result.

Thanks in advance

Super, it worked as expected.

My MSR installation date from all the way back at the begining of this treck. I do recollect adjusting the # of logs and size but not adding the "mode". In any case, I see from the dist-config/logging.yaml that the default is 0644 (which would work just fine) and that it is commented out. That is probably what everybody have and the reason why I was the lone woolf out there. I think I will follow the pack and comment it out.

EDIT: I did add the "mode" back in dec 2021 to fix a similar issue. Things have changed/evolved since causing the issue to show up again.

Many thanks

All my docker applications, including reactor, have a volume in my "automation" folder on the host.

vezinpi@RPI8G:~/automation $ ls -l
total 32
drwxr-xr-x  2 vezinpi vezinpi 4096 May 28  2023 docker-compose
drwxrwxrwx  4 vezinpi vezinpi 4096 Jan 14 13:41 esphome
drwxrwxrwx  8     472     472 4096 Feb  8 07:45 grafana
drwxrwxrwx 12 vezinpi vezinpi 4096 Feb  6 15:25 homeassistant
drwx------  3 vezinpi root    4096 Feb 22  2023 influxdb2
drwxrwxrwx  6 vezinpi vezinpi 4096 Jun 20  2024 reactor
drwxr-xr-x  9 vezinpi root    4096 Feb  8 03:28 ssl
drwxrwxrwx 11 vezinpi vezinpi 4096 Feb  8 07:52 zwave-js-ui

Here is the reactor folder:

vezinpi@RPI8G:~/automation $ ls -l reactor
total 64
drwxrwxrwx 2 vezinpi vezinpi  4096 Feb  5 21:38 config
drwxrwxr-x 2 root    root     4096 Feb  6 14:07 dist-config
drwxrwxrwx 2 vezinpi vezinpi  4096 Feb  8 06:23 logs
-rwxrw-rw- 1 vezinpi vezinpi 45473 Jan  3  2022 reactor-config-backup.json
drwxrwxrwx 7 vezinpi vezinpi  4096 Jun 20  2024 storage
vezinpi@RPI8G:~/automation $

Here is the log folder. Please note that some files still have read/write permissions for "other" . This is me changing the permission on the host to grant me access from my PC. The most recent one are back to write only (222). As the log rotation progresses they will all become 222.

vezinpi@RPI8G:~/automation/reactor $ ls -l logs
total 44688
-rwxrw-rw- 1 vezinpi vezinpi    6572 Feb  6 14:07 hass_config.json
-rwxrw-rw- 1 vezinpi vezinpi  288139 Feb  6 14:07 hass_services.json
-rwxrw-rw- 1 vezinpi vezinpi  308677 Feb  6 14:07 hass_states.json
--w--w--w- 1 root    root    1802037 Feb  8 08:02 reactor.log
--w--w--w- 1 root    root    4194194 Feb  8 06:23 reactor.log.1
--w--w-rw- 1 root    root    4194347 Feb  7 06:16 reactor.log.10
--w--w-rw- 1 root    root    4194366 Feb  8 02:48 reactor.log.2
--w--w-rw- 1 root    root    4193980 Feb  7 21:59 reactor.log.3
--w--w-rw- 1 root    root    4194236 Feb  7 19:04 reactor.log.4
--w--w-rw- 1 root    root    4194260 Feb  7 17:18 reactor.log.5
--w--w-rw- 1 root    root    4194318 Feb  7 15:13 reactor.log.6
--w--w-rw- 1 root    root    4194256 Feb  7 12:39 reactor.log.7
--w--w-rw- 1 root    root    4193917 Feb  7 10:39 reactor.log.8
--w--w-rw- 1 root    root    4194228 Feb  7 09:10 reactor.log.9
-rw-r--r-- 1 root    root      11755 Feb  5 19:45 unhandled.json
-rwxrw-rw- 1 vezinpi vezinpi   24164 Feb 28  2022 vera-status-initial.json
-rwxrw-rw- 1 vezinpi vezinpi   48401 Feb 28  2022 vera-user_data-initial.json
-rwxrw-rw- 1 vezinpi vezinpi 1263301 Nov  6  2022 zwavejs_devices_initial.json
vezinpi@RPI8G:~/automation/reactor $

config/logging.yaml

vezinpi@RPI8G:~/automation/reactor/config $ more logging.yaml
---
logging:
  default:
    level: 4
    streams:
      - type: console
        level: 0
      - type: file
        name: "reactor.log"
        mode: 0666
        maxsize: 4  # megabytes max size
        keep: 10     # copies of old logs
        #
        # capture_console: if true, (most) console output will be captured to
        #                  this stream (if you have multiple streams, this
        #                  feature can only be used by ONE of them). If you
        #                  turn this on (true), set the "console" type stream
        #                  (above) log level to 0 to avoid duplicate logging
        #                  entries. The default is false, console not captured.
        #capture_console: true
  app:
    level: 4
  httpapi:
    level: 4
  httpproxy:
    level: 4
  wsapi:
    level: 4
  Structure:
    level: 4
  Controller:
    level: 4
  OWMWeatherController:
    level: 4
  VeraController:
    level: 4
  HubitatController:
    level: 4
  HassController:
    level: 4
  Rule:
    level: 5
  Engine:
    level: 5
(END)

Hope this help

Ok, I guess that I did not put enough information to be clear. I skipped the intro and went directely into what I beleive to be the issue. I should stick with the issue not the solution. My bad.

I do not go in the container to access the logs or change permissions but I did looked at them, trying understand how that works. Docker volumes, map the /var/reactor of the container to a directory on the host with read/write premissions. From the host it is then, via samba, shared to my PC where I would like to access the logs.

Because of the permissions of the files, I cannot access the files directely from my PC. I have to change the permissions on the Host before I can access them (It can however, be access from the hosts by using "sudo" ).

What I was trying to say in my initial post is that the permission are set to 222 in the container that get mapped to the the hosts and eventually to my PC. Changing the permissions on the host is only temporary until Reactor do a log rotation where the files changed back to 222. If the logfiles in the container were created with something like 226 the "read" permission for "other" would ripple all the way to the hosts a then to the PC.

Like I said in my first post, I am not a Docker specialist but I thought that the only way to permanentely change the logs permissions would be by the application at the container level where they are created.

That being said, I have been wrong before!

Again, not a big deal just convenience.

Not a big issue simply a request if easily doable.

The MSR logs files inside the container are owned by root witch is fine however, the permissions are very restrictive. I do not know if there is something wrong with my installation but the logs permission are set to 222 (write only). Even if the docker volume is set for Read/Write the log files are retaining these values.

I go around the problem by doing a chmod 777 on all reactor logs but every time there is an MSR log rotation the permissions are set back to 222. So unless the permission are implemented in the container there is no permanent solution to this (that I know of).

I do not know much about Docker container so I do not know what is involved here.

Can the logfiles permission be simply chaged in the container to at least allow "other" read permission?

Could the MSR log rotation routine implement a chmod to set the permission?

Just a small anoyance

Thanks

@mrFarmer said in [SOLVED]Hass websocket falsely reporting ready on boot??:

Yes, clear status messages. Click reload. Wait until I see Connected and then go to the status page to see them in alerts.

When you say reload do you mean "Restart Reactor" from the "Tool" menu? If so, the alarm will show right back until you refresh the page or restart your browser again. In my case the messages are only transitory following a "Restart Reactor" and are gone after I refresh the page.

Roger that.

Again many thanks for your patience.

All right, that did the trick.

I can clearly see in the log where it is waiting for the connection to be stable and sending the request only after. This is great!

The 3 alarm are still showing when I use the "reboot reactor" from the Tools menu. It seems that it is only transitory since a screen refresh or re-starting the browser clears it. This is also fine.

Just making sure that I understand the process. Please correct me where I am wrong.

• without adding wait_all_controllers: true to the engine subsection, there is no delay

• with the wait_all_controllers: true the default delay is 60 second

• If the default delay is not enough then we can use startup_wait: xxxx to change the default delay

• In all cases the delay is only the maximum delay and the wait will be terminated when the connections is made.

• If I have 5 controllers, are they all treated individually or the slowest one need to be up before anything happen?

@toggledbits said in Hass websocket falsely reporting ready on boot??:

The controllers section is an array. Make sure DynamicGroupController and SystemController are the last two entries in the array.

I am not sure I understand this one. I never played with the reactor.yaml file, I simply took the template and fill it up. I fail to see why these 2 controller need to be last. In my case I had 2 unused one between the two like it is in the template. I did move them but I am not sure that it really did anything.

Many thanks for your support

With startup_wait: 120000 I have the same result as before.

-Rule set to trigger at 00:55z
-Shutdown down completed at 00:54:27z
-First log entry after power up at 00:58:06
-Socket connection with Hass at 00:58:12z

[latest-25016]2025-02-06T00:54:27.398Z <Structure:NOTICE> Structure Structure#1 stopped
[latest-25016]2025-02-06T00:54:27.398Z <app:NOTICE> Closing APIs...
[latest-25016]2025-02-06T00:54:27.398Z <wsapi:NOTICE> wsapi: closing...
[latest-25016]2025-02-06T00:54:27.399Z <wsapi:NOTICE> wsapi: disconnecting from "192.168.2.33#1" (1001 service closing)
[latest-25016]2025-02-06T00:54:27.401Z <httpapi:NOTICE> HTTP API closing...
[latest-25016]2025-02-06T00:54:27.403Z <wsapi:NOTICE> wsapi: server closed
[latest-25016]2025-02-06T00:54:27.405Z <wsapi:WARN> client close from unknown connection? "192.168.2.33#1"

[latest-25016]2025-02-06T00:58:06.180Z <app:null> Reactor build latest-25016-d47fea38 starting on v20.10.0 /usr/local/bin/node
[latest-25016]2025-02-06T00:58:06.198Z <app:null> Process ID 1 user/group 0/0; docker; platform linux/arm64 #1 SMP PREEMPT Debian 1:6.6.74-1+rpt1 (2025-01-27); locale (undefined)
[latest-25016]2025-02-06T00:58:06.203Z <app:null> Basedir /opt/reactor; data in /var/reactor/storage
[latest-25016]2025-02-06T00:58:06.207Z <app:null> NODE_PATH=/opt/reactor:/opt/reactor/node_modules
[latest-25016]2025-02-06T00:58:06.278Z <app:null> Resolved timezone=America/Toronto, environment TZ=America/Toronto; offset minutes from UTC=-300
[latest-25016]2025-02-06T00:58:06.337Z <app:null> Configured locale (undefined); selected locale(s) en-US.UTF-8
[latest-25016]2025-02-06T00:58:06.532Z <app:null> Loaded locale en-US for en-US
[latest-25016]2025-02-06T00:58:06.534Z <app:null> Local date/time using configured timezone and locale formatting is "2/5/2025, 7:58:06 PM"
[latest-25016]2025-02-06T00:58:07.077Z <Structure:null> Module Structure v24287
[latest-25016]2025-02-06T00:58:07.086Z <Capabilities:null> Module Capabilities v24312
[latest-25016]2025-02-06T00:58:07.289Z <Capabilities:NOTICE> System capabilities loaded from core distribution, data version 25004 revision 1
[latest-25016]2025-02-06T00:58:07.784Z <Plugin:null> Module Plugin v22300
[latest-25016]2025-02-06T00:58:08.260Z <TimerBroker:null> Module TimerBroker v22283
[latest-25016]2025-02-06T00:58:08.284Z <Entity:null> Module Entity v25014
[latest-25016]2025-02-06T00:58:08.455Z <Controller:null> Module Controller v25014
[latest-25016]2025-02-06T00:58:08.786Z <default:null> Module Ruleset v24288
[latest-25016]2025-02-06T00:58:08.789Z <default:null> Module Rulesets v24220
[latest-25016]2025-02-06T00:58:09.072Z <GlobalExpression:null> Module GlobalExpression v24209
[latest-25016]2025-02-06T00:58:09.216Z <Predicate:null> Module Predicate v24350
[latest-25016]2025-02-06T00:58:09.274Z <AlertManager:null> Module AlertManager v24099
[latest-25016]2025-02-06T00:58:09.310Z <Rule:null> Module Rule v24329
[latest-25016]2025-02-06T00:58:09.348Z <GlobalReaction:null> Module GlobalReaction v24220
[latest-25016]2025-02-06T00:58:09.368Z <Engine:null> Module Engine v24344
[latest-25016]2025-02-06T00:58:09.422Z <httpapi:null> Module httpapi v24298
[latest-25016]2025-02-06T00:58:09.517Z <wsapi:null> Module wsapi v25016
[latest-25016]2025-02-06T00:58:09.520Z <app:NOTICE> Starting Structure...
[latest-25016]2025-02-06T00:58:09.548Z <Structure:NOTICE> Structure#1 plugin ID influx disabled; skipping
[latest-25016]2025-02-06T00:58:09.553Z <Structure:INFO> Structure#1 loading controller interface hass (HassController)
[latest-25016]2025-02-06T00:58:09.796Z <HassController:null> Module HassController v25010
[latest-25016]2025-02-06T00:58:12.086Z <Structure:INFO> Structure#1 loading controller interface groups (DynamicGroupController)
[latest-25016]2025-02-06T00:58:12.119Z <DynamicGroupController:null> Module DynamicGroupController v24279
[latest-25016]2025-02-06T00:58:12.157Z <Structure:INFO> Structure#1 loading controller interface reactor_system (SystemController)
[latest-25016]2025-02-06T00:58:12.177Z <SystemController:null> Module SystemController v24279
[latest-25016]2025-02-06T00:58:12.202Z <Structure:INFO> Starting controller HassController#hass
[latest-25016]2025-02-06T00:58:12.203Z <HassController:NOTICE> HassController#hass starting...
[latest-25016]2025-02-06T00:58:12.205Z <Structure:INFO> Starting controller DynamicGroupController#groups
[latest-25016]2025-02-06T00:58:12.218Z <Controller:NOTICE> Controller DynamicGroupController#groups is now online.
[latest-25016]2025-02-06T00:58:12.218Z <Structure:INFO> Starting controller SystemController#reactor_system
[latest-25016]2025-02-06T00:58:12.226Z <Controller:NOTICE> Controller SystemController#reactor_system is now online.
[latest-25016]2025-02-06T00:58:12.515Z <Engine:null> [Engine]Engine#1 config [Object]{ "enabled": true, "startup_wait": 120000, "monitored_entities": [ "vera>device_XXX" ] }
[latest-25016]2025-02-06T00:58:12.563Z <HassController:INFO> HassController#hass performing one-time initialization for HassController class
[latest-25016]2025-02-06T00:58:12.598Z <Controller:INFO> HassController#hass loaded hass capabilities ver 25004 rev 1 format 1 
[latest-25016]2025-02-06T00:58:12.686Z <Controller:INFO> HassController#hass loaded implementation data ver 25004 rev 2 format 1 
[latest-25016]2025-02-06T00:58:12.715Z <HassController:INFO> HassController#hass device mapping data loaded; checking...
[latest-25016]2025-02-06T00:58:12.752Z <HassController:NOTICE> HassController#hass connecting to wss://192.168.2.163:8123/api/websocket
[latest-25016]2025-02-06T00:58:12.818Z <app:NOTICE> Starting HTTP server and API...
[latest-25016]2025-02-06T00:58:12.861Z <httpapi:NOTICE> [HTTPAPI]#1 starting HTTP service on port 8111
[latest-25016]2025-02-06T00:58:12.874Z <app:NOTICE> Starting Reaction Engine...
[latest-25016]2025-02-06T00:58:12.876Z <Engine:INFO> Reaction Engine starting
[latest-25016]2025-02-06T00:58:12.878Z <Engine:INFO> Checking rule sets...
[latest-25016]2025-02-06T00:58:12.907Z <Engine:INFO> Checking rules...
[latest-25016]2025-02-06T00:58:12.921Z <Rule:5:Rule.js:209> Rule#rule-134 cleaning loaded condition states
[latest-25016]2025-02-06T00:58:12.931Z <Rule:5:Rule.js:209> Rule#rule-136 cleaning loaded condition states

At 00:58:15z Sending reaction request to hass failed

[latest-25016]2025-02-06T00:58:15.289Z <Engine:5:Engine.js:1786> [Engine]Engine#1 reaction rule-m6rz6ol1:S step 0 perform [Object]{ "entity": "hass>switch_plug_in_outlet_floater", "action": "power_switch.on" }
[latest-25016]2025-02-06T00:58:15.293Z <HassController:INFO> HassController#hass perform power_switch.on on Switch#hass>switch_plug_in_outlet_floater with [Object]{  }
[latest-25016]2025-02-06T00:58:15.296Z <HassController:WARN> HassController#hass unknown service homeassistant.turn_on in power_switch.on action on Switch#hass>switch_plug_in_outlet_floater
[latest-25016]2025-02-06T00:58:15.296Z <HassController:INFO> HassController#hass no entity/target for homeassistant.(undefined)
[latest-25016]2025-02-06T00:58:15.296Z <HassController:INFO> HassController#hass: sending payload for power_switch.on on Switch#hass>switch_plug_in_outlet_floater action: [Object]{ "type": "call_service", "service_data": {  }, "domain": "homeassistant", "service": "turn_on" }
[latest-25016]2025-02-06T00:58:15.301Z <Engine:5:Engine.js:1641> _process_reaction_queue() task returned, new status 3; task 1, history 86213
[latest-25016]2025-02-06T00:58:15.303Z <HassController:ERR> HassController#hass request 1738803495298<2/5/2025, 7:58:15 PM> (call_service) failed: [Error] WebSocket is not open: readyState 0 (CONNECTING) [-]
[latest-25016]2025-02-06T00:58:15.304Z <Engine:5:Engine.js:1688> _process_reaction_queue ending with 1 in queue; none delayed/ready; waiting
[latest-25016]2025-02-06T00:58:15.305Z <HassController:WARN> HassController#hass action power_switch.on([Object]{  }) on Switch#hass>switch_plug_in_outlet_floater failed!
[latest-25016]2025-02-06T00:58:15.306Z <HassController:INFO> Service call payload:
{"type":"call_service","service_data":{},"domain":"homeassistant","service":"turn_on","id":1738803495298}
[latest-25016]2025-02-06T00:58:15.307Z <HassController:INFO> Service data:
{}
[latest-25016]2025-02-06T00:58:15.309Z <Engine:ERR> [Engine]Engine#1 reaction rule-m6rz6ol1:S step 0 perform power_switch.on failed: [Error] WebSocket is not open: readyState 0 (CONNECTING) [-]
[latest-25016]2025-02-06T00:58:15.309Z <Engine:INFO> [Engine]Engine#1 action args: [Object]{  }
[latest-25016]2025-02-06T00:58:15.310Z <Engine:5:Engine.js:1688> _process_reaction_queue() wake-up!
[latest-25016]2025-02-06T00:58:15.311Z <Engine:5:Engine.js:1627> _process_reaction_queue() running task 1: [Object]{ "tid": 1, "id": "rule-m6rz6ol1:S", "rule": "rule-m6rz6ol1", "__reaction": [RuleReaction#rule-m6rz6ol1:S], "next_step": 1, "status": 1, "ts": 1738803495021, "parent": --null--, "__resolve": --function--, "__reject": --function--, "__promise": [object Promise], "attempts": 0, "history_id": 86213 }
[latest-25016]2025-02-06T00:58:15.313Z <Engine:INFO> Resuming reaction rule-m6rz6ol1<SET> (rule-m6rz6ol1:S) from step 1
[latest-25016]2025-02-06T00:58:15.313Z <Engine:INFO> rule-m6rz6ol1<SET> all actions completed.
[latest-25016]2025-02-06T00:58:15.314Z <Engine:5:Engine.js:1641> _process_reaction_queue() task returned, new status -1; task 1, history 86213
[latest-25016]2025-02-06T00:58:15.323Z <Engine:5:Engine.js:1688> _process_reaction_queue ending with 0 in queue; none delayed/ready; waiting

After that I have several socket up and down message until 00:58:52z where it seemed to stabilised.

Error: Hub reports it is starting but not yet ready
    at /opt/reactor/server/lib/HassController.js:1291:66
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
[latest-25016]2025-02-06T00:58:30.573Z <HassController:NOTICE> HassController#hass websocket closing, 1006 
[latest-25016]2025-02-06T00:58:35.574Z <HassController:NOTICE> HassController#hass connecting to wss://192.168.2.163:8123/api/websocket
[latest-25016]2025-02-06T00:58:35.892Z <HassController:NOTICE> HassController#hass connected, starting protocol
[latest-25016]2025-02-06T00:58:35.900Z <HassController:INFO> HassController#hass successful authentication with wss://192.168.2.163:8123; fetching initial data...
[latest-25016]2025-02-06T00:58:35.908Z <HassController:INFO> HassController#hass Hass reports version "2025.1.0" location Maison timezone America/Toronto state NOT_RUNNING safe_mode false
[latest-25016]2025-02-06T00:58:35.909Z <HassController:ERR> HassController#hass failed to complete startup: [Error] Hub reports it is starting but not yet ready [-]
[latest-25016]2025-02-06T00:58:35.910Z <HassController:CRIT> Error: Hub reports it is starting but not yet ready [-]
Error: Hub reports it is starting but not yet ready
    at /opt/reactor/server/lib/HassController.js:1291:66
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
[latest-25016]2025-02-06T00:58:35.912Z <HassController:NOTICE> HassController#hass websocket closing, 1006 
[latest-25016]2025-02-06T00:58:40.918Z <HassController:NOTICE> HassController#hass connecting to wss://192.168.2.163:8123/api/websocket
[latest-25016]2025-02-06T00:58:40.954Z <HassController:NOTICE> HassController#hass connected, starting protocol
[latest-25016]2025-02-06T00:58:40.959Z <HassController:INFO> HassController#hass successful authentication with wss://192.168.2.163:8123; fetching initial data...
[latest-25016]2025-02-06T00:58:40.963Z <HassController:INFO> HassController#hass Hass reports version "2025.1.0" location Maison timezone America/Toronto state NOT_RUNNING safe_mode false
[latest-25016]2025-02-06T00:58:40.964Z <HassController:ERR> HassController#hass failed to complete startup: [Error] Hub reports it is starting but not yet ready [-]
[latest-25016]2025-02-06T00:58:40.964Z <HassController:CRIT> Error: Hub reports it is starting but not yet ready [-]
Error: Hub reports it is starting but not yet ready
    at /opt/reactor/server/lib/HassController.js:1291:66
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
[latest-25016]2025-02-06T00:58:40.966Z <HassController:NOTICE> HassController#hass websocket closing, 1006 
[latest-25016]2025-02-06T00:58:45.969Z <HassController:NOTICE> HassController#hass connecting to wss://192.168.2.163:8123/api/websocket
[latest-25016]2025-02-06T00:58:46.716Z <HassController:NOTICE> HassController#hass connected, starting protocol
[latest-25016]2025-02-06T00:58:46.735Z <HassController:INFO> HassController#hass successful authentication with wss://192.168.2.163:8123; fetching initial data...
[latest-25016]2025-02-06T00:58:46.747Z <HassController:INFO> HassController#hass Hass reports version "2025.1.0" location Maison timezone America/Toronto state NOT_RUNNING safe_mode false
[latest-25016]2025-02-06T00:58:46.748Z <HassController:ERR> HassController#hass failed to complete startup: [Error] Hub reports it is starting but not yet ready [-]
[latest-25016]2025-02-06T00:58:46.748Z <HassController:CRIT> Error: Hub reports it is starting but not yet ready [-]
Error: Hub reports it is starting but not yet ready
    at /opt/reactor/server/lib/HassController.js:1291:66
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
[latest-25016]2025-02-06T00:58:46.750Z <HassController:NOTICE> HassController#hass websocket closing, 1006 
[latest-25016]2025-02-06T00:58:51.756Z <HassController:NOTICE> HassController#hass connecting to wss://192.168.2.163:8123/api/websocket
[latest-25016]2025-02-06T00:58:51.898Z <HassController:NOTICE> HassController#hass connected, starting protocol
[latest-25016]2025-02-06T00:58:51.930Z <HassController:INFO> HassController#hass successful authentication with wss://192.168.2.163:8123; fetching initial data...
[latest-25016]2025-02-06T00:58:52.055Z <HassController:INFO> HassController#hass Hass reports version "2025.1.0" location Maison timezone America/Toronto state RUNNING safe_mode false
[latest-25016]2025-02-06T00:58:52.935Z <Rule:5:Rule.js:366> Rule#rule-grpol1jp4l Summer Day At Home requesting eval; entity-changed from Entity#hass>input_select_house_mode
[latest-25016]2025-02-06T00:58:52.936Z <Rule:5:Rule.js:366> Rule#rule-grp15p0yq5k Summer Evening At Home requesting eval; entity-changed from Entity#hass>input_select_house_mode
[latest-25016]2025-02-06T00:58:52.936Z <Rule:5:Rule.js:366> Rule#rule-grpol67dc7 Summer Night At Home requesting eval; entity-chang

Well, I just added wait_all_controllers: true and got the following:

Commented out the wait_all_controllers: true and change the startup_wait from 60000 to 120000. Will be re-testing my test case shortly.

Standby

Hi, @toggledbits

I just noticed that following a reboot of my raspberry pi, some of the rules, that I was expecting to recover, are not catching up following a reboot. I have made a simple test rule (rule-m6rz6ol1) with only "after Date/time" as trigger and "turn on a lamp" as a set reaction. All my infrastructure is on the same board so Reactor, Hass, Zwavejs, ... are all rebooting.

Here is the sequence of the test case (All time converted to Zulu to match logs):

• Rule "after Date/Time" set to 14:05:00z
• Shutdown on Raspberry Pi at 14:04:00z
• Power back up at 14:08:00z
• Rule overview shows true as of 14:08:14z waiting for 00:00:00 in GUI

From the log I can see that MSR is picking up the rule and knows that the state of the rule has changed from false to true and tries to send the update to HASS but failed with websocket error.

Here is what I see from the log:

• 14:04:04z shutdown complete
• 14:08:08z Power up
• 14:08:13.111z websocket connection
• 14:08:15:323z Reaction to the light failed, Websocket not opened
• After there is a series of websocket connection attempt until 14:08:51z where it seemed to be really ready.

Back in 2021 we had a discussion (https://smarthome.community/topic/700/solved-start-up?_=1738766986566) and you proposed to add a startup_delay:xxxx and startup_wait:xxxx parameter in the engine section of "reactor.yaml". When I try the startup_delay (this used to be a hard delay), the engine failed to start (I think). I then try the startup_wait:xxxx without any success. Since it wait for the connection status to be up to cancel the delay, it does not do anyting since Hass is reporting the socket up without really being up ( I think...).

Questions:

• Did I figured it all wrong?
• should the startup_delay:xxxxx have worked?
• Any ideas?

Here is the log:

OK now I am stuck. I did add the log but when I submit the editor complained saying that I am limited to 32767 characters. The log from the shutdown to the time the websocket is stable is about 300000 character long. What are my options?

@tunnus @toggledbits Thank you both for all your explanation.

Much appreciated.

@toggledbits said in [Solved] Local expression evaluation:

Also: it's not correct to compare a time string to another time string. Basically, everything about this expression won't work.

I understand that, as you explained, expression cannot auto evaluate based on time. However when manually trigger, the expression do work as intended with time and all.

I Know that your not in the business of teaching others how to code but does it means that, inside an expression, we should never attempt to perform actions based on time like:

if strftime("%H:%M:%S") < "08:00:00" then
...

Thanks