search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.88k stars 3.59k forks source link

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

Open lenschith opened 1 month ago

lenschith commented 1 month ago

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 PRETTYNAME="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

lsiepel commented 4 days ago

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.