Getting EValidator java dump after upgrade to OH 2.4 - running my Set Default.rules

[ohb1138 (Justus Reich)]

• Platform information:
  • Hardware: Docker Container x84_64/1GB RAM
  • OS: Linux openhab-2.4.0-final-deb-12.2018 4.4.59+ #23824 SMP PREEMPT Fri Oct 12 18:31:34 CST 2018 x86_64 GNU/Linux
  • Java Runtime Environment: openjdk version “1.8.0_192”
    OpenJDK Runtime Environment (Zulu 8.33.0.1-linux64) (build 1.8.0_192-b01)
    OpenJDK 64-Bit Server VM (Zulu 8.33.0.1-linux64) (build 25.192-b01, mixed mode)
  • openHAB version: Upgrade from OH 2.3 Release Build to OH 2.4 Release Build

The funny thing is sometimes it works and sometimes it doesn’t. This means that I see this error only at system startup (but not every time probably 3 of 5 times) and the rule runs fine when triggered while the system is up and running for a while. It seems to me that this behaviour might be related to my other issue and Richs explanation to it:

Getting error "The name 'sendMail' cannot be resolved to an item or type;" after upgrade to 2.4 Release Build

Platform information: Hardware: Docker Container x84_64/1GB RAM OS: Linux openhab-2.4.0-final-deb-12.2018 4.4.59+ #23824 SMP PREEMPT Fri Oct 12 18:31:34 CST 2018 x86_64 GNU/Linux Java Runtime Environment: openjdk version “1.8.0_192” OpenJDK Runtime Environment (Zulu 8.33.0.1-linux64) (build 1.8.0_192-b01) OpenJDK 64-Bit Server VM (Zulu 8.33.0.1-linux64) (build 25.192-b01, mixed mode) openHAB version: Upgrade from OH 2.3 Release Build to OH 2.4 Release Build Issue of the topic: Getting err…

But maybe I am wrong and some one can help me understand what happens …

Issue of the topic: Getting following error in karaf console at system start:

