Rules are not working

aro · June 21, 2017, 6:48pm

i think reinstalling has helped a bit
but now i get this warning:
20:45:01.909 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update ‘14.00’ for item ‘alexa_temp_set’ to handler for channel ‘homematic:HM-TC-IT-WM-W-EU:d28cb354:MEQ0743206:2#SET_TEMPERATURE’, because no thing with the UID ‘homematic:HM-TC-IT-WM-W-EU:d28cb354:MEQ0743206’ could be found.

and the part “d28cb354” is incorrect, but in .items it is correct. so why does openhab still know this old id?

and i set tls to true and still get this error:
20:45:01.164 [ERROR] [.script.engine.ScriptExecutionThread] - Rule ‘test’: An error occured during the script execution: index=0, size=0

Dim · June 21, 2017, 8:05pm

Try to replace the sendMail entry in your test rule with a logInfo to see if you still get the error.

rule "test"
when
	Item number1 received command
then
	logInfo("Test", "Test Log Entry triggered by number1 command")
end

My mail.cfg for google looks like:

hostname=smtp.gmail.com
port=587
tls=true
ssl=false
from=someone@gmail.com
username=someone@gmail.com
password=my_password

aro · June 22, 2017, 2:45pm

is this what you wanted to see?

16:43:43.594 [INFO ] [.eclipse.smarthome.model.script.Test] - Test Log Entry triggered by Thermostat command

Dim · June 22, 2017, 2:57pm

Yeah, just to check if the rule itself was firing correctly… so it is
Now, if you fix your mail.cfg and put back the sendMail action (did the installation succeed from PaperUI?)… it should work…try it

aro · June 22, 2017, 4:25pm

Finally my rule is working, but the order of doing it is wrong:

import org.openhab.core.library.types.*
import org.openhab.core.persistence.*
import org.openhab.model.script.actions.*
import org.java.math.*
import org.joda.time.*

rule "Thermo"
when
Item temp_set received command
then
Thread::sleep(30)
temp_set.postUpdate((receivedCommand as Number) + 1)
end

so i tell Alexa 25 Degrees and this is the log:

18:21:59.659 [INFO ] [marthome.event.ItemStateChangedEvent] - temp_set changed from 14.00 to 25
18:21:59.659 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'temp_set' received command 24
18:21:59.668 [INFO ] [marthome.event.ItemStateChangedEvent] - temp_set changed from 25 to 24

why is it changed to 24 at the end??

Dim · June 22, 2017, 4:59pm

(maybe?) something is updating the state of the item after your rule is fired

What do you see in the logs (events and openhab) with the rule disabled?

Actually, I don’t see in your logs the rule working… it should modify the state of the item (almost) immediately after the item received the command. Add a logInfo entry after the postUpdate to see what is going on.

I don’t use Alexa to help with debugging but start from there.

Try to find out what sends command with value 24 to the item

aro · June 22, 2017, 5:12pm

so this is my rule now:

import org.openhab.core.library.types.*
import org.openhab.core.persistence.*
import org.openhab.model.script.actions.*
import org.java.math.*
import org.joda.time.*

rule "Thermo"
when
Item temp_set received command
then
Thread::sleep(30)
temp_set.postUpdate((receivedCommand as Number) + 1)
logInfo("Test", "Test Log Entry triggered by thermo command")
end

and this is my log:

