Problem with Hue switches randomly reporting 4XXX action when pressing any of the other buttons

nelson.aponte · September 25, 2023, 9:22pm

I’m running OH 4.0.3 on an RPi 4 with CentOS 8.

When I upgraded to 4.03 from 3.4, I also implemented the API v2. After that, I started facing an issue with the rule that handles the actions from the Dimmer Switch, where pressing the 1st button randomly generates, apart from the 100X action, a 4003.

I have faced the issue multiple times but, I haven’t been able to reproduce it deterministically. I enabled the TRACE logging level for the Hue binding, but it generates so much text that it’s almost unmanageable taking into account that the issue seems random at the moment.

Is anyone else facing the same issue?

Here is the rule. The conditions for 100X actions are at the beginning, and the 4003 is at the end. They are all else if, so there shouldn’t be a way to jump from within a 100X case to the 4003.
I would like to note that none of the items affected by the sendCommands has any related rule that would trigger the 4003 to happen.

rule "Main Dimmer Button Pressed"
when
    Item HM_Switch_Dimmer_1_Event received command
then
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Dimmer Switch Button pressed.")
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Button pressed: " + HM_Switch_Dimmer_1_Event.state.toString)
    if (HM_Switch_Dimmer_1_Event.state.toString == "1002") {
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Starting execution of Dimmer Button 1 short pressed.")
        if (group_LR_Lamp_Switch.state == OFF) {
            group_LR_Lamp_Switch.sendCommand(ON)
        } else if (group_LR_Lamp_Switch.state == ON) {
            group_LR_Lamp_Switch.sendCommand(OFF)
        }
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Ending execution of Dimmer Button 1 short pressed.")
    } else if (HM_Switch_Dimmer_1_Event.state.toString == "1000") {
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Starting execution of Dimmer Button 1 initial pressed.")
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Ending execution of Dimmer Button 1 initial pressed.")
    } else if (HM_Switch_Dimmer_1_Event.state.toString == "1001") {
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Starting execution of Dimmer Button 1 hold.")
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Ending execution of Dimmer Button 1 hold.")
    } else if (HM_Switch_Dimmer_1_Event.state.toString == "1003") {
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Starting execution of Dimmer Button 1 long pressed.")
        if (LR2_Light_Switch.state == OFF) {
            LR2_Light_Switch.sendCommand(ON)
        } else {
            LR2_Light_Switch.sendCommand(OFF)
        }
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Ending execution of Dimmer Button 1 long pressed.")
    } else if (HM_Switch_Dimmer_1_Event.state.toString == "2002") {
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Starting execution of Dimmer Button 2 short pressed.")
        if (KT_Light_Switch.state == OFF) {
        KT_Light_Switch.sendCommand(ON)
        } else if (KT_Light_Switch.state == ON) {
        KT_Light_Switch.sendCommand(OFF)
        }
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Ending execution of Dimmer Button 2 short pressed.")
    } else if (HM_Switch_Dimmer_1_Event.state.toString == "2003") {
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Starting execution of Dimmer Button 2 long pressed.")
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Ending execution of Dimmer Button 2 long pressed.")
    } else if (HM_Switch_Dimmer_1_Event.state.toString == "3002") {
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Starting execution of Dimmer Button 3 short pressed.")
        if (group_TL_Lamp_Switch.state == OFF) {
            group_TL_Lamp_Switch.sendCommand(ON)
        } else if (group_TL_Lamp_Switch.state == ON) {
            group_TL_Lamp_Switch.sendCommand(OFF)
        }
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Ending execution of Dimmer Button 3 short pressed.")
    } else if (HM_Switch_Dimmer_1_Event.state.toString == "3003") {
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Starting execution of Dimmer Button 3 long pressed.")
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Ending execution of Dimmer Button 3 long pressed.")
    } else if (HM_Switch_Dimmer_1_Event.state.toString == "4002") {
        logDebug(logName, "'Main Dimmer Button Pressed' rule> Starting execution of Dimmer Button 4 short pressed.")
        if (Override_Home_Away.state == OFF) {
            if (Override_Sleep_Mode.state == OFF) {
                Override_Sleep_Mode.sendCommand(ON)
            } else {
                Override_Sleep_Mode.sendCommand(OFF)
            }
        }
        logDebug(logName, "Ending execution of Dimmer Button 4 short pressed.")
    } else if (HM_Switch_Dimmer_1_Event.state.toString == "4003") {
        logDebug(logName, "Starting execution of Dimmer Button 4 long pressed.")
        if (Override_Home_Away.state == OFF) {
            Override_Home_Away.sendCommand(ON)
        } else {
            Override_Home_Away.sendCommand(OFF)
        }
        logDebug(logName, "execution of Dimmer Button 4 long pressed.")    }
end

AndrewFG · September 26, 2023, 6:39am

I would need to see the log text in order to try to fix the issue. I suggest to leave the trace logging running until you see the issue again, and then send me the part of the log from around the time when the issue occurs.

nelson.aponte · September 26, 2023, 6:55am

I’ll do that as soon as I can!
Thanks for your prompt response.

nelson.aponte · October 2, 2023, 9:55pm

Hi.

I have to say that I’ve had the TRACE log running for days but I haven’t been able to reproduce the issue again.
I also updated the bride’s OS a couple of days ago to 1.60.1960062030 and nothing.

nelson.aponte · February 12, 2024, 3:08pm

Hi, @AndrewFG. After a long time, I finally took the time to get some logs and more details.

As a reminder, I have been having problems with my Dimmer and Tap switches since I migrated from the API V1 to the V2. Before that, there was no issue. The rules remained the same.

Occasionally, they trigger an incorrect rule, as if the binding was silently sending the wrong button-last-event value. However, the behavior is not consistent. The problem itself is that sometimes pressing any of the buttons (e.g., 3XXX) generates instead a 4XXX, or at least, the rule for the 4002 is triggered. I cannot consistently reproduce it.

I experience the problem regardless of whether the rule is coded in DSL Rules or Scala (Java - JRule Automation). I’m in the process of migrating my rules from DSL to Scala, yet I faced the problem before I started migrating anything and even after I migrated the rules for the switches.

As you can see below, both in the DSL and Scala versions there is only 1 place in the whole rules library where the incorrectly triggered condition is present, that is, in the file containing the rules for the switches.

DSL Rules

Scala

When I press the 1st button (for example) of the dimmer switch, this is what is shown in the hue logs. The log doesn’t show that the event was 4000

