[SOLVED] Rules reload on MAX! binding reconnect

I have a similar issue (startup rules being triggered about every 8:15 hours) after upgrading to OH 2.5. I also have the zwave and max binding, however there seems to be no binding activity before the startup rule execution. I have increased the logging level and check if this provides more information.
I have also creates a ticket to request more logging output when startup rules are executed.

1 Like

From what I see there is a short time (1, maybe 2 minutes) between the time I see things being updated and the reloading being evident from my log lines. However, I can already see the cpu go up to roughly 100%. I think that in the time in between, the rules have started to reload.

The common thing that I am seeing is that things get updated. I wouldnā€™t look to deeply into Max! binding. I am certain that I have seen no Max! cube reboots in my logs, other than the ones I caused today.

For me the cause seems to be the MAX! addon. I can see this in the logs before the rules are refreshed:

2019-12-24 00:32:06.616 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - maxRequestsPerConnection reached, reconnecting.
2019-12-24 00:32:07.671 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Open new connection... to 192.168.178.44 port 62910
2019-12-24 00:32:07.676 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Connect to MAX! Cube
...
2019-12-24 00:32:08.251 [DEBUG] [mon.registry.AbstractManagedProvider] - Updated element max:bridge:KEQ0565677 in ManagedThingProvider.
2019-12-24 00:32:08.253 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Room properties updated
...
2019-12-24 00:32:08.297 [DEBUG] [x.internal.handler.MaxDevicesHandler] - MAX! Shutter Contact JEQ0396104 configuration update
2019-12-24 00:32:08.445 [DEBUG] [mon.registry.AbstractManagedProvider] - Updated element max:shuttercontact:KEQ0565677:JEQ0396104 in ManagedThingProvider.

So the question is: Why does the MAX binding reconnect cause all rules to be revalidated?

I donā€™t want to hijack this thread though, so if you have a different issue I will open a seperate thread.

Donā€™t know but clearly the recommendation on MAX! is to use the ā€˜exclusiveā€™ permanent connection to the cube in binding settings.

Yes, I am using the exclusive mode, but there is a ā€œ1000 requests until connection is closed and reopenedā€-configuration, and the request interval is 30 seconds. As 1000 * 30 seconds is 8:20 hours, every 8:20 hours the connection is reopened and somehow this triggers the startup rules.

I think you can change that, too.
Your error seems strange, though, as the binding should not touch any files.
Eventually you have a rule to trigger upon one of the cube channels ?

Either way, youā€™re invading someone elseā€™s thread, so I moved this to a separate one.

Yes I can change it, but itā€™s the default value and it worked beforeā€¦

See aso my comment here: Openhab unstable after upgrade to 2.5

I think the MAX! binding updates the thing configuration on each reconnect and this triggers the startup rulesā€¦

No it only does that in your box (if at all), so there must be something specific about your setup.
Did you use a .things file to create the maxcube thing ? If so, try deleting that and create the thing via UI.

Well, as I posted, if I reboot my max cube from the UI, a rules reload is triggered. My max configuration is all set up from UI. I have not seen the 8 hour, 15 minutes reload, but I will check my logs now that I have had openhab running without restarting over Christmas.

So the max binding is not reconnecting periodically on your device? Do you also use OH 2.5 and the default values? ( exclusive mode = true, maxRequestsPerConnection = 1000 and refreshInterval = 30s?).
I donā€™t have use *.things files, only *.items and *.rules files.

If I understand the code correctly, the binding will reconnect after 1000 requests are exceeded.

And when it reconnects, it seems to receive an MMessage again and update the thing configuration, which actually looks like some kind of bug:

if (!roomPropertiesSet) {
    setProperties(msg);
}
setProperties(msg);

I think the second setProperties shoudnā€™t be there, then it wouldnā€™t update the things on reconnect and therefore no startup rules would be triggered. Or do I misunderstand some part of the code here?

Frankly I donā€™t know. It probably does. But at least it does not trigger any rules reload.

Donā€™t know. But this excerpt clearly does not make sense all by itself.

Okay, thanks for your help so far!
The excerpt is from here: https://github.com/openhab/openhab-addons/blob/master/bundles/org.openhab.binding.max/src/main/java/org/openhab/binding/max/internal/handler/MaxCubeBridgeHandler.java#L761-L764

I have now removed the second setProperties() and will check what happens.

Though it should not trigger any rules,
I made a small change that should avoid unnecessary updates to the config.
Iā€™m doing small test and will submit the PR if successful

note the line @dominicdesu found should probably be fixed as well. => Iā€™ve added it to the PR now

1 Like

I have checked my logs. From time to time my network has problems and the connection to the cube is lost. The cube then goes offline and a few moments later the connection is reestablished. Basically everything works well, except for the fact that I have a crappy network. However, this cube going offline and coming online again causes the Max things to be updated and the rules reloading.

I am certain that before 2.5 openhab would from time to time lose the connection to the cube. However, the rule reloading problem didnā€™t exist before 2.5 m5. What was changed?

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.