11:12:02.552 [ERROR] [.xtext.validation.CompositeEValidator] - Error executing EValidator
java.util.ConcurrentModificationException: null
	at org.eclipse.emf.common.util.AbstractEList$EIterator.checkModCount(AbstractEList.java:758) ~[?:?]
	at org.eclipse.emf.common.util.AbstractEList$EIterator.doNext(AbstractEList.java:712) ~[?:?]
	at org.eclipse.emf.common.util.AbstractEList$EIterator.next(AbstractEList.java:692) ~[?:?]
	at org.eclipse.emf.common.util.AbstractTreeIterator.next(AbstractTreeIterator.java:133) ~[?:?]
	at org.eclipse.xtext.resource.impl.DefaultResourceDescription.computeExportedObjects(DefaultResourceDescription.java:88) ~[?:?]
	at org.eclipse.xtext.resource.DerivedStateAwareResourceDescriptionManager$1.getLookUp(DerivedStateAwareResourceDescriptionManager.java:84) ~[?:?]
	at org.eclipse.xtext.resource.impl.AbstractResourceDescription.getExportedObjects(AbstractResourceDescription.java:50) ~[?:?]
	at org.eclipse.xtext.resource.impl.AbstractCompoundSelectable$4.apply(AbstractCompoundSelectable.java:75) ~[?:?]
	at org.eclipse.xtext.resource.impl.AbstractCompoundSelectable$4.apply(AbstractCompoundSelectable.java:71) ~[?:?]
	at com.google.common.collect.Iterators$8.transform(Iterators.java:799) ~[22:com.google.guava:18.0.0]
	at com.google.common.collect.TransformedIterator.next(TransformedIterator.java:48) ~[22:com.google.guava:18.0.0]
	at com.google.common.collect.TransformedIterator.next(TransformedIterator.java:48) ~[22:com.google.guava:18.0.0]
	at com.google.common.collect.Iterators$5.hasNext(Iterators.java:548) ~[22:com.google.guava:18.0.0]
	at com.google.common.collect.TransformedIterator.hasNext(TransformedIterator.java:43) ~[22:com.google.guava:18.0.0]
	at com.google.common.collect.Iterators.addAll(Iterators.java:361) ~[22:com.google.guava:18.0.0]
	at com.google.common.collect.Iterables.addAll(Iterables.java:354) ~[22:com.google.guava:18.0.0]
	at com.google.common.collect.Sets.newLinkedHashSet(Sets.java:328) ~[22:com.google.guava:18.0.0]
	at org.eclipse.xtext.xbase.lib.IterableExtensions.toSet(IterableExtensions.java:619) ~[160:org.eclipse.xtext.xbase.lib:2.14.0.v20180522-1629]
	at org.eclipse.xtext.xbase.validation.UniqueClassNameValidator.checkUniqueInIndex(UniqueClassNameValidator.java:102) ~[?:?]
	at org.eclipse.xtext.xbase.validation.UniqueClassNameValidator.doCheckUniqueName(UniqueClassNameValidator.java:95) ~[?:?]
	at org.eclipse.xtext.xbase.validation.UniqueClassNameValidator.doCheckUniqueName(UniqueClassNameValidator.java:87) ~[?:?]
	at org.eclipse.xtext.xbase.validation.UniqueClassNameValidator.lambda$checkUniqueName$0(UniqueClassNameValidator.java:74) ~[?:?]
	at java.lang.Iterable.forEach(Iterable.java:75) ~[?:?]
	at org.eclipse.xtext.xbase.validation.UniqueClassNameValidator.checkUniqueName(UniqueClassNameValidator.java:76) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.xtext.validation.AbstractDeclarativeValidator$MethodWrapper.invoke(AbstractDeclarativeValidator.java:118) ~[154:org.eclipse.xtext:2.14.0.v20180522-1821]
	at org.eclipse.xtext.validation.AbstractDeclarativeValidator.internalValidate(AbstractDeclarativeValidator.java:312) ~[154:org.eclipse.xtext:2.14.0.v20180522-1821]
	at org.eclipse.xtext.validation.AbstractInjectableValidator.validate(AbstractInjectableValidator.java:71) ~[154:org.eclipse.xtext:2.14.0.v20180522-1821]
	at org.eclipse.xtext.validation.CompositeEValidator.validate(CompositeEValidator.java:151) [154:org.eclipse.xtext:2.14.0.v20180522-1821]
	at org.eclipse.emf.ecore.util.Diagnostician.doValidate(Diagnostician.java:171) [66:org.eclipse.emf.ecore:2.12.0.v20160420-0247]
	at org.eclipse.emf.ecore.util.Diagnostician.validate(Diagnostician.java:158) [66:org.eclipse.emf.ecore:2.12.0.v20160420-0247]
	at org.eclipse.emf.ecore.util.Diagnostician.validate(Diagnostician.java:137) [66:org.eclipse.emf.ecore:2.12.0.v20160420-0247]
	at org.eclipse.emf.ecore.util.Diagnostician.validate(Diagnostician.java:108) [66:org.eclipse.emf.ecore:2.12.0.v20160420-0247]
	at org.eclipse.smarthome.model.core.internal.ModelRepositoryImpl.validateModel(ModelRepositoryImpl.java:280) [128:org.eclipse.smarthome.model.core:0.10.0.oh240]
	at org.eclipse.smarthome.model.core.internal.ModelRepositoryImpl.addOrRefreshModel(ModelRepositoryImpl.java:93) [128:org.eclipse.smarthome.model.core:0.10.0.oh240]
	at org.eclipse.smarthome.model.core.internal.folder.FolderObserver.checkFile(FolderObserver.java:227) [128:org.eclipse.smarthome.model.core:0.10.0.oh240]
	at org.eclipse.smarthome.model.core.internal.folder.FolderObserver.processIgnoredFiles(FolderObserver.java:137) [128:org.eclipse.smarthome.model.core:0.10.0.oh240]
	at org.eclipse.smarthome.model.core.internal.folder.FolderObserver.addModelParser(FolderObserver.java:85) [128:org.eclipse.smarthome.model.core:0.10.0.oh240]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.apache.felix.scr.impl.inject.methods.BaseMethod.invokeMethod(BaseMethod.java:228) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.inject.methods.BaseMethod.access$500(BaseMethod.java:41) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.inject.methods.BaseMethod$Resolved.invoke(BaseMethod.java:664) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.inject.methods.BaseMethod.invoke(BaseMethod.java:510) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.inject.methods.BindMethod.invoke(BindMethod.java:42) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1809) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:1784) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeBindMethod(SingleComponentManager.java:409) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:333) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:302) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1216) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1137) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:944) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:880) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1168) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:125) [39:org.apache.felix.scr:2.1.2]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) [?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:920) [?:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225) [?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:469) [?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:891) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:877) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:128) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:944) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:727) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.addedService(DependencyManager.java:1053) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.addedService(DependencyManager.java:1007) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1216) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1137) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:944) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:880) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1168) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:125) [39:org.apache.felix.scr:2.1.2]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) [?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:920) [?:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225) [?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:469) [?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:891) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:877) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:128) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:944) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:727) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:661) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:427) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:665) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:339) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:381) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.Activator.access$200(Activator.java:49) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:263) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.AbstractExtender.createExtension(AbstractExtender.java:196) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:169) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:49) [39:org.apache.felix.scr:2.1.2]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482) [?:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415) [?:?]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232) [?:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444) [?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:908) [?:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:213) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:120) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:112) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:168) [?:?]
	at org.eclipse.osgi.container.Module.publishEvent(Module.java:476) [?:?]
	at org.eclipse.osgi.container.Module.start(Module.java:467) [?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1634) [?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1614) [?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1585) [?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1528) [?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [?:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340) [?:?]
11:12:04.983 [INFO ] [del.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'SetDefaults.rules', using it anyway:
Error executing EValidator
11:12:04.986 [INFO ] [del.co

This is the corresponding rule file:

// Setting Default Values at System Start

rule "Heizung Defaults to AUTO"
when Time cron "17 42 0 ? * MON-SUN" or
     Time cron "17 52 6 ? * MON-FRI" or
     Time cron "17 52 7 ? * SAT-SUN"
// Debug
//when Item modeBudHeiz changed

then
  // Heizungsmodus auf << Programm >> gleich << AUTO >> setzen

  logInfo("FILE", "***** SET_DEFAULTS: Checking Heizungsmodus: " + modeBudHeiz.state)

  if (modeBudHeiz.state != "auto") {
    modeBudHeiz.sendCommand("auto")
    Thread::sleep(3000) // let persistence finish restoring a few seconds
    logInfo("FILE", "***** SET_DEFAULTS setzt Heizungsmodus auf: " + modeBudHeiz.state)
  }
  end

rule "Set Default Values"
when
    System started
then
  Thread::sleep(5000) // let persistence finish restoring a few seconds
	logInfo("FILE", "***** SET_DEFAULTS starting: Setting System Defaults at openHAB2 startup or recycle *****")

  // Standard Luftdruckwert für Ginsheim
  STDPres.postUpdate(1013.25)
  Thread::sleep(3000) // let persistence finish restoring a few seconds
  logInfo("FILE", "***** Standard Luftdruckwert STDPres wird gesetzt auf Default: " + STDPres.state)

  // Standard Kalibrierwert für Devolo Sensor setzen
  WzTempCalibWert.postUpdate(0.6)
  WzHumiCalibWert.postUpdate(-7.0)
  Thread::sleep(3000) // let persistence finish restoring a few seconds
  logInfo("FILE", "***** WzTempCalibWert wird gesetzt auf Default: " + WzTempCalibWert.state)
  logInfo("FILE", "***** WzHumiCalibWert wird gesetzt auf Default: " + WzHumiCalibWert.state)

  // Standard Temperatur für das Wohnzimmer setzen
  comfGruppeEGtemp.postUpdate(22.9)
  Thread::sleep(3000) // let persistence finish restoring a few seconds
  logInfo("FILE", "***** comfGruppeEGtemp wird gesetzt auf Default: " + comfGruppeEGtemp.state)

  // Setting default for Wasserdruck Notification
  if (EmailStatusDruck.state != NULL) logInfo("FILE", "***** EmailStatusDruck ist gesetzt mit dem Wert: " + EmailStatusDruck.state)

	if (EmailStatusDruck.state == NULL) {
    EmailStatusDruck.postUpdate("off")
    logInfo("FILE", "***** EmailStatusDruck hatte noch keinen Wert und wird gesetzt auf: " + EmailStatusDruck.state)
  }

  // Setting default for MamaIstKalt
    MamaIstKalt.postUpdate(0)
    Thread::sleep(3000) // let persistence finish restoring a few seconds
    logInfo("FILE", "***** MamaIstKalt wird gesetzt auf Default: " + MamaIstKalt.state)

  // Setting default for PartyPauseModus
    PartyPauseModus.postUpdate(0)
    Thread::sleep(3000) // let persistence finish restoring a few seconds
    logInfo("FILE", "***** PartyPauseModus wird gesetzt auf Default: " + PartyPauseModus.state)

  // Setting default for ManualOverWrite
    ManualOverWrite.postUpdate(0)
    Thread::sleep(3000) // let persistence finish restoring a few seconds
    logInfo("FILE", "***** ManualOverWrite wird gesetzt auf Default: " + ManualOverWrite.state)

  // Setting Min und Max Werte für Heizungsdruck Chart
    minBudHeizDruck.postUpdate(0)
    maxBudHeizDruck.postUpdate(2.5)
    Thread::sleep(3000) // let persistence finish restoring a few seconds
    logInfo("FILE", "***** minBudHeizDruck wird gesetzt auf Default: " + minBudHeizDruck.state)
    logInfo("FILE", "***** maxBudHeizDruck wird gesetzt auf Default: " + maxBudHeizDruck.state)

  // Online Status von Sensor und Thermostaten abfragen und in Variablen setzen
    var wz_status = getThingStatusInfo("zwave:device:73a3cf04:node2").getStatus()
    ZwaveWzStat.postUpdate(wz_status.toString())

    var gh_status = getThingStatusInfo("zwave:device:73a3cf04:node3").getStatus()
    ZwaveGhStat.postUpdate(gh_status.toString())

    var statavm1 = getThingStatusInfo("avmfritz:FRITZ_DECT_300:fritzbox:SOME_FB_AIN").getStatus()
    DevFD3CdgEZstat.postUpdate(statavm1.toString())

    var statavm2 = getThingStatusInfo("avmfritz:Comet_DECT:fritzbox:SOME_FB_AIN").getStatus()
    DevCD3CogBZstat.postUpdate(statavm2.toString())

    var statavm3 = getThingStatusInfo("avmfritz:FRITZ_DECT_300:fritzbox:SOME_FB_AIN").getStatus()
    DevFD3CegKstat.postUpdate(statavm3.toString())

    var statavm4 = getThingStatusInfo("avmfritz:FRITZ_DECT_300:fritzbox:SOME_FB_AIN").getStatus()
    DevFD3CegWZFstat.postUpdate(statavm4.toString())

    var statavm5 = getThingStatusInfo("avmfritz:FRITZ_DECT_300:fritzbox:SOME_FB_AIN").getStatus()
    DevFD3CegWZTstat.postUpdate(statavm5.toString())

  // Kontrolle ob Devolo Sensor (Wohnzimmer) online ist
  if (wz_status.toString() == 'OFFLINE')
  {
    logInfo("FILE", "***** SET_DEFAULTS: The zWave Thing << Devolo Sensor >> is " + wz_status)
    val message = "SET_DEFAULTS Rule: Devolo Sensor (Wohnzimmer) is >> " + wz_status + " <<. Please consider rebooting the Docker container !!!"
    sendMail("bla@yahoo.kx", "SET_DEFAULTS: Devolo Sensor (WZ) is " + wz_status + " !!!", message)
  }
  if (wz_status.toString() == 'ONLINE')
  {
    logInfo("FILE", "***** SET_DEFAULTS: zWave Thing << Devolo Sensor (Wohnzimmer) >> is " + wz_status)
    val message = "SET_DEFAULTS Rule: Devolo Sensor (Wohnzimmer) is >> " + wz_status + " <<. Nothing to do !!!"
    sendMail("bla@yahoo.kx", "SET_DEFAULTS: Devolo Sensor (WZ) is " + wz_status + " !!!", message)
  }

  // Kontrolle ob Fibaro Sensor (Gartenhaus) online ist
  if (gh_status.toString() == 'OFFLINE')
  {
    logInfo("FILE", "***** SET_DEFAULTS: The zWave Thing << Fibaro Sensor (Gartenhaus) >> is " + gh_status)
    val message = "SET_DEFAULTS Rule: Fibaro Sensor (Gartenhaus) is >> " + gh_status + " <<. Please consider rebooting the Docker container !!!"
    sendMail("bla@yahoo.kx", "SET_DEFAULTS: Fibaro Sensor (GH) is " + gh_status + " !", message)
  }
  if (gh_status.toString() == 'ONLINE')
  {
    logInfo("FILE", "***** SET_DEFAULTS: zWave Thing << Fibaro Sensor (Gartenhaus) >> is " + gh_status)
    val message = "SET_DEFAULTS Rule: Fibaro Sensor (Gartenhaus) is >> " + gh_status + " <<. Nothing to do !!!"
    sendMail("bla@yahoo.kx", "SET_DEFAULTS: Fibaro Sensor (GH) is " + gh_status + " !", message)
  }

  // Korrigieren der Außentemperatur
    corrBudAussen.postUpdate((istBudAussen.state as DecimalType) - 1.3)
    logInfo("FILE", "***** istBudAussen wird korrigiert auf: " + corrBudAussen.state)

  // repeat 'if' for other items

#
  Thread::sleep(3000) // let persistence finish restoring a few seconds
  logInfo("FILE", "***** SET_DEFAULTS finished: Setting System Defaults at openHAB2 startup or recycle *****")

end

I would be happy to understand why this happens and if it is critical. When the rule is triggered when the system is running for a while (e.g. changing the rule rile) then it runs without errors … That is why I assume that Richs explanation of my other issue might be true here as well …

[vzorglub (Vincent Regaud)]

@ohb1138

I would be happy to understand why this happens and if it is critical.

Yes Rich’s explanation is correct. These errors happen sometimes (Not all the time) at system start-up. This is because the start-up process is not a sequence but things start in parallel.
Sometimes the system tries to run a rule when not all the “vocabulary” has been loaded yet. In your case sendMail. But sometimes I see the same message for item names or even ON not recognized.

These errors are not critical. The devs are working on the start-up “sequence” issues and it should be resolved eventually. In the mean time ignore these errors. After start-up, as you say, these rules should be running just fine.

[ohb1138 (Justus Reich)]

Thanks Vincent!

But what about the java core dump of the EValidatior?
Does your explanation include this behaviour as well?

Would it make sense to put a delay into the rules file?

Thanks for a final comment!

Cheers
Justus

[vzorglub (Vincent Regaud)]

@ohb1138

But what about the java core dump of the EValidatior?
Does your explanation include this behaviour as well?

Yes

@ohb1138

Would it make sense to put a delay into the rules file?

No

Why are you using `Thread::sleep(3000) again and again?
What are you hoping to achieve with that?

[ohb1138 (Justus Reich)]

@vzorglub

Why are you using `Thread::sleep(3000) again and again?
What are you hoping to achieve with that?

When I am logging data into the log file it mostly logs the previous value as it always takes some time before the item has the updated value. And to be sure that I am logging the new value I am waiting for 3 seconds before I initiate the logging command …

And of course I need to do that in every path of the if branches …

If there is a better way to accomplish that, I am happy for any suggestion

[ohb1138 (Justus Reich)]

createTimer has a very uncomfortable syntax.
That is why I used the Thread::sleep(3000) command.

[vzorglub (Vincent Regaud)]

The problem with Thread::sleep is that it “locks” that thread and the system only have 5 in total.

250ms should be enough time to update an item value on the event bus.
Thread::sleep should be avoided if more that 500ms

Group you items updates together, wait 250ms and do you logInfo together

Try this:
I put the whole rule in a timer after 5 seconds, that replaces the first Thread:sleep(5000)
Then I group the postupdates (First batch together) wait 250ms and do the logInfos
The you have the if statements. Again only do the item update and then at the end of the rule post the logInfos together after waiting 250ms.

Your rule should now take 20ms to run. Time to create the timer
When timer executes, it should take not more than 1s in total to run. instead of your previous systax that was monoplolising a thread for at least 29 seconds

rule "Set Default Values"
when
        System started
then
    createTimer(now.plusSeconds(5), [ | //Thread::sleep(5000) // let persistence finish restoring a few seconds
        logInfo("FILE", "***** SET_DEFAULTS starting: Setting System Defaults at openHAB2 startup or recycle *****")

        // Standard Luftdruckwert für Ginsheim
        STDPres.postUpdate(1013.25)

        // Standard Kalibrierwert für Devolo Sensor setzen
        WzTempCalibWert.postUpdate(0.6)
        WzHumiCalibWert.postUpdate(-7.0)

        // Standard Temperatur für das Wohnzimmer setzen
        comfGruppeEGtemp.postUpdate(22.9)

        Thread::sleep(250) // let persistence finish restoring a few seconds

        logInfo("FILE", "***** Standard Luftdruckwert STDPres wird gesetzt auf Default: " + STDPres.state)
        logInfo("FILE", "***** WzTempCalibWert wird gesetzt auf Default: " + WzTempCalibWert.state)
        logInfo("FILE", "***** WzHumiCalibWert wird gesetzt auf Default: " + WzHumiCalibWert.state)
        logInfo("FILE", "***** comfGruppeEGtemp wird gesetzt auf Default: " + comfGruppeEGtemp.state)

        // Setting default for Wasserdruck Notification
        if (EmailStatusDruck.state != NULL) logInfo("FILE", "***** EmailStatusDruck ist gesetzt mit dem Wert: " + EmailStatusDruck.state)

	    if (EmailStatusDruck.state == NULL) {
            EmailStatusDruck.postUpdate("off")
            logInfo("FILE", "***** EmailStatusDruck hatte noch keinen Wert und wird gesetzt auf: " + EmailStatusDruck.state)
        }

        // Setting default for MamaIstKalt
        MamaIstKalt.postUpdate(0)
    
        // Setting default for PartyPauseModus
        PartyPauseModus.postUpdate(0)

        // Setting default for ManualOverWrite
        ManualOverWrite.postUpdate(0)

        // Setting Min und Max Werte für Heizungsdruck Chart
        minBudHeizDruck.postUpdate(0)
        maxBudHeizDruck.postUpdate(2.5)

        // Online Status von Sensor und Thermostaten abfragen und in Variablen setzen
        var wz_status = getThingStatusInfo("zwave:device:73a3cf04:node2").getStatus()
        ZwaveWzStat.postUpdate(wz_status.toString())

        var gh_status = getThingStatusInfo("zwave:device:73a3cf04:node3").getStatus()
        ZwaveGhStat.postUpdate(gh_status.toString())

        var statavm1 = getThingStatusInfo("avmfritz:FRITZ_DECT_300:fritzbox:SOME_FB_AIN").getStatus()
        DevFD3CdgEZstat.postUpdate(statavm1.toString())

        var statavm2 = getThingStatusInfo("avmfritz:Comet_DECT:fritzbox:SOME_FB_AIN").getStatus()
        DevCD3CogBZstat.postUpdate(statavm2.toString())

        var statavm3 = getThingStatusInfo("avmfritz:FRITZ_DECT_300:fritzbox:SOME_FB_AIN").getStatus()
        DevFD3CegKstat.postUpdate(statavm3.toString())

        var statavm4 = getThingStatusInfo("avmfritz:FRITZ_DECT_300:fritzbox:SOME_FB_AIN").getStatus()
        DevFD3CegWZFstat.postUpdate(statavm4.toString())

        var statavm5 = getThingStatusInfo("avmfritz:FRITZ_DECT_300:fritzbox:SOME_FB_AIN").getStatus()
        DevFD3CegWZTstat.postUpdate(statavm5.toString())

        // Kontrolle ob Devolo Sensor (Wohnzimmer) online ist
        if (wz_status.toString() == 'OFFLINE') {
            logInfo("FILE", "***** SET_DEFAULTS: The zWave Thing << Devolo Sensor >> is " + wz_status)
            val message = "SET_DEFAULTS Rule: Devolo Sensor (Wohnzimmer) is >> " + wz_status + " <<. Please consider rebooting the Docker container !!!"
            sendMail("bla@yahoo.kx", "SET_DEFAULTS: Devolo Sensor (WZ) is " + wz_status + " !!!", message)
        }
        if (wz_status.toString() == 'ONLINE') {
            logInfo("FILE", "***** SET_DEFAULTS: zWave Thing << Devolo Sensor (Wohnzimmer) >> is " + wz_status)
            val message = "SET_DEFAULTS Rule: Devolo Sensor (Wohnzimmer) is >> " + wz_status + " <<. Nothing to do !!!"
            sendMail("bla@yahoo.kx", "SET_DEFAULTS: Devolo Sensor (WZ) is " + wz_status + " !!!", message)
        }

        // Kontrolle ob Fibaro Sensor (Gartenhaus) online ist
        if (gh_status.toString() == 'OFFLINE') {
            logInfo("FILE", "***** SET_DEFAULTS: The zWave Thing << Fibaro Sensor (Gartenhaus) >> is " + gh_status)
            val message = "SET_DEFAULTS Rule: Fibaro Sensor (Gartenhaus) is >> " + gh_status + " <<. Please consider rebooting the Docker container !!!"
            sendMail("bla@yahoo.kx", "SET_DEFAULTS: Fibaro Sensor (GH) is " + gh_status + " !", message)
        }
        if (gh_status.toString() == 'ONLINE') {
            logInfo("FILE", "***** SET_DEFAULTS: zWave Thing << Fibaro Sensor (Gartenhaus) >> is " + gh_status)
            val message = "SET_DEFAULTS Rule: Fibaro Sensor (Gartenhaus) is >> " + gh_status + " <<. Nothing to do !!!"
            sendMail("bla@yahoo.kx", "SET_DEFAULTS: Fibaro Sensor (GH) is " + gh_status + " !", message)
        }

        // Korrigieren der Außentemperatur
        corrBudAussen.postUpdate((istBudAussen.state as DecimalType) - 1.3)
        logInfo("FILE", "***** istBudAussen wird korrigiert auf: " + corrBudAussen.state)

        // repeat 'if' for other items

        Thread::sleep(250) // let persistence finish restoring a few seconds
        logInfo("FILE", "***** MamaIstKalt wird gesetzt auf Default: " + MamaIstKalt.state)
        logInfo("FILE", "***** PartyPauseModus wird gesetzt auf Default: " + PartyPauseModus.state)
        logInfo("FILE", "***** ManualOverWrite wird gesetzt auf Default: " + ManualOverWrite.state)
        logInfo("FILE", "***** minBudHeizDruck wird gesetzt auf Default: " + minBudHeizDruck.state)
        logInfo("FILE", "***** maxBudHeizDruck wird gesetzt auf Default: " + maxBudHeizDruck.state)

        logInfo("FILE", "***** SET_DEFAULTS finished: Setting System Defaults at openHAB2 startup or recycle *****")
    ])
end

[ohb1138 (Justus Reich)]

Thanks Vincent, I will try that … also good to know that 250ms should be sufficient for storing the values right before logging them

I must admit that with OH 2.4 I got several times some “Low configured threats” warnings and I new that Thread is not the best way but I did not knew better.

Now, I do! Thank you!!!

[ohb1138 (Justus Reich)]

I have actually the issue in any other rule file as well. And as there are several rules per file which are triggered separately, I am using the Thread command in every rule to give some time before logging.

What would you suggest to do?

Should I simply reduce the time from 3000ms to 250ms or is there a smarter way to wait until persistence gets updated?

[ohb1138 (Justus Reich)]

Changing the rule to your suggested way creates this error now:

14:18:55.355 [ERROR] [org.quartz.core.JobRunShell          ] - Job DEFAULT.2018-12-21T14:18:55.086+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  logInfo(<XStringLiteralImpl>,<XStringLiteralImpl>)
  <XFeatureCallImplCustom>.postUpdate(<XNumberLiteralImpl>)
  <XFeatureCallImplCustom>.postUpdate(<XNumberLiteralImpl>)
  <XFeatureCallImplCustom>.postUpdate(<XUnaryOperationImplCustom>)
  <XFeatureCallImplCustom>.postUpdate(<XNumberLiteralImpl>)
  <XFeatureCallImplCustom>::sleep(<XNumberLiteralImpl>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@7f29917a
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@2176c63a
  <XFeatureCallImplCustom>.postUpdate(<XNumberLiteralImpl>)
  <XFeatureCallImplCustom>.postUpdate(<XNumberLiteralImpl>)
  <XFeatureCallImplCustom>.postUpdate(<XNumberLiteralImpl>)
  <XFeatureCallImplCustom>.postUpdate(<XNumberLiteralImpl>)
  <XFeatureCallImplCustom>.postUpdate(<XNumberLiteralImpl>)
  var wz_status
  <XFeatureCallImplCustom>.postUpdate(<XMemberFeatureCallImplCustom>)
  var gh_status
  <XFeatureCallImplCustom>.postUpdate(<XMemberFeatureCallImplCustom>)
  var statavm1
  <XFeatureCallImplCustom>.postUpdate(<XMemberFeatureCallImplCustom>)
  var statavm2
  <XFeatureCallImplCustom>.postUpdate(<XMemberFeatureCallImplCustom>)
  var statavm3
  <XFeatureCallImplCustom>.postUpdate(<XMemberFeatureCallImplCustom>)
  var statavm4
  <XFeatureCallImplCustom>.postUpdate(<XMemberFeatureCallImplCustom>)
  var statavm5
  <XFeatureCallImplCustom>.postUpdate(<XMemberFeatureCallImplCustom>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@a836c66
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@4c670f6
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@70fcc568
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@58ec8d29
  <XFeatureCallImplCustom>.postUpdate(<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  <XFeatureCallImplCustom>::sleep(<XNumberLiteralImpl>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XStringLiteralImpl>)
} ] threw an unhandled Exception: 
java.lang.reflect.UndeclaredThrowableException: null
	at com.sun.proxy.$Proxy170.apply(Unknown Source) ~[?:?]
	at org.eclipse.smarthome.model.script.internal.actions.TimerExecutionJob.execute(TimerExecutionJob.java:49) ~[?:?]
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202) [107:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [107:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
Caused by: org.eclipse.smarthome.model.script.engine.ScriptExecutionException: The name 'MamaIstKalt' cannot be resolved to an item or type; line 55, column 11, length 11
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:141) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:902) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:865) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:224) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:768) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:220) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:447) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:228) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:190) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.ClosureInvocationHandler.doInvoke(ClosureInvocationHandler.java:46) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.AbstractClosureInvocationHandler.invoke(AbstractClosureInvocationHandler.java:29) ~[?:?]
	... 4 more
