Timer sometimes does not expire

hansblafoo · December 30, 2018, 10:16am

Hi there,

I’m running openhab 2.4.0-1 and I’m experiencing some troubles with the expire binding recently. In my corridor, I have an Aqara Human Body Sensor and a Philips Hue Light. If the body sensor detects movements (and it is not too bright), the Hue bulb is triggered to switch into a dimmed state (either 30 or 100 percent, depending on brightness and time). A timer (Switch item with expire binding for 75s) is also started in order to turn the light off. This works around 90% of the time, but in the remainder, the timer never expires. I haven’t found any pattern yet to isolate the problem, but maybe, you have an idea.

As you can see, I followed the Timer design pattern shown here in the forums, but maybe I’m missing an important point. Is there something wrong with my rule/item configuration? Or is this a known bug?

Thanks in advance!

Hans

My items file:

Switch Flur_hinten_Hue1_Switch "Lampe (Flur hinten) [%s]"         <light> {mqtt=">[broker:zigbee2mqtt/flur_hinten_hue1/set:command:*:JS(setZigbeeState.js)],<[broker:zigbee2mqtt/flur_hinten_hue1:state:JSONPATH($.state)]"}
Switch Flur_hinten_Hue1_Switch_Timer {expire="75s,command=OFF"}
Dimmer Flur_hinten_Hue1_Dimm "Lampe (Flur hinten) Dimm"         <light>  {mqtt=">[broker:zigbee2mqtt/flur_hinten_hue1/set:command:*:JS(setZigbeeBrightness.js)],<[broker:zigbee2mqtt/flur_hinten_hue1:state:JS(getZigbeeBrightness.js)]"}
Switch Flur_hinten_Human_Body_Sensor1_MOTION "Bewegung (Flur hinten) [%s]" &lt;motion&gt; {mqtt="&lt;[broker:zigbee2mqtt/flur_hinten_human_body_sensor1:state:JS(getZigbeeOccupancy2Switch.js)]" }
Number Flur_hinten_Human_Body_Sensor1_BRIGHTNESS "Helligkeit (Flur hinten) [%d lumen]" {mqtt="&lt;[broker:zigbee2mqtt/flur_hinten_human_body_sensor1:state:JSONPATH($.illuminance)]"}

My rules file:

rule "Flur_hinten_Hue_Auto_Licht"
when
    Item Flur_hinten_Human_Body_Sensor1_MOTION changed to ON  
then
    logInfo("FILE", "Flurbewegungssensor hat Status auf ON geändert")

    if(Flur_hinten_Human_Body_Sensor1_BRIGHTNESS.state < 3 && now.getHourOfDay < 22 && now.getHourOfDay >= 8) {
        logInfo("FILE", "Zeige 100% Helligkeit")
        Flur_hinten_Hue1_Dimm.sendCommand(100);
    }
    else if(Flur_hinten_Human_Body_Sensor1_BRIGHTNESS.state < 10) {
        logInfo("FILE", "Zeige 30% Helligkeit")
        Flur_hinten_Hue1_Dimm.sendCommand(30);
    }

    //timer reset
    logInfo("FILE", "Setze den Lampentimer zurück")
    Flur_hinten_Hue1_Switch_Timer.postUpdate(OFF)

    //start the timer
    logInfo("FILE", "Starte den Lampentimer")
    Flur_hinten_Hue1_Switch_Timer.sendCommand(ON)
end

rule "Flur_hinten_Hue1_Switch_Timer expired"
when
    Item Flur_hinten_Hue1_Switch_Timer received command OFF
then
    logInfo("FILE", "Lampentimer hat off erhalten")
    // Timer body
    Flur_hinten_Hue1_Switch.sendCommand(OFF)
end

Logs:

//HAPPY CASE: everything works as expected
2018-12-30 01:45:58.555 [vent.ItemStateChangedEvent] - Flur_hinten_Human_Body_Sensor1_MOTION changed from OFF to ON
2018-12-30 01:45:58.573 [INFO ] [.eclipse.smarthome.model.script.FILE] - Flurbewegungssensor hat Status auf ON geändert
2018-12-30 01:45:58.607 [INFO ] [.eclipse.smarthome.model.script.FILE] - Zeige 30% Helligkeit
2018-12-30 01:45:58.617 [ome.event.ItemCommandEvent] - Item 'Flur_hinten_Hue1_Dimm' received command 30
2018-12-30 01:45:58.617 [INFO ] [.eclipse.smarthome.model.script.FILE] - Setze den Lampentimer zurück
2018-12-30 01:45:58.628 [INFO ] [.eclipse.smarthome.model.script.FILE] - Starte den Lampentimer
2018-12-30 01:45:58.645 [ome.event.ItemCommandEvent] - Item 'Flur_hinten_Hue1_Switch_Timer' received command ON
2018-12-30 01:45:58.650 [vent.ItemStateChangedEvent] - Flur_hinten_Hue1_Dimm changed from 29.80392156862745 to 30
2018-12-30 01:45:58.663 [vent.ItemStateChangedEvent] - Flur_hinten_Hue1_Switch_Timer changed from OFF to ON
2018-12-30 01:45:58.784 [vent.ItemStateChangedEvent] - Flur_hinten_Hue1_Switch_Timer changed from ON to OFF
2018-12-30 01:45:58.987 [vent.ItemStateChangedEvent] - Flur_hinten_Hue1_Dimm changed from 30 to 29.80392156862745
2018-12-30 01:46:58.399 [vent.ItemStateChangedEvent] - Flur_hinten_Human_Body_Sensor1_MOTION changed from ON to OFF
2018-12-30 01:47:14.206 [ome.event.ItemCommandEvent] - Item 'Flur_hinten_Hue1_Switch_Timer' received command OFF
2018-12-30 01:47:14.229 [vent.ItemStateChangedEvent] - Flur_hinten_Hue1_Switch_Timer changed from ON to OFF
2018-12-30 01:47:14.265 [INFO ] [.eclipse.smarthome.model.script.FILE] - Lampentimer hat off erhalten
2018-12-30 01:47:14.286 [ome.event.ItemCommandEvent] - Item 'Flur_hinten_Hue1_Switch' received command OFF
2018-12-30 01:47:14.311 [vent.ItemStateChangedEvent] - Flur_hinten_Hue1_Switch changed from ON to OFF

