Getting back to the original problem, we took your word for granted that it’s the MAX! addon to cause rule reloads although that still seems pretty odd. Yes 1000 * 30 secs is 8:15 but it still could be just coincidence.
Can you exclude possible dependency of files or rules on the binding to reconnect or the cube to restart (changing Thing status to OFFLINE), are you sure there’s no binding restart or cube boot ?
Have you cleared the cache, did you reinstall ?
Actually there are two aspects to this:
- Max! binding updates thing configuration periodically.
- OpenHAB triggers “system started” rules when thing configuration is updated.
Which one is the behaviour you think is strange/not normal?
This happens every 8 hours in the logs:
2019-12-24 17:08:50.693 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Sending request #999 to MAX! Cube
2019-12-24 17:09:20.859 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - maxRequestsPerConnection reached, reconnecting.
2019-12-24 17:09:21.911 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Open new connection... to xxxxxxxxxx port 62910
2019-12-24 17:09:21.914 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Connect to MAX! Cube
...
2019-12-24 17:09:22.288 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - === M Message ===
2019-12-24 17:09:22.291 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - === Rooms ===
...
2019-12-24 17:09:22.477 [DEBUG] [mon.registry.AbstractManagedProvider] - Updated element max:bridge:KEQ0xx in ManagedThingProvider.
2019-12-24 17:09:22.479 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Room properties updated
...
2019-12-24 17:09:22.662 [DEBUG] [mon.registry.AbstractManagedProvider] - Updated element max:shuttercontact:KEQ0xx:JEQ0xxxx in ManagedThingProvider.
2019-12-24 17:09:22.666 [DEBUG] [x.internal.handler.MaxDevicesHandler] - Config updated: {rfAddress=054f9e, serialNumber=JEQ0xxxx, action-deviceDelete=-1, name=Fenster links, room=Wohnzimmer, roomId=1}
...
2019-12-24 17:09:23.781 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Sending request #1 to MAX! Cube
2019-12-24 17:09:24.828 [DEBUG] [el.core.internal.ModelRepositoryImpl] - Refreshing resource 'presence.rules'
2019-12-24 17:09:25.758 [DEBUG] [el.core.internal.ModelRepositoryImpl] - Refreshing resource 'voice.rules'
2019-12-24 17:09:26.321 [DEBUG] [el.core.internal.ModelRepositoryImpl] - Refreshing resource 'mail.rules'
2019-12-24 17:09:26.670 [DEBUG] [el.core.internal.ModelRepositoryImpl] - Refreshing resource 'zwave.rules'
2019-12-24 17:09:26.990 [DEBUG] [el.core.internal.ModelRepositoryImpl] - Refreshing resource 'alarms.rules'
2019-12-24 17:09:27.331 [DEBUG] [el.core.internal.ModelRepositoryImpl] - Refreshing resource 'lighting.rules'
and in the events accordingly:
2019-12-24 17:09:22.479 [me.event.ThingUpdatedEvent] - Thing 'max:bridge:KEQ0xx' has been updated.
2019-12-24 17:09:22.663 [me.event.ThingUpdatedEvent] - Thing 'max:shuttercontact:KEQ0xx:JEQ0xxxx' has been updated.
2019-12-24 17:09:22.697 [me.event.ThingUpdatedEvent] - Thing 'max:shuttercontact:KEQ0xx:JRE0xxxx' has been updated.
I cleared the cache after updating to OH 2.5, but I did not reinstall anything.
I’d like to vote for both
Yes, both. But you already found the/one reason for #1 while #2 is really the oddmost one.
Okay, after removing the mentioned line setProperties(msg);
, the configuration update of the bridge doesn’t occur anymore (at least it doesn’t appear in the logs). However, configuration update of the other things still happens and this maybe still leads to the rules refresh?
2019-12-28 02:41:47.892 [DEBUG] [x.internal.handler.MaxDevicesHandler] - MAX! Thermostat KEQ0911327 configuration update
2019-12-28 02:41:47.942 [DEBUG] [x.internal.handler.MaxDevicesHandler] - Config updated: {windowOpenTemp=5.0, boostDuration=0, decalcification=12, rfAddress=0c6e43, serialNumber=KEQ0xxx, offsetTemp=0.5, maxTempSetpoint=26.0, action-deviceDelete=-1, minTempSetpoint=4.5, valveMaximum=100, comfortTemp=20.5, refreshActualRate=0, ecoTemp=16.5, room=Wohnzimmer, roomId=1, boostValvePos=80, name=Thermostat LV, valveOffset=0, windowOpenDuration=15}
I agree with you that both are strange. Even if I change the Max! bridge thing configuration through PaperUI, the rules are refreshed. For other bindings (hue, zwave) this doesn’t seem to be the case…
The only thing I can think of is that due to the multiple updates happening in very short time zone race condition occurs.
There is nothing I’m aware of in the max binding that is related to rules.
Note that scanning the forum most folks experiencing issues with oh2.5 have bindings that make config changes (max, zwave, miio… + few more) I can imagine the is a correlation.
Hi all,
It looks like @marcel_verpaalen is already working on your problem No. 1.
The 2nd problem sounds really odd. Currently I have to admit that I do not have a clue what could be the cause of it. But I never heard about a relation between updating a configuration of a thing and refreshing / reloading rule files before. @dominicdesu Just to be clear: You are talking about reloading rule files? Do you? I am asking because in your linked issue you are talking about triggering startup rules which from my point of view is something different.
I am aware of a feasible issue related to configuration updates: It is possible to create an interminable loop - e.g if the ThingHandler
calls updateConfiguration()
from its initialize()
method, because a configuration update leads to a new initialization of the thing.
I am talking about this:
2019-12-24 17:09:24.828 [DEBUG] [el.core.internal.ModelRepositoryImpl] - Refreshing resource 'presence.rules'
2019-12-24 17:09:25.758 [DEBUG] [el.core.internal.ModelRepositoryImpl] - Refreshing resource 'voice.rules'
2019-12-24 17:09:26.321 [DEBUG] [el.core.internal.ModelRepositoryImpl] - Refreshing resource 'mail.rules'
2019-12-24 17:09:26.670 [DEBUG] [el.core.internal.ModelRepositoryImpl] - Refreshing resource 'zwave.rules'
2019-12-24 17:09:26.990 [DEBUG] [el.core.internal.ModelRepositoryImpl] - Refreshing resource 'alarms.rules'
2019-12-24 17:09:27.331 [DEBUG] [el.core.internal.ModelRepositoryImpl] - Refreshing resource 'lighting.rules'
I was assuming this reloads the rules and therefore also triggers the “System started” rules?
I hope I’ll find some time over the next few days to further debug this issue. Also note that I didn’t had this behaviour in OH 2.4…
Thanks for clarifying. Yes, after a .rules
file was reloaded the framework runs the rules with trigger “System started”.
This is the exact stack trace when I modify a configuration option of the MAX! bridge in PaperUI:
Daemon Thread [OH-thingHandler-4] (Suspended (breakpoint at line 265 in RuleEngineImpl))
owns: MaxDevicesHandler (id=333)
owns: MaxCubeBridgeHandler (id=334)
RuleEngineImpl.scheduleStartupRules() line: 265
RuleEngineImpl.added(Item) line: 169
RuleEngineImpl.added(Object) line: 1
ItemRegistryImpl(AbstractRegistry<E,K,P>).notifyListeners(E, EventType) line: 346
ItemRegistryImpl(AbstractRegistry<E,K,P>).notifyListenersAboutAddedElement(E) line: 379
ItemRegistryImpl.notifyListenersAboutAddedElement(Item) line: 367
ItemRegistryImpl.notifyListenersAboutAddedElement(Identifiable) line: 1
ItemRegistryImpl(AbstractRegistry<E,K,P>).added(Provider<E>, E) line: 157
ItemRegistryImpl.added(Provider<Item>, Item) line: 388
ItemRegistryImpl.added(Provider, Identifiable) line: 1
ItemRegistryImpl(AbstractRegistry<E,K,P>).added(Provider, Object) line: 1
ChannelItemProvider.createItemForLink(ItemChannelLink) line: 257
ChannelItemProvider.access$2(ChannelItemProvider, ItemChannelLink) line: 227
ChannelItemProvider$1.added(Thing) line: 316
ChannelItemProvider$1.updated(Thing, Thing) line: 336
ChannelItemProvider$1.updated(Object, Object) line: 1
ThingRegistryImpl(AbstractRegistry<E,K,P>).notifyListeners(E, E, EventType) line: 366
ThingRegistryImpl(AbstractRegistry<E,K,P>).notifyListenersAboutUpdatedElement(E, E) line: 387
ThingRegistryImpl.notifyListenersAboutUpdatedElement(Thing, Thing) line: 143
ThingRegistryImpl.notifyListenersAboutUpdatedElement(Identifiable, Identifiable) line: 1
ThingRegistryImpl(AbstractRegistry<E,K,P>).updated(Provider<E>, E, E) line: 291
ThingRegistryImpl(AbstractRegistry<E,K,P>).updated(Provider, Object, Object) line: 1
ManagedThingProvider(AbstractProvider<E>).notifyListeners(E, E, EventType) line: 62
ManagedThingProvider(AbstractProvider<E>).notifyListenersAboutUpdatedElement(E, E) line: 87
ManagedThingProvider(AbstractManagedProvider<E,K,PE>).update(E) line: 119
ThingManagerImpl$1$1.run() line: 261
ThingManagerImpl$1$1.run() line: 1
AccessController.doPrivileged(PrivilegedAction<T>) line: not available [native method]
ThingManagerImpl$1.thingUpdated(Thing) line: 249
MaxDevicesHandler(BaseThingHandler).updateConfiguration(Configuration) line: 441
MaxDevicesHandler.setDeviceConfiguration(Device) line: 562
MaxDevicesHandler.onDeviceConfigUpdate(Bridge, Device) line: 573
MaxCubeBridgeHandler.processCMessage(CMessage) line: 729
MaxCubeBridgeHandler.processMessage(Message) line: 674
MaxCubeBridgeHandler.readLines(String) line: 631
MaxCubeBridgeHandler.sendCubeCommand(CubeCommand) line: 564
MaxCubeBridgeHandler.refreshData() line: 468
21378183.run() line: not available
Executors$RunnableAdapter<T>.call() line: 511
ScheduledThreadPoolExecutor$ScheduledFutureTask<V>(FutureTask<V>).runAndReset() line: 308
ScheduledThreadPoolExecutor$ScheduledFutureTask<V>.access$301(ScheduledThreadPoolExecutor$ScheduledFutureTask) line: 180
ScheduledThreadPoolExecutor$ScheduledFutureTask<V>.run() line: 294
WrappedScheduledExecutorService(ThreadPoolExecutor).runWorker(ThreadPoolExecutor$Worker) line: 1149
ThreadPoolExecutor$Worker.run() line: 624
Thread.run() line: 748
Okay, after removing all MAX things in the PaperUI and rediscovering them, there seems to be no refreshing of rules anymore…
Maybe there was some internal incompatibility between the MAX things which have been added in OH 2.x and 2.5…
Anyways, thanks everybody for your support!
Thank you too for your testing. You identified a minor improvement for the future version of the MAX! binding.
A final word on the “System started” trigger: It is supposed to be triggered whenever an item will be added, updated or removed.
… but not for things, correct?
By any chance, could there be an (unwanted) link in the core such as a backpointer that results in changes to items, too, when the thing that an item is linked to gets changed as we have it here ?
No, I cannot confirm that. I think Thing changes will trigger “System started” too.
So the reason for the strange behavior here was the (unnecessary, soon to be removed) update to the maxcube thing ? Then why did that not happen to everybody ?
I think I have to clarify what I am talking about:
I mean “System started” trigger for rules. And yes, they got triggered because of the configuration changes on the MAX! Things.
I still have no clue why the .rules
files got reloaded in @dominicdesu setup.
Now I’m confused. After I’ve removed and readded the max things, the “System started” rules are not executed anymore, neither periodically (when the MAX binding updates the thing configuration) nor if I manually change the thing configuration in PaperUI.
So it doesn’t seem that updates to thing configurations trigger the “System started” rules, which would also match with the documentation.
I just experienced an all-rules-reload after I deleted an exec binding thing that was linked to by an item. Duh. I think we should file that as a bug, but how ? What’s the exact conditions this happens under ?
So far I see this happening when:
- I add an item
- delete an item
- in certain circumstances when an item is updated.
I have not yet seen it happen when I delete a thing. However, what I think happend in your case that deleting the thing caused an update to the item that triggered the reload.
I agree this is a bug. I think it was introduced in 2.5 m6.