[SOLVED] Actual rule execution lags after updating to OH 2.5

Hi,

after updating to OH 2.5 my currently used two rules do not work any more.

Setup

I have two Tradfri motion sensors in two different rooms. If they detect motion OH should switch the light (Tradfri E27 bulbs) in the room on.
I’m using zigbee2mqtt/mosquitto with a CC2351 to control the sensors and bulbs.

Rules

$ cat /etc/openhab2/rules/bathroom.sensor.rules 
#----------------------------------------------
var Timer lightsOffTimer = null


rule "Motion in bathroom detected"
when
  Item Sensor_Motion_GF_Bathroom_Occupancy received update ON
then
  logInfo('occupancy_bathroom_on', 'Motion detected.')

  Light_GF_Bathroom_CeilingLights_MainLight_Brightness.sendCommand('100')

  logInfo('occupancy_bathroom_on', 'Turned Light_GF_Bathroom_CeilingLights_MainLight on.')

  if (lightsOffTimer !== null) {
    logInfo('occupancy_bathroom_on', 'Further motion detected. Canceled timer to turn off lights.')

    lightsOffTimer.cancel()
  }
end


rule "No more motion in bathroom detected"
when
  Item Sensor_Motion_GF_Bathroom_Occupancy received update OFF
then

  logInfo('occupancy_bathroom_off', 'No more motion detected. Room probably unoccupied.')

  val currentBrightness = Light_GF_Bathroom_CeilingLights_MainLight_Brightness.state

  if(currentBrightness == 0) {
    logInfo('occupancy_bathroom_off', 'Lights already off. No need for a change.')
    return;
  }

  logInfo('occupancy_bathroom_off', 'Flash lights to notify about imminent turn out of lights.')

  if((currentBrightness as Number) > 50) {
    Light_GF_Bathroom_CeilingLights_MainLight_Brightness.sendCommand('25')
    Light_GF_Bathroom_CeilingLights_MainLight_Brightness.sendCommand('100')
    Light_GF_Bathroom_CeilingLights_MainLight_Brightness.sendCommand('25')
    Light_GF_Bathroom_CeilingLights_MainLight_Brightness.sendCommand(currentBrightness.toString)
  }
  else {
    Light_GF_Bathroom_CeilingLights_MainLight_Brightness.sendCommand('15')
    Light_GF_Bathroom_CeilingLights_MainLight_Brightness.sendCommand(currentBrightness.toString)
    Light_GF_Bathroom_CeilingLights_MainLight_Brightness.sendCommand('15')
    Light_GF_Bathroom_CeilingLights_MainLight_Brightness.sendCommand(currentBrightness.toString)
  }

  logInfo('occupancy_bathroom_off', 'Done flashing lights. Setting timer now.')

  lightsOffTimer = createTimer(now.plusSeconds(30), [|
    logInfo('occupancy_bathroom_off', 'Timer ended. Turning off lights now.')

    Light_GF_Bathroom_CeilingLights_MainLight_Brightness.sendCommand('0')
    logInfo('occupancy_bathroom_off', 'Turned off Light_GF_Bathroom_CeilingLights_MainLight.')
    lightsOffTimer = null
  ])
end

The other room has a slightly other rule, but is basically the same that’s why I’m not posting it in order to keep it short here.

Output

OH logs the correct things and seems to switch the light on:

14:09:18.423 [INFO ] [smarthome.event.ItemStateChangedEvent] - Sensor_Motion_GF_Bathroom_Occupancy changed from OFF to ON
14:09:18.428 [INFO ] [me.model.script.occupancy_bathroom_on] - Motion detected.
14:09:18.432 [INFO ] [smarthome.event.ItemStateChangedEvent] - Sensor_Motion_GF_Bathroom_LinkQuality changed from 19.215686274509803155297049670480191707611083984375 to 20.3921568627450966459946357645094394683837890625
14:09:18.452 [INFO ] [smarthome.event.ItemStateChangedEvent] - Sensor_Motion_GF_Bathroom_LastSeen changed from 2019-12-25T13:54:13.000+0100 to 2019-12-25T14:09:18.000+0100
14:09:18.451 [INFO ] [me.model.script.occupancy_bathroom_on] - Turned Light_GF_Bathroom_CeilingLights_MainLight on.
14:09:18.461 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'Light_GF_Bathroom_CeilingLights_MainLight_Brightness' received command 100
14:09:18.497 [INFO ] [arthome.event.ItemStatePredictedEvent] - Light_GF_Bathroom_CeilingLights_MainLight_Brightness predicted to become 100
14:09:18.514 [INFO ] [smarthome.event.ItemStateChangedEvent] - Light_GF_Bathroom_CeilingLights_MainLight_Brightness changed from 0 to 100

