Question about Thread::sleep

hannibal29 · August 15, 2017, 1:01pm

Hi all,

I currently have a problem in understanding the Thread::sleep command in rules. I used this in some of my rules to get a short processing delay (max. 2sec) with my “old” OH 1.8.3 setup and had never an issue with it.

Now as I’m reinventing everything from scratch with OH2.1 I discovered following behaviour:

When I use a Thread::sleep in a new rule (60sec) it seems that during this 60sec all rules are paused, even if they are distributed across multiple files.

I know I can solve this with a timer. Just want to understand if this is the expected behaviour that during a Thread::sleep is counting the whole rule engine is paused?

Thanks for any feedback,
Sebastian

rlkoshak · August 15, 2017, 3:51pm

That is not how it is supposed to work. It should only pause the one thread that that particular instance if that rule is running in. It should not pause all rules processing.

First try it in the latest snapshot to make sure it hasn’t already been fixed.

Then I recommend creating as simple as example you can and posting an issue at the ESH repo. This is incorrect behavior.

hannibal29 · August 15, 2017, 7:30pm

Ok, thanks for the feedback.

That’s also what I thought.

Currently I’m running in OH2.1 stable.
So I will setup a test environment with latest snapshot to verify this behaviour as soon as I have time.

hannibal29 · August 18, 2017, 6:11pm

Ok,
I have an update for this.

Tried it with a simple example

Items:

witch StartUp      "StartUp Switch"   // triggers rules to with defined delay after system startup
Switch TestSwitch   "Test Switch"      // to test manuell rule triggers during delay
String Result       "Result"           // shows result string

Rule file 1

rule "StartUp"
when
  System started
then
  logDebug("RULES", "+++ Rule 'StartUp' started +++")
  StartUp.sendCommand(OFF)
  Thread::sleep(60000)
  StartUp.sendCommand(ON)
  Thread::sleep(3000)
  StartUp.sendCommand(OFF)
  logDebug("RULES", "--- Rule 'StartUp' completed ---")
end

Rule file 2

rule "Test"
when
  Item TestSwitch received command
then
  logDebug("RULES", "+++ Rule 'Test' started +++")
  Result.postUpdate("Test rule triggered via REST")
  logDebug("RULES", "--- Rule 'Test' completed ---")
end

rule "Test2"
when
  Item StartUp received command ON
then
  logDebug("RULES", "+++ Rule 'Test2' started +++")
  Result.postUpdate("Test2 rule triggered via StartUp rule")
  logDebug("RULES", "--- Rule 'Test2' completed ---")
end

I tried it with 2.1.0 release build und 2.2.0 SNAPSHOT build #1017
Same result for both versions.

Here are the logs (with some comments) for 2.1.0

*** STARTUP openhab 2.1.0 release build ***

2017-08-18 18:40:15.749 [INFO ] [org.apache.felix.fileinstall        ] - Updating configuration from org.ops4j.pax.logging.cfg
2017-08-18 18:40:16.283 [WARN ] [les.properties.AutoEncryptionSupport] - User limit of inotify watches reached
java.io.IOException: User limit of inotify watches reached
	at sun.nio.fs.LinuxWatchService$Poller.implRegister(LinuxWatchService.java:264)[:1.8.0_144]
	at sun.nio.fs.AbstractPoller.processRequests(AbstractPoller.java:260)[:1.8.0_144]
	at sun.nio.fs.LinuxWatchService$Poller.run(LinuxWatchService.java:329)[:1.8.0_144]
	at java.lang.Thread.run(Thread.java:748)[:1.8.0_144]
2017-08-18 18:40:16.345 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.bundle.core/4.0.8
2017-08-18 18:40:16.364 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.config.core/4.0.8
2017-08-18 18:40:16.370 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.deployer.kar/4.0.8
2017-08-18 18:40:16.372 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.diagnostic.core/4.0.8
2017-08-18 18:40:16.404 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.features.command/4.0.8
2017-08-18 18:40:16.408 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.http.core/4.0.8
2017-08-18 18:40:16.438 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.instance.core/4.0.8
2017-08-18 18:40:16.530 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.jaas.command/4.0.8
2017-08-18 18:40:16.532 [INFO ] [ll.impl.action.osgi.CommandExtension] - Updating commands for bundle org.apache.karaf.jaas.command/4.0.8
2017-08-18 18:40:16.538 [INFO ] [ll.impl.action.osgi.CommandExtension] - Updating commands for bundle org.apache.karaf.jaas.command/4.0.8
2017-08-18 18:40:16.546 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.kar.core/4.0.8
2017-08-18 18:40:16.565 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.log.core/4.0.8
2017-08-18 18:40:16.568 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.package.core/4.0.8
2017-08-18 18:40:16.579 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.scr.command/4.0.8
2017-08-18 18:40:16.583 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.service.core/4.0.8
2017-08-18 18:40:16.618 [INFO ] [ll.impl.action.osgi.CommandExtension] - Command registration delayed for bundle org.apache.karaf.shell.commands/4.0.8. Missing dependencies: [org.jledit.EditorFactory]
2017-08-18 18:40:16.807 [INFO ] [ll.impl.action.osgi.CommandExtension] - Command registration delayed for bundle org.apache.karaf.shell.ssh/4.0.8. Missing dependencies: [org.apache.sshd.SshServer]
2017-08-18 18:40:16.812 [INFO ] [pache.sshd.common.util.SecurityUtils] - BouncyCastle not registered, using the default JCE provider
2017-08-18 18:40:16.820 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.system.core/4.0.8
2017-08-18 18:40:16.877 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.shell.commands/4.0.8
2017-08-18 18:40:16.895 [INFO ] [j.pax.web.service.internal.Activator] - EventAdmin support enabled, servlet events will be postet to topics.
2017-08-18 18:40:16.897 [INFO ] [j.pax.web.service.internal.Activator] - LogService support enabled, log events will be created.
2017-08-18 18:40:16.899 [INFO ] [j.pax.web.service.internal.Activator] - Pax Web started
2017-08-18 18:40:16.992 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.shell.ssh/4.0.8
2017-08-18 18:40:17.032 [INFO ] [org.eclipse.jetty.util.log          ] - Logging initialized @2298ms
2017-08-18 18:40:17.216 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.apache.karaf.wrapper.core/4.0.8
2017-08-18 18:40:17.271 [INFO ] [rvice.jetty.internal.JettyServerImpl] - Pax Web available at [0.0.0.0]:[8443]
2017-08-18 18:40:17.272 [INFO ] [vice.jetty.internal.JettyFactoryImpl] - SPDY not available, creating standard ServerConnector for Http
2017-08-18 18:40:17.273 [INFO ] [rvice.jetty.internal.JettyServerImpl] - Pax Web available at [0.0.0.0]:[8080]
2017-08-18 18:40:17.280 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [9]] to http service
2017-08-18 18:40:17.342 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.io.rest.docs_2.1.0 [194]] to http service
2017-08-18 18:40:17.384 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2017-08-18 18:40:17.423 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.io.rest.docs_2.1.0 [194], contextID=default], with context-name: 
2017-08-18 18:40:17.483 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.io.rest.docs_2.1.0 [194], contextID=default]}
2017-08-18 18:40:17.502 [INFO ] [org.eclipse.jetty.server.Server     ] - jetty-9.2.19.v20160908
2017-08-18 18:40:17.545 [INFO ] [.jetty.server.handler.ContextHandler] - Started o.e.j.s.h.ContextHandler@66800add{/static,null,AVAILABLE}
2017-08-18 18:40:17.599 [INFO ] [eclipse.jetty.server.ServerConnector] - Started 0.0.0.0:8443@10bc9073{SSL-http/1.1}{0.0.0.0:8443}
2017-08-18 18:40:17.603 [INFO ] [eclipse.jetty.server.ServerConnector] - Started default@743d90eb{HTTP/1.1}{0.0.0.0:8080}
2017-08-18 18:40:17.603 [INFO ] [org.eclipse.jetty.server.Server     ] - Started @2869ms
2017-08-18 18:40:17.633 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.ui.dashboard_2.1.0 [170]] to http service
2017-08-18 18:40:17.640 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2017-08-18 18:40:17.646 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.1.0 [170], contextID=default], with context-name: 
2017-08-18 18:40:17.659 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.1.0 [170], contextID=default]}
2017-08-18 18:40:17.663 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://192.168.178.20:8080
2017-08-18 18:40:17.664 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://192.168.178.20:8443
2017-08-18 18:40:17.983 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.eclipse.smarthome.core.audio_0.9.0.b5 [99]] to http service
2017-08-18 18:40:18.003 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2017-08-18 18:40:18.008 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.b5 [99], contextID=default], with context-name: 
2017-08-18 18:40:18.011 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.b5 [99], contextID=default]}
2017-08-18 18:40:18.100 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2017-08-18 18:40:18.104 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [9], contextID=default], with context-name: 
2017-08-18 18:40:18.108 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [9], contextID=default]}
2017-08-18 18:40:18.165 [INFO ] [org.quartz.impl.StdSchedulerFactory ] - Using default implementation for ThreadExecutor
2017-08-18 18:40:18.196 [INFO ] [rg.quartz.core.SchedulerSignalerImpl] - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
2017-08-18 18:40:18.196 [INFO ] [org.quartz.core.QuartzScheduler     ] - Quartz Scheduler v.2.2.1 created.
2017-08-18 18:40:18.197 [INFO ] [org.quartz.simpl.RAMJobStore        ] - RAMJobStore initialized.
2017-08-18 18:40:18.198 [INFO ] [org.quartz.core.QuartzScheduler     ] - Scheduler meta-data: Quartz Scheduler (v2.2.1) 'openHAB-job-scheduler' with instanceId 'NON_CLUSTERED'
  Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
  NOT STARTED.
  Currently in standby mode.
  Number of jobs executed: 0
  Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 2 threads.
  Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.

2017-08-18 18:40:18.199 [INFO ] [org.quartz.impl.StdSchedulerFactory ] - Quartz scheduler 'openHAB-job-scheduler' initialized from specified file: '/opt/openhab/openhab2_Testsystem_2-1/runtime/etc/quartz.properties'
2017-08-18 18:40:18.199 [INFO ] [org.quartz.impl.StdSchedulerFactory ] - Quartz scheduler version: 2.2.1
2017-08-18 18:40:18.199 [INFO ] [org.quartz.core.QuartzScheduler     ] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED started.
2017-08-18 18:40:20.211 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'main.items'
2017-08-18 18:40:20.242 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'StartUp' has been added.
2017-08-18 18:40:20.263 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'TestSwitch' has been added.
2017-08-18 18:40:20.265 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'Result' has been added.
2017-08-18 18:40:20.464 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
2017-08-18 18:40:21.841 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'two.rules'
2017-08-18 18:40:22.049 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'one.rules'
2017-08-18 18:40:22.227 [INFO ] [org.quartz.core.QuartzScheduler     ] - JobFactory set to: org.eclipse.smarthome.model.rule.runtime.internal.engine.GuiceAwareJobFactory@6d03497a
2017-08-18 18:40:22.228 [INFO ] [org.quartz.core.QuartzScheduler     ] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED paused.
2017-08-18 18:40:22.446 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'main.things'
2017-08-18 18:40:22.448 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'main.things' is either empty or cannot be parsed correctly!
2017-08-18 18:40:22.506 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'Strip_Brightness-milight:rgbLed:ACCF23DBA370:5:ledbrightness' has been added.
2017-08-18 18:40:22.507 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'LocalSun_Rise-astro:sun:local:rise#start' has been added.
2017-08-18 18:40:22.508 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'FernseherWZ_ButtonPress-harmonyhub:device:Wohnzimmer:36437306:buttonPress' has been added.
2017-08-18 18:40:22.520 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'HABServer192168178190_Online-network:device:192_168_178_190:online' has been added.
2017-08-18 18:40:22.521 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'LocalTime_Date-ntp:ntp:local:string' has been added.
2017-08-18 18:40:22.523 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'Bulb_Brightness-milight:whiteLed:ACCF23DBA370:1:ledbrightness' has been added.
2017-08-18 18:40:22.665 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.eclipse.smarthome.ui_0.9.0.b5 [136]] to http service
2017-08-18 18:40:22.749 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2017-08-18 18:40:22.762 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.b5 [136], contextID=default], with context-name: 
2017-08-18 18:40:22.810 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.b5 [136], contextID=default]}
2017-08-18 18:40:22.845 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.eclipse.smarthome.ui.icon_0.9.0.b5 [137]] to http service
2017-08-18 18:40:22.852 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2017-08-18 18:40:22.861 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.b5 [137], contextID=default], with context-name: 
2017-08-18 18:40:22.864 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.b5 [137], contextID=default]}
2017-08-18 18:40:22.931 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.jupnp_2.2.0 [162]] to http service
2017-08-18 18:40:22.962 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2017-08-18 18:40:22.967 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@5adbbc8d, with context-name: 
2017-08-18 18:40:22.981 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@5adbbc8d}
2017-08-18 18:40:23.083 [INFO ] [ll.impl.action.osgi.CommandExtension] - Registering commands for bundle org.openhab.core.karaf/2.1.0
2017-08-18 18:40:23.522 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.eclipse.smarthome.ui.basic_0.9.0.b5 [190]] to http service
2017-08-18 18:40:23.527 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2017-08-18 18:40:23.532 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.b5 [190], contextID=default], with context-name: 
2017-08-18 18:40:23.547 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.b5 [190], contextID=default]}
2017-08-18 18:40:23.739 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-08-18 18:40:23.860 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.eclipse.smarthome.ui.classic_0.9.0.b5 [191]] to http service
2017-08-18 18:40:23.894 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2017-08-18 18:40:23.908 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.eclipse.smarthome.ui.classic_0.9.0.b5 [191], contextID=default], with context-name: 
2017-08-18 18:40:23.915 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.classic_0.9.0.b5 [191], contextID=default]}
2017-08-18 18:40:23.917 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2017-08-18 18:40:23.980 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.eclipse.smarthome.ui.paper_0.9.0.b5 [192]] to http service
2017-08-18 18:40:23.990 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2017-08-18 18:40:23.993 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.b5 [192], contextID=default], with context-name: 
2017-08-18 18:40:23.998 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.b5 [192], contextID=default]}
2017-08-18 18:40:23.999 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-08-18 18:40:24.306 [INFO ] [vice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.core_2.1.0 [166]] to http service
2017-08-18 18:40:24.315 [INFO ] [rg.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
2017-08-18 18:40:24.320 [INFO ] [ce.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.core_2.1.0 [166], contextID=default], with context-name: 
2017-08-18 18:40:24.339 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.1.0 [166], contextID=default]}

*** HERE WE GO ***

** Startup rule is triggered by 'System started' **

2017-08-18 18:40:27.740 [DEBUG] [eclipse.smarthome.model.script.RULES] - +++ Rule 'StartUp' started +++
2017-08-18 18:40:27.747 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'StartUp' received command OFF
2017-08-18 18:40:27.754 [INFO ] [marthome.event.ItemStateChangedEvent] - StartUp changed from NULL to OFF

** Manually trigger TestSwitch via REST while Thread::sleep is counting -> Rule 'Test' is NOT triggered**

2017-08-18 18:40:35.972 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'TestSwitch' received command ON
2017-08-18 18:40:35.973 [INFO ] [marthome.event.ItemStateChangedEvent] - TestSwitch changed from NULL to ON
2017-08-18 18:40:41.306 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'TestSwitch' received command ON
2017-08-18 18:40:46.807 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'TestSwitch' received command ON
2017-08-18 18:40:54.508 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'TestSwitch' received command ON
2017-08-18 18:41:12.447 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'TestSwitch' received command ON

** Thread::sleep is over -> change item 'StartUp' immediately followed by another Thread:sleep -> rule 'Test2' is NOT triggered ** 
 
2017-08-18 18:41:27.753 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'StartUp' received command ON
2017-08-18 18:41:27.763 [INFO ] [marthome.event.ItemStateChangedEvent] - StartUp changed from OFF to ON
2017-08-18 18:41:30.753 [DEBUG] [eclipse.smarthome.model.script.RULES] - --- Rule 'StartUp' completed ---

** What is this? **

2017-08-18 18:41:30.758 [INFO ] [org.quartz.core.QuartzScheduler     ] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED started.

** Rule 'Startup' finished **

2017-08-18 18:41:30.758 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'StartUp' received command OFF
2017-08-18 18:41:30.761 [INFO ] [marthome.event.ItemStateChangedEvent] - StartUp changed from ON to OFF

** Manually trigger TestSwitch via REST -> Rule 'Test' is triggered**

2017-08-18 18:41:31.132 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'TestSwitch' received command ON
2017-08-18 18:41:31.153 [DEBUG] [eclipse.smarthome.model.script.RULES] - +++ Rule 'Test' started +++
2017-08-18 18:41:31.155 [DEBUG] [eclipse.smarthome.model.script.RULES] - --- Rule 'Test' completed ---
2017-08-18 18:41:31.157 [INFO ] [marthome.event.ItemStateChangedEvent] - Result changed from NULL to Test rule triggered via REST

So, I’m not a developer but it seems I can reproduce this behaviour. Or am I missing something?

Cheers
Sebastian

hannibal29 · August 21, 2017, 4:45pm

So, I just created an issue for this

hannibal29 · September 10, 2017, 7:16pm

Issue was fixed in latest snapshot