Possible inconsistency on persistence layer initialization,

[lo92fr]

Hello All,

I'm currently working on the Linky binding, try to fix a reliability issue I've got with timeseries handling on the binding.

The binding exposes 4 different time series 👍

• Daily Consumptions
• Weekly Consumptions
• Monthly Consumptions
• Yearly Consumptions.

What I observe is that when I start the binding 👍

• Sometimes All 4 timeseries are correctly initialized.
• Sometimes only 1 or 2 timeseries are correctly initialized, over are empty.
• Sometimes All 4 timeseries are empty.

I first was thinking of course it was an error in my binding.
But after trace the issue, I've found the following issues:

I put a trace on GenericItem::applyTimeSeries(), and one another trace in
PersistenceManageImpl:timeSeriesUpdated().

Normally, appyTimeSeries should called PersistentManagerImple.timeSeriesUpdated().

But what I find is that sometimes, the timeSeriesListeners in applyTimeSeries is not initialize when applyTimeSeries is called. It seems to come mainly of the fact that there is a lot of item in the registry, and the loop in PeristenceManagerImpl:allItemsChaned is not fully end when the timeseries update event occurs.

@OverRide
public void allItemsChanged(Collection oldItemNames) {
itemRegistry.getItems().forEach(this::added);
}

Of course, I can delay a little bit my addon initialization to prevent this condition.
But it seems strange that there is not some sort of locking / protection in the PersistenceManagerImpl to prevent this.

I take a full trace to explain more in details what happened

What we can see is that:

• at 10:48:41.531 : PersistenceManagerImpl.onReadyMarkerAdded() : the PersistenceManagerImpl is start a little after my binding initialization.
  This function launch the loop to register the persistence listenner on all items.

• at 10:49:05.305, the loop only end at this point, near the end of the trace. The item registry contains around ~500 entries.

• at 10:48:44.314 : the binding start to send timeseries update.

• at 10:48:44.958 : we receive event in the core for timeseries update, but at this point, the timeseries listener is not yet initialized.

• at 10:48:45.010 : for another timeseries, this time listener is correctly initialized !

• at 10:48:45.319 : we see that only Month timeseries are correctly handle.

____________________________
Welcome to Apache Felix Gogo

g! 

10:48:27.499 [INFO ] [org.openhab.core.Activator          ] - Starting openHAB 5.0.0 (Unknown Build No.)

...

10:48:32.119 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Linky.items'

...

10:48:37.974 [DEBUG] [rnal.discovery.LinkyDiscoveryService] - Start Linky device background discovery
10:48:37.977 [DEBUG] [nal.handler.BridgeLocalSerialHandler] - isInitialized() = false
10:48:37.985 [DEBUG] [ernal.handler.ThingLinkyLocalHandler] - Initializing Linky handler for 21454992660003
10:48:38.013 [DEBUG] [rnal.handler.BridgeRemoteBaseHandler] - Initializing Linky API bridge handler.


10:48:38.103 [INFO ] [rnal.handler.ThingLinkyRemoteHandler] - ThingLinkyRemoteHandler, startLevel: 10

10:48:38.126 [DEBUG] [rnal.handler.ThingLinkyRemoteHandler] - Initializing Linky handler for 21454992660003

10:48:38.126 [INFO ] [rnal.handler.ThingLinkyRemoteHandler] - ThingLinkyRemoteHandler.initialize(), startLevel: 10

// PersistenceManagerImpl: onReadyMarkerAdded, line 382
10:48:41.531 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.onReadyMarkerAdded()

10:48:41.593 [INFO ] [openhab.event.StartlevelEvent       ] - Startlevel '20' reached.
10:48:41.594 [INFO ] [openhab.event.StartlevelEvent       ] - Startlevel '30' reached.
10:48:41.594 [INFO ] [openhab.event.StartlevelEvent       ] - Startlevel '40' reached.
10:48:41.594 [INFO ] [openhab.event.StartlevelEvent       ] - Startlevel '50' reached.
10:48:41.594 [INFO ] [openhab.event.StartlevelEvent       ] - Startlevel '70' reached.