14:18:55.381 [ERROR] [org.quartz.core.ErrorLogger          ] - Job (DEFAULT.2018-12-21T14:18:55.086+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  logInfo(<XStringLiteralImpl>,<XStringLiteralImpl>)
  <XFeatureCallImplCustom>.postUpdate(<XNumberLiteralImpl>)
  <XFeatureCallImplCustom>.postUpdate(<XNumberLiteralImpl>)
  <XFeatureCallImplCustom>.postUpdate(<XUnaryOperationImplCustom>)
  <XFeatureCallImplCustom>.postUpdate(<XNumberLiteralImpl>)
  <XFeatureCallImplCustom>::sleep(<XNumberLiteralImpl>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@7f29917a
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@2176c63a
  <XFeatureCallImplCustom>.postUpdate(<XNumberLiteralImpl>)
  <XFeatureCallImplCustom>.postUpdate(<XNumberLiteralImpl>)
  <XFeatureCallImplCustom>.postUpdate(<XNumberLiteralImpl>)
  <XFeatureCallImplCustom>.postUpdate(<XNumberLiteralImpl>)
  <XFeatureCallImplCustom>.postUpdate(<XNumberLiteralImpl>)
  var wz_status
  <XFeatureCallImplCustom>.postUpdate(<XMemberFeatureCallImplCustom>)
  var gh_status
  <XFeatureCallImplCustom>.postUpdate(<XMemberFeatureCallImplCustom>)
  var statavm1
  <XFeatureCallImplCustom>.postUpdate(<XMemberFeatureCallImplCustom>)
  var statavm2
  <XFeatureCallImplCustom>.postUpdate(<XMemberFeatureCallImplCustom>)
  var statavm3
  <XFeatureCallImplCustom>.postUpdate(<XMemberFeatureCallImplCustom>)
  var statavm4
  <XFeatureCallImplCustom>.postUpdate(<XMemberFeatureCallImplCustom>)
  var statavm5
  <XFeatureCallImplCustom>.postUpdate(<XMemberFeatureCallImplCustom>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@a836c66
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@4c670f6
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@70fcc568
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@58ec8d29
  <XFeatureCallImplCustom>.postUpdate(<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  <XFeatureCallImplCustom>::sleep(<XNumberLiteralImpl>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  logInfo(<XStringLiteralImpl>,<XStringLiteralImpl>)
} ] threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception.
	at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [107:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [107:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
Caused by: java.lang.reflect.UndeclaredThrowableException
	at com.sun.proxy.$Proxy170.apply(Unknown Source) ~[?:?]
	at org.eclipse.smarthome.model.script.internal.actions.TimerExecutionJob.execute(TimerExecutionJob.java:49) ~[?:?]
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202) ~[?:?]
	... 1 more
Caused by: org.eclipse.smarthome.model.script.engine.ScriptExecutionException: The name 'MamaIstKalt' cannot be resolved to an item or type; line 55, column 11, length 11
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:141) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:902) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:865) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:224) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:768) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:220) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:447) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:228) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:190) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.ClosureInvocationHandler.doInvoke(ClosureInvocationHandler.java:46) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.AbstractClosureInvocationHandler.invoke(AbstractClosureInvocationHandler.java:29) ~[?:?]
	at com.sun.proxy.$Proxy170.apply(Unknown Source) ~[?:?]
	at org.eclipse.smarthome.model.script.internal.actions.TimerExecutionJob.execute(TimerExecutionJob.java:49) ~[?:?]
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202) ~[?:?]
... 1 more