//BAD CASE: Flur_hinten_Hue1_Switch_Timer does not expire
2018-12-30 01:58:15.958 [INFO ] [.eclipse.smarthome.model.script.FILE] - Flurbewegungssensor hat Status auf ON geändert
2018-12-30 01:58:15.973 [vent.ItemStateChangedEvent] - Flur_hinten_Human_Body_Sensor1_MOTION changed from OFF to ON
2018-12-30 01:58:15.997 [INFO ] [.eclipse.smarthome.model.script.FILE] - Zeige 30% Helligkeit
2018-12-30 01:58:16.008 [ome.event.ItemCommandEvent] - Item 'Flur_hinten_Hue1_Dimm' received command 30
2018-12-30 01:58:16.008 [INFO ] [.eclipse.smarthome.model.script.FILE] - Setze den Lampentimer zurück
2018-12-30 01:58:16.019 [INFO ] [.eclipse.smarthome.model.script.FILE] - Starte den Lampentimer
2018-12-30 01:58:16.037 [ome.event.ItemCommandEvent] - Item 'Flur_hinten_Hue1_Switch_Timer' received command ON
2018-12-30 01:58:16.060 [vent.ItemStateChangedEvent] - Flur_hinten_Hue1_Switch_Timer changed from OFF to ON
2018-12-30 01:58:16.174 [vent.ItemStateChangedEvent] - Flur_hinten_Hue1_Dimm changed from 29.80392156862745 to 30
2018-12-30 01:58:16.296 [vent.ItemStateChangedEvent] - Flur_hinten_Hue1_Switch changed from OFF to ON
2018-12-30 01:58:16.428 [vent.ItemStateChangedEvent] - Flur_hinten_Hue1_Dimm changed from 30 to 29.80392156862745
2018-12-30 01:59:15.824 [vent.ItemStateChangedEvent] - Flur_hinten_Human_Body_Sensor1_MOTION changed from ON to OFF

Platform information:
- Hardware: RPi 2B+
- OS: OpenHabian (last release) with Raspbian stretch
- Java Runtime Environment: openjdk 1.8.0_152
- openHAB version: 2.4.0-1

rossko57 · December 30, 2018, 11:47am

hansblafoo:

//timer reset
 logInfo("FILE", "Setze den Lampentimer zurück")
 Flur_hinten_Hue1_Switch_Timer.postUpdate(OFF)
 //start the timer
 logInfo("FILE", "Starte den Lampentimer")
 Flur_hinten_Hue1_Switch_Timer.sendCommand(ON)

I don’t like this bit, although I haven’t worked out the consequences exactly.
What is the purpose of the OFF update?
Bear in mind the expire timer will be reset and started anew by the following command anyway, regardless of what state the Item has.

openHAB multi-threading means this kind of action may not work out as you expect.
The rule will fire off an OFF-update and an ON-command onto the OH event bus. At some later time, OH will process those. But they won’t necessarily finish their work in the same order they started in.

In particular, if the target Item gets updated to OFF after the command-ON has started the expire timer, that timer will be cancelled i.e. no command-OFF comes from expire if the target Item is already state OFF.

hansblafoo · December 30, 2018, 12:39pm

Thanks a lot for your reply. I just commented these lines in the rules file and I will see whether this behaviour does not occur anymore.

I followed the design pattern proposed here Design Pattern: Expire Binding Based Timers and I thought that this OFF update might be necessary in order to maintain a consistent internal state of the item. However, if openHab is multithreaded that heavily, it is logical that this might happen and since it looks like a race condition, it is very likely that this is true. However, I don’t see why even in this small piece of code, multithreading should be used. Synchronizing via the item object seems to be really natural to me but it does not seem to work this way.

rossko57 · December 30, 2018, 1:07pm

It’s not that the rule is getting multithreaded, this goes to the heart of how openHAB works with its event bus. In this case you fire off a postUpdate and a sendCommand. The rule doesn’t process this directly, they get passed to several other parts of OH - there’ll be an Item updater, bindings listening for events (like expire binding), autoupdate listening for commands and perhaps making more updates, etc.

It’s just a thought shift. e.g. if you issue a command to an Item and want X to happen when it changes state - then you should make a separate rule to do X listening for state change, not assume that happens immediately where you issue the command.
Another way to look at it is considering the Item object as modeled on a real world device rather than programmers variable.

vzorglub · December 30, 2018, 5:48pm

This may be the cause of your problem:

  //timer reset
    logInfo("FILE", "Setze den Lampentimer zurück")
    Flur_hinten_Hue1_Switch_Timer.postUpdate(OFF)

    //start the timer
    logInfo("FILE", "Starte den Lampentimer")
    Flur_hinten_Hue1_Switch_Timer.sendCommand(ON)

Why reseting the timer with an OFF update before sending an ON command?
The two instructions may be colliding in the binding.
Sending an ON command will also reset the timer
Just do:

    //start the timer
    logInfo("FILE", "Starte den Lampentimer")
    Flur_hinten_Hue1_Switch_Timer.sendCommand(ON)

hansblafoo · December 30, 2018, 7:23pm

Jepp, already changed it this way and I’m looking whether the problems are gone now.