// Linky pooling event loop start
10:48:43.131 [INFO ] [rnal.handler.ThingLinkyRemoteHandler] - ThingLinkyRemoteHandler.pooling(), startLevel: 70

// And update data
10:48:43.131 [INFO ] [rnal.handler.ThingLinkyRemoteHandler] - updateData() called
10:48:43.618 [INFO ] [rnal.handler.ThingLinkyRemoteHandler] - updateEnergyData() called

// ========================= Send the timeseries from Linky addon, startLevel = 70
10:48:44.314 [INFO ] [rnal.handler.ThingLinkyRemoteHandler] - ThingLinkyRemoteHandler.updateTimeSeries(), startLevel: 70
10:48:44.318 [DEBUG] [rnal.handler.ThingLinkyRemoteHandler] - Send timeseries channel (21454992660003) linky-remote-daily consumption with org.openhab.core.types.TimeSeries@4529b896
10:48:44.441 [INFO ] [openhab.event.ItemTimeSeriesEvent   ] - Item 'Linky_Melody_Daily_Conso_Day' shall process timeseries [Entry[timestamp=2022-03-18T23:00:00Z, state=72.857 kWh],.... ]

10:48:44.545 [INFO ] [rnal.handler.ThingLinkyRemoteHandler] - ThingLinkyRemoteHandler.updateTimeSeries(), startLevel: 70
10:48:44.545 [DEBUG] [rnal.handler.ThingLinkyRemoteHandler] - Send timeseries channel (21454992660003) linky-remote-weekly consumption with org.openhab.core.types.TimeSeries@82c686c5
10:48:44.556 [INFO ] [openhab.event.ItemTimeSeriesEvent   ] - Item 'Linky_Melody_Weekly_Conso_Week' shall process timeseries [Entry[timestamp=2022-03-18T23:00:00Z, state=155.284 kWh],... ]

10:48:44.584 [INFO ] [rnal.handler.ThingLinkyRemoteHandler] - ThingLinkyRemoteHandler.updateTimeSeries(), startLevel: 70
10:48:44.584 [DEBUG] [rnal.handler.ThingLinkyRemoteHandler] - Send timeseries channel (21454992660003) linky-remote-monthly consumption with org.openhab.core.types.TimeSeries@b2bd36c4

10:48:44.586 [INFO ] [rnal.handler.ThingLinkyRemoteHandler] - ThingLinkyRemoteHandler.updateTimeSeries(), startLevel: 70
10:48:44.586 [DEBUG] [rnal.handler.ThingLinkyRemoteHandler] - Send timeseries channel (21454992660003) linky-remote-yearly consumption with org.openhab.core.types.TimeSeries@c985d64d
10:48:44.590 [INFO ] [openhab.event.ItemTimeSeriesEvent   ] - Item 'Linky_Melody_Monthly_Conso_Month' shall process timeseries [Entry[timestamp=2022-02-28T23:00:00Z, state=838.923 kWh]...]
10:48:44.590 [INFO ] [openhab.event.ItemTimeSeriesEvent   ] - Item 'Linky_Melody_Yearly_Conso_Year' shall process timeseries [Entry[timestamp=2021-12-31T23:00:00Z, state=0 kWh], ...]


// Receive timeseries event on item side and apply



// Persitence listener not registerd for Daily timeseries : GenericItem.applyTimeSeries(), line 308
10:48:44.940 [INFO ] [org.openhab.core.items.GenericItem  ] - GenericItem.applyTimeSeries() : Linky_Melody_Daily_Conso_Day
10:48:44.958 [INFO ] [org.openhab.core.items.GenericItem  ] - GenericItem.applyTimeSeries() : listenerSize:0
10:48:44.979 [INFO ] [hab.event.ItemTimeSeriesUpdatedEvent] - Item 'Linky_Melody_Daily_Conso_Day' updated timeseries [Entry[timestamp=2022-03-18T23:00:00Z, state=72.857], ...]