But nothing happens in the real, dark world :wink: . The bulbs remain dark. At least for some time. After a couple of minutes (that differs between 2 minutes up to ten to fifteen minutes) the light switches on. So there’s a huge lag somewhere.

Before the update the light switched on immediately. Where does the lag come from? How can I fix it?

Kind regards


  • Platform information:
    • Hardware: RPi 3B+
    • OS: Raspbian GNU/Linux 9
    • Java Runtime Environment:
      • openjdk version “1.8.0_152”
      • OpenJDK Runtime Environment (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 1.8.0_152-b76)
      • OpenJDK Client VM (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 25.152-b76, mixed mode, Evaluation)
    • openHAB version: 2.5.0 (Release Build)

I’m running OH on a Pi 3 and when I have lag issues, not that often, usually stopping OH and cleaning the cache fixes the lag. After cleaning I usually reboot but I think restarting should suffice.

sudo systemctl stop openhab2

sudo openhab-cli clean-cache

sudo systemctl start openhab2 or sudo reboot

Did you check the mqtt traffic?

The outbound one to the light in particular.
What happens if you switch light from UI ?

Hi,

thanks for the quick answers.

Thanks for the hint. Did it, but it didn’t solve the issue. But I’ll remember that one. Cleaning caches might be useful someday.

MQTT Log when activating the motion sensor

Dez 26 12:28:13 rpi npm[675]:   zigbee2mqtt:info 2019-12-26 12:28:13 MQTT publish: topic 'zigbee2mqtt/sensors/occupancy/bm/stairs/occupancy', payload 'true'
Dez 26 12:28:13 rpi npm[675]:   zigbee2mqtt:info 2019-12-26 12:28:13 MQTT publish: topic 'zigbee2mqtt/sensors/occupancy/bm/stairs/linkquality', payload '47'
Dez 26 12:28:13 rpi npm[675]:   zigbee2mqtt:info 2019-12-26 12:28:13 MQTT publish: topic 'zigbee2mqtt/sensors/occupancy/bm/stairs/battery', payload '47'
Dez 26 12:28:13 rpi npm[675]:   zigbee2mqtt:info 2019-12-26 12:28:13 MQTT publish: topic 'zigbee2mqtt/sensors/occupancy/bm/stairs/last_seen', payload '2019-12-26T12:28:13+01:00'
Dez 26 12:28:13 rpi npm[675]:   zigbee2mqtt:info 2019-12-26 12:28:13 Zigbee publish to device 'bulbs/bm/stairs/ceilinglight', genLevelCtrl - moveToLevelWithOnOff - {"level":650,"transtime":0} - {"manufSpec":0,"disDefaultRsp":0} - 1
Dez 26 12:28:13 rpi npm[675]:   zigbee2mqtt:error 2019-12-26 12:28:13 Zigbee publish to device 'bulbs/bm/stairs/ceilinglight', genLevelCtrl - moveToLevelWithOnOff - {"level":650,"transtime":0} - {"manufSpec":0,"disDefaultRsp":0} - null failed with error RangeError [ERR_OUT_OF_RANGE]: The value of "value" is out of range. It must be >= 0 and <= 255. Received 650
Dez 26 12:28:13 rpi npm[675]:   zigbee2mqtt:info 2019-12-26 12:28:13 MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"zigbee_publish_error","message":"RangeError [ERR_OUT_OF_RANGE]: The value of \"value\" is out of range. It must be >= 0 and <= 255. Received 650","meta":{"entity":{"ID":"0xd0cf5efffeda0e40","type":"device","friendlyName":"bulbs/bm/stairs/ceilinglight"},"message":"255.0"}}'

