Rules are not working

Kees_van_Gelder · June 21, 2017, 4:05pm

have you checked yr event log?
have you installed the mail binding (or action or whatever)
have you properly configured yr mail.cfg?

aro · June 21, 2017, 4:15pm

I am running openhab on an synology server, but there i get no error.
but when i try to see the log in the console with:

log:set DEBUG org.openhab.binding.homematic

i get this error:
Error executing command: Error writing log config to config admin

i installed the mail action, and mail.cfg looks like this:

The SMTP server hostname, e.g. “smtp.gmail.com”

hostname=smtp.gmail.com

the SMTP port to use (optional, defaults to 25 (resp. 587 for TLS/SSL))

port=465

the username and password if the SMTP server requires authentication

username=MYGMAILADRESS
password=MYPASSWORD

The email address to use for sending mails

from=MYGMAILADRESS

set to “true”, if STARTTLS is enabled (not required) for the connection

(optional, defaults to false)

#tls=

set to “true”, if SSL negotiation should occur on connection

do not use both tls=true and ssl=true

(optional, defaults to false)

#ssl=

set to “true”, if POP before SMTP (another authentication mechanism)

should be enabled. Username and Password are taken from the above

configuration (optional, default to false)

#popbeforesmtp=

Character set used to encode message body

(optional, if not provided platform default is used)

#charset=

Kees_van_Gelder · June 21, 2017, 4:21pm

I was actually hoping if the log would show if the rule was doing anything at all

on first glance… I use port 587 and tls=true and that works without problems.
but you may have good reasons for 465. I trhink 465 is ssl

aro · June 21, 2017, 4:32pm

i changed the port to yours and now i get errors in the log:

2017-06-21 18:31:22.717 [ERROR] [.script.engine.ScriptExecutionThread] - Rule ‘Rollo’: An error occured during the script execution: index=0, size=0

2017-06-21 18:31:29.235 [ERROR] [.script.engine.ScriptExecutionThread] - Rule ‘Rollo’: An error occured during the script execution: index=0, size=0

and i get this warning when updating the .rules:
2017-06-21 18:30:44.329 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: ‘number1’. Ignoring ‘org.eclipse.smarthome.core.library.items.NumberItem’.

Kees_van_Gelder · June 21, 2017, 4:40pm

I am no expert on this, but i doubt if the error is in the mail.cfg, did you set the tls to ‘true’?
seems there is a problem with yr item 'number1’
What command are you sending?

Dim · June 21, 2017, 4:43pm

My view on this deployment here: Debugging with console

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.