19:09:59.169 [DEBUG] [ematic.handler.HomematicThingHandler] - Received command '24' for channel 'homematic:HM-TC-IT-WM-W-EU:0a924f93:MEQ0743206:2#SET_TEMPERATURE'
19:09:59.170 [DEBUG] [ternal.communicator.HomematicGateway] - Sending datapoint 'MEQ0743206:2#SET_TEMPERATURE' with value '24.0' to gateway with id '0a924f93'
19:09:59.543 [INFO ] [.eclipse.smarthome.model.script.Test] - Test Log Entry triggered by thermo command
19:09:59.704 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#CONTROL_MODE' from gateway with id '0a924f93'
19:09:59.717 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0743206:2#LOWBAT_REPORTING' from gateway with id '0a924f93'
19:09:59.723 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0743206:2#COMMUNICATION_REPORTING' from gateway with id '0a924f93'
19:09:59.728 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0743206:2#WINDOW_OPEN_REPORTING' from gateway with id '0a924f93'
19:09:59.729 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#BOOST_STATE' from gateway with id '0a924f93'
19:09:59.730 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Double) value '24.0' for 'MEQ0743206:2#SET_TEMPERATURE' from gateway with id '0a924f93'
19:09:59.738 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Double) value '5.0' for 'MEQ0743206:2#PARTY_TEMPERATURE' from gateway with id '0a924f93'
19:09:59.739 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#PARTY_START_TIME' from gateway with id '0a924f93'
19:09:59.740 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#PARTY_START_DAY' from gateway with id '0a924f93'
19:09:59.741 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#PARTY_START_MONTH' from gateway with id '0a924f93'
19:09:59.753 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#PARTY_START_YEAR' from gateway with id '0a924f93'
19:09:59.758 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#PARTY_STOP_TIME' from gateway with id '0a924f93'
19:09:59.763 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'temp_set' received command 24
19:09:59.766 [INFO ] [marthome.event.ItemStateChangedEvent] - temp_set changed from 14.00 to 25
19:09:59.777 [INFO ] [marthome.event.ItemStateChangedEvent] - temp_set changed from 25 to 24.00
19:09:59.758 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#PARTY_STOP_DAY' from gateway with id '0a924f93'
19:09:59.785 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#PARTY_STOP_MONTH' from gateway with id '0a924f93'
19:09:59.790 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#PARTY_STOP_YEAR' from gateway with id '0a924f93'

openhab receives the value 24, but i can see in the alexa app, the “she” understands 25. I have no idea where to search for the missing one… If it helps: the problem is also with the percentage of the rollershutters…

Dim · June 22, 2017, 5:23pm

How are you linking alexa to OH2? via Homematic ? (I don’t use either, so I am a noob on this one)

It seems that your Homematic is the one sending the value 24 to openHAB… you need to check why this is happening.
If alexa is linked to Homematic and Homematic to OH2… something is wrong between the alexa & Homematic comms (?)
Alexa sends 25 to Homematic, homematic goes crazy and sends 24 to OH2… ?

Also: I don’t think that your rule is working… I don’t see an update from 24 to 25 after the command is received… (and before the logInfo entry)

aro · June 22, 2017, 5:29pm

first of all i think my rule works, because i get his without it:

19:25:23.600 [DEBUG] [ematic.handler.HomematicThingHandler] - Received command '13' for channel 'homematic:HM-TC-IT-WM-W-EU:0a924f93:MEQ0743206:2#SET_TEMPERATURE'
19:25:23.601 [DEBUG] [ternal.communicator.HomematicGateway] - Sending datapoint 'MEQ0743206:2#SET_TEMPERATURE' with value '13.0' to gateway with id '0a924f93'
19:25:24.131 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#CONTROL_MODE' from gateway with id '0a924f93'
19:25:24.144 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0743206:2#LOWBAT_REPORTING' from gateway with id '0a924f93'
19:25:24.153 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0743206:2#COMMUNICATION_REPORTING' from gateway with id '0a924f93'
19:25:24.161 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0743206:2#WINDOW_OPEN_REPORTING' from gateway with id '0a924f93'
19:25:24.166 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#BOOST_STATE' from gateway with id '0a924f93'
19:25:24.171 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Double) value '13.0' for 'MEQ0743206:2#SET_TEMPERATURE' from gateway with id '0a924f93'
19:25:24.172 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Double) value '5.0' for 'MEQ0743206:2#PARTY_TEMPERATURE' from gateway with id '0a924f93'
19:25:24.184 [INFO ] [marthome.event.ItemStateChangedEvent] - temp_set changed from 24.00 to 13.00
19:25:24.190 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#PARTY_START_TIME' from gateway with id '0a924f93'
19:25:24.194 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#PARTY_START_DAY' from gateway with id '0a924f93'
19:25:24.195 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#PARTY_START_MONTH' from gateway with id '0a924f93'
19:25:24.200 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'temp_set' received command 13
19:25:24.210 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#PARTY_START_YEAR' from gateway with id '0a924f93'
19:25:24.211 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#PARTY_STOP_TIME' from gateway with id '0a924f93'
19:25:24.212 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#PARTY_STOP_DAY' from gateway with id '0a924f93'
19:25:24.221 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#PARTY_STOP_MONTH' from gateway with id '0a924f93'
19:25:24.222 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#PARTY_STOP_YEAR' from gateway with id '0a924f93'