// Persitence listener not registerd for Weekly timeseries : GenericItem.applyTimeSeries(), line 308
10:48:44.982 [INFO ] [org.openhab.core.items.GenericItem  ] - GenericItem.applyTimeSeries() : Linky_Melody_Weekly_Conso_Week
10:48:44.986 [INFO ] [org.openhab.core.items.GenericItem  ] - GenericItem.applyTimeSeries() : listenerSize:0
10:48:44.992 [INFO ] [hab.event.ItemTimeSeriesUpdatedEvent] - Item 'Linky_Melody_Weekly_Conso_Week' updated timeseries [Entry[timestamp=2022-03-18T23:00:00Z, state=155.284],....]


// Persitence listener  registerd for Monthly timeseries : GenericItem.applyTimeSeries(), line 308
10:48:45.008 [INFO ] [org.openhab.core.items.GenericItem  ] - GenericItem.applyTimeSeries() : Linky_Melody_Monthly_Conso_Month
10:48:45.010 [INFO ] [org.openhab.core.items.GenericItem  ] - GenericItem.applyTimeSeries() : listenerSize:1
10:48:45.014 [INFO ] [hab.event.ItemTimeSeriesUpdatedEvent] - Item 'Linky_Melody_Monthly_Conso_Month' updated timeseries [Entry[timestamp=2022-02-28T23:00:00Z, state=838.923], ...]


// Persistence listener  registerd for Yearly timeseries : GenericItem.applyTimeSeries(), line 308
10:48:45.033 [INFO ] [org.openhab.core.items.GenericItem  ] - GenericItem.applyTimeSeries() : Linky_Melody_Yearly_Conso_Year
10:48:45.035 [INFO ] [org.openhab.core.items.GenericItem  ] - GenericItem.applyTimeSeries() : listenerSize:0
10:48:45.037 [INFO ] [hab.event.ItemTimeSeriesUpdatedEvent] - Item 'Linky_Melody_Yearly_Conso_Year' updated timeseries [Entry[timestamp=2021-12-31T23:00:00Z, state=0], ...]


// Only Month timeseries is update because of missing listener
// PersistenceManagerImpl.timeSeriesUpdated, line 338
10:48:45.319 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.timeSeriesUpdated() : Linky_Melody_Monthly_Conso_Month


10:48:46.595 [INFO ] [openhab.event.StartlevelEvent       ] - Startlevel '80' reached.
10:48:46.595 [INFO ] [openhab.event.StartlevelEvent       ] - Startlevel '100' reached.

..

// PersistenceManagerImpl: onReadyMarkerAdded, line 388
10:49:05.305 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.onReadyMarkerAdded():end()

Your Environment

• Openhab 5.0 snapshoot dev from 18 March
• Windows OS
• Eclipse Dev setup
• Persistence layer is influxdb2 2.7.11 on Fedora 41

[openhab-bot]

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/timeseries-and-current-state/163142/8

[lo92fr]

One more note.
I’ve currently find a workaround by adding in the binding pooling code a loop waiting on the ready marker of persistence:restore :

                logger.info("ThingLinkyRemoteHandler.pooling(), startLevel: " + startLevelService.getStartLevel());
                while (!readyService.isReady(marker)) {
                    logger.info("ThingLinkyRemoteHandler.pooling(), marker: " + readyService.isReady(marker));
                    try {
                        Thread.sleep(1000);
                    } catch (InterruptedException ex) {
                    }
                }

Where marker is:
    private final ReadyMarker marker = new ReadyMarker("persistence", "restore");

[lo92fr]

Hello,

I've also add you to this ticket a open sooner this week.
This is about possible calling sendTimeSeries before persistence:restore is fully end, and possible lost of the update values in this case...

@florian-h05 , @joerg1985, @mherwege, @J-N-K , @holgerfriedrich.
@lolodomo, @clinique, @lsiepel.
@weymann.

[J-N-K]

So the issue is that the thing handler is initialized (and sending data) before the persistence service has finished restoring values?

[lo92fr]

Yes, more precisly that the thing handler send timeseries before the persistence listener is set on the different items.
So the event is sent, but is lost in middle of nowhere because no timeseries implementation currently listenning for it.

[lo92fr]

Hello @J-N-K,

I trace the issue more in depth.

The matter is that we trigger in the same loop :

1. Code to set the listenner on the item.
2. Logic to restore data from the persistent layers.

Step 1 is a very fast operation, just do a basic setter operation.
But Step2 is very time consumming as we have to query the persistence layer for each items.

So as you can see, the loop that start at 10:35:25.879 "allItmsChangedBegin" only end at 10:35:39.421 "allItmsChangedEnd" (about 15s latter).
Some listenners affection are done only after timeseries is send from the binding. This is the case for exemple for Linky_Melody_Daily_Conso_Day

• Affectation of listenner is done at 10:35:38.584.
• But handling the timeseries update is done before at 10:35:32.120 where listener is not yet initialized, so ignoring silently the update "GenericItem.applyTimeSeries(): 0".

Trace 1:

____________________________
Welcome to Apache Felix Gogo

g! 
10:35:10.008 [INFO ] [org.openhab.core.Activator          ] - Starting openHAB 5.0.0 (Unknown Build No.)
10:35:25.117 [INFO ] [.influxdb.InfluxDBPersistenceService] - InfluxDB persistence service started.


10:35:25.877 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.onReadyMarkerAdded(): {}20
10:35:25.879 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.onReadyMarkerAdded(): allItemsChanged Begin

10:35:28.463 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.addItem pa: {} {}2025-03-25T10:35:28.463043Linky_Melody_Monthly_Conso_Month 
10:35:28.468 [TRACE] [.influxdb.InfluxDBPersistenceService] - Query-Filter: itemname: Linky_Melody_Monthly_Conso_Month, ordering: DESCENDING, state: null,  operator: EQ, getBeginDate: null, getEndDate: 2025-03-25T10:35:28.467042600+01:00[Europe/Paris], getPageSize: 1000, getPageNumber: 0
10:35:28.492 [TRACE] [.influxdb.InfluxDBPersistenceService] - Query-Filter: itemname: Linky_Melody_Monthly_Conso_Month, ordering: ASCENDING, state: null,  operator: EQ, getBeginDate: 2025-03-25T10:35:28.490303100+01:00[Europe/Paris], getEndDate: null, getPageSize: 2147483647, getPageNumber: 0
10:35:28.498 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.addItem pb: {} {}2025-03-25T10:35:28.498815600Linky_Melody_Monthly_Conso_Month 
10:35:28.498 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.addItem pc: {} {}2025-03-25T10:35:28.498815600Linky_Melody_Monthly_Conso_Month 


10:35:32.023 [INFO ] [rnal.handler.ThingLinkyRemoteHandler] - ThingLinkyRemoteHandler.updateTimeSeries(), startLevel: 30
10:35:32.027 [DEBUG] [rnal.handler.ThingLinkyRemoteHandler] - Send timeseries channel (21454992660003) linky-remote-daily consumption with org.openhab.core.types.TimeSeries@45e99a13

10:35:32.092 [INFO ] [rnal.handler.ThingLinkyRemoteHandler] - ThingLinkyRemoteHandler.updateTimeSeries(), startLevel: 30
10:35:32.092 [DEBUG] [rnal.handler.ThingLinkyRemoteHandler] - Send timeseries channel (21454992660003) linky-remote-weekly consumption with org.openhab.core.types.TimeSeries@5bfc7beb

10:35:32.106 [INFO ] [rnal.handler.ThingLinkyRemoteHandler] - ThingLinkyRemoteHandler.updateTimeSeries(), startLevel: 30
10:35:32.107 [DEBUG] [rnal.handler.ThingLinkyRemoteHandler] - Send timeseries channel (21454992660003) linky-remote-monthly consumption with org.openhab.core.types.TimeSeries@42e75bf1

10:35:32.108 [INFO ] [rnal.handler.ThingLinkyRemoteHandler] - ThingLinkyRemoteHandler.updateTimeSeries(), startLevel: 30
10:35:32.108 [DEBUG] [rnal.handler.ThingLinkyRemoteHandler] - Send timeseries channel (21454992660003) linky-remote-yearly consumption with org.openhab.core.types.TimeSeries@c7fd02a1

10:35:32.111 [INFO ] [rnal.handler.ThingLinkyRemoteHandler] - updateData() called

10:35:32.120 [INFO ] [org.openhab.core.items.GenericItem  ] - GenericItem.applyTimeSeries(): 0 - Linky_Melody_Daily_Conso_Day 

10:35:32.126 [INFO ] [org.openhab.core.items.GenericItem  ] - GenericItem.applyTimeSeries(): 1 - Linky_Melody_Weekly_Conso_Week 
10:35:32.128 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.timeSeriesUpdated() : Linky_Melody_Weekly_Conso_Week

10:35:32.129 [INFO ] [org.openhab.core.items.GenericItem  ] - GenericItem.applyTimeSeries(): 1 - Linky_Melody_Monthly_Conso_Month 
10:35:32.129 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.timeSeriesUpdated() : Linky_Melody_Monthly_Conso_Month

10:35:32.129 [INFO ] [org.openhab.core.items.GenericItem  ] - GenericItem.applyTimeSeries(): 0 - Linky_Melody_Yearly_Conso_Year 


10:35:38.584 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.addItem pa: {} {}2025-03-25T10:35:38.584117Linky_Melody_Daily_Conso_Day 
10:35:38.586 [TRACE] [.influxdb.InfluxDBPersistenceService] - Query-Filter: itemname: Linky_Melody_Daily_Conso_Day, ordering: DESCENDING, state: null,  operator: EQ, getBeginDate: null, getEndDate: 2025-03-25T10:35:38.586117400+01:00[Europe/Paris], getPageSize: 1000, getPageNumber: 0
10:35:38.602 [TRACE] [.influxdb.InfluxDBPersistenceService] - Query-Filter: itemname: Linky_Melody_Daily_Conso_Day, ordering: ASCENDING, state: null,  operator: EQ, getBeginDate: 2025-03-25T10:35:38.599311+01:00[Europe/Paris], getEndDate: null, getPageSize: 2147483647, getPageNumber: 0
10:35:38.606 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.addItem pb: {} {}2025-03-25T10:35:38.606308800Linky_Melody_Daily_Conso_Day 

...
10:35:39.421 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.onReadyMarkerAdded(): allItemsChanged End

10:35:39.421 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.onReadyMarkerAdded(): allItemsChanged Begin StartEventHandling
10:35:51.155 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.onReadyMarkerAdded(): allItemsChanged End StartEventHandling

10:35:51.155 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.onReadyMarkerAdded(): mark marker ready

I can see different way to fix the issue.

1. One will be to separate the allItemsChanged() loop into two distinctive loop.

• The first will be responsible to only set the listenner.
• The second will be adding the item to the persistence container, that will trigger the restore from persistence layer.

I give a try to this solution, and it fix the issues.
First loop only take around 20ms, and so all listenners are initialized far before binding begin to send values.
Second loop take more time, but I think it's not an issue.

11:01:51.852 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.onReadyMarkerAdded(): allItemsChanged Begin

11:01:51.852 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.addPersistenceListenners begin: {}2025-03-25T11:01:51.852474900
11:01:51.854 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.addPersistenceListenners end : {}2025-03-25T11:01:51.854475200

11:01:51.854 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.addToPersistenceServiceContainer begin: {}2025-03-25T11:01:51.854475200
11:02:02.051 [INFO ] [ence.internal.PersistenceManagerImpl] - PersistenceManagerImpl.addToPersistenceServiceContainer end: {}2025-03-25T11:02:02.050367

2. Other possibilities can be to wait on the marker 👍

code would be something like:

  private final ReadyMarker marker = new ReadyMarker("persistence", "restore");

  while (!readyService.isReady(marker)) {
                    logger.info("ThingLinkyRemoteHandler.pooling(), marker: " + readyService.isReady(marker));
                    try {
                        Thread.sleep(1000);
                    } catch (InterruptedException ex) {
                    }
                }

We would need to have this done before hitting the GenericItem.applyTimeSeries.

I try by putting this code in my binding, it works, but i would delay the binding initialization a lot because marker in only set after all items are restored from the peristence layer.

So not sure this is a very good idea, and don't know where we can put this call in the openhab core to make things work correctly.

Laurent.