I awoke this morning with additional troubleshooting ideas. I added to my .things, .items, and .rules files to include an echo test string and Things channel syntax change. However, first I need to reply to your suggestions, and thank you for your help.
- Iâll use âfencesâ now that I learnedhow to use them. Thank you for the reference.
- I have found OH3 does not execute rules that are triggered with System started when configuration files are saved. Therefore I always kill and restart OH3. This is awkward but appears to be arequirement.
rule "Startup_Initializations"
when
System started
then
- The MQTT Essentials Best Practices reference resonated with 1 of my troubleshooting ideas. With mqtt1 the slash / is used as a level separator. I remember a google reference where the colon appeared to be used in the .things channel definition. So Iâm not sure which of the following is correct; 1, 2, 3 or 4, 5, 6?
Bridge mqtt:broker:hsbroker "hsbroker" [ host="10.0.0.9", secure=false ] {
Thing topic OutboundThing "To WatchMan" {
Channels:
Type string: mqttTest0 "Friendly Name 0" [commandTopic="/WatchMan/OHOB_WM_String"]
}
Thing topic InBoundThing "From WatchMan"
{
Channels:
Type number: mqttEchoTest "EchoTest Name" [stateTopic="SomeTopic"]
Type number: mqttTest1 "Friendly Name 1" [stateTopic="/OHIB/OHC/12"]
Type number: mqttTest2 "Friendly Name 2" [stateTopic="/OHIB/OHC/13"]
Type number: mqttTest3 "Friendly Name 3" [stateTopic="/OHIB/OHC/14"]
Type number: mqttTest4 "Friendly Name 4" [stateTopic=":OHIB:OHC:12"]
Type number: mqttTest5 "Friendly Name 5" [stateTopic=":OHIB:OHC:13"]
Type number: mqttTest6 "Friendly Name 6" [stateTopic=":OHIB:OHC:14"]
}
}
- My interpretation of the log files is that startup is NOT consistent. For example, in the following 1st log mqtt is initializing at 09:43:00.719 but there is no mention of
things
going online. In the subsequent 2nd log mqtt is initialized at 10:22:55.720 and things
logs are split before and after 10:22:55.720. Why were things
not logged in the 1st log? Perhaps there is a timing race problem in OH3?
1st log:
openhab> log:tail
09:42:09.402 [WARN ] [.core.karaf.internal.FeatureInstaller] - The ui add-on 'classic' does not exist - ignoring it.
09:42:10.464 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.items'
09:42:11.979 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
09:42:12.369 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.sitemap'
09:42:12.822 [INFO ] [del.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'HS5150.sitemap', using it anyway:
Sitemap should contain either only frames or none at all
09:42:13.088 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.things'
09:42:15.009 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.rules'
09:42:43.505 [INFO ] [del.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'HS5150.rules', using it anyway:
This expression is not allowed in this context, since it doesn't cause any side effects.
09:42:44.333 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
09:42:46.426 [INFO ] [org.openhab.ui.internal.UIService ] - Started UI on port 8080
09:42:55.030 [INFO ] [.io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = c86a53f2-1c89-4f8f-996c-521ad3c68bce, base URL = http://localhost:8080)
09:42:56.327 [WARN ] [.core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'mqtt:broker:hsbroker' takes more than 5000ms.
09:43:00.719 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '10.0.0.9' with clientid fa6e97ee-9d56-415a-98db-829bcf94fa9e
09:43:09.257 [WARN ] [.core.karaf.internal.FeatureInstaller] - The ui add-on 'classic' does not exist - ignoring it.
09:43:18.746 [INFO ] [.model.script.Startup_Initializations] - >>>>> RUNNING RULE = Startup_Initializations. Pausing for 999 msec
09:43:19.759 [INFO ] [.model.script.Startup_Initializations] - >>>>> RUNNING RULE = Startup_Initializations at 03/19/21 @ 09:43:19 AM
09:43:19.759 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Date' changed from 2021-03-19T09:40:05.673486700-0700 to 2021-03-19T09:43:19.759857600-0700
09:43:19.775 [INFO ] [.model.script.Startup_Initializations] - >>>>> OpenHAB IS DELAYING 60 SECONDS TO ALLOW IT TO ORGANIZE ITSELF
09:44:34.649 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
09:44:34.649 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
09:44:34.649 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
09:44:34.649 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
09:44:34.649 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
09:44:34.649 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
09:44:34.649 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
09:44:34.649 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
09:44:34.664 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
09:44:34.664 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
09:44:35.666 [INFO ] [.model.script.Startup_Initializations] - >>>>>>>>>>>>> RULE = Startup_Initializations. Ready to publish via actions.publishMQTT
09:44:35.666 [INFO ] [.model.script.Startup_Initializations] - >>>>>>>>>>>>> RULE = Startup_Initializations. mqttActions = org.openhab.binding.mqtt.internal.action.MQTTActions@53cde000
09:44:42.678 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'HS5150-1' failed: An error occurred during the script execution: index=0, size=0 in HS5150
09:44:42.678 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.
09:44:50.208 [INFO ] [ab.core.model.script.Update_OHCstring] - >>>>> ENTERED RULE = Update_OHCstring. Roberts_Counter_Now = 0 GreenFlag = 1 Traffic_BrakeOHOB = 0 second = 50
09:44:50.208 [INFO ] [ab.core.model.script.Update_OHCstring] - >>>>> RUNNING RULE = Update_OHCstring. Roberts_Counter_Now = 0
09:44:50.208 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Date' changed from 2021-03-19T09:43:19.759857600-0700 to 2021-03-19T09:44:50.208694300-0700
09:44:50.224 [INFO ] [ab.core.model.script.Update_OHCstring] - >>>>> OpenHAB is READY 03/19/21 @ 09:44:50 AM
09:44:54.557 [INFO ] [ab.core.model.script.Update_OHCstring] - >>>>>>>>>>>>> RULE = Update_OHCstring. Ready to publish via actions.publishMQTT
09:44:54.572 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'OHOB_WM_String' changed from
03/19/21 @ 09:39:20 AM >
MsgStamp:2;
00:25;
MsgStamp:2;
EOS< to
2nd log:
openhab> log:tail
10:20:58.154 [WARN ] [org.apache.karaf.shell.ssh.Activator ] - Error starting activator
java.lang.IllegalStateException: Service not tracked for class interface org.osgi.service.cm.ConfigurationAdmin
at org.apache.karaf.util.tracker.BaseActivator.getTrackedService(BaseActivator.java:369) ~[bundleFile:?]
at org.apache.karaf.util.tracker.BaseActivator.ensureStartupConfiguration(BaseActivator.java:154) ~[bundleFile:?]
at org.apache.karaf.shell.ssh.Activator.doStart(Activator.java:96) ~[bundleFile:?]
at org.apache.karaf.util.tracker.BaseActivator.run(BaseActivator.java:312) [bundleFile:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:834) [?:?]
10:21:08.616 [WARN ] [.core.karaf.internal.FeatureInstaller] - The ui add-on 'classic' does not exist - ignoring it.
10:21:09.632 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.items'
10:21:11.162 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
10:21:11.584 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.sitemap'
10:21:12.115 [INFO ] [del.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'HS5150.sitemap', using it anyway:
Sitemap should contain either only frames or none at all
10:21:12.349 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.things'
10:21:14.714 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.rules'
10:22:01.206 [INFO ] [del.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'HS5150.rules', using it anyway:
This expression is not allowed in this context, since it doesn't cause any side effects.
10:22:06.035 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
10:22:08.874 [WARN ] [.core.karaf.internal.FeatureInstaller] - The ui add-on 'classic' does not exist - ignoring it.
10:22:13.538 [INFO ] [org.openhab.ui.internal.UIService ] - Started UI on port 8080
10:22:23.975 [INFO ] [.io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = c86a53f2-1c89-4f8f-996c-521ad3c68bce, base URL = http://localhost:8080)
10:22:53.565 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'HS5150-1' failed: The name 'Pause_Time' cannot be resolved to an item or type; line 361, column 102, length 10 in HS5150
10:22:53.783 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.
10:22:54.346 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:topic:hsbroker:OutboundThing' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
10:22:54.549 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:topic:hsbroker:InBoundThing' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
10:22:54.736 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mail:smtp:GmailThing' changed from UNINITIALIZED to INITIALIZING
10:22:54.877 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mail:smtp:GmailThing' changed from INITIALIZING to ONLINE
10:22:54.970 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:hsbroker' changed from UNINITIALIZED to INITIALIZING
10:22:55.064 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:hsbroker' changed from INITIALIZING to OFFLINE
10:22:55.158 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:topic:hsbroker:InBoundThing' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
10:22:55.173 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:topic:hsbroker:OutboundThing' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
10:22:55.205 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:topic:hsbroker:InBoundThing' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
10:22:55.220 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:topic:hsbroker:OutboundThing' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
10:22:55.720 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '10.0.0.9' with clientid 115e6f9c-f257-4333-9e5e-e5c05aea0884
10:22:55.845 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:hsbroker' changed from OFFLINE to ONLINE
10:22:55.876 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:topic:hsbroker:OutboundThing' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
10:22:55.876 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:topic:hsbroker:InBoundThing' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
10:23:16.816 [INFO ] [enhab.core.model.script.Timed_Control] - >>>>> WatchmansEchoStatus = 3
10:23:16.889 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Date' changed from 2021-03-19T10:20:38.333884400-0700 to 2021-03-19T10:23:16.800580-0700
10:23:16.885 [INFO ] [ab.core.model.script.Update_OHCstring] - >>>>> ENTERED RULE = Update_OHCstring. Roberts_Counter_Now = 0 GreenFlag = 1 Traffic_BrakeOHOB = 0 second = 16
10:23:17.000 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'WatchmansEchoStatus' changed from 3 to 1
10:23:17.035 [INFO ] [ab.core.model.script.Update_OHCstring] - >>>>> RUNNING RULE = Update_OHCstring. Roberts_Counter_Now = 0
10:23:17.042 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'OH_Events_Log' changed from Timed_Control texting 9252345805@tmomail.net to Presence set to C111
10:23:17.075 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'OH_Events_Log' changed from Presence set to C111 to Timed_Control texting 9252345805@tmomail.net
10:23:17.043 [INFO ] [ab.core.model.script.Update_OHCstring] - >>>>> OpenHAB is READY 03/19/21 @ 10:23:16 AM
10:23:17.106 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Date' changed from 2021-03-19T10:23:16.800580-0700 to 2021-03-19T10:23:17.043936500-0700
10:23:21.320 [INFO ] [ab.core.model.script.Update_OHCstring] - >>>>>>>>>>>>> RULE = Update_OHCstring. Ready to publish via actions.publishMQTT
10:23:21.320 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'OHOB_WM_String' changed from
03/19/21 @ 10:20:38 AM >
MsgStamp:215;
00:25;
MsgStamp:215;
EOS< to
- I added code at the end of the
System started
triggered .rules
file to help eliminate possible Things
issues per below. I tried both val mqqtActions
and val mqqtActions
, and i added actions.publishMQTT("SomeTopic", "SomePayload")
to circumvent Things channels
.
// Import Thing Actions -----------------------------------------------------------------------------------------
// https://community.openhab.org/t/sendmail-not-working-2-5-0-m2/80041/4
val mailActions = getActions("mail", "mail:smtp:GmailThing")
// var mailActions = getActions("mail", "mail:smtp:GmailThing")
logInfo("Startup_Initializations", ">>>>>>>>>>>>> RULE = Startup_Initializations. mailActions = " + mailActions)
Thread::sleep(1000) // Configuration Delay
// https://www.openhab.org/blog/2018-12-16-mqtt-arrives-in-the-modern-openhab-2-x-architecture.html
// https://github.com/fguiraldelli/openhab2-addons/blob/master/bundles/org.openhab.binding.mqtt.generic/xtend_examples.md
logInfo("Startup_Initializations", ">>>>>>>>>>>>> RULE = Startup_Initializations. Ready to publish via actions.publishMQTT")
val mqttActions = getActions("mqtt","mqtt:broker:hsbroker")
// var mqttActions = getActions("mqtt","mqtt:broker:hsbroker")
logInfo("Startup_Initializations", ">>>>>>>>>>>>> RULE = Startup_Initializations. mqttActions = " + mqttActions)
Thread::sleep(7000) // Configuration Delay
actions.publishMQTT("SomeTopic", "SomePayload")
logInfo("Startup_Initializations", ">>>>>>>>>>>>> RULE = Startup_Initializations. Published via actions.publishMQTT")
logInfo("Startup_Initializations", "<<<<< EXITING RULE = Startup_Initializations")
- This 3rd log further demonstrated non-repeatability pointing to a possible system initialization race condition. Note again no mention of
things
online.
3rd Log
openhab> log:tail
10:49:37.565 [WARN ] [org.apache.karaf.shell.ssh.Activator ] - Error starting activator
java.lang.IllegalStateException: Service not tracked for class interface org.osgi.service.cm.ConfigurationAdmin
at org.apache.karaf.util.tracker.BaseActivator.getTrackedService(BaseActivator.java:369) ~[bundleFile:?]
at org.apache.karaf.util.tracker.BaseActivator.ensureStartupConfiguration(BaseActivator.java:154) ~[bundleFile:?]
at org.apache.karaf.shell.ssh.Activator.doStart(Activator.java:96) ~[bundleFile:?]
at org.apache.karaf.util.tracker.BaseActivator.run(BaseActivator.java:312) [bundleFile:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:834) [?:?]
10:49:48.956 [WARN ] [.core.karaf.internal.FeatureInstaller] - The ui add-on 'classic' does not exist - ignoring it.
10:49:50.127 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.items'
10:49:51.721 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
10:49:52.112 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.sitemap'
10:49:52.596 [INFO ] [del.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'HS5150.sitemap', using it anyway:
Sitemap should contain either only frames or none at all
10:49:52.924 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.things'
10:49:54.954 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
10:49:55.048 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.rules'
10:50:26.864 [INFO ] [del.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'HS5150.rules', using it anyway:
This expression is not allowed in this context, since it doesn't cause any side effects.
10:50:29.910 [INFO ] [org.openhab.ui.internal.UIService ] - Started UI on port 8080
10:50:39.580 [INFO ] [.io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = c86a53f2-1c89-4f8f-996c-521ad3c68bce, base URL = http://localhost:8080)
10:50:41.444 [WARN ] [.core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'mqtt:broker:hsbroker' takes more than 5000ms.
10:50:43.464 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '10.0.0.9' with clientid 1777005a-6466-4ddd-a07b-0caa1230b9ea
10:50:48.884 [WARN ] [.core.karaf.internal.FeatureInstaller] - The ui add-on 'classic' does not exist - ignoring it.
10:51:03.015 [INFO ] [.model.script.Startup_Initializations] - >>>>> RUNNING RULE = Startup_Initializations. Pausing for 999 msec
10:51:04.017 [INFO ] [.model.script.Startup_Initializations] - >>>>> RUNNING RULE = Startup_Initializations at 03/19/21 @ 10:51:04 AM
10:51:04.033 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Date' changed from 2021-03-19T10:49:05.582678100-0700 to 2021-03-19T10:51:04.017930500-0700
10:51:04.049 [INFO ] [.model.script.Startup_Initializations] - >>>>> OpenHAB IS DELAYING 60 SECONDS TO ALLOW IT TO ORGANIZE ITSELF
10:52:19.956 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
10:52:19.971 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
10:52:19.971 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
10:52:19.971 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
10:52:19.971 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
10:52:19.971 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
10:52:19.971 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
10:52:19.971 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
10:52:19.971 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
10:52:19.971 [INFO ] [.model.script.Startup_Initializations] - >>>>> ReStarting OH HS5150
10:52:19.987 [INFO ] [.model.script.Startup_Initializations] - >>>>> Persistence RestoreOnStartup 1 second timer starting now **********************
10:52:20.002 [INFO ] [.model.script.Startup_Initializations] - >>>>>>>>>>>>> RULE = Startup_Initializations. mailActions = org.openhab.binding.mail.internal.action.SendMailActions@1a802c2c
10:52:21.000 [INFO ] [.model.script.Startup_Initializations] - >>>>> Persistence RestoreOnStartup 1 second timer expired ***************************
10:52:21.031 [INFO ] [.model.script.Startup_Initializations] - >>>>> OpenHAB is ReStarting OH HS5150 03/19/21 @ 10:51:04 AM. NOW NOTIFY THE WORLD MS0
10:52:21.031 [INFO ] [.model.script.Startup_Initializations] - >>>>>>>>>>>>> RULE = Startup_Initializations. Ready to publish via actions.publishMQTT
10:52:21.031 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'IP_HS5150_Exec_R' received command OFF
10:52:21.046 [INFO ] [.model.script.Startup_Initializations] - >>>>>>>>>>>>> RULE = Startup_Initializations. mqttActions = org.openhab.binding.mqtt.internal.action.MQTTActions@a83a4a8
10:52:21.046 [WARN ] [core.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
java.lang.reflect.UndeclaredThrowableException: null
at com.sun.proxy.$Proxy469.apply(Unknown Source) ~[?:?]
at org.openhab.core.model.script.actions.ScriptExecution.lambda$0(ScriptExecution.java:82) ~[?:?]
at org.openhab.core.internal.scheduler.SchedulerImpl.lambda$12(SchedulerImpl.java:166) ~[bundleFile:?]
at org.openhab.core.internal.scheduler.SchedulerImpl.lambda$1(SchedulerImpl.java:76) [bundleFile:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: org.openhab.core.model.script.engine.ScriptExecutionException: The name 'mailActions' cannot be resolved to an item or type; line 568, column 4, length 11
at org.openhab.core.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:141) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:992) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:955) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:236) ~[?:?]
at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:216) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:858) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:232) ~[?:?]
at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:216) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:459) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:240) ~[?:?]
at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:216) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:472) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:256) ~[?:?]
at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:216) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:459) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:240) ~[?:?]
at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:216) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:202) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.ClosureInvocationHandler.doInvoke(ClosureInvocationHandler.java:47) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.AbstractClosureInvocationHandler.invoke(AbstractClosureInvocationHandler.java:30) ~[?:?]
... 10 more
10:52:21.062 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Date' changed from 2021-03-19T10:51:04.017930500-0700 to 2021-03-19T10:52:21.031134400-0700
10:52:28.071 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'HS5150-1' failed: An error occurred during the script execution: index=0, size=0 in HS5150
10:52:28.071 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.
10:52:30.441 [INFO ] [ab.core.model.script.Update_OHCstring] - >>>>> ENTERED RULE = Update_OHCstring. Roberts_Counter_Now = 0 GreenFlag = 1 Traffic_BrakeOHOB = 0 second = 30
10:52:30.441 [INFO ] [ab.core.model.script.Update_OHCstring] - >>>>> RUNNING RULE = Update_OHCstring. Roberts_Counter_Now = 0
10:52:30.472 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Date' changed from 2021-03-19T10:52:21.031134400-0700 to 2021-03-19T10:52:30.457342900-0700
10:52:30.472 [INFO ] [ab.core.model.script.Update_OHCstring] - >>>>> OpenHAB is READY 03/19/21 @ 10:52:30 AM
10:52:33.624 [INFO ] [ab.core.model.script.Update_OHCstring] - >>>>>>>>>>>>> RULE = Update_OHCstring. Ready to publish via actions.publishMQTT
10:52:33.624 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'OHOB_WM_String' changed from
- Notice also at 10:52:21.046 the log message is shown. The following line of code to be executed is a 7 second pause followed by
actions.publishMQTT("SomeTopic", "SomePayload")
upon which the code fail.
- I have a different rule that triggers on
Time cron "0/10 * * * * ?"
that also fails
logInfo("Update_OHCstring", ">>>>>>>>>>>>> RULE = Update_OHCstring. Ready to publish via actions.publishMQTT")
actions.publishMQTT("SomeTopic", "SomePayload")
logInfo("Update_OHCstring", ">>>>>>>>>>>>> RULE = Update_OHCstring. Published via actions.publishMQTT")
11:17:20.392 [INFO ] [ab.core.model.script.Update_OHCstring] - >>>>>>>>>>>>> RULE = Update_OHCstring. Ready to publish via actions.publishMQTT
11:17:20.392 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'HS5150-7' failed: An error occurred during the script execution: index=0, size=0 in HS5150
- I think my next step is to write a very simple
.rule
file with nothing more than the actions.publishMQTT
.
Any thoughts?
Why the inconsistencies as evidenced by the log files?
A OH3 error? Probably not.
A mqtt error? Probably not.
A race issue? Seems likely.
Thanks again