MQTT log switching the light from PaperUI

Using a switch

Dez 26 12:32:55 rpi npm[675]:   zigbee2mqtt:info 2019-12-26 12:32:55 Zigbee publish to device 'bulbs/bm/stairs/ceilinglight', genOnOff - on - {} - {"manufSpec":0,"disDefaultRsp":0} - 1
Dez 26 12:32:55 rpi npm[675]:   zigbee2mqtt:info 2019-12-26 12:32:55 MQTT publish: topic 'zigbee2mqtt/bulbs/bm/stairs/ceilinglight/state', payload 'ON'
Dez 26 12:32:55 rpi npm[675]:   zigbee2mqtt:info 2019-12-26 12:32:55 MQTT publish: topic 'zigbee2mqtt/bulbs/bm/stairs/ceilinglight/linkquality', payload '52'
Dez 26 12:32:55 rpi npm[675]:   zigbee2mqtt:info 2019-12-26 12:32:55 MQTT publish: topic 'zigbee2mqtt/bulbs/bm/stairs/ceilinglight/brightness', payload '0'
Dez 26 12:32:55 rpi npm[675]:   zigbee2mqtt:info 2019-12-26 12:32:55 MQTT publish: topic 'zigbee2mqtt/bulbs/bm/stairs/ceilinglight/last_seen', payload '2019-12-26T12:32:55+01:00'

Using a dimmer

Dez 26 12:34:11 rpi npm[675]:   zigbee2mqtt:info 2019-12-26 12:34:11 Zigbee publish to device 'bulbs/bm/stairs/ceilinglight', genLevelCtrl - moveToLevelWithOnOff - {"level":650,"transtime":0} - {"manufSpec":0,"disDefaultRsp":0} - 1
Dez 26 12:34:11 rpi npm[675]:   zigbee2mqtt:error 2019-12-26 12:34:11 Zigbee publish to device 'bulbs/bm/stairs/ceilinglight', genLevelCtrl - moveToLevelWithOnOff - {"level":650,"transtime":0} - {"manufSpec":0,"disDefaultRsp":0} - null failed with error RangeError [ERR_OUT_OF_RANGE]: The value of "value" is out of range. It must be >= 0 and <= 255. Received 650
Dez 26 12:34:11 rpi npm[675]:   zigbee2mqtt:info 2019-12-26 12:34:11 MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"zigbee_publish_error","message":"RangeError [ERR_OUT_OF_RANGE]: The value of \"value\" is out of range. It must be >= 0 and <= 255. Received 650","meta":{"entity":{"ID":"0xd0cf5efffeda0e40","type":"device","friendlyName":"bulbs/bm/stairs/ceilinglight"},"message":"255.0"}}'
Dez 26 12:34:11 rpi npm[675]:   zigbee2mqtt:info 2019-12-26 12:34:11 Zigbee publish to device 'bulbs/bm/stairs/ceilinglight', genLevelCtrl - moveToLevelWithOnOff - {"level":650,"transtime":0} - {"manufSpec":0,"disDefaultRsp":0} - 1
Dez 26 12:34:11 rpi npm[675]:   zigbee2mqtt:error 2019-12-26 12:34:11 Zigbee publish to device 'bulbs/bm/stairs/ceilinglight', genLevelCtrl - moveToLevelWithOnOff - {"level":650,"transtime":0} - {"manufSpec":0,"disDefaultRsp":0} - null failed with error RangeError [ERR_OUT_OF_RANGE]: The value of "value" is out of range. It must be >= 0 and <= 255. Received 650
Dez 26 12:34:11 rpi npm[675]:   zigbee2mqtt:info 2019-12-26 12:34:11 MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"zigbee_publish_error","message":"RangeError [ERR_OUT_OF_RANGE]: The value of \"value\" is out of range. It must be >= 0 and <= 255. Received 650","meta":{"entity":{"ID":"0xd0cf5efffeda0e40","type":"device","friendlyName":"bulbs/bm/stairs/ceilinglight"},"message":"255.0"}}'

So, obviously OH sends a brightness value of 650 to the bulbs which gets rejected. Thing is: I don’t know why. I forgot to post my things and items. I don’t see a mistake in it (and it worked in 2.4.x).

Things

$ cat /etc/openhab2/things/tradfri.lights.things 

//---------
// BATHROOM
//---------


Thing mqtt:topic:tfb1br1 "Deckenlampe" (mqtt:broker:zigbee2mqtt) @ "Bad" {
    Channels:
        Type switch : switch "An/Aus" [
            stateTopic="zigbee2mqtt/bulbs/gf/bathroom/ceiling1/state",
            commandTopic="zigbee2mqtt/bulbs/gf/bathroom/ceiling1/set/state",
            on="ON", off="OFF",
            retained=true
        ]
        Type dimmer : brightness "Helligkeit" [
            stateTopic="zigbee2mqtt/bulbs/gf/bathroom/ceiling1/brightness",
            commandTopic="zigbee2mqtt/bulbs/gf/bathroom/ceiling1/set/brightness_percent",
            formatBeforePublish="%d",
            min=0, max=255,
            off="OFF", on="ON",
            retained=true
        ] 
        Type switch : availability "Availability" [
            stateTopic="zigbee2mqtt/bulbs/gf/bathroom/ceiling1/availability",
            off="offline", on="online",
            retained=true
        ]
        Type dimmer : linkquality "Verbindungsqualität" [
            stateTopic="zigbee2mqtt/bulbs/gf/bathroom/ceiling1/linkquality",
            min=0, max=255,
            retained=true
        ]
        Type datetime : lastseen "Zuletzt online" [stateTopic="zigbee2mqtt/bulbs/gf/bathroom/ceiling1/last_seen", retained=true] 
}

//---------
// STAIRS
//---------

Thing mqtt:topic:tfb0st1 "Deckenlampe" (mqtt:broker:zigbee2mqtt) @ "Treppe" {
    Channels:
        Type switch : switch "An/Aus" [
            stateTopic="zigbee2mqtt/bulbs/bm/stairs/ceilinglight/state",
            commandTopic="zigbee2mqtt/bulbs/bm/stairs/ceilinglight/set/state",
            on="ON", off="OFF",
            retained=true
        ]
        Type dimmer : brightness "Helligkeit" [
            stateTopic="zigbee2mqtt/bulbs/bm/stairs/ceilinglight/brightness",
            commandTopic="zigbee2mqtt/bulbs/bm/stairs/ceilinglight/set/brightness_percent",
            formatBeforePublish="%d",
            min=0, max=255,
            off="OFF", on="ON",
            retained=true
        ] 
        Type switch : availability "Availability" [
            stateTopic="zigbee2mqtt/bulbs/bm/stairs/ceilinglight/availability",
            off="offline", on="online",
            retained=true
        ]
        Type dimmer : linkquality "Verbindungsqualität" [
            stateTopic="zigbee2mqtt/bulbs/bm/stairs/ceilinglight/linkquality",
            min=0, max=255,
            retained=true
        ]
        Type datetime : lastseen "Zuletzt online" [stateTopic="zigbee2mqtt/bulbs/bm/stairs/ceilinglight/last_seen", retained=true] 
}

Items

///// Bathroom /////
Switch      Light_GF_Bathroom_CeilingLights_MainLight_Switch         "An/Aus"                                <DimmableLight>     (gFP_Lights)    {channel="mqtt:topic:tfb1br1:switch"}
Dimmer      Light_GF_Bathroom_CeilingLights_MainLight_Brightness     "Helligkeit [%d %%]"                    <DimmableLight>     (gFP_Lights)    {channel="mqtt:topic:tfb1br1:brightness"}
DateTime    Light_GF_Bathroom_CeilingLights_MainLight_LastSeen       "Zuletzt [%1$ta %1$td. %1$tb %1$tR]"    <Time>              (gFP_Lights)    {channel="mqtt:topic:tfb1br1:lastseen"}
Dimmer      Light_GF_Bathroom_CeilingLights_MainLight_LinkQuality    "Signalstärke [%d %%]"                  <qualityofservice>  (gFP_Lights)    {channel="mqtt:topic:tfb1br1:linkquality"}
Switch      Light_GF_Bathroom_CeilingLights_MainLight_Availability   "Online"                                <switch>            (gFP_Lights)    {channel="mqtt:topic:tfb1br1:availability"}


////////// Basement //////////

///// Stairs /////
Switch      Light_BM_Stairs_CeilingLights_MainLight_Switch         "An/Aus"                                <DimmableLight>     (gFP_Lights)    {channel="mqtt:topic:tfb0st1:switch"}
Dimmer      Light_BM_Stairs_CeilingLights_MainLight_Brightness     "Helligkeit [%d %%]"                    <DimmableLight>     (gFP_Lights)    {channel="mqtt:topic:tfb0st1:brightness"}
DateTime    Light_BM_Stairs_CeilingLights_MainLight_LastSeen       "Zuletzt [%1$ta %1$td. %1$tb %1$tR]"    <Time>              (gFP_Lights)    {channel="mqtt:topic:tfb0st1:lastseen"}
Dimmer      Light_BM_Stairs_CeilingLights_MainLight_LinkQuality    "Signalstärke [%d %%]"                  <qualityofservice>  (gFP_Lights)    {channel="mqtt:topic:tfb0st1:linkquality"}
Switch      Light_BM_Stairs_CeilingLights_MainLight_Availability   "Online"                                <switch>            (gFP_Lights)    {channel="mqtt:topic:tfb0st1:availability"}

Any thoughts on this?

Kind regards

PS: The logs are from the stairs light because the bathroom is currently occupied :smiley: :joy:

Hmm, well we know it starts off as a command 100 within openHAB.
Your MQTT channel is configured with min/max 0-255 for scaling.
So the MQTT binding should be sending out 255.
You haven’t shown us what passes between OH and broker, but there’s no reason to think that isn’t working.
The target here is not a simple device though, it is zigbee2mqtt
Let’s consider what happens if that is set up to expect 0-100 mqtt data, that needs converting to 0-255 data for zigbee.
If it does a simple “multiply by 2.55” and applies that to incoming 255 … you get 650

I think you either need to set up zigbee2mqtt for no scaling (no idea how to do that) or remove the 255 scaling at openHAB.

Other users also experienced lags with CC2531 and OH 2.5 (see Zigbee binding stopped working since 2.5 M4). Maybe there is an underlying issue that affects both zigbee2mqtt and zigbee binding? Is this a possiblity? (I don’t know enough about openhab architecture to judge this.)

Users other than yourself? I have heard of none. Since zigbee2mqtt is maintained by completely different people than the zigbee binding, the only commonalities (other than the Zigbee RF environment) would be OS and openHAB core, I would expect.

To be precise: three others, namely “m0rgoth” (who reported the issue), “Markus.P” and “georgcampana”.

1 Like

Sorry. I quickly (too quickly, apparently) scanned that thread and missed there were multiple users that showed me the same “m” icon. :scream:
I did not notice whether anybody filed a GitHub Issue against core to get this noticed.

1 Like

It is possible there is an addon bundle/binding interaction causing issues. Perhaps people could compare installed binding or bundles to help isolate the issue. This type of problem is not unheard of here.

I think the big changes in M4 involved a new version of Karaf and better enforcement of syntax rules. Instead of logging, they either break the system or cause an addon reload every minute trying to load invalid data.

Hi,

I think, exactly this was the problem. It seems something changed here from 2.4.x to 2.5.

If you look closely, the commandTopic of the brightness channel is zigbee2mqtt/bulbs/gf/bathroom/ceiling1/set/brightness_percent. I’d guess the math changed somewhere and the value gets multiplied two times :man_shrugging:

I reset min to 0 and max to 100, cleaned caches and restart the RPi and it seems to work just fine now. Let’s just hope the linked issue doesn’t hit me, too…

Thanks