Bug?: Rules Running Multiple Times

shorin · April 14, 2017, 5:01am

I have an issue with rules running more than once - specifically, rules based on cron jobs. Rules based on device changes seem to work fine.

I’ve researched, and I think what I’m seeing is related to the bug: https://github.com/openhab/openhab2-addons/issues/1949 However, my issue isn’t that I’m triggering on multiple events. I’m only triggering on one cron job, but I’m seeing multiple instances in the logs.

I’ve also read Possible bug: rules fire more then once I’m using Notepad++ for editing, so I don’t think the temp file issue is at play here. I am seeing the multiple instances of a file in the logs when I save an update (not my primary issue here, but I figured I’d mention it for clarity):

2017-04-13 22:06:16.844 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'notification.rules'
2017-04-13 22:06:16.904 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'notification.rules'

The rule that I started noticing this on was one to monitor whether communications had been lost between OH2 and my Veras. In trying to troubleshoot, I removed all my other rules in the system, and then paired this one down to a very slim version for testing:

rule "Vera Communication Monitor"
when Time cron "0 /10 * * * ?"
then
	logInfo("          Notifications - Communications", "!!!!!!    Vera Communication Status - Testing..."
	logInfo("          Notifications - Communications", "!!!!!!    Vera Communication Status - Current: " + VeraHouseTime.state + "  Last: " + VeraHouseTimeLast.state)
	
	VeraHouseTimeLast.postUpdate( VeraHouseTime.state )
	VeraShopTimeLast.postUpdate( VeraShopTime.state )
	
end

And here’s what I got in the log after a reboot of the server:

2017-04-13 22:20:02.740 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Testing...
2017-04-13 22:20:02.740 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Testing...
2017-04-13 22:20:02.743 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Current: 2017-04-13 22:19:53 N  Last: NULL
2017-04-13 22:20:02.743 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Current: 2017-04-13 22:19:53 N  Last: NULL

And at the next instance of it running:

2017-04-13 22:30:00.002 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Testing...
2017-04-13 22:30:00.002 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Testing...
2017-04-13 22:30:00.004 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Current: 2017-04-13 22:30:00 N  Last: 2017-04-13 22:19:53 N
2017-04-13 22:30:00.006 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Current: 2017-04-13 22:30:00 N  Last: 2017-04-13 22:30:00 N

At this point, I have no rules but this one, so I decided to remove this rule as well - I couldn’t think of anything else that might be better to try. Restarted the server, and I see I’m still getting duplicates in the log for my astro devices at startup (there should be two suns - one regular, one offset, and a moon).

2017-04-13 23:04:23.423 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-daily-sun at midnight for thing astro:sun:0451ef7e
2017-04-13 23:04:23.423 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-daily-moon at midnight for thing astro:moon:b3d70a42
2017-04-13 23:04:23.425 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-positional with interval of 300 seconds for thing astro:moon:b3d70a42
2017-04-13 23:04:23.426 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-daily-sun at midnight for thing astro:sun:offset
2017-04-13 23:04:23.426 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-positional with interval of 300 seconds for thing astro:sun:0451ef7e
2017-04-13 23:04:23.427 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-daily-sun at midnight for thing astro:sun:0451ef7e
2017-04-13 23:04:23.429 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-positional with interval of 300 seconds for thing astro:sun:0451ef7e
2017-04-13 23:04:26.353 [INFO ] [.astro.internal.job.AbstractDailyJob] - Scheduled astro event-jobs for thing astro:moon:b3d70a42
2017-04-13 23:04:26.908 [INFO ] [.astro.internal.job.AbstractDailyJob] - Scheduled astro event-jobs for thing astro:sun:offset
2017-04-13 23:04:26.908 [INFO ] [.astro.internal.job.AbstractDailyJob] - Scheduled astro event-jobs for thing astro:sun:0451ef7e

As you can see, it tries to do two instances of thing astro:sun:0451ef7e. I looked back through the logs, it’s been there all along (different ones duplicate, and I’ve seen up to 3 instances of a device in the log). I don’t think it’s caused an issue, but I’m only turning lights on/off based on these events at this point, so duplication shouldn’t hurt anything…

I’m assuming that the astro devices are ran off of cron as well. If so, then it would definitely point to there being some issue with cron rules running multiple times.

I’m thinking my next step in this would be to remove all my astro things. Before I do that, I figured I’d get some feedback as I’m definitely no expert in OH2, or Linux…

Thoughts?..

Thanks,

Danny

Udo_Hartmann · April 14, 2017, 11:11am

Did you restart openHAB yet?

shorin · April 14, 2017, 1:24pm

Multiple times. As mentioned above, I’ve even re-booted the computer.

Oli · April 14, 2017, 2:18pm

To me it seems that you are actually having multiple issues.
As for the rules running twice: have you checked your rule directory with “ls -al” to check for duplicate files?
The fact that you are seeing sun/moon things with different IDs suggests you have defined astro things at least twice. There was a different thread with similar issue, just can’t find it. Did you configure astro several times? like one time creating a thing file, one time via autodiscover?
astro:moon:b3d70a42
astro:sun:offset
astro:sun:0451ef7e
That not good! There should be only one ID for sun and moon! e.g.:
astro:moon:local
astro:sun:local
You should sort that out first, then see what issues remain.

shorin · April 14, 2017, 5:57pm

Multiple issues wouldn’t surprise me…

I used the “ls -al” and there are no duplicates.

I do have two sun things defined. One uses an offset so that I can get events 30min before/after sunset/sunrise. I also use the one at actual sunrise/sunset for things as well. One was set up using paperUI, and one was created using a thing file:

astro:sun:offset [ geolocation="xx.xxxxxx,-yy.yyyy", interval=60 ] {
    Channels:
        Type rangeEvent : rise#event [
            offset=30
        ]
		Type rangeEvent : set#event [
            offset=-30
        ]
}

When they were created, I don’t remember seeing any duplicate runs at that point, but it’s possible. I was thinking my next step would be to blow out all the astro things, so it sounds like you’re thinking having two sun things could be a problem.

When I set it up, I did some research and didn’t find anything that would indicate an issue, but it definitely could be… I figured that as long as they have different IDs, they’d play nice and they seem to have done that so far (unless they’re the cause for this issue).

So, what’s the “correct” way to handle this? Just have them offset to the earliest I need something ,and then delay in the rules that need the later time by using a timer? I can do that, but it seemed like just having two events set up how I need them was a better approach, but maybe not.

Thanks,

Danny

shorin · April 14, 2017, 6:33pm

I removed all the astro things to troubleshoot. Put back in my test rule above (only rule in there). I’m still getting the duplication:

2017-04-14 13:10:02.533 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Testing...
2017-04-14 13:10:02.534 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Testing...
2017-04-14 13:10:02.535 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Current: 2017-04-14 13:09:55 D  Last: NULL
2017-04-14 13:10:02.535 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Current: 2017-04-14 13:09:55 D  Last: NULL

2017-04-14 13:20:00.003 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Testing...
2017-04-14 13:20:00.003 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Testing...
2017-04-14 13:20:00.004 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Current: 2017-04-14 13:19:52 D  Last: 2017-04-14 13:09:55 D
2017-04-14 13:20:00.004 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Current: 2017-04-14 13:19:52 D  Last: 2017-04-14 13:09:55 D

2017-04-14 13:30:00.003 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Testing...
2017-04-14 13:30:00.005 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Current: 2017-04-14 13:30:00 D  Last: 2017-04-14 13:19:52 D
2017-04-14 13:30:00.007 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Testing...
2017-04-14 13:30:00.008 [INFO ] [      Notifications - Communications] - !!!!!!    Vera Communication Status - Current: 2017-04-14 13:30:00 D  Last: 2017-04-14 13:30:00 D

Oli · April 14, 2017, 7:02pm

as far as i can tell, your things file is ok for setting an offset. it just should be all for the same thing id.
Both configuring via thing file or paperUI are OK. I’d say the catch is to decide for one way and stick to it so you don’t get mixed things.
personally I would use paperUI. There, go to config, things, select your Local Sun thing. Then edit the Range event for the chanell you are interested in by clicking the pen icon.
For my own setup i found the existing chanells sufficient. If you take a look at the times for sunset,dusk, civil dusk, nautical dusk etc…there is most likely one that fits sunset +30 minutes.

shorin · April 15, 2017, 12:23am

I looked at the dusk times, and none were about 30 min earlier like I wanted. I did a pretty quick look when I originally set this up, so I’ll take another look now - maybe I missed one. If not, I can do the timer to offset the few I need a little later.

But back to the problem at hand, I’ve removed the astro binding entirely, so I’m sure it’s not the culprit here. I’ve removed all the rules except for the test rule above, and I’m still duplicating rules… Something’s going on, but I’m not sure what.

The only other thing I see going on in my logs is a persistence error at startup. Persistence works OK, so I haven’t tried to figure it out yet. I don’t think it’s related, but my issue definitely seems to be a weird one, so I’ll mention it just in case…

2017-04-14 13:09:45.710 [ERROR] [g.eclipse.smarthome.core.persistence] - [org.eclipse.smarthome.core.persistence.persistencemanager(37)] The addPersistenceService method has thrown an exception
java.lang.ClassCastException: java.lang.Double cannot be cast to java.lang.String
	at org.openhab.persistence.jdbc.db.JdbcBaseDAO.getState(JdbcBaseDAO.java:504)
	at org.openhab.persistence.jdbc.db.JdbcBaseDAO.doGetHistItemFilterQuery(JdbcBaseDAO.java:343)
	at org.openhab.persistence.jdbc.internal.JdbcMapper.getHistItemFilterQuery(JdbcMapper.java:154)
	at org.openhab.persistence.jdbc.internal.JdbcPersistenceService.query(JdbcPersistenceService.java:201)
	at org.openhab.core.persistence.internal.QueryablePersistenceServiceDelegate.query(QueryablePersistenceServiceDelegate.java:47)
	at org.eclipse.smarthome.core.persistence.internal.PersistenceManagerImpl.initialize(PersistenceManagerImpl.java:250)
	at org.eclipse.smarthome.core.persistence.internal.PersistenceManagerImpl.startEventHandling(PersistenceManagerImpl.java:365)
	at org.eclipse.smarthome.core.persistence.internal.PersistenceManagerImpl.addPersistenceService(PersistenceManagerImpl.java:95)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_101]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_101]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_101]
	at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_101]
	at org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:224)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.inject.BaseMethod.access$500(BaseMethod.java:39)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.inject.BaseMethod$Resolved.invoke(BaseMethod.java:617)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:501)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.inject.BindMethod.invoke(BindMethod.java:655)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1722)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:1699)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeBindMethod(SingleComponentManager.java:371)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:320)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:291)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1215)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1136)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:945)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:881)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1167)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:127)[32:org.apache.felix.scr:2.0.6]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:482)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:998)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.openhab.core.persistence.internal.PersistenceServiceFactory.registerDelegateService(PersistenceServiceFactory.java:72)
	at org.openhab.core.persistence.internal.PersistenceServiceFactory.addPersistenceService(PersistenceServiceFactory.java:52)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_101]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_101]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_101]
	at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_101]
	at org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:224)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.inject.BaseMethod.access$500(BaseMethod.java:39)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.inject.BaseMethod$Resolved.invoke(BaseMethod.java:617)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:501)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.inject.BindMethod.invoke(BindMethod.java:655)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1722)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:1699)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeBindMethod(SingleComponentManager.java:371)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:320)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:291)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1215)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1136)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:945)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:881)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1167)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:127)[32:org.apache.felix.scr:2.0.6]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:886)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:873)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:132)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:940)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:740)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:674)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:429)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:657)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:341)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:403)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.Activator.access$200(Activator.java:54)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:278)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.utils.extender.AbstractExtender.createExtension(AbstractExtender.java:259)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.utils.extender.AbstractExtender.modifiedBundle(AbstractExtender.java:232)[32:org.apache.felix.scr:2.0.6]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444)[org.osgi.core-6.0.0.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.Module.start(Module.java:457)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1582)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1562)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1533)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1476)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]

shorin · April 15, 2017, 8:04pm

Until I can figure out a real fix, I’ve decided to band-aid it so it at least works. I put in a bit that gets set so only one instance should be able to actually do anything (unless they’re running exactly in parallel, which I find unlikely). I also added the try/catch/finally to ensure that the bit will always be set back to false in case something errors for some reason.

So far, it seems to work fine like this, and it’s easy to comment out to test for actual fixes to the problem.

Here’s what I implemented:

var boolean veraComRunning = false

rule "Vera Communication Monitor"
when Time cron "0 /10 * * * ?"
then
	if(veraComRunning == false) {
		veraComRunning = true
		
		try {
			logInfo("          Notifications - Communications", "!!!!!!    Vera Communication Status - Testing..."
			logInfo("          Notifications - Communications", "!!!!!!    Vera Communication Status - Current: " + VeraHouseTime.state + "  Last: " + VeraHouseTimeLast.state)
			
			//do all the actual monitoring stuff here...
			
		} catch(Throwable t) {
			logError("          Notifications - Communications", "!!!!!!    Error running the Vera Communications Test...   !!!!!!")
		} finally {
			VeraHouseTimeLast.postUpdate( VeraHouseTime.state )
			VeraShopTimeLast.postUpdate( VeraShopTime.state )
			Thread::sleep(100)   //sleep to give any other rule instances time to run before setting the veraComRunning bit back to false
			veraComRunning = false
		}
	
	}
end

poertner · April 15, 2017, 8:13pm

I got a similar problem after an “apt-get upgrade” i did a week ago.
now in this simple time based rule the sound plays 4x on my sonos …

rule "aufstehlicht_jenny_grün"
when
	Time cron "0 40 6 ? * MON-FRI"
then
		sendCommand(HueColorKueche_Color, new HSBType(new DecimalType(120),new PercentType(100),new PercentType(100)))
		Thread::sleep(200)
		sendCommand(HueColorBad_Color, new HSBType(new DecimalType(120),new PercentType(100),new PercentType(100)))
		Thread::sleep(200)
		sendCommand("Sonos_Bad_NotificationSound" , "ukulele.mp3")
end

bruxi · April 18, 2017, 11:29am

Hi,

it’s the same for me. Some rules trigger two to four times, like this one here sent the message 4 times the last time.

rule "Send Trashcan Notification"
when
Time cron "0 0 15,18,21,23 * * ?"
then
        if(TrashcanNotification.state==ON) {
                logInfo("Trashbin","Sending Trashcan notification to bot1")
                sendTelegram("bot1","Du musst noch die "+TrashcanColor.state+"e Muelltonne an die Strasse stellen")
                Thread::sleep(5000)
                logInfo("Trashbin","Sending Trashcan notification to bot2")
                sendTelegram("bot2","Du musst noch die "+TrashcanColor.state+"e Muelltonne an die Strasse stellen")
end

The same is with other rules. I don’t have duplicate files or something.

Here’s an extract from the log:
2017-04-11 15:00:00.066 [INFO ] [ipse.smarthome.model.script.Trashbin] - Sending Trashcan notification to bot1
2017-04-11 15:00:00.494 [INFO ] [ipse.smarthome.model.script.Trashbin] - Sending Trashcan notification to bot1
2017-04-11 15:00:05.893 [INFO ] [ipse.smarthome.model.script.Trashbin] - Sending Trashcan notification to bot2
2017-04-11 15:00:05.908 [INFO ] [ipse.smarthome.model.script.Trashbin] - Sending Trashcan notification to bot2
2017-04-11 15:00:06.150 [INFO ] [ipse.smarthome.model.script.Trashbin] - Sending Trashcan notification to bot1
2017-04-11 15:00:06.245 [INFO ] [ipse.smarthome.model.script.Trashbin] - Sending Trashcan notification to bot1
2017-04-11 15:00:11.327 [INFO ] [ipse.smarthome.model.script.Trashbin] - Sending Trashcan notification to bot2
2017-04-11 15:00:11.400 [INFO ] [ipse.smarthome.model.script.Trashbin] - Sending Trashcan notification to bot2