Strange issue: BetteryLevel batch resetting

I am troubleshooting an issue that started yesterday. Here is some rubber ducking :slight_smile: and maybe someone ran into that already.

The short version is that:

  • I have a BatteryLevel group
  • All my battery powered items are in this group
  • I am using BatteryLevel*: strategy = everyChange, everyDay, restoreOnStartup

Everything is working fine for a long time in that regard.
Yesterday, most of my devices suddenly got updated to 18.

I upgraded OH and did a restart. The Battery levels started recovering after the restart.
As I woke up devices, I saw the actual battery level coming in.
Suddenly again, most of my devices (around 56/60) got reset all to the same value, this time 19.

First I thought about an issue with Z2M but I have the issue on both some zwave and zigbee devices. Moreover, everything looks normal in Z2M.

Looking at a graph, I see the rest coming every 2 hours, then the freq. changed to some 1h then less than that.

I am using git so I can see my history. So far, I did not spot what could be the cause of this “reset”. Morever my last chanegs are not related to battery levels…

Any idea is welcome !

And here came another:

2024-12-08 17:47:32.469 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'BatteryLevel' received command 20
2024-12-08 17:47:32.471 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Office_Marquise__BatteryLevel' received command 20
2024-12-08 17:47:32.471 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'BalconyStreet_RainSensor__Battery' received command 20
2024-12-08 17:47:32.472 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Office_Marquise__BatteryLevel' predicted to become 20
2024-12-08 17:47:32.474 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'BalconyStreet_RainSensor__Battery' predicted to become 20
2024-12-08 17:47:32.477 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'LivingRoom_FibEye__BatteryLevel' received command 20
2024-12-08 17:47:32.477 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'BalconyStreet_SNZB02D__Battery' received command 20
2024-12-08 17:47:32.478 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'LivingRoom_Velux__BatteryLevel' received command 20
2024-12-08 17:47:32.478 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'LivingRoom_Window_Right__BatteryLevel' received command 20
2024-12-08 17:47:32.479 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'LivingRoom_Window_Left__BatteryLevel' received command 20
2024-12-08 17:47:32.480 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'LivingRoom_SNZB02D__Battery' received command 20
2024-12-08 17:47:32.483 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Hallway_MainDoor_BatteryLevel' received command 20
2024-12-08 17:47:32.485 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Hallway_FibEye__BatteryLevel' received command 20
2024-12-08 17:47:32.487 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Hallway_SNZB02D_ElecPannel__Battery' received command 20
... and many more

For me it looks like something is command your group.
Did you changed your rules or something?
Or misslinked a channel to the group item…
I.e. if I set my light dimmer group to 50 all lights get a command 50.

Greets.

1 Like

Yes, I did consider that. I have 2 rules with Member of BatteryLevele but:

  • they work for a while now
  • they are “read/only” (I check the level and send alerts)
  • I disabled those rules for now

In the meantime, I reverted all the commits (3) I made the last day although they are related to temperature and not related to batteries… I don’t see anything that would cause such a trouble but I may miss something. So monitoring for now and If that works, I will reintroduce my commits one by one so see when it breaks.

I am seeing a bunch of zwave errors just before the values are changed. Not sure whether this is a cause or consequence.

The value appears to be incremental. 18…19…20…21…
With some more monitoring I guess I will figure out whether this is a temp, hour, or some random incremented value…

2024-12-08 18:32:47.197 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.handleCommand()' on 'org.openhab.binding.zwave.handler.ZWaveThingHandler@1194293d': Value must be between 0 and 100
java.lang.IllegalArgumentException: Value must be between 0 and 100
	at org.openhab.core.library.types.PercentType.validateValue(PercentType.java:93) ~[bundleFile:?]
	at org.openhab.core.library.types.PercentType.<init>(PercentType.java:88) ~[bundleFile:?]
	at org.openhab.core.library.types.DecimalType.as(DecimalType.java:194) ~[bundleFile:?]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.convertCommandToDataType(ZWaveThingHandler.java:1241) ~[?:?]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.handleCommand(ZWaveThingHandler.java:1177) ~[?:?]
	at jdk.internal.reflect.GeneratedMethodAccessor249.invoke(Unknown Source) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:569) ~[?:?]
	at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:147) [bundleFile:?]
	at org.openhab.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [bundleFile:?]
	at jdk.proxy2143.$Proxy2311.handleCommand(Unknown Source) [?:?]
	at org.openhab.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:95) [bundleFile:?]
	at org.openhab.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [bundleFile:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:569) ~[?:?]
	at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:147) [bundleFile:?]
	at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.lang.Thread.run(Thread.java:840) [?:?]

Do you have a sitemap with the batterylevel showing and maybe here you set the value.
What I find strange is that

 Item 'BatteryLevel' received command 20

Something command that item. I think from openhab…
It it is changed by something else it would be

 Item 'BatteryLevel' changed from x to 20

Without the received command…
I don’t know anything about zwave.

Yes, atm I am at the same conclusion: “something sends a command to those Battery items”.
I can see it started yesterday at 23:30. My latest changes were at 15:00 the day before so it does not match at all. I inspected all “my” .sendCommand in search of an error/typo but I see nothing that would send such a value.

Here is another extract of what I get:

2024-12-08 19:02:47.470 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Hallway2_FibEye__BatteryLevel' received command 22
2024-12-08 19:02:47.470 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Office_Marquise__BatteryLevel' predicted to become 22
2024-12-08 19:02:47.470 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'LivingRoom_FibEye__BatteryLevel' predicted to become 22
2024-12-08 19:02:47.471 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'LivingRoom_Velux__BatteryLevel' predicted to become 22
2024-12-08 19:02:47.471 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Office_Marquise__BatteryLevel' changed from 21 to 22

I am wondering about that [penhab.event... as well but that may be a trick to keep the string short. Maybe some frontail trick…

I suspect, on my end or maybe in OH, a silly error like a missing " or >. Yet the parser should(™) catch that.

Reverting my commits, it is “holding it” now.
So the issue may be in one of my changes. I am now very intersted in knowing what causes the issue… For now, I will let run in the current state to validate that it really works again.

Very strange… it did hold around 4 hours and started again…

Digging into the logs, I see:

2024-12-09 10:41:54.177 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'BatteryLevel' received command 38

That explains the issue however, I am not, at least via rules, sending this command.
I searched my code and I get no hit for BatteryLevel. so no postUpdate/sendCommand from my end.

So the challenge is now to find what is sending this command in my back.

By default the class name generating the log statement is fixed. If the class name is longer than the fixed length (17 characters I think) it cuts off the front part of the class name. This is normal and configurable from log4j2.xml.

Any links? Like @Baschtlwaschtl mentioned above, is a Channel is linked to the Group that could explain the commands send to members of the Group.

The thing is… I did not touch the BatteryLevel in a while so I don’t get why I get this behavior now.

My group is defined as:

Group:Number:AVG                  BatteryLevel             "Battery Level [%.1f %%]"                            <battery>

I have many items in the group. Here is one of them:

Number                      Hallway_SNZB02D_ElecPannel__Battery               "Hallway - Elec Panel Battery"                  <battery>        (ZigBee, BatteryLevel)                             {channel="mqtt:topic:_MosquittoBroker:snzb02d_zb023:battery" [profile="basic-profiles:round", scale=0]}

It happens to be a ZigBee device but I have some Zwave devices in the mix.

Today I uninstalled your battery addon @rlkoshak but I was not using it yet.
I turned OFF the android tablet running HabPanel and since, I don’t see the issue.
But since it appears to be random, I will wait a bit.

Atm, I am a bit puzzled by the value sent to the command. It seems to be incremental. It started at 14. I am now at 44.

I am now running ok for a while (no code item/rules changes).

The command seems to be coming every ~45 min but not always. I don’t see other items/groups affected. My OH is not exposed to the internet (I have seem people having troubles with that).

I will leave it like that for now and turn on my tablet tomorrow again to see if that does something.I really don’t get why it would but at that point, I am observing…

The UI Widget? It can’t send any commands so that wouldn’t be it.

After you do that test, what happens if you restart OH? Does it start back at 1?

That’s a good question indeed. I will test that too.

I spotted something. I had my tablet with HabPanel off the whole night. Everything worked “as usual”. I turn on the tablet + HabPanel today at 8:18. I instantly got:

2024-12-10 08:17:44.743 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'BatteryLevel' received command 100
2024-12-10 08:17:44.745 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Office_FibEye__BatteryLevel' received command 100
... many more...

It is actually possible that I always add this issue but never noticed. The “magic number” could be the BatteryLevel of the tablet. It was indeed down recently.

I still don’t explain what/how/why this tablet would send this command but I think I am getting closer to an explanation…

Yes I agree with you. Moreover, I was not using it yet.
Having an unexplained issue, I decided to remove battery related stuff, especially when not used. But your addon looks nice, I just never had the time to see how it works and set it up. I will likely reinstall once the mystery is solved :slight_smile:

Found it ! :tada:

So I did have the issue “forever” but only noticed recently because of a constellation of conditions:

  • not so long ago, I added a rule “If Member of BatteryLevel changed and below… send notif”
  • my tablet crashed and the battery drained
  • I started getting a gazilions of notifications about ALL my devices being low on battery, all with the same value… which I found highly UNlikely.

So the “culprit” is the OpenHab App and its default of BatteryLevel.

Nicely however, this can be turned on/off and renamed.

Conclusion:

  • if you KNOW what you are doing, everyhting should be fine but read on…
  • I would recommend NOT using a group called BatteryLevel (I switched to BatteryPercent) to stay clear from the default value in case I reinstall the App and forget about this issue)
  • Make sure to configure the App as you wish and either do not send the value or rename the rather generic BatteryLevel into something more specific that has no chance to collide with the group name

1 Like

If someone needs more details, here are how to define the required items:

Number                BatteryLevelTablet                                             "Tablet Battery Level [%d %%]"                       <battery>        (BatteryPercent, Tablet)
String                ChargingStateTablet                                            "Tablet Charging State"                              <poweroutlet>    (Tablet)

Whatever name BatteryLevelTablet should NOT be a group and should match what you defined in the OpenHab App on the Tablet.

Ha very nice…
Glad you got it…
Greets

Thanks for your support during my rubber ducking session :slight_smile:
This issue puzzled me a bit but in the end, the issue makes sense :slight_smile:

I would add to the above that the App allows defining a device ID.
That is probably better than renaming BatteryLevel into BatteryLevelXYZ.
Defining the device id as MyTablet__ for instance, will yield to the App sending the enabled channels such as MyTablet__BatteryLevel, etc…