[ohb1138 (Justus Reich)]

I moved back to my original rule version and reduced the Thread calls before logging down to 300ms and the first one to 2500ms … I don’t get anymore the last shown java dump and the first one less frequent … I will try to prevent any further usage of the Thread command …

[vzorglub (Vincent Regaud)]

@ohb1138

Should I simply reduce the time from 3000ms to 250ms or is there a smarter way to wait until persistence gets updated?

It has nothing to do with persistence.
When an item receives an update, it takes a bit of time for it’s state to actually change.

In your rules do the logInfo before the postUpdate instead of the other way around
This way you don’t have to wait
For example:

logInfo("ITEM UPDATE", "Heating updated to 10")
Heating.postUpdate(10)

[vzorglub (Vincent Regaud)]

Actually you don’t need that timer or sleep at the beginning of the rule.
Do this:

rule "Set Default Values"
when
        System started
then
        logInfo("FILE", "***** SET_DEFAULTS starting: Setting System Defaults at openHAB2 startup or recycle *****")

        // Standard Luftdruckwert für Ginsheim
        STDPres.postUpdate(1013.25)

        // Standard Kalibrierwert für Devolo Sensor setzen
        WzTempCalibWert.postUpdate(0.6)
        WzHumiCalibWert.postUpdate(-7.0)

        // Standard Temperatur für das Wohnzimmer setzen
        comfGruppeEGtemp.postUpdate(22.9)

        Thread::sleep(250) // let persistence finish restoring a few seconds

        logInfo("FILE", "***** Standard Luftdruckwert STDPres wird gesetzt auf Default: " + STDPres.state)
        logInfo("FILE", "***** WzTempCalibWert wird gesetzt auf Default: " + WzTempCalibWert.state)
        logInfo("FILE", "***** WzHumiCalibWert wird gesetzt auf Default: " + WzHumiCalibWert.state)
        logInfo("FILE", "***** comfGruppeEGtemp wird gesetzt auf Default: " + comfGruppeEGtemp.state)

        // Setting default for Wasserdruck Notification
        if (EmailStatusDruck.state != NULL) logInfo("FILE", "***** EmailStatusDruck ist gesetzt mit dem Wert: " + EmailStatusDruck.state)

	    if (EmailStatusDruck.state == NULL) {
            EmailStatusDruck.postUpdate("off")
            logInfo("FILE", "***** EmailStatusDruck hatte noch keinen Wert und wird gesetzt auf: " + EmailStatusDruck.state)
        }

        // Setting default for MamaIstKalt
        MamaIstKalt.postUpdate(0)
    
        // Setting default for PartyPauseModus
        PartyPauseModus.postUpdate(0)

        // Setting default for ManualOverWrite
        ManualOverWrite.postUpdate(0)

        // Setting Min und Max Werte für Heizungsdruck Chart
        minBudHeizDruck.postUpdate(0)
        maxBudHeizDruck.postUpdate(2.5)

        // Online Status von Sensor und Thermostaten abfragen und in Variablen setzen
        var wz_status = getThingStatusInfo("zwave:device:73a3cf04:node2").getStatus()
        ZwaveWzStat.postUpdate(wz_status.toString())

        var gh_status = getThingStatusInfo("zwave:device:73a3cf04:node3").getStatus()
        ZwaveGhStat.postUpdate(gh_status.toString())

        var statavm1 = getThingStatusInfo("avmfritz:FRITZ_DECT_300:fritzbox:SOME_FB_AIN").getStatus()
        DevFD3CdgEZstat.postUpdate(statavm1.toString())

        var statavm2 = getThingStatusInfo("avmfritz:Comet_DECT:fritzbox:SOME_FB_AIN").getStatus()
        DevCD3CogBZstat.postUpdate(statavm2.toString())

        var statavm3 = getThingStatusInfo("avmfritz:FRITZ_DECT_300:fritzbox:SOME_FB_AIN").getStatus()
        DevFD3CegKstat.postUpdate(statavm3.toString())

        var statavm4 = getThingStatusInfo("avmfritz:FRITZ_DECT_300:fritzbox:SOME_FB_AIN").getStatus()
        DevFD3CegWZFstat.postUpdate(statavm4.toString())

        var statavm5 = getThingStatusInfo("avmfritz:FRITZ_DECT_300:fritzbox:SOME_FB_AIN").getStatus()
        DevFD3CegWZTstat.postUpdate(statavm5.toString())

        // Kontrolle ob Devolo Sensor (Wohnzimmer) online ist
        if (wz_status.toString() == 'OFFLINE') {
            logInfo("FILE", "***** SET_DEFAULTS: The zWave Thing << Devolo Sensor >> is " + wz_status)
            val message = "SET_DEFAULTS Rule: Devolo Sensor (Wohnzimmer) is >> " + wz_status + " <<. Please consider rebooting the Docker container !!!"
            sendMail("bla@yahoo.kx", "SET_DEFAULTS: Devolo Sensor (WZ) is " + wz_status + " !!!", message)
        }
        if (wz_status.toString() == 'ONLINE') {
            logInfo("FILE", "***** SET_DEFAULTS: zWave Thing << Devolo Sensor (Wohnzimmer) >> is " + wz_status)
            val message = "SET_DEFAULTS Rule: Devolo Sensor (Wohnzimmer) is >> " + wz_status + " <<. Nothing to do !!!"
            sendMail("bla@yahoo.kx", "SET_DEFAULTS: Devolo Sensor (WZ) is " + wz_status + " !!!", message)
        }

        // Kontrolle ob Fibaro Sensor (Gartenhaus) online ist
        if (gh_status.toString() == 'OFFLINE') {
            logInfo("FILE", "***** SET_DEFAULTS: The zWave Thing << Fibaro Sensor (Gartenhaus) >> is " + gh_status)
            val message = "SET_DEFAULTS Rule: Fibaro Sensor (Gartenhaus) is >> " + gh_status + " <<. Please consider rebooting the Docker container !!!"
            sendMail("bla@yahoo.kx", "SET_DEFAULTS: Fibaro Sensor (GH) is " + gh_status + " !", message)
        }
        if (gh_status.toString() == 'ONLINE') {
            logInfo("FILE", "***** SET_DEFAULTS: zWave Thing << Fibaro Sensor (Gartenhaus) >> is " + gh_status)
            val message = "SET_DEFAULTS Rule: Fibaro Sensor (Gartenhaus) is >> " + gh_status + " <<. Nothing to do !!!"
            sendMail("bla@yahoo.kx", "SET_DEFAULTS: Fibaro Sensor (GH) is " + gh_status + " !", message)
        }

        // Korrigieren der Außentemperatur
        corrBudAussen.postUpdate((istBudAussen.state as DecimalType) - 1.3)
        logInfo("FILE", "***** istBudAussen wird korrigiert auf: " + corrBudAussen.state)

        // repeat 'if' for other items

        Thread::sleep(250) // let persistence finish restoring a few seconds
        logInfo("FILE", "***** MamaIstKalt wird gesetzt auf Default: " + MamaIstKalt.state)
        logInfo("FILE", "***** PartyPauseModus wird gesetzt auf Default: " + PartyPauseModus.state)
        logInfo("FILE", "***** ManualOverWrite wird gesetzt auf Default: " + ManualOverWrite.state)
        logInfo("FILE", "***** minBudHeizDruck wird gesetzt auf Default: " + minBudHeizDruck.state)
        logInfo("FILE", "***** maxBudHeizDruck wird gesetzt auf Default: " + maxBudHeizDruck.state)

        logInfo("FILE", "***** SET_DEFAULTS finished: Setting System Defaults at openHAB2 startup or recycle *****")
end

[ohb1138 (Justus Reich)]

@vzorglub

In your rules do the logInfo before the postUpdate instead of the other way around
This way you don’t have to wait
For example:

logInfo("ITEM UPDATE", "Heating updated to 10")
Heating.postUpdate(10)

But I am logging the actual state of the item in my logging command (see below) to confirm that it has the right value.

        logInfo("FILE", "***** PartyPauseModus wird gesetzt auf Default: " + PartyPauseModus.state)

With your approach I have no verifcation that the value was set.

[vzorglub (Vincent Regaud)]

@ohb1138

But I am logging the actual state of the item in my logging command (see below) to confirm that it has the right value.

But why?
The system logs that anyway

[ohb1138 (Justus Reich)]

Paranoia?

I thought it is ok to log the state after the change to verify that it is really changed - not knowing that the Thread timer is so costly and blocking …

[vzorglub (Vincent Regaud)]

@ohb1138

I thought it is ok to log the state after the change to verify that it is really changed

It is ok, but the system does that for you regardless in your events.log
Let openHAB do it for you

[ohb1138 (Justus Reich)]

@vzorglub

Let openHAB do it for you

Will do I think it is time to build some faith and trust …

[rlkoshak (Rich Koshak)]

@ohb1138

What would you suggest to do?

Should I simply reduce the time from 3000ms to 250ms or is there a smarter way to wait until persistence gets updated?

• (OH 1.x and OH 2.x Rules DSL only] Why have my Rules stopped running? Why Thread::sleep is a bad idea

@ohb1138

With your approach I have no verifcation that the value was set.

Look in events.log for that if you must have this security blanket. But in all the years I’ve used OH I’ve never encountered a case where a postUpdate did not update an Item.

[ohb1138 (Justus Reich)]

Thanks Rich,

I will start replacing the Thread commands with the timerCreate but the syntax of the timer is not very convenient and error-prone missing brackets or the pipe and so on …

Thanks for clarifying that Thread is so “destructive” …