2024-02-02 17:00:45.398 [DEBUG] [e.internal.handler.C4000:lip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateChannels() from resource id:f95fe-e180-46f2-9eb8-8263d247, type:motion
2024-02-02 17:00:45.398 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'motion' update with 'ON' (fullUpdate:false, isDefined:true)
2024-02-02 17:00:45.399 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'motion-last-updated' update with '2024-02-02T17:00:46.129+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:00:45.399 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'last-updated' update with '2024-02-02T17:00:45.399247020+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:00:45.399 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> onResource() consumed resource id:f95fe-e180-46f2-9eb8-8263d247, type:motion
2024-02-02 17:00:46.404 [TRACE] [.hue.internal.connection.Clip2Bridge] - onEventData() data:[{"creationtime":"2024-02-02T16:00:46Z","data":[{"id":"d2d47-5cdb-428a-bd1e-6d4d3ea25","id_v1":"/sensors/85","light":{"light_level":7380,"light_level_report":{"changed":"2024-02-02T16:00:46.378Z","light_level":7380},"light_level_valid":true},"owner":{"rid":"12e169ad-ba67-41a0-8623-a33f0db","rtype":"device"},"type":"light_level"}],"id":"93420ae9-b5b3-4ed7-bdcb-3f21089a9e92","type":"update"}]
2024-02-02 17:00:46.405 [DEBUG] [.internal.handler.Clip2BridgeHandler] - onResourcesEventTask() resource count 1
2024-02-02 17:00:46.405 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateChannels() from resource id:d2d47-5cdb-428a-bd1e-6d4d3ea25, type:light_level
2024-02-02 17:00:46.405 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'light-level' update with '4.470159628939716 lx' (fullUpdate:false, isDefined:true)
2024-02-02 17:00:46.406 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'light-level-last-updated' update with '2024-02-02T17:00:46.378+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:00:46.406 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'last-updated' update with '2024-02-02T17:00:46.406192546+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:00:46.406 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> onResource() consumed resource id:d2d47-5cdb-428a-bd1e-6d4d3ea25, type:light_level
2024-02-02 17:00:50.526 [TRACE] [.hue.internal.connection.Clip2Bridge] - onEventData() data:[{"creationtime":"2024-02-02T16:00:51Z","data":[{"button":{"button_report":{"event":"initial_press","updated":"2024-02-02T16:00:51.257Z"},"last_event":"initial_press"},"id":"4a230-606b-4608-8e6b-787636854","id_v1":"/sensors/71","owner":{"rid":"8b9196ac-9193-4376-bbfd-0b25da8","rtype":"device"},"type":"button"}],"id":"20669363-a082-4e9c-8124-af5292f7e31e","type":"update"}]
2024-02-02 17:00:50.527 [DEBUG] [.internal.handler.Clip2BridgeHandler] - onResourcesEventTask() resource count 1
2024-02-02 17:00:50.527 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 8b9196ac-9193-4376-bbfd-0b25da8 -> updateChannels() from resource id:4a230-606b-4608-8e6b-787636854, type:button
2024-02-02 17:00:50.527 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 8b9196ac-9193-4376-bbfd-0b25da8 -> updateState() 'button-last-event' update with '1000' (fullUpdate:false, isDefined:true)
2024-02-02 17:00:50.528 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 8b9196ac-9193-4376-bbfd-0b25da8 -> updateState() 'button-last-updated' update with '2024-02-02T17:00:51.257+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:00:50.528 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 8b9196ac-9193-4376-bbfd-0b25da8 -> updateState() 'last-updated' update with '2024-02-02T17:00:50.528323514+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:00:50.528 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 8b9196ac-9193-4376-bbfd-0b25da8 -> onResource() consumed resource id:4a230-606b-4608-8e6b-787636854, type:button
2024-02-02 17:00:51.536 [TRACE] [.hue.internal.connection.Clip2Bridge] - onEventData() data:[{"creationtime":"2024-02-02T16:00:51Z","data":[{"id":"d2d47-5cdb-428a-bd1e-6d4d3ea25","id_v1":"/sensors/85","light":{"light_level":1360,"light_level_report":{"changed":"2024-02-02T16:00:51.451Z","light_level":1360},"light_level_valid":true},"owner":{"rid":"12e169ad-ba67-41a0-8623-a33f0db","rtype":"device"},"type":"light_level"}],"id":"4c94ab72-7523-4818-9363-a6ed040ef883","type":"update"}]
2024-02-02 17:00:51.536 [DEBUG] [.internal.handler.Clip2BridgeHandler] - onResourcesEventTask() resource count 1
2024-02-02 17:00:51.536 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateChannels() from resource id:d2d47-5cdb-428a-bd1e-6d4d3ea25, type:light_level
2024-02-02 17:00:51.537 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'light-level' update with '0.3677288255958491 lx' (fullUpdate:false, isDefined:true)
2024-02-02 17:00:51.537 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'light-level-last-updated' update with '2024-02-02T17:00:51.451+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:00:51.537 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'last-updated' update with '2024-02-02T17:00:51.537591863+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:00:51.537 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> onResource() consumed resource id:d2d47-5cdb-428a-bd1e-6d4d3ea25, type:light_level
2024-02-02 17:00:56.646 [TRACE] [.hue.internal.connection.Clip2Bridge] - onEventData() data:[{"creationtime":"2024-02-02T16:00:57Z","data":[{"id":"d2d47-5cdb-428a-bd1e-6d4d3ea25","id_v1":"/sensors/85","light":{"light_level":0,"light_level_report":{"changed":"2024-02-02T16:00:57.380Z","light_level":0},"light_level_valid":true},"owner":{"rid":"12e169ad-ba67-41a0-8623-a33f0db","rtype":"device"},"type":"light_level"}],"id":"e31f95e2-9-4849-869e-29ba960ce7ce","type":"update"}]
2024-02-02 17:00:56.647 [DEBUG] [.internal.handler.Clip2BridgeHandler] - onResourcesEventTask() resource count 1
2024-02-02 17:00:56.647 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateChannels() from resource id:d2d47-5cdb-428a-bd1e-6d4d3ea25, type:light_level
2024-02-02 17:00:56.647 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'light-level' update with '0 lx' (fullUpdate:false, isDefined:true)
2024-02-02 17:00:56.648 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'light-level-last-updated' update with '2024-02-02T17:00:57.380+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:00:56.648 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'last-updated' update with '2024-02-02T17:00:56.648488883+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:00:56.648 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> onResource() consumed resource id:d2d47-5cdb-428a-bd1e-6d4d3ea25, type:light_level
2024-02-02 17:01:09.909 [TRACE] [.hue.internal.connection.Clip2Bridge] - onEventData() data:[{"creationtime":"2024-02-02T16:01:10Z","data":[{"id":"f95fe-e180-46f2-9eb8-8263d247","id_v1":"/sensors/84","motion":{"motion":false,"motion_report":{"changed":"2024-02-02T16:01:10.645Z","motion":false},"motion_valid":true},"owner":{"rid":"12e169ad-ba67-41a0-8623-a33f0db","rtype":"device"},"type":"motion"}],"id":"49cedfd3-6a5d-48e7-bffc-3607c4056330","type":"update"}]
2024-02-02 17:01:09.909 [DEBUG] [.internal.handler.Clip2BridgeHandler] - onResourcesEventTask() resource count 1
2024-02-02 17:01:09.910 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateChannels() from resource id:f95fe-e180-46f2-9eb8-8263d247, type:motion
2024-02-02 17:01:09.910 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'motion' update with 'OFF' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:09.910 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'motion-last-updated' update with '2024-02-02T17:01:10.645+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:09.910 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'last-updated' update with '2024-02-02T17:01:09.910631995+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:09.910 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> onResource() consumed resource id:f95fe-e180-46f2-9eb8-8263d247, type:motion
2024-02-02 17:01:11.118 [TRACE] [.hue.internal.connection.Clip2Bridge] - onEventData() data:[{"creationtime":"2024-02-02T16:01:11Z","data":[{"id":"f95fe-e180-46f2-9eb8-8263d247","id_v1":"/sensors/84","motion":{"motion":true,"motion_report":{"changed":"2024-02-02T16:01:11.855Z","motion":true},"motion_valid":true},"owner":{"rid":"12e169ad-ba67-41a0-8623-a33f0db","rtype":"device"},"type":"motion"}],"id":"f2c80f00-4093-4549-a972-af562c330112","type":"update"}]
2024-02-02 17:01:11.118 [DEBUG] [.internal.handler.Clip2BridgeHandler] - onResourcesEventTask() resource count 1
2024-02-02 17:01:11.118 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateChannels() from resource id:f95fe-e180-46f2-9eb8-8263d247, type:motion
2024-02-02 17:01:11.118 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'motion' update with 'ON' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:11.119 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'motion-last-updated' update with '2024-02-02T17:01:11.855+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:11.119 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> updateState() 'last-updated' update with '2024-02-02T17:01:11.119452250+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:11.119 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 12e169ad-ba67-41a0-8623-a33f0db -> onResource() consumed resource id:f95fe-e180-46f2-9eb8-8263d247, type:motion
2024-02-02 17:01:11.137 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> handleCommand() put resource id:1d67-fabf-407a-a2f7-cd060787, type:light
2024-02-02 17:01:11.137 [DEBUG] [.internal.handler.Clip2BridgeHandler] - putResource() id:1d67-fabf-407a-a2f7-cd060787, type:light
2024-02-02 17:01:11.138 [TRACE] [.hue.internal.connection.Clip2Bridge] - PUT https://10.XX.XX.103/clip/v2/resource/light/1d67-fabf-407a-a2f7-cd060787 HTTP/2 >> {"type":"light","id":"1d67-fabf-407a-a2f7-cd060787","on":{"on":true}}
2024-02-02 17:01:11.211 [TRACE] [.hue.internal.connection.Clip2Bridge] - HTTP/2 207 (Content-Type: application/json) << {"data":[{"rid":"1d67-fabf-407a-a2f7-cd060787","rtype":"light"}],"errors":[{"description":"device (light) has communication issues, command (.on.on) may not have effect"}]}
2024-02-02 17:01:11.211 [INFO ] [e.internal.handler.Clip2ThingHandler] - Command 'ON' for thing 'hue:device:1:3', channel 'hue:device:1:3:color' succeeded with errors: device (light) has communication issues, command (.on.on) may not have effect
2024-02-02 17:01:11.215 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> handleCommand() put resource id:1d67-fabf-407a-a2f7-cd060787, type:light
2024-02-02 17:01:11.216 [DEBUG] [.internal.handler.Clip2BridgeHandler] - putResource() id:1d67-fabf-407a-a2f7-cd060787, type:light
2024-02-02 17:01:11.216 [TRACE] [.hue.internal.connection.Clip2Bridge] - PUT https://10.XX.XX.103/clip/v2/resource/light/1d67-fabf-407a-a2f7-cd060787 HTTP/2 >> {"type":"light","id":"1d67-fabf-407a-a2f7-cd060787","on":{"on":true},"dimming":{"brightness":10.0},"color":{"xy":{"x":0.5646,"y":0.4035}}}
2024-02-02 17:01:11.339 [TRACE] [.hue.internal.connection.Clip2Bridge] - HTTP/2 207 (Content-Type: application/json) << {"data":[{"rid":"1d67-fabf-407a-a2f7-cd060787","rtype":"light"}],"errors":[{"description":"device (light) has communication issues, command (.on.on) may not have effect"},{"description":"device (light) has communication issues, command (.dimming.brightness) may not have effect"},{"description":"device (light) has communication issues, command (.color.xy) may not have effect"}]}
2024-02-02 17:01:11.339 [INFO ] [e.internal.handler.Clip2ThingHandler] - Command 'ON' for thing 'hue:device:1:3', channel 'hue:device:1:3:color' succeeded with errors: device (light) has communication issues, command (.on.on) may not have effect; device (light) has communication issues, command (.dimming.brightness) may not have effect; device (light) has communication issues, command (.color.xy) may not have effect
2024-02-02 17:01:12.127 [TRACE] [.hue.internal.connection.Clip2Bridge] - onEventData() data:[{"creationtime":"2024-02-02T16:01:11Z","data":[{"id":"1d67-fabf-407a-a2f7-cd060787","id_v1":"/lights/3","on":{"on":true},"owner":{"rid":"df97-f416-46f8-8c2f-18ad0a8","rtype":"device"},"type":"light"}],"id":"58855a92-9965-4a35-a753-cd9be7fc731a","type":"update"},{"creationtime":"2024-02-02T16:01:12Z","data":[{"dimming":{"brightness":100.0},"id":"2c6e95d1-064c-4d75-9f7b-bd20d7ca12cb","id_v1":"/groups/3","on":{"on":true},"owner":{"rid":"fa3baffc-0714-43a4-bfa7-00b0b8c3abbc","rtype":"room"},"type":"grouped_light"}],"id":"fbef5b65-3137-4a4f-b8e1-40729b096f36","type":"update"},{"creationtime":"2024-02-02T16:01:12Z","data":[{"dimming":{"brightness":9.88},"id":"1d67-fabf-407a-a2f7-cd060787","id_v1":"/lights/3","owner":{"rid":"df97-f416-46f8-8c2f-18ad0a8","rtype":"device"},"type":"light"},{"color":{"xy":{"x":0.5646,"y":0.4035}},"color_temperature":{"mirek":null,"mirek_valid":false},"id":"1d67-fabf-407a-a2f7-cd060787","id_v1":"/lights/3","owner":{"rid":"df97-f416-46f8-8c2f-18ad0a8","rtype":"device"},"type":"light"}],"id":"27c94305-be69-410a-9169-b8ed9c9b5e8b","type":"update"},{"creationtime":"2024-02-02T16:01:12Z","data":[{"dimming":{"brightness":9.88},"id":"2c6e95d1-064c-4d75-9f7b-bd20d7ca12cb","id_v1":"/groups/3","owner":{"rid":"fa3baffc-0714-43a4-bfa7-00b0b8c3abbc","rtype":"room"},"type":"grouped_light"},{"dimming":{"brightness":77.47},"id":"5d88e7cb-e76c-4f34-9989-70cf41cdcf6f","id_v1":"/groups/0","owner":{"rid":"e7af0afc-f964-4b50-a400-64c3b587a4ec","rtype":"bridge_home"},"type":"grouped_light"}],"id":"4bee3718-62fc-4560-a2cd-6af1677e65f0","type":"update"}]
2024-02-02 17:01:12.128 [DEBUG] [.internal.handler.Clip2BridgeHandler] - onResourcesEventTask() resource count 6
2024-02-02 17:01:12.128 [DEBUG] [.internal.handler.Clip2BridgeHandler] - onResourcesEventTask() merged to 4 resources
2024-02-02 17:01:12.128 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateChannels() from resource id:1d67-fabf-407a-a2f7-cd060787, type:light
2024-02-02 17:01:12.128 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'color-temperature' update with 'UNDEF' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.128 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'color-temperature-abs' update with 'UNDEF' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.128 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'color' update with '33.803,86.69500,9.880' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.129 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'color-xy-only' update with '33.803,86.69500,100' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.129 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'effect' update with 'NO_EFFECT' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.129 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'dimming-only' update with '9.880' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.129 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'on-off-only' update with 'ON' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.129 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'alert' update with 'NO_ACTION' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.129 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'last-updated' update with '2024-02-02T17:01:12.129749937+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.129 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> onResource() consumed resource id:1d67-fabf-407a-a2f7-cd060787, type:light
2024-02-02 17:01:12.129 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateChannels() from resource id:1d67-fabf-407a-a2f7-cd060787, type:light
2024-02-02 17:01:12.130 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'color-temperature' update with 'UNDEF' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.130 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'color-temperature-abs' update with 'UNDEF' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.130 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'color' update with '33.803,86.69500,9.880' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.130 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'color-xy-only' update with '33.803,86.69500,100' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.130 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'effect' update with 'NO_EFFECT' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.130 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'dimming-only' update with '9.880' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.130 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'on-off-only' update with 'ON' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.131 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'alert' update with 'NO_ACTION' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.131 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'last-updated' update with '2024-02-02T17:01:12.131155049+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:12.131 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> onResource() consumed resource id:1d67-fabf-407a-a2f7-cd060787, type:light
2024-02-02 17:01:12.147 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> handleCommand() put resource id:1d67-fabf-407a-a2f7-cd060787, type:light
2024-02-02 17:01:12.147 [DEBUG] [.internal.handler.Clip2BridgeHandler] - putResource() id:1d67-fabf-407a-a2f7-cd060787, type:light
2024-02-02 17:01:12.147 [TRACE] [.hue.internal.connection.Clip2Bridge] - PUT https://10.XX.XX.103/clip/v2/resource/light/1d67-fabf-407a-a2f7-cd060787 HTTP/2 >> {"type":"light","id":"1d67-fabf-407a-a2f7-cd060787","on":{"on":true},"dimming":{"brightness":10.0},"color":{"xy":{"x":0.5646,"y":0.4035}}}
2024-02-02 17:01:12.168 [TRACE] [.hue.internal.connection.Clip2Bridge] - HTTP/2 207 (Content-Type: application/json) << {"data":[{"rid":"1d67-fabf-407a-a2f7-cd060787","rtype":"light"}],"errors":[{"description":"device (light) has communication issues, command (.on.on) may not have effect"},{"description":"device (light) has communication issues, command (.dimming.brightness) may not have effect"},{"description":"device (light) has communication issues, command (.color.xy) may not have effect"}]}
2024-02-02 17:01:12.168 [INFO ] [e.internal.handler.Clip2ThingHandler] - Command 'ON' for thing 'hue:device:1:3', channel 'hue:device:1:3:color' succeeded with errors: device (light) has communication issues, command (.on.on) may not have effect; device (light) has communication issues, command (.dimming.brightness) may not have effect; device (light) has communication issues, command (.color.xy) may not have effect
2024-02-02 17:01:12.172 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> handleCommand() put resource id:1d67-fabf-407a-a2f7-cd060787, type:light
2024-02-02 17:01:12.173 [DEBUG] [.internal.handler.Clip2BridgeHandler] - putResource() id:1d67-fabf-407a-a2f7-cd060787, type:light
2024-02-02 17:01:12.198 [TRACE] [.hue.internal.connection.Clip2Bridge] - PUT https://10.XX.XX.103/clip/v2/resource/light/1d67-fabf-407a-a2f7-cd060787 HTTP/2 >> {"type":"light","id":"1d67-fabf-407a-a2f7-cd060787","on":{"on":true},"dimming":{"brightness":10.0},"color":{"xy":{"x":0.5646,"y":0.4035}}}
2024-02-02 17:01:12.219 [TRACE] [.hue.internal.connection.Clip2Bridge] - HTTP/2 207 (Content-Type: application/json) << {"data":[{"rid":"1d67-fabf-407a-a2f7-cd060787","rtype":"light"}],"errors":[{"description":"device (light) has communication issues, command (.on.on) may not have effect"},{"description":"device (light) has communication issues, command (.dimming.brightness) may not have effect"},{"description":"device (light) has communication issues, command (.color.xy) may not have effect"}]}
2024-02-02 17:01:12.220 [INFO ] [e.internal.handler.Clip2ThingHandler] - Command 'ON' for thing 'hue:device:1:3', channel 'hue:device:1:3:color' succeeded with errors: device (light) has communication issues, command (.on.on) may not have effect; device (light) has communication issues, command (.dimming.brightness) may not have effect; device (light) has communication issues, command (.color.xy) may not have effect
2024-02-02 17:01:14.639 [TRACE] [.hue.internal.connection.Clip2Bridge] - onEventData() data:[{"creationtime":"2024-02-02T16:01:15Z","data":[{"button":{"button_report":{"event":"initial_press","updated":"2024-02-02T16:01:15.408Z"},"last_event":"initial_press"},"id":"4a230-606b-4608-8e6b-787636854","id_v1":"/sensors/71","owner":{"rid":"8b9196ac-9193-4376-bbfd-0b25da8","rtype":"device"},"type":"button"}],"id":"5dfc3f4b-0d39-4617-a05a-974a58be0b82","type":"update"}]
2024-02-02 17:01:14.640 [DEBUG] [.internal.handler.Clip2BridgeHandler] - onResourcesEventTask() resource count 1
2024-02-02 17:01:14.640 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 8b9196ac-9193-4376-bbfd-0b25da8 -> updateChannels() from resource id:4a230-606b-4608-8e6b-787636854, type:button
2024-02-02 17:01:14.640 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 8b9196ac-9193-4376-bbfd-0b25da8 -> updateState() 'button-last-event' update with '1000' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:14.640 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 8b9196ac-9193-4376-bbfd-0b25da8 -> updateState() 'button-last-updated' update with '2024-02-02T17:01:15.408+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:14.641 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 8b9196ac-9193-4376-bbfd-0b25da8 -> updateState() 'last-updated' update with '2024-02-02T17:01:14.641047320+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:14.641 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 8b9196ac-9193-4376-bbfd-0b25da8 -> onResource() consumed resource id:4a230-606b-4608-8e6b-787636854, type:button
2024-02-02 17:01:14.652 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> handleCommand() put resource id:1d67-fabf-407a-a2f7-cd060787, type:light
2024-02-02 17:01:14.653 [DEBUG] [.internal.handler.Clip2BridgeHandler] - putResource() id:1d67-fabf-407a-a2f7-cd060787, type:light
2024-02-02 17:01:14.653 [TRACE] [.hue.internal.connection.Clip2Bridge] - PUT https://10.XX.XX.103/clip/v2/resource/light/1d67-fabf-407a-a2f7-cd060787 HTTP/2 >> {"type":"light","id":"1d67-fabf-407a-a2f7-cd060787","on":{"on":false}}
2024-02-02 17:01:14.730 [TRACE] [.hue.internal.connection.Clip2Bridge] - HTTP/2 207 (Content-Type: application/json) << {"data":[{"rid":"1d67-fabf-407a-a2f7-cd060787","rtype":"light"}],"errors":[{"description":"device (light) has communication issues, command (.on.on) may not have effect"}]}
2024-02-02 17:01:14.730 [INFO ] [e.internal.handler.Clip2ThingHandler] - Command 'OFF' for thing 'hue:device:1:3', channel 'hue:device:1:3:color' succeeded with errors: device (light) has communication issues, command (.on.on) may not have effect
2024-02-02 17:01:15.646 [TRACE] [.hue.internal.connection.Clip2Bridge] - onEventData() data:[{"creationtime":"2024-02-02T16:01:15Z","data":[{"id":"1d67-fabf-407a-a2f7-cd060787","id_v1":"/lights/3","on":{"on":false},"owner":{"rid":"df97-f416-46f8-8c2f-18ad0a8","rtype":"device"},"type":"light"}],"id":"cf5aea56-fe4e-45be-95d4-b8d0e58185d9","type":"update"},{"creationtime":"2024-02-02T16:01:15Z","data":[{"dimming":{"brightness":0.0},"id":"2c6e95d1-064c-4d75-9f7b-bd20d7ca12cb","id_v1":"/groups/3","on":{"on":false},"owner":{"rid":"fa3baffc-0714-43a4-bfa7-00b0b8c3abbc","rtype":"room"},"type":"grouped_light"},{"dimming":{"brightness":100.0},"id":"5d88e7cb-e76c-4f34-9989-70cf41cdcf6f","id_v1":"/groups/0","owner":{"rid":"e7af0afc-f964-4b50-a400-64c3b587a4ec","rtype":"bridge_home"},"type":"grouped_light"}],"id":"7d48a819-ebe2-474c-9e47-f7d77eac71e8","type":"update"}]
2024-02-02 17:01:15.647 [DEBUG] [.internal.handler.Clip2BridgeHandler] - onResourcesEventTask() resource count 3
2024-02-02 17:01:15.647 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateChannels() from resource id:1d67-fabf-407a-a2f7-cd060787, type:light
2024-02-02 17:01:15.647 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'color-temperature' update with 'UNDEF' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:15.647 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'color-temperature-abs' update with 'UNDEF' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:15.648 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'color' update with '33.803,86.69500,0' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:15.648 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'color-xy-only' update with '33.803,86.69500,100' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:15.648 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'effect' update with 'NO_EFFECT' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:15.648 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'dimming-only' update with '9.880' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:15.649 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'on-off-only' update with 'OFF' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:15.649 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'alert' update with 'NO_ACTION' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:15.649 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> updateState() 'last-updated' update with '2024-02-02T17:01:15.649545585+0100' (fullUpdate:false, isDefined:true)
2024-02-02 17:01:15.649 [DEBUG] [e.internal.handler.Clip2ThingHandler] - df97-f416-46f8-8c2f-18ad0a8 -> onResource() consumed resource id:1d67-fabf-407a-a2f7-cd060787, type:light
2024-02-02 17:01:25.638 [TRACE] [.hue.internal.connection.Clip2Bridge] - onEventData() data:[{"creationtime":"2024-02-02T16:01:26Z","data":[{"id":"f95fe-e180-46f2-9eb8-8263d247","id_v1":"/sensors/84","motion":{"motion":false,"motion_report":{"changed":"2024-02-02T16:01:26.380Z","motion":false},"motion_valid":true},"owner":{"rid":"12e169ad-ba67-41a0-8623-a33f0db","rtype":"device"},"type":"motion"}],"id":"1c8154a3-8acd-4e85-b1d2-cdfbc3bb6585","type":"update"}]
2024-02-02 17:01:25.638 [DEBUG] [.internal.handler.Clip2BridgeHandler] - onResourcesEventTask() resource count 1

And the rule logs:

2024-02-02 17:00:00.445 [INFO ] [openhab.automation.jrule.rules.JRule] - [TEST] Test > STARTING.
2024-02-02 17:00:00.446 [INFO ] [openhab.automation.jrule.rules.JRule] - [TEST] 2024-02-02T17:00:00.446431659
2024-02-02 17:00:00.447 [INFO ] [openhab.automation.jrule.rules.JRule] - [TEST] -999999999-01-01T05:30
2024-02-02 17:00:00.448 [INFO ] [openhab.automation.jrule.rules.JRule] - [TEST] Test > ENDING.
2024-02-02 17:00:14.528 [WARN ] [gram.internal.action.TelegramActions] - Failed to send telegram message: Bad Request: message text is empty
2024-02-02 17:00:14.693 [WARN ] [gram.internal.action.TelegramActions] - Failed to send telegram message: Bad Request: message text is empty
2024-02-02 17:00:22.973 [WARN ] [gram.internal.action.TelegramActions] - Failed to send telegram message: Bad Request: message text is empty
2024-02-02 17:00:23.025 [WARN ] [gram.internal.action.TelegramActions] - Failed to send telegram message: Bad Request: message text is empty
2024-02-02 17:00:50.530 [INFO ] [openhab.automation.jrule.rules.JRule] - [Switches] 'Tap Switch Button Pressed' rule> STARTING.
2024-02-02 17:00:50.532 [INFO ] [openhab.automation.jrule.rules.JRule] - [Switches] 'Tap Switch Button Pressed' rule> Button 4 pressed.
2024-02-02 17:00:50.533 [INFO ] [e.internal.handler.JRuleEventHandler] - [Switches] SendCommand 'ON' to 'Override_Sleep_Mode'
2024-02-02 17:00:50.535 [INFO ] [openhab.automation.jrule.rules.JRule] - [Switches] 'Tap Switch Button Pressed' rule> Rules for Button 4 successfully executed.
2024-02-02 17:00:50.537 [INFO ] [openhab.automation.jrule.rules.JRule] - [Switches] 'Tap Switch Button Pressed' rule> ENDING.
2024-02-02 17:01:02.334 [INFO ] [openhab.automation.jrule.rules.JRule] - [Locks] Locks Routines > Door lock locked > Starting.
2024-02-02 17:01:02.335 [INFO ] [openhab.automation.jrule.rules.JRule] - [Locks] Send Notification > Sending notification via Telegram.
2024-02-02 17:01:02.454 [INFO ] [openhab.automation.jrule.rules.JRule] - [Locks] Send Notification > Notification via Telegram sent.
2024-02-02 17:01:02.455 [INFO ] [openhab.automation.jrule.rules.JRule] - [Locks] Locks Routines > Door lock locked > Ending.
2024-02-02 17:01:14.643 [INFO ] [openhab.automation.jrule.rules.JRule] - [Switches] 'Tap Switch Button Pressed' rule> STARTING.
2024-02-02 17:01:14.645 [INFO ] [openhab.automation.jrule.rules.JRule] - [Switches] 'Tap Switch Button Pressed' rule> Button 1 pressed.
2024-02-02 17:01:14.646 [INFO ] [e.internal.handler.JRuleEventHandler] - [Switches] SendCommand 'OFF' to 'MBR_Light_Switch'
2024-02-02 17:01:14.648 [INFO ] [openhab.automation.jrule.rules.JRule] - [Switches] 'Tap Switch Button Pressed' rule> Rules for Button 1 successfully executed.
2024-02-02 17:01:14.649 [INFO ] [openhab.automation.jrule.rules.JRule] - [Switches] 'Tap Switch Button Pressed' rule> ENDING.
2024-02-02 17:02:00.445 [INFO ] [openhab.automation.jrule.rules.JRule] - [TEST] Test > STARTING.
2024-02-02 17:02:00.446 [INFO ] [openhab.automation.jrule.rules.JRule] - [TEST] 2024-02-02T17:02:00.446820169
2024-02-02 17:02:00.448 [INFO ] [openhab.automation.jrule.rules.JRule] - [TEST] -999999999-01-01T05:30
2024-02-02 17:02:00.449 [INFO ] [openhab.automation.jrule.rules.JRule] - [TEST] Test > ENDING.
2024-02-02 17:02:26.142 [INFO ] [openhab.automation.jrule.rules.JRule] - [Locks] Locks Routines > Door lock motor blocked > STARTING.
2024-02-02 17:02:26.144 [INFO ] [openhab.automation.jrule.rules.JRule] - [Locks] Send Notification > Sending notification via Telegram.
2024-02-02 17:02:26.327 [INFO ] [openhab.automation.jrule.rules.JRule] - [Locks] Send Notification > Notification via Telegram sent.
2024-02-02 17:02:26.329 [INFO ] [openhab.automation.jrule.rules.JRule] - [Locks] Locks Routines > Door lock blocked > ENDING.
2024-02-02 17:03:00.128 [INFO ] [openhab.automation.jrule.rules.JRule] - [Locks] Locks Routines > Door lock unlocked > STARTING.
2024-02-02 17:03:00.130 [INFO ] [openhab.automation.jrule.rules.JRule] - [Locks] Send Notification > Sending notification via Telegram.
2024-02-02 17:03:00.311 [INFO ] [openhab.automation.jrule.rules.JRule] - [Locks] Send Notification > Notification via Telegram sent.
2024-02-02 17:03:00.313 [INFO ] [openhab.automation.jrule.rules.JRule] - [Locks] Locks Routines > Door lock unlocked > ENDING.

Here is the complete rule in DSL format:

rule "Switch Button 1"
when
    Item HM_Switch_Tap_1_Event received command
then
    logDebug(logName, "'Tap Switch Button Pressed' rule> Starting execution.")
    if (HM_Switch_Tap_1_Event.state.toString == "1000") {
        logDebug(logName, "'Tap Switch Button Pressed' rule> Button 1 pressed.")
        if (MBR_Light_Switch.state == OFF) {
            MBR_Light_Switch.sendCommand(ON)
        } else if (MBR_Light_Switch.state == ON) {
            MBR_Light_Switch.sendCommand(OFF)
        }
        logDebug(logName, "'Tap Switch Button Pressed' rule> Rules for Button 1 successfully executed.")
    } else if (HM_Switch_Tap_1_Event.state.toString == "2000") {
        logDebug(logName, "'Tap Switch Button Pressed' rule> Button 2 pressed.")
        if (MBR_Scene_Study_White.state == OFF) {
            MBR_Scene_Study_White.sendCommand(ON)
        } else if (MBR_Scene_Study_White.state == ON) {
            MBR_Scene_Automated.sendCommand(ON)
        }
        logDebug(logName, "'Tap Switch Button Pressed' rule> Rules for Button 2 successfully executed.")
    } else if (HM_Switch_Tap_1_Event.state.toString == "3000") {
        logDebug(logName, "'Tap Switch Button Pressed' rule> Button 3 pressed.")
        if (MBR_Scene_Study_Yellow.state == OFF) {
            MBR_Scene_Study_Yellow.sendCommand(ON)
        } else if (MBR_Scene_Study_Yellow.state == ON) {
            MBR_Scene_Automated.sendCommand(ON)
        }
        logDebug(logName, "'Tap Switch Button Pressed' rule> Rules for Button 3 successfully executed.")
    } else if (HM_Switch_Tap_1_Event.state.toString == "4000") {
        logDebug(logName, "'Tap Switch Button Pressed' rule> Button 4 pressed.")
        if (Override_Sleep_Mode.state == OFF) {
            Override_Sleep_Mode.sendCommand(ON)
        } else if (Override_Sleep_Mode.state == ON) {
            Override_Sleep_Mode.sendCommand(OFF)
        }
        logDebug(logName, "'Tap Switch Button Pressed' rule> Rules for Button 4 successfully executed.")
    }
    logDebug(logName, "'Tap Switch Button Pressed' rule> Ending execution.")
end

And in Scala format:

@JRuleName("TapSwitch1ButtonPressed")
    @JRuleLogName("Switches")
    @JRuleWhenItemReceivedUpdate(item = JRuleItemNames.HM_Switch_Tap_1_Event)
    def MainDimmerButtonPressed(): Unit = {
        logInfo("'Tap Switch Button Pressed' rule> STARTING.")
        val button: String= JRuleItems.HM_Switch_Tap_1_Event.getStateAsString()
        if ( button == "1000")
            logInfo("'Tap Switch Button Pressed' rule> Button 1 pressed.")
            if (JRuleItems.MBR_Light_Switch.getStateAsOnOff() == OFF)
                JRuleItems.MBR_Light_Switch.sendCommand(ON)
            else if (JRuleItems.MBR_Light_Switch.getStateAsOnOff() == ON)
                JRuleItems.MBR_Light_Switch.sendCommand(OFF)
            logInfo("'Tap Switch Button Pressed' rule> Rules for Button 1 successfully executed.")
        else if (button == "2000")
            logInfo("'Tap Switch Button Pressed' rule> Button 2 pressed.")
            if (JRuleItems.MBR_Scene_Study_White.getStateAsOnOff() == OFF)
                JRuleItems.MBR_Scene_Study_White.sendCommand(ON)
            else if (JRuleItems.MBR_Scene_Study_White.getStateAsOnOff() == ON)
                JRuleItems.MBR_Scene_Automated.sendCommand(ON)
            logInfo("'Tap Switch Button Pressed' rule> Rules for Button 2 successfully executed.")
        else if (button == "3000")
            logInfo("'Tap Switch Button Pressed' rule> Button 3 pressed.")
            if (JRuleItems.MBR_Scene_Study_Yellow.getStateAsOnOff() == OFF)
                JRuleItems.MBR_Scene_Study_Yellow.sendCommand(ON)
            else if (JRuleItems.MBR_Scene_Study_Yellow.getStateAsOnOff() == ON)
                JRuleItems.MBR_Scene_Automated.sendCommand(ON)
            logInfo("'Tap Switch Button Pressed' rule> Rules for Button 3 successfully executed.")
        else if (button == "4000")
            logInfo("'Tap Switch Button Pressed' rule> Button 4 pressed.")
            if (JRuleItems.Override_Sleep_Mode.getStateAsOnOff() == OFF)
                JRuleItems.Override_Sleep_Mode.sendCommand(ON)
            else if (JRuleItems.Override_Sleep_Mode.getStateAsOnOff() == ON)
                JRuleItems.Override_Sleep_Mode.sendCommand(OFF)
            logInfo("'Tap Switch Button Pressed' rule> Rules for Button 4 successfully executed.")
        logInfo("'Tap Switch Button Pressed' rule> ENDING.")
    }

AndrewFG · February 12, 2024, 5:48pm

Why are you using “Item .. received command” here? The OH documentation says “triggers the rule when an Item is commanded; a command does not by itself imply that the Item received an update or changed”…

Indeed why are you using an Item (HM_Switch_Tap_1_Event) here at all? Your use case is a perfect example where the button Thing’s trigger channel should be used directly to trigger the rule. See the OH documentation link above line #7 in the table.

rule "Switch Button 1"
when
    Channel hue:device:bridgeId:8b9196ac-9193-4376-bbfd-0b25da8:button-last-event triggered
then
    ...

nelson.aponte · February 12, 2024, 8:02pm

Hi, @AndrewFG

Thanks for your prompt response. At some point in time, I changed to using the trigger channel sintaxis instead of storing the value in the Item. If I remember correctly, I was still getting the same error and the drawback was that I couldn’t easily visually check the value received as the channel changes right away. I had to check the logs and the hue log is updated almost every second, so it’s a Hide & Seek game.

I believe the trigger channel is important for other conditions, but for the buttons of the switches the fact that the value is not continuous is not important and actually expected. Therefore, I only evaluate them on a change. Of course, don’t hesitate to point out if you think I’m wrong.

In my test, the item always changes and retains the last value received from the channel, so I display it on the MainUI and that’s how I can easily check the received value. I can see them change from X000 to X001 to X002/3 on the dimmer switch, so it even helped me understand how the logical values are connected to the physical interaction.
I could change the trigger to received update, or even the trigger channel sintaxis but I don’t think it’ll make any difference.

I’ve even thought there was a problem with the rules themselves, not the binding, as it’s illogical that I’m the only person with the problem. I don’t think I’m the only one using the dimmer or tap switches. Yet, the logic of the rules is quite simple and the sintaxis seems to be correct.

AndrewFG · February 12, 2024, 8:21pm

If you use an Item then ‘received command’ is anyway certainly wrong. Try ‘changed’ (or eventually ‘updated’)…

nelson.aponte · February 12, 2024, 9:45pm

By chance, the Scala version (which is the current one) used the Received Update trigger already

    @JRuleName("Dimmer Switch 1 Button Pressed")
    @JRuleLogName("Switches")
    @JRuleWhenItemReceivedUpdate(item = JRuleItemNames.HM_Switch_Dimmer_1_Event)

AndrewFG · February 12, 2024, 10:58pm

I don’t really understand what you are asking. You seem to be complaining that your item gets a state 4002; yet none of your logs show a 4002, so how do you believe that 4002 is coming? Also none of your rules is handling a case of 4002, so even if you would be getting a 4002 (which I dont see evidence of) why would that be an issue in your rules?

nelson.aponte · February 13, 2024, 6:34am

You’re right, I didn’t mention the most important thing.

Look at both logs at this time
2024-02-02 17:00:50.527

About the 4002, I also mixed things by putting the logs and rules for the Tap Switch. With the Tap Switch the rule for the 4000 value is incorrectly triggered after a 1000 (for example) value is reported by the binding. That’s what you can see in the logs and rules. The problem seems to be in the rule, not the binding, but looking at the rule I cannot find how a 1000 value can trigger the condition for a 4000 value.

For the Dimmer Switch (for which I don’t have logs at the moment because I don’t use it that much), the rule for the 4002 value is executed when I’m actually expecting the 2002, for example. It’s the same scenario where I haven’t been able to consistently reproduce it.

AndrewFG · February 13, 2024, 11:32am

Several suggestions…

Use Item .. changed in the trigger
Use triggeringItem within the rule
Don’t re-check item state inside the rule; do it once and store in a ‘val’ constant
Never compare string values using == the correct method is .equals()
And use “if ("constant text".equals(variable))” instead of “if (variable.equals("constant text"))”; reason is that the latter causes an NPE if variable is null

rule "Switch Button 1"
when
    Item HM_Switch_Tap_1_Event changed
then
    ..
    val newValue = triggeringItem.state.toString
    if ("1000".equals(newValue)) {
        ..
    } else if ("2000".equals(newValue)) {
        ..
    } else if ("3000".equals(newValue)) {
        ..
    } else if ("4000".equals(newValue)) {
        ..
    }
end

nelson.aponte · February 13, 2024, 9:57pm

I applied all of your suggestions. This is what the code looks like now for both Dimmer and Tap switches:

package org.openhab.automation.jrule.rules.user

import org.openhab.automation.jrule.rules.{JRule, JRuleName, JRuleWhenItemChange, JRuleLogName}
import org.openhab.automation.jrule.generated.items.{JRuleItems, JRuleItemNames}
import org.openhab.automation.jrule.rules.value.JRuleOnOffValue.*
import org.openhab.automation.jrule.generated.items
import org.openhab.automation.jrule.rules.event.JRuleItemEvent
import org.openhab.automation.jrule.internal.JRuleLog

class Switches extends JRule {

    @JRuleName("Dimmer Switch 1 Button Pressed")
    @JRuleLogName("Switches")
    @JRuleWhenItemChange(item = JRuleItemNames.HM_Switch_Dimmer_1_Event)
    def DimmerSwitch1ButtonPressed(event: JRuleItemEvent): Unit = {
        logInfo("'Dimmer Switch 1 Button Pressed' rule> STARTING.")
        val button = event.getItem().getStateAsString()
        //val button: String = JRuleItems.HM_Switch_Dimmer_1_Event.getStateAsString()
        logInfo(s"'Dimmer Switch 1 Button Pressed' rule> Button pressed: $button")
        if (button.equals("1002"))
            logInfo("'Dimmer Switch 1 Button Pressed' rule> Starting execution of Dimmer Button 1 short pressed.")
            if (JRuleItems.group_LR_Lamp_Switch.getStateAsOnOff() == OFF)
                JRuleItems.group_LR_Lamp_Switch.sendCommand(ON)
            else if (JRuleItems.group_LR_Lamp_Switch.getStateAsOnOff() == ON)
                JRuleItems.group_LR_Lamp_Switch.sendCommand(OFF)
            logInfo("'Dimmer Switch 1 Button Pressed' rule> Ending execution of Dimmer Button 1 short pressed.")
        else if (button.equals("1003"))
            logInfo("'Dimmer Switch 1 Button Pressed' rule> Starting execution of Dimmer Button 1 long pressed.")
            if (JRuleItems.LR2_Light_Switch.getStateAsOnOff() == OFF)
                JRuleItems.LR2_Light_Switch.sendCommand(ON)
            else
                JRuleItems.LR2_Light_Switch.sendCommand(OFF)
            logInfo("'Dimmer Switch 1 Button Pressed' rule> Ending execution of Dimmer Button 1 long pressed.")
        else if (button.equals("2002"))
            logInfo("'Dimmer Switch 1 Button Pressed' rule> Starting execution of Dimmer Button 2 short pressed.")
            if (JRuleItems.KT_Light_Switch.getStateAsOnOff() == OFF)
                JRuleItems.KT_Light_Switch.sendCommand(ON)
            else if (JRuleItems.KT_Light_Switch.getStateAsOnOff() == ON)
                JRuleItems.KT_Light_Switch.sendCommand(OFF)
            logInfo("'Dimmer Switch 1 Button Pressed' rule> Ending execution of Dimmer Button 2 short pressed.")
        else if (button.equals("2003"))
            logInfo("'Dimmer Switch 1 Button Pressed' rule> Starting execution of Dimmer Button 2 long pressed.")
            logInfo("'Dimmer Switch 1 Button Pressed' rule> Ending execution of Dimmer Button 2 long pressed.")
        else if (button.equals("3002"))
            logInfo("'Dimmer Switch 1 Button Pressed' rule> Starting execution of Dimmer Button 3 short pressed.")
            if (JRuleItems.group_TL_Lamp_Switch.getStateAsOnOff() == OFF)
                JRuleItems.group_TL_Lamp_Switch.sendCommand(ON)
            else if (JRuleItems.group_TL_Lamp_Switch.getStateAsOnOff() == ON)
                JRuleItems.group_TL_Lamp_Switch.sendCommand(OFF)
            logInfo("'Dimmer Switch 1 Button Pressed' rule> Ending execution of Dimmer Button 3 short pressed.")
        else if (button.equals("3003"))
            logInfo("'Dimmer Switch 1 Button Pressed' rule> Starting execution of Dimmer Button 3 long pressed.")
            logInfo("'Dimmer Switch 1 Button Pressed' rule> Ending execution of Dimmer Button 3 long pressed.")
        else if (button.equals("4002"))
            logInfo("'Dimmer Switch 1 Button Pressed' rule> Starting execution of Dimmer Button 4 short pressed.")
            if (JRuleItems.Override_Home_Away.getStateAsOnOff() == OFF)
                if (JRuleItems.Override_Sleep_Mode.getStateAsOnOff() == OFF)
                    JRuleItems.Override_Sleep_Mode.sendCommand(ON)
                else
                    JRuleItems.Override_Sleep_Mode.sendCommand(OFF)
            logInfo("Ending execution of Dimmer Button 4 short pressed.")
        else if (button.equals("4003"))
            logInfo("Starting execution of Dimmer Button 4 long pressed.")
            if (JRuleItems.Override_Home_Away.getStateAsOnOff() == OFF)
                JRuleItems.Override_Home_Away.sendCommand(ON)
            else
                JRuleItems.Override_Home_Away.sendCommand(OFF)
            logInfo("execution of Dimmer Button 4 long pressed.")
        logInfo("'Dimmer Switch 1 Button Pressed' rule> ENDING.")
    }
    
    @JRuleName("TapSwitch1ButtonPressed")
    @JRuleLogName("Switches")
    @JRuleWhenItemChange(item = JRuleItemNames.HM_Switch_Tap_1_Event)
    def MainDimmerButtonPressed(event: JRuleItemEvent): Unit = {
        logInfo("'Tap Switch Button Pressed' rule> STARTING.")
        val button = event.getItem().getStateAsString()
        //val button: String= JRuleItems.HM_Switch_Tap_1_Event.getStateAsString()
        if (button.equals("1000"))
            logInfo("'Tap Switch Button Pressed' rule> Button 1 pressed.")
            if (JRuleItems.MBR_Light_Switch.getStateAsOnOff() == OFF)
                JRuleItems.MBR_Light_Switch.sendCommand(ON)
            else if (JRuleItems.MBR_Light_Switch.getStateAsOnOff() == ON)
                JRuleItems.MBR_Light_Switch.sendCommand(OFF)
            logInfo("'Tap Switch Button Pressed' rule> Rules for Button 1 successfully executed.")
        else if (button.equals("2000"))
            logInfo("'Tap Switch Button Pressed' rule> Button 2 pressed.")
            if (JRuleItems.MBR_Scene_Study_White.getStateAsOnOff() == OFF)
                JRuleItems.MBR_Scene_Study_White.sendCommand(ON)
            else if (JRuleItems.MBR_Scene_Study_White.getStateAsOnOff() == ON)
                JRuleItems.MBR_Scene_Automated.sendCommand(ON)
            logInfo("'Tap Switch Button Pressed' rule> Rules for Button 2 successfully executed.")
        else if (button.equals("3000"))
            logInfo("'Tap Switch Button Pressed' rule> Button 3 pressed.")
            if (JRuleItems.MBR_Scene_Study_Yellow.getStateAsOnOff() == OFF)
                JRuleItems.MBR_Scene_Study_Yellow.sendCommand(ON)
            else if (JRuleItems.MBR_Scene_Study_Yellow.getStateAsOnOff() == ON)
                JRuleItems.MBR_Scene_Automated.sendCommand(ON)
            logInfo("'Tap Switch Button Pressed' rule> Rules for Button 3 successfully executed.")
        else if (button.equals("4000"))
            logInfo("'Tap Switch Button Pressed' rule> Button 4 pressed.")
            if (JRuleItems.Override_Sleep_Mode.getStateAsOnOff() == OFF)
                JRuleItems.Override_Sleep_Mode.sendCommand(ON)
            else if (JRuleItems.Override_Sleep_Mode.getStateAsOnOff() == ON)
                JRuleItems.Override_Sleep_Mode.sendCommand(OFF)
            logInfo("'Tap Switch Button Pressed' rule> Rules for Button 4 successfully executed.")
        logInfo("'Tap Switch Button Pressed' rule> ENDING.")
    }
}

I will let you know if I keep experiencing the problem.

AndrewFG · February 14, 2024, 2:57pm

You should NOT use “if (button.equals("1000"))” – use “if ("1000".equals(button))” instead; reason is that the former causes an NPE if button is null…

nelson.aponte · February 14, 2024, 3:22pm

Thanks for the hint. I was wondering if you had put the “XXXX” first intentionally.

I’ll change it.