Rule executing 5 seconds after being requested

Hi,

I have the following rule which when I click on the button in the web interface, is going to execute a rule.

When I turn on with the web interface my Hue lights then hit the button right after, I have to wait 5 seconds before it executes the rule. Can you please help me troubleshoot this? Please look at the timestamp in the logs.

Rule:
rule "Bureau rue lumiere froide"
when
Item e2_chambre_rue_boutton_virtuel_lumiere_froide received command
then
logInfo(“maison”, String::format(“Value : %1$d”, (e2_chambre_rue_Hue_1_ColorTemp.state as DecimalType).intValue))
logInfo(“maison”, String::format(“Value : %1$d”, (e2_chambre_rue_Hue_2_ColorTemp.state as DecimalType).intValue))
logInfo(“maison”, String::format(“Value : %1$d”, (e2_chambre_rue_Hue_3_ColorTemp.state as DecimalType).intValue))
while ( (e2_chambre_rue_Hue_1_ColorTemp.state as DecimalType).intValue > 0 &&
(e2_chambre_rue_Hue_2_ColorTemp.state as DecimalType).intValue > 0 &&
(e2_chambre_rue_Hue_3_ColorTemp.state as DecimalType).intValue > 0 ) {
sendCommand(e2_chambre_rue_Hue_1_ColorTemp, 0)
sendCommand(e2_chambre_rue_Hue_2_ColorTemp, 0)
sendCommand(e2_chambre_rue_Hue_3_ColorTemp, 0)
sendCommand(e2_chambre_rue_Hue_1_brightness, 100)
sendCommand(e2_chambre_rue_Hue_2_brightness, 100)
sendCommand(e2_chambre_rue_Hue_3_brightness, 100)
logInfo(“maison”, “Sleeping 1 second”)
Thread::sleep(1000)
}
logInfo(“maison”, “Out of the while loop”)
logInfo(“maison”, String::format(“Value : %1$d”, (e2_chambre_rue_Hue_1_ColorTemp.state as DecimalType).intValue))
logInfo(“maison”, String::format(“Value : %1$d”, (e2_chambre_rue_Hue_2_ColorTemp.state as DecimalType).intValue))
logInfo(“maison”, String::format(“Value : %1$d”, (e2_chambre_rue_Hue_3_ColorTemp.state as DecimalType).intValue))
end

Log:
11:57:16.225 [INFO ] [me.event.ThingStatusInfoChangedEvent] - ‘hue:0220:1:bulb6’ changed from ONLINE to OFFLINE: Bridge reports light as not reachable
11:57:17.600 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘e2_chambre_rue_lumiere’ received command ON
11:57:17.611 [INFO ] [marthome.event.ItemStateChangedEvent] - e2_chambre_rue_lumiere changed from OFF to ON
11:57:17.948 [INFO ] [me.event.ThingStatusInfoChangedEvent] - ‘hue:0220:0017882cbbb0:bulb6’ changed from ONLINE to OFFLINE: Bridge reports light as not reachable
11:57:19.924 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘e2_chambre_rue_boutton_virtuel_lumiere_froide’ received command ON
11:57:26.193 [INFO ] [me.event.ThingStatusInfoChangedEvent] - ‘hue:0220:1:bulb4’ changed from ONLINE to OFFLINE: Bridge reports light as not reachable
11:57:26.213 [INFO ] [me.event.ThingStatusInfoChangedEvent] - ‘hue:0220:1:bulb6’ changed from OFFLINE: Bridge reports light as not reachable to ONLINE
11:57:27.935 [INFO ] [me.event.ThingStatusInfoChangedEvent] - ‘hue:0220:0017882cbbb0:bulb4’ changed from ONLINE to OFFLINE: Bridge reports light as not reachable
11:57:27.955 [INFO ] [me.event.ThingStatusInfoChangedEvent] - ‘hue:0220:0017882cbbb0:bulb6’ changed from OFFLINE: Bridge reports light as not reachable to ONLINE
11:57:30.113 [INFO ] [clipse.smarthome.model.script.maison] - Value : 61
11:57:30.123 [INFO ] [clipse.smarthome.model.script.maison] - Value : 61
11:57:30.133 [INFO ] [clipse.smarthome.model.script.maison] - Value : 61
11:57:30.174 [INFO ] [marthome.event.ItemStateChangedEvent] - e2_chambre_rue_Hue_1_ColorTemp changed from 61 to 0
11:57:30.178 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘e2_chambre_rue_Hue_1_ColorTemp’ received command 0
11:57:30.192 [INFO ] [marthome.event.ItemStateChangedEvent] - e2_chambre_rue_Hue_2_ColorTemp changed from 61 to 0
11:57:30.199 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘e2_chambre_rue_Hue_2_ColorTemp’ received command 0
11:57:30.201 [INFO ] [clipse.smarthome.model.script.maison] - Sleeping 1 second
11:57:30.217 [INFO ] [marthome.event.ItemStateChangedEvent] - e2_chambre_rue_Hue_3_ColorTemp changed from 61 to 0
11:57:30.221 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘e2_chambre_rue_Hue_3_ColorTemp’ received command 0
11:57:30.245 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘e2_chambre_rue_Hue_1_brightness’ received command 100
11:57:30.265 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘e2_chambre_rue_Hue_2_brightness’ received command 100
11:57:30.286 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘e2_chambre_rue_Hue_3_brightness’ received command 100
11:57:31.223 [INFO ] [clipse.smarthome.model.script.maison] - Out of the while loop
11:57:31.235 [INFO ] [clipse.smarthome.model.script.maison] - Value : 0
11:57:31.245 [INFO ] [clipse.smarthome.model.script.maison] - Value : 0
11:57:31.255 [INFO ] [clipse.smarthome.model.script.maison] - Value : 0
11:57:56.192 [INFO ] [me.event.ThingStatusInfoChangedEvent] - ‘hue:0220:1:bulb4’ changed from OFFLINE: Bridge reports light as not reachable to ONLINE
11:57:57.941 [INFO ] [me.event.ThingStatusInfoChangedEvent] - ‘hue:0220:0017882cbbb0:bulb4’ changed from OFFLINE: Bridge reports light as not reachable to ONLINE

As you can see, here is the action to push on the virtual button in the web page:
11:57:19.924 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘e2_chambre_rue_boutton_virtuel_lumiere_froide’ received command ON

And here is the first loginfo:
11:57:30.113 [INFO ] [clipse.smarthome.model.script.maison] - Value : 61

There are 6 seconds difference between the time I pressed the virtual button in the web interface and the execution of the rule.

I don’t understand why.

Just a guess, your HUE bulbs are reporting a change to OFFLINE frequently, I would search in that direction.

But if you look the first time of my rule it is a LogInfo. And this is taking 6 seconds to print cfr logs. What does it have to do with my hue bulb?

IMHO the system isn’t trying to send anything to a thing that is known to be OFFLINE.