Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[network] Incorrect Timestamp Update After Restart in Network Binding #17404

Open
lenschith opened this issue Sep 11, 2024 · 11 comments
Open

[network] Incorrect Timestamp Update After Restart in Network Binding #17404

lenschith opened this issue Sep 11, 2024 · 11 comments
Labels
bug An unexpected problem or unintended behavior of an add-on

Comments

@lenschith
Copy link

lenschith commented Sep 11, 2024

Description:

After restarting the openHAB system (Docker container on Raspberry Pi 5), the "lastseen" items from the Network Binding are overwritten with UNDEF if the devices are not reachable at the time of restart. The items are initially loaded correctly from the MapDB and displayed, but subsequently, the timestamp is set to UNDEF if the devices are not reachable during the restart. Once the devices are back online and reachable, the timestamp updates normally. This behavior occurs in both Bridge-Mode and Macvlan-Mode and has been observed since the update to openHAB 4.2.1.

Expected Behavior:

Before Restart: The timestamp of items showing device availability is correct.
After Restart: If the devices are not reachable at the time of restart, the items are correctly loaded from the MapDB, but then the timestamp is set to UNDEF.
After Devices Are Reachable: The timestamp updates as expected, but the UNDEF value persists until the next update.
Log Examples:

Example 1:

2024-08-29 15:35:23.972 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'User1Zuletztgesehen_Zuletztgesehen' changed from NULL to 2024-08-29T11:14:47.918796970+0200
2024-08-29 15:35:25.330 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:User1aZuletztOnline' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (NOT_YET_READY)
2024-08-29 15:35:27.703 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:User1ZuletztOnline' changed from UNINITIALIZED (NOT_YET_READY) to INITIALIZING
2024-08-29 15:35:27.712 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:User1ZuletztOnline' changed from INITIALIZING to ONLINE
2024-08-29 15:35:40.224 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'User1Zuletztgesehen_Zuletztgesehen' changed from 2024-08-29T11:14:47.918796970+0200 to UNDEF

Example 2:

2024-08-29 17:23:30.817 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:Mobiltelefon_Test' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (NOT_YET_READY)
2024-08-29 17:23:31.297 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Mobiletelefon_Test_zuletzt_gesehen_Zuletzt_gesehen' changed from NULL to 2024-08-29T17:21:25.284348485+0200
2024-08-29 17:23:32.331 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:Mobiltelefon_Test' changed from UNINITIALIZED (NOT_YET_READY) to INITIALIZING
2024-08-29 17:23:32.392 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:Mobiltelefon_Test' changed from INITIALIZING to ONLINE
2024-08-29 17:23:37.553 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Mobiletelefon_Test_zuletzt_gesehen_Zuletzt_gesehen' changed from 2024-08-29T17:21:25.284348485+0200 to UNDEF

System Environment:

openHAB Version: 4.2.1
Docker Version: 20.10.24+dfsg1, build 297e128
Raspberry Pi Model: 5 (8GB)
Operating System: Raspberry Pi OS
Raspberry Pi 5 Model B Rev 1.0
PRETTY_NAME="Debian GNU/Linux 12 (bookworm)"
Linux raspxx 6.6.47-v8-16k+ #1792 SMP PREEMPT Thu Aug 22 15:13:10 BST 2024 aarch64 GNU/Linux

Network Configuration: Tested in Bridge-Mode and Macvlan-Mode

Additional Tests:

A test system with Network Binding and MapDB shows the same behavior. Switching from Pi4 to Pi5 did not resolve the issue.

Troubleshooting:

Container Restarts: The issue persists regardless of the restart method (manual or during backup jobs).
Update to openHAB 4.2.1: I think, the problem started after this update.

Regards, Lenschi

@lenschith lenschith added the bug An unexpected problem or unintended behavior of an add-on label Sep 11, 2024
@lenschith lenschith changed the title Incorrect Timestamp Update After Restart in Network Binding [network] Incorrect Timestamp Update After Restart in Network Binding Sep 11, 2024
@lsiepel
Copy link
Contributor

lsiepel commented Nov 1, 2024

Agree, to me it also seems wrong to set the channel lastseen to UNDEF. From openHAB's pov any timestamp might be the last time the client is observed. Forcibly removing this timestamp by UNDEF iis not something i would expect.

I must say that this only occurs at binding start. Because the state update is forced immediate after the binding is started. This is due to a REFRESH command by the framework. In between the binding start and the command (< 1second), there is not enough time for the binding to query for presence detection (can take up to multiple seconds).

