JPA persistence not restoring at startup - PersistenceService used before Persistence (config) is initialized

justin · January 29, 2016, 1:56am

I am using the built-in Derby database. Persistence was working in a 1.8.0 SNAPSHOT build. I have recently upgraded to 1.8.0.

Here is are some (appropriate) parts of the debug log:

2016-01-28 20:28:52.747 [DEBUG] [org.openhab.model.core.internal.folder.FolderObserver:98] Refreshing folder ‘persistence’
2016-01-28 20:28:53.072 [DEBUG] [org.openhab.model.persistence.internal.PersistenceModelActivator:23] Registered ‘persistence’ configuration parser
2016-01-28 20:29:03.060 [DEBUG] [org.openhab.model.core.internal.folder.FolderObserver:98] Refreshing folder ‘persistence’
2016-01-28 20:29:03.079 [INFO] [org.openhab.model.core.internal.ModelRepositoryImpl:80] Loading model ‘jpa.persist’
2016-01-28 20:29:13.134 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceServiceActivator:31] JPA persistence bundle has been started.
2016-01-28 20:29:13.152 [DEBUG] [org.openhab.model.core.internal.folder.FolderObserver:98] Refreshing folder ‘persistence’
2016-01-28 20:29:13.162 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:61] Activating jpa binding…
2016-01-28 20:29:13.162 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:62] Activating jpa binding…done
2016-01-28 20:29:13.163 [DEBUG] [org.openhab.core.persistence.internal.PersistenceManager:146] Initializing jpa persistence service.
2016-01-28 20:29:13.399 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:143] Querying for historic item: ${item1}
2016-01-28 20:29:13.401 [WARN] [org.openhab.persistence.jpa.internal.JpaPersistenceService:146] Trying to create EntityManagerFactory but we don’t have configuration yet!
2016-01-28 20:29:13.403 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:143] Querying for historic item: ${item2}
2016-01-28 20:29:13.403 [WARN] [org.openhab.persistence.jpa.internal.JpaPersistenceService:146] Trying to create EntityManagerFactory but we don’t have configuration yet!
…
2016-01-28 20:29:13.413 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:143] Querying for historic item: ${item13}
2016-01-28 20:29:13.413 [WARN] [org.openhab.persistence.jpa.internal.JpaPersistenceService:146] Trying to create EntityManagerFactory but we don’t have configuration yet!
2016-01-28 20:29:14.352 [DEBUG] [org.openhab.persistence.jpa.internal.JpaConfiguration:41] Update config…
2016-01-28 20:29:14.352 [DEBUG] [org.openhab.persistence.jpa.internal.JpaConfiguration:49] url: jdbc:derby:persist2.db;create=true
2016-01-28 20:29:14.352 [DEBUG] [org.openhab.persistence.jpa.internal.JpaConfiguration:59] driver: org.apache.derby.jdbc.EmbeddedDriver
2016-01-28 20:29:14.353 [INFO] [org.openhab.persistence.jpa.internal.JpaConfiguration:79] syncmappings was not specified!
2016-01-28 20:29:14.353 [DEBUG] [org.openhab.persistence.jpa.internal.JpaConfiguration:84] Update config…done
2016-01-28 20:29:14.737 [DEBUG] [org.openhab.model.core.internal.folder.FolderObserver:98] Refreshing folder ‘scripts’
2016-01-28 20:29:14.737 [DEBUG] [org.openhab.model.core.internal.folder.FolderObserver:98] Refreshing folder ‘items’
2016-01-28 20:29:14.737 [DEBUG] [org.openhab.model.item.internal.GenericItemProvider:341] Start processing binding configuration of Item ‘${item1} (Type=SwitchItem, State=Uninitialized)’ with ‘ZWaveGenericBindingProvider’ reader.
2016-01-28 20:29:14.738 [DEBUG] [org.openhab.model.item.internal.GenericItemProvider:341] Start processing binding configuration of Item ‘${item2} (Type=SwitchItem, State=Uninitialized)’ with ‘ZWaveGenericBindingProvider’ reader.
…
2016-01-28 20:29:14.758 [DEBUG] [org.openhab.model.item.internal.GenericItemProvider:341] Start processing binding configuration of Item ‘${item13} (Type=SwitchItem, State=Uninitialized)’ with ‘ZWaveGenericBindingProvider’ reader.
2016-01-28 20:29:14.765 [INFO] [org.openhab.core.service.AbstractActiveService:169] ZWave Refresh Service has been started
2016-01-28 20:29:23.432 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:94] Storing item: ${item1}
2016-01-28 20:29:23.456 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:113] Stored new value: ON
2016-01-28 20:29:23.457 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:218] Creating EntityManagerFactory…
2016-01-28 20:29:23.681 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:238] Creating EntityManagerFactory…done
2016-01-28 20:29:24.803 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:124] Persisting item…
2016-01-28 20:29:25.287 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:129] Persisting item…done
2016-01-28 20:29:25.298 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:138] Storing item…done

Interesting parts:

20:29:13.399: JpaPersistenceService.Query is called to restore bindings, but JPA is not initialized (yet)
20:29:14.352: JpaConfiguration.activate is called
20:29:23.432: ZWave refresh from current state reads live values, tries to persist
20:29:23.457: JpaPersistenceService is able to create EMF

If I touch items/${file}.items, it reloads the items, and then refreshes:

2016-01-28 20:50:36.148 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:143] Querying for historic item: ${item}
2016-01-28 20:50:36.149 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:170] The query: SELECT n FROM JpaPersistentItem n WHERE n.realName = :itemName ORDER BY n.timestamp DESC
2016-01-28 20:50:36.149 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:177] Creating query…
2016-01-28 20:50:36.149 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:185] Creating query…done
2016-01-28 20:50:36.149 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:187] Retrieving result list…
2016-01-28 20:50:36.174 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:190] Retrieving result list…done
2016-01-28 20:50:36.175 [DEBUG] [org.openhab.persistence.jpa.internal.JpaPersistenceService:194] Convert to HistoricItem: 1
2016-01-28 20:50:36.175 [DEBUG] [org.openhab.core.persistence.internal.PersistenceManager:377] Restored item state from ‘Jan 28, 2016 8:29:34 PM’ for item ‘${item}’ → ‘OFF’

The Persistence node on the wiki shows “Workaround 2” which touches the *.rules files after startup, so they get reloaded after items are refreshed from storage. However, this would be “Workaround 3” for *.items, so I figured I would create a post here.

manfred_bergmann · February 25, 2016, 6:08pm

Sorry for not writing earlier.
I should check the forum more often.

I see stuff like this on my server, too:
2016-01-28 20:29:13.403 [WARN] [org.openhab.persistence.jpa.internal.JpaPersistenceService:146] Trying to create EntityManagerFactory but we don’t have configuration yet!

But it’s non-critical and most probably because the bundles are not started in a particular order.

Is this problem exclusively to JPA binding?
I have, except the warning message, not had a real problem using JPA and PostgreSQL.

Manfred

justin · April 5, 2016, 2:09am

My persistence/jpa.persist includes:

Items {
    * : strategy = everyChange, everyDay, restoreOnStartup
}

Shouldn’t there be an order-of-activation for the bundles? If not, there is a race condition between (a) creating the persistence service and (b) activating the “items strategy restoreOnStartup”.

That is, it appears that the *.items file is loaded and items are created, which in turn triggers “restoreOnStartup”, but there is no persistence service available. Once the persistence service becomes available, the item does not try to re-query for the “restoreOnStartup”.

In my case, the ZWave Refresh Service asks the underlying device to retrieve its state which then gets pushed back to the database, which happens after the persistence service was activated. However, I also have a non-zwave Item whose state is not being restored at startup (remains at unknown) because the “restoreOnStartup” fails, and the ZWave Refresh Service is not applicable.

Thus, the state of non-zwave devices is not restored at startup, meaning “restoreOnStartup” is not working correctly.

manfred_bergmann · April 5, 2016, 7:12am

AFAIK there is no particular order.
But I’m probably not the right one to ask.
I’m only having the one persistence service (JPA) and restoring the items works even though the persistence service may be loaded after the items file.
Why that works I don’t know.
Someone else need to answer that.

Manfred

Flowyk · May 14, 2019, 9:06pm

Hi, is there any way to fix this? Or is jpa binding just useless?
I have same problem on openHAB 2.5.0~M1-1, it does not restore state of my items.

Number Configuration_OnBrightness “Brightness of lights in living room” (gConfiguration)
2019-05-14 22:49:28.568 [DEBUG] [e.jpa.internal.JpaPersistenceService] - Querying for historic item: Configuration_OnBrightness
2019-05-14 22:49:28.569 [WARN ] [e.jpa.internal.JpaPersistenceService] - Trying to create EntityManagerFactory but we don’t have configuration yet!

Flowyk · May 14, 2019, 9:53pm

Well, after trying JDBC alternative, I will return to JPA binding that can not restore items on startup but at least does not create stupid tables for every item at runtime.

@chris Can you please give me a hint on how to fix the issue of not loading item states on startup, how did you solved it for z-wave items?