Rules don't ever run

I recently migrated to Openhabian 3 on a Raspberry Pi 3+. My setup is simple. I have a Aeotech Z-wave controller, a switched outlet for a lamp in the living room, and a dimmer switch for the outdoor lights on the front of the house. I want to turn all of the lights on as it’s getting dark. I want to turn the floor lamp off at 2am, and the outdoor lights off at dawn.

Nothing is running. I’ve set up everything using the UI this time (mostly following the documentation).

Oh yeah. I’ve got a Yamaha receiver, and I’ve installed the binding for it, but I haven’t set it up in any way.

BTW, when I look at my Things via the UI, every Thing is showing Online.

Here’s my most recent openhab.log:

less openhab.log.7
2021-08-14 02:44:10.147 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'xxxxx/xxxxx'.
2021-08-14 02:44:10.216 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to 'xx.xxxxxx,xx.xxxxxx'.
2021-08-14 02:44:10.219 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'en_US'.
2021-08-14 02:44:29.041 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2021-08-14 02:44:35.235 [INFO ] [org.openhab.ui.internal.UIService   ] - Started UI on port 8080
2021-08-14 02:44:36.413 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.
2021-08-14 02:44:37.536 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel
2021-08-14 02:44:47.573 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null

Here’s my most recent events.log

2021-08-14 02:44:38.898 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'yamahareceiver:yamahaAV:5f9ec1b3_ed59_1900_4530_00a0de90e62f' changed from UNINITIALIZED to INITIALIZING
2021-08-14 02:44:38.975 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'yamahareceiver:yamahaAV:5f9ec1b3_ed59_1900_4530_00a0de90e62f' changed from INITIALIZING to OFFLINE (CONFIGURATION_PENDING): Waiting for connection with Yamaha device
2021-08-14 02:44:39.359 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'yamahareceiver:zone:5f9ec1b3_ed59_1900_4530_00a0de90e62f:Main_Zone' changed from UNINITIALIZED to INITIALIZING
2021-08-14 02:44:39.398 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'yamahareceiver:zone:5f9ec1b3_ed59_1900_4530_00a0de90e62f:Zone_2' changed from UNINITIALIZED to INITIALIZING
2021-08-14 02:44:39.471 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'yamahareceiver:zone:5f9ec1b3_ed59_1900_4530_00a0de90e62f:Main_Zone' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
2021-08-14 02:44:39.478 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'yamahareceiver:zone:5f9ec1b3_ed59_1900_4530_00a0de90e62f:Zone_2' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
2021-08-14 02:44:39.964 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'astro:sun:local' changed from UNINITIALIZED to INITIALIZING
2021-08-14 02:44:40.021 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'astro:sun:local' changed from INITIALIZING to ONLINE
2021-08-14 02:44:40.338 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'yamahareceiver:yamahaAV:5f9ec1b3_ed59_1900_4530_00a0de90e62f' changed from OFFLINE (CONFIGURATION_PENDING): Waiting for connection with Yamaha device to ONLINE
2021-08-14 02:44:40.443 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'yamahareceiver:zone:5f9ec1b3_ed59_1900_4530_00a0de90e62f:Main_Zone' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2021-08-14 02:44:40.471 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'yamahareceiver:zone:5f9ec1b3_ed59_1900_4530_00a0de90e62f:Zone_2' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2021-08-14 02:44:40.700 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'astro:moon:local' changed from UNINITIALIZED to INITIALIZING
2021-08-14 02:44:40.723 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'astro:moon:local' changed from INITIALIZING to ONLINE
2021-08-14 02:44:47.562 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:2397bc54d3:node2' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2021-08-14 02:44:47.720 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:2397bc54d3' changed from UNINITIALIZED to INITIALIZING
2021-08-14 02:44:47.732 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:2397bc54d3' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-08-14 02:44:47.772 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:2397bc54d3:node8' changed from UNINITIALIZED to INITIALIZING
2021-08-14 02:44:47.784 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:2397bc54d3:node8' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-08-14 02:44:47.789 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:2397bc54d3:node2' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2021-08-14 02:44:47.800 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:2397bc54d3:node2' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

Here’s my lights on code:

triggers:
  - id: "1"
    configuration:
      event: START
      channelUID: astro:sun:local:civilDusk#event
    type: core.ChannelEventTrigger
conditions: []
actions:
  - inputs: {}
    id: "2"
    configuration:
      itemName: ZWaveNode002DZ6HD600WDimmer_Dimmer
      command: ON
    type: core.ItemCommandAction
  - inputs: {}
    id: "3"
    configuration:
      itemName: ZWaveNode008DZR15SceneCapableReceptacle_Switch
      command: ON
    type: core.ItemCommandAction

And the floor lamp off code (I don’t think I need to include the dimmer off code as it’s similar):

triggers:
  - id: "1"
    configuration:
      time: 02:00
    type: timer.TimeOfDayTrigger
conditions: []
actions:
  - inputs: {}
    id: "2"
    configuration:
      itemName: ZWaveNode008DZR15SceneCapableReceptacle_Switch
      command: OFF
    type: core.ItemCommandAction

What am I doing wrong?

  • does the time shown in the events.log/openhab.log match with the time in your timezone ?
  • what is shown in events.log at the time the astro binding reaches civilDusk ( is the trigger raised ) ?
  • what is shown at that time for your lights items ?
1 Like

Running the date command on the Rapsberry Pi, I discovered that the time was about 7 hours ahead of what it should have been. That could explain why the SceneCapableReceptacle_Switch did not turn off. It thought it was past 2am already. I’ve corrected that.

Here’s the events.log from the time when the lights should have shut off:

2021-08-14 02:57:32.232 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:2397bc54d3:node2' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-08-14 02:57:32.264 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:2397bc54d3:node8' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-08-14 02:57:32.446 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZWaveNode002DZ6HD600WDimmer_Dimmer' changed from NULL to 0
2021-08-14 02:57:32.576 [INFO ] [openhab.event.ConfigStatusInfoEvent ] - ConfigStatusInfo [configStatusMessages=[]]
2021-08-14 02:57:32.581 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:2397bc54d3:node2' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-08-14 02:57:36.744 [INFO ] [openhab.event.ConfigStatusInfoEvent ] - ConfigStatusInfo [configStatusMessages=[]]
2021-08-14 02:57:36.803 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZWaveNode008DZR15SceneCapableReceptacle_Switch' changed from NULL to OFF
2021-08-14 02:57:36.825 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:2397bc54d3:node8' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-08-14 02:57:42.612 [INFO ] [openhab.event.RuleUpdatedEvent      ] - Rule 'Living_Room_Light_Off' has been updated.
2021-08-14 02:58:06.187 [INFO ] [openhab.event.RuleUpdatedEvent      ] - Rule 'LightsOnDusk' has been updated.
2021-08-14 02:58:17.622 [INFO ] [openhab.event.RuleUpdatedEvent      ] - Rule 'Front_Door_Lights_Off_Dawn' has been updated.
2021-08-14 02:59:02.046 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZWaveNode008DZR15SceneCapableReceptacle_Switch' changed from NULL to OFF
2021-08-14 02:59:02.056 [INFO ] [openhab.event.ItemUpdatedEvent      ] - Item 'ZWaveNode008DZR15SceneCapableReceptacle_Switch' has been updated.
2021-08-14 02:59:16.912 [INFO ] [openhab.event.ItemUpdatedEvent      ] - Item 'ZWaveNode008DZR15SceneCapableReceptacle_SceneNumber' has been updated.
2021-08-14 02:59:42.735 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZWaveNode002DZ6HD600WDimmer_Dimmer' changed from NULL to 0
2021-08-14 02:59:42.738 [INFO ] [openhab.event.ItemUpdatedEvent      ] - Item 'ZWaveNode002DZ6HD600WDimmer_Dimmer' has been updated.
2021-08-14 02:59:55.533 [INFO ] [openhab.event.ItemUpdatedEvent      ] - Item 'ZWaveNode002DZ6HD600WDimmer_SceneNumber' has been updated.
2021-08-14 03:00:12.192 [INFO ] [openhab.event.RuleUpdatedEvent      ] - Rule 'Living_Room_Light_Off' has been updated.
2021-08-14 03:00:24.963 [INFO ] [openhab.event.RuleUpdatedEvent      ] - Rule 'LightsOnDusk' has been updated.
2021-08-14 03:00:34.178 [INFO ] [openhab.event.RuleUpdatedEvent      ] - Rule 'Front_Door_Lights_Off_Dawn' has been updated.
2021-08-14 03:20:07.046 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ZWaveNode008DZR15SceneCapableReceptacle_Switch' received command ON
2021-08-14 03:20:07.067 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'ZWaveNode008DZR15SceneCapableReceptacle_Switch' predicted to become ON
2021-08-14 03:20:07.082 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZWaveNode008DZR15SceneCapableReceptacle_Switch' changed from OFF to ON
2021-08-14 03:20:13.396 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ZWaveNode002DZ6HD600WDimmer_Dimmer' received command 100
2021-08-14 03:20:13.411 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'ZWaveNode002DZ6HD600WDimmer_Dimmer' predicted to become 100
2021-08-14 03:20:13.421 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZWaveNode002DZ6HD600WDimmer_Dimmer' changed from 0 to 100
2021-08-14 04:46:00.008 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:morningNight#event triggered START
2021-08-14 05:51:00.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:moon:local:set#event triggered END
2021-08-14 09:07:18.663 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ZWaveNode008DZR15SceneCapableReceptacle_Switch' received command OFF
2021-08-14 09:07:18.674 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'ZWaveNode008DZR15SceneCapableReceptacle_Switch' predicted to become OFF
2021-08-14 09:07:18.684 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZWaveNode008DZR15SceneCapableReceptacle_Switch' changed from ON to OFF
2021-08-14 11:14:00.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:astroDawn#event triggered START
2021-08-14 11:14:00.006 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:morningNight#event triggered END
2021-08-14 11:54:00.003 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:nauticDawn#event triggered START
2021-08-14 11:54:00.006 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:astroDawn#event triggered END
2021-08-14 12:31:00.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:nauticDawn#event triggered END
2021-08-14 12:31:00.006 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDawn#event triggered START
2021-08-14 12:31:00.017 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ZWaveNode002DZ6HD600WDimmer_Dimmer' received command OFF
2021-08-14 12:31:00.032 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'ZWaveNode002DZ6HD600WDimmer_Dimmer' predicted to become OFF
2021-08-14 12:31:00.043 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZWaveNode002DZ6HD600WDimmer_Dimmer' changed from 100 to 0
2021-08-14 13:01:00.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDawn#event triggered END
2021-08-14 13:01:00.006 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:rise#event triggered START
2021-08-14 13:04:00.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:rise#event triggered END
2021-08-14 13:04:00.006 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:daylight#event triggered START

I’m a bit confused by this line:
2021-08-14 04:46:00.008 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:morningNight#event triggered START

I don’t have anything set up to use that event.

The log shows triggers for all events that are defined in the astro binding.
This is independent if you use them or not.

I didn’t know that.

That did seem to be the problem. Thank you!

1 Like