so you can see, that the rule changes the value, but then something says to overwrite my “ruled” value.

the connection looks like this:

i have the homematic binding in openhab so i can see my devices there. then i have the hue emulation addon to find devices, which must be described in the .items file. so the received command in openhab is “13” when i say “14”. I though i could add the missing 1 with a rule so i can ignore that alexa messes things up because i have no idea how to seach for it…

Dim · June 22, 2017, 5:56pm

I may be missing something here… How do you connect Alexa to your system(s)? (via the Hue Emulation?)

You could try to connect Alexa directly to OH2 to see if this will improve the things:

aro · June 22, 2017, 6:21pm

had the same idea, the result is the same… i said 25 and the value is 24…

20:19:33.621 [DEBUG] [ematic.handler.HomematicThingHandler] - Received command '24' for channel 'homematic:HM-TC-IT-WM-W-EU:0a924f93:MEQ0743206:2#SET_TEMPERATURE'
20:19:33.629 [DEBUG] [ternal.communicator.HomematicGateway] - Sending datapoint 'MEQ0743206:2#SET_TEMPERATURE' with value '24.0' to gateway with id '0a924f93'
20:19:34.164 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#CONTROL_MODE' from gateway with id '0a924f93'
20:19:34.164 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0743206:2#LOWBAT_REPORTING' from gateway with id '0a924f93'
20:19:34.168 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0743206:2#COMMUNICATION_REPORTING' from gateway with id '0a924f93'
20:19:34.168 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0743206:2#WINDOW_OPEN_REPORTING' from gateway with id '0a924f93'
20:19:34.169 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#BOOST_STATE' from gateway with id '0a924f93'
20:19:34.172 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Double) value '24.0' for 'MEQ0743206:2#SET_TEMPERATURE' from gateway with id '0a924f93'
20:19:34.177 [INFO ] [marthome.event.ItemStateChangedEvent] - temp_set changed from 14.00 to 24.00
20:19:34.183 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Double) value '5.0' for 'MEQ0743206:2#PARTY_TEMPERATURE' from gateway with id '0a924f93'
20:19:34.187 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#PARTY_START_TIME' from gateway with id '0a924f93'
20:19:34.188 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#PARTY_START_DAY' from gateway with id '0a924f93'
20:19:34.191 [INFO ] [marthome.event.ItemStateChangedEvent] - Thermo_MZ_2_SetTemperature changed from 14.00 to 24.00
20:19:34.193 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#PARTY_START_MONTH' from gateway with id '0a924f93'
20:19:34.197 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#PARTY_START_YEAR' from gateway with id '0a924f93'
20:19:34.201 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#PARTY_STOP_TIME' from gateway with id '0a924f93'
20:19:34.202 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#PARTY_STOP_DAY' from gateway with id '0a924f93'
20:19:34.207 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#PARTY_STOP_MONTH' from gateway with id '0a924f93'
20:19:34.235 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#PARTY_STOP_YEAR' from gateway with id '0a924f93'
20:19:34.239 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'temp_set' received command 24

Dim · June 22, 2017, 6:24pm

Did you install the Alexa skill?
what happens if you say 22? (or another number)… does OH2 send a different value to the homematic gateway?
strange stuff
I am sure that when you will find the root-cause and fix it you will be laughing

aro · June 22, 2017, 6:33pm

yes, the alexa skill is installed. no matter which number, it’s always 1 below…
now i said 27:

20:30:38.921 [DEBUG] [ematic.handler.HomematicThingHandler] - Received command '26' for channel 'homematic:HM-TC-IT-WM-W-EU:0a924f93:MEQ0743206:2#SET_TEMPERATURE'
20:30:38.922 [DEBUG] [ternal.communicator.HomematicGateway] - Sending datapoint 'MEQ0743206:2#SET_TEMPERATURE' with value '26.0' to gateway with id '0a924f93'
20:30:39.459 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#CONTROL_MODE' from gateway with id '0a924f93'
20:30:39.460 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0743206:2#LOWBAT_REPORTING' from gateway with id '0a924f93'
20:30:39.460 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0743206:2#COMMUNICATION_REPORTING' from gateway with id '0a924f93'
20:30:39.460 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0743206:2#WINDOW_OPEN_REPORTING' from gateway with id '0a924f93'
20:30:39.460 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#BOOST_STATE' from gateway with id '0a924f93'
20:30:39.461 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Double) value '26.0' for 'MEQ0743206:2#SET_TEMPERATURE' from gateway with id '0a924f93'
20:30:39.462 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Double) value '5.0' for 'MEQ0743206:2#PARTY_TEMPERATURE' from gateway with id '0a924f93'
20:30:39.462 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#PARTY_START_TIME' from gateway with id '0a924f93'
20:30:39.462 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#PARTY_START_DAY' from gateway with id '0a924f93'
20:30:39.463 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#PARTY_START_MONTH' from gateway with id '0a924f93'
20:30:39.463 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#PARTY_START_YEAR' from gateway with id '0a924f93'
20:30:39.471 [INFO ] [marthome.event.ItemStateChangedEvent] - temp_set changed from 11.00 to 26.00
20:30:39.473 [INFO ] [marthome.event.ItemStateChangedEvent] - Thermo_MZ_2_SetTemperature changed from 11.00 to 26.00
20:30:39.495 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#PARTY_STOP_TIME' from gateway with id '0a924f93'
20:30:39.499 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#PARTY_STOP_DAY' from gateway with id '0a924f93'
20:30:39.508 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'temp_set' received command 26
20:30:39.531 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '1' for 'MEQ0743206:2#PARTY_STOP_MONTH' from gateway with id '0a924f93'
20:30:39.535 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '0' for 'MEQ0743206:2#PARTY_STOP_YEAR' from gateway with id '0a924f93'

OH2 sends the wrong number to the gatewaym but i don’t know, why it’s recveiving the wrong number
yeah, i think so too, but it would be enough if my rule could add 1 to the value

rossko57 · June 22, 2017, 7:26pm

Bear in mind an Item sent a command will usually autoupdate after a short time to the value of the command. That might overwrite any postUpdate that happened in between. Maybe you need autoupdate=“false” here.

aro · June 22, 2017, 7:31pm

and where should it be added? like this?

import org.openhab.core.library.types.*
import org.openhab.core.persistence.*
import org.openhab.model.script.actions.*
import org.java.math.*
import org.joda.time.*

rule "Thermo"
when
Item temp_set received command
then
autoupdate="false"
Thread::sleep(30)
temp_set.postUpdate((receivedCommand as Number) + 1)
logInfo("Test", "Test Log Entry triggered by thermo command")
end

rossko57 · June 22, 2017, 7:36pm

No, it is a property of an Item. It goes in the Item’s definition curly brackets {} just like a binding.

http://docs.openhab.org/configuration/items.html#binding-configuration

aro · June 23, 2017, 5:16am

so like this?

//Wandthermostat
Number temp_set "Thermostat" [ "TargetTemperature" ] {channel="homematic:HM-TC-IT-WM-W-EU:0a924f93:MEQ0743206:2#SET_TEMPERATURE", autoupdate="false"}

Dim · June 23, 2017, 5:21am

correct

aro · June 23, 2017, 5:33am

ok, i try it, but it will take until monday

aro · June 26, 2017, 4:40pm

hey again!
it didn’t work as well…

i said “15”, 14 is received, (12 is the previous value) my rule changed it to 15, but at the end again to 14…

18:36:27.116 [INFO ] [.eclipse.smarthome.model.script.Test] - Test Log Entry triggered by thermo command
18:36:27.215 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'temp_set' received command 14
18:36:27.218 [INFO ] [marthome.event.ItemStateChangedEvent] - temp_set changed from 12.00 to 15
18:36:27.232 [INFO ] [marthome.event.ItemStateChangedEvent] - temp_set changed from 15 to 14.00

this is the .items:
Number temp_set "Thermostat" [ "TargetTemperature" ] {channel="homematic:HM-TC-IT-WM-W-EU:ff0a6a69:MEQ0743206:2#SET_TEMPERATURE", autoupdate="false"}

and this is .rules:
import org.openhab.core.library.types.*
import org.openhab.core.persistence.*
import org.openhab.model.script.actions.*
import org.java.math.*
import org.joda.time.*

rule "Thermo"
when
Item temp_set received command
then
Thread::sleep(30)
temp_set.postUpdate((receivedCommand as Number) + 1)
logInfo("Test", "Test Log Entry triggered by thermo command")
end