Test jar openHAB 4.2.x+: https://1drv.ms/u/s!AnMcxmvEeupwj4tJIT-V2IgG3v0MUA?e=gDdt6a

  1. Make sure you have openHAB 4.2.x or 4.3.0
  2. Uninstall the current binding (all things, channels and configuration remains available)
  3. Drrop the jar into your addon folder.
  4. Observe the new behavior and please report your results.

@lenschith
Copy link
Author

lenschith commented Nov 6, 2024

I tested this today according to the instructions, but couldn't see any improvement. it's still the same behavior

2024-11-06 20:48:47.850 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MobilePhone_Last_seen' changed from 2024-11-06T20:46:59.844894818+0100 to UNDEF
2024-11-06 20:48:48.499 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:MobilePhone' changed from ONLINE to UNIINITIALIZED
2024-11-06 20:48:48.569 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:MobilePhone' changed from UNINITIALIZED to UNIINITIALIZED (HANDLER_MISSING_ERROR)
2024-11-06 20:48:49.476 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:MobilePhone' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (NOT_YET_READY)
2024-11-06 20:48:50.786 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:MobilePhone' changed from UNINITIALIZED (NOT_YET_READY) to INITIALIZING
2024-11-06 20:48:50.857 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:MobilePhone' changed from INITIALIZING to ONLINE

this value is contained in the mapDB, RestoreOnStartUp

2024-11-06 20:48:59.601 [WARN ] [penhab.automation.script.ui.lastseen] - MobilePhone persist: 2024-11-06T20:46:59.844894818+0100

UNDEF is still displayed in the item

2024-11-06 20:48:47.850 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MobilePhone_Last_seen' changed from 2024-11-06T20:46:59.844894818+0100 to UNDEF

@lsiepel
Copy link
Contributor

lsiepel commented Nov 6, 2024

Could you verify the used binding version from karaf console? Double check the stock version is not running alongside.

@lenschith
Copy link
Author

lenschith commented Nov 7, 2024

I hope this are the correct information.

image

openhab> bundle:list | grep -i Network                                                                        
182 │ Active │  80 │ 4.2.2                 │ openHAB Core :: Bundles :: Network I/O
285 │ Active │  80 │ 4.3.0.202411011717    │ openHAB Add-ons :: Bundles :: Network Binding

before reboot. MobilePhone online

2024-11-07 21:14:03.364 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MobilePhone_Zuletzt_gesehen' changed from 2024-11-07T21:13:57.136958132+0100 to 2024-11-07T21:14:03.360748634+0100
2024-11-07 21:14:09.620 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MobilePhone_Zuletzt_gesehen' changed from 2024-11-07T21:14:03.360748634+0100 to 2024-11-07T21:14:09.616651610+0100

Container rebootet, MobilePhone offline (MobilePhone WLAN Connection disabled)

2024-11-07 21:18:00.820 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:MobilePhone' changed from UNINITIALIZED (NOT_YET_READY) to INITIALIZING
2024-11-07 21:18:00.860 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:MobilePhone' changed from INITIALIZING to ONLINE
2024-11-07 21:18:06.116 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MobilePhone_Zuletzt_gesehen' changed from 2024-11-07T21:15:22.740786966+0100 to UNDEF

the item shows UNDEF. I add a rule to fill the item with the previous state. but you can see, the next check change to UNDEF too!

2024-11-07 21:23:08.010 [WARN ] [.automation.script.ui.lastseen_undef] - Rule: SetMobilePhone from persist: 
2024-11-07 21:23:08.105 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'MobilePhone_Zuletzt_gesehen' received command 2024-11-07T21:15:22.740786966+0100
2024-11-07 21:23:08.118 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'MobilePhone_Zuletzt_gesehen' predicted to become 2024-11-07T21:15:22.740786966+0100
2024-11-07 21:23:08.136 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MobilePhone_Zuletzt_gesehen' changed from UNDEF to 2024-11-07T21:15:22.740786966+0100
2024-11-07 21:23:09.551 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MobilePhone_Zuletzt_gesehen' changed from 2024-11-07T21:15:22.740786966+0100 to UNDEF

@lsiepel
Copy link
Contributor

lsiepel commented Nov 10, 2024

There is another location that sets the lastseen channel to UNDEF. (line 149). To fix this it is not enough to just remove it. From the bindings perspective it is totally fine to set the state to UNDEF as there is no value from the bindings pov. Also the lastseen channel is read only, so setting the command won't work.

Created a new jar, this should make the channel writable so if you perform the exact same tests i would now assume it is fixed.
You can re-use the link to the jar from the previous post.

@lenschith
Copy link
Author

Hello I have test the New JAR

openhab> bundle:list | grep -i Network                                                                        
182 │ Active │  80 │ 4.2.2                 │ openHAB Core :: Bundles :: Network I/O
286 │ Active │  80 │ 4.3.0.202411101415    │ openHAB Add-ons :: Bundles :: Network Binding

Restart the Container, MobilePhone WLAN disabled

2024-11-10 20:02:53.587 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:MobilePhone' changed from UNINITIALIZED (NOT_YET_READY) to INITIALIZING
2024-11-10 20:02:53.625 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:MobilePhone' changed from INITIALIZING to ONLINE

The state set to UNDEF??

2024-11-10 20:02:58.894 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MobilePhone_Zuletzt_gesehen' changed from 2024-11-10T19:56:25.708943866+0100 to UNDEF

Check the mapDB Persiststate. (RestoreOnStartup)

2024-11-10 20:03:13.276 [WARN ] [penhab.automation.script.ui.lastseen] - StartLevel 100% MobilePhone persist: 2024-11-10T19:56:25.708943866+0100`

Set the Item with the previous State

2024-11-10 20:05:12.351 [WARN ] [.automation.script.ui.lastseen_undef] - SetMobilePhone from persist: 
2024-11-10 20:05:12.390 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'MobilePhone_Zuletzt_gesehen' received command 2024-11-10T19:56:25.708943866+0100
2024-11-10 20:05:12.396 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'MobilePhone_Zuletzt_gesehen' predicted to become 2024-11-10T19:56:25.708943866+0100
2024-11-10 20:05:12.415 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MobilePhone_Zuletzt_gesehen' changed from UNDEF to 2024-11-10T19:56:25.708943866+0100

After I set the state manual with a Rule. The Networkbinding did not change the state again to UNDEF

The new state if the Device online again, where written to the Item

2024-11-10 20:10:15.704 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MobilePhone_Zuletzt_gesehen' changed from 2024-11-10T19:56:25.708943866+0100 to 2024-11-10T20:10:11.777111917+0100

But why is the last value still overwritten with UNDEF when the container starts? Actually, this should work without manual intervention with a rule?

Regards Lenschi

@lsiepel
Copy link
Contributor

lsiepel commented Nov 10, 2024

The binding can only react to a command from openHAB.
And restoreOnStartup is just setting the item state and not sending a command to the channel. Therefore the binding remains to have an internal state of null for last-seen. And becasue the device is not reachable it remains null resulting in the channel set to UNDEF, this is by design.

Later on you send a command (by a rule) and the binding reacts to that by setting the internal state / last-seen to the given value. This is what i added in the jar.

I hesitate to continue with this as

  1. it is somewhat a hack to set the internal state by allowing a command to a readonly channel.
  2. it is a sub-par solution to the problem.
  3. im not the binding maintainer, there maybe different thoughts on how to fix this.

The best solution might be to drop the whole UNDEF setting in the binding. To me it makes sense. But this might not be agreed on by others.

Could you tell something about the actuall use-case / issue you have ? Does it cause issues with some scripts running or otherwise?

@lenschith
Copy link
Author

The problem is as soon as the container/openHAB is restarted and a device cannot be reached during this time. I can no longer see the time of the last seen.
So I can't show when a car, roommate or something else was last seen. This occurs in every last seen status when the device was no longer visible.

I haven't noticed this behavior in the past, it only came with an update. Unfortunately I can't say since which version.
So the binding is no longer reliable for this purpose for me. Even after rebooting the system, I would like to know when the device was last seen.

After restarting the openHAB system (Docker container on Raspberry Pi 5), the "lastseen" items from the Network Binding are overwritten with UNDEF if the devices are not reachable at the time of restart.

@lsiepel
Copy link
Contributor

lsiepel commented Nov 10, 2024

i

The behavior is clear, should have stated that. Was mainly interested in the use case. Personally i don't care that a device's lastseen state is set to UNDEF until it reachable again. My openHAB rarely reboots (maybe 2 times a year), no automations are affected and i don;t see a purpose to look at these values at all, it will get updated evantually.
Obviously for you it might be important and was mainly interested in how you use this last-seen channel.

A simple woraround could be to add a rule that whenever a command is received with the UNDEF state you can issue a postUpdate with the last state from persistence.

@lenschith
Copy link
Author

So my system starts up more often. During host updates, openHAB update, monthly backup, RSYNC jobs...
My presence ads are then no longer available. That's a shame because it wasn't like that before.

I've had a rule that sets the value automatically for a long time, but I don't think it's a clean solution. I actually think that the binding should take over this work again ;)

Thank you.
Regards Lenschi

@lsiepel
Copy link
Contributor

lsiepel commented Nov 10, 2024

It was added in 4.2.0 by #16235 maybe @wborn can share his view on this.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug An unexpected problem or unintended behavior of an add-on
Projects
None yet
Development

No branches or pull requests

2 participants