[SOLVED] Rules reload on MAX! binding reconnect

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:

  1. Max! binding updates thing configuration periodically.
  2. 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 :wink:

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 ?

1 Like

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.

Another one: Openhab unstable after upgrade to 2.5

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.