PostgreSQL on OH3

auzick · April 8, 2021, 10:23pm

Having some trouble setting up JDBC/Postgres working on OH3.

I worked through what I thought were all of my mistakes in configuration, but now I’m stymied on this error:

2021-04-08 17:08:48.049 [ERROR] [org.openhab.persistence.jdbc        ] - bundle org.openhab.persistence.jdbc:3.0.1 (235)[org.openhab.persistence.jdbc.internal.JdbcPersistenceService(322)] : The activate method has thrown an exception
java.lang.StringIndexOutOfBoundsException: begin 0, end -1, length 0
        at java.lang.String.checkBoundsBeginEnd(String.java:3319) ~[?:?]
        at java.lang.String.substring(String.java:1874) ~[?:?]
        at org.openhab.persistence.jdbc.utils.StringUtilsExt.stringBeforeSubstr(StringUtilsExt.java:220) ~[?:?]
        at org.openhab.persistence.jdbc.utils.StringUtilsExt.parseJdbcURL(StringUtilsExt.java:165) ~[?:?]
        at org.openhab.persistence.jdbc.utils.StringUtilsExt.parseJdbcURL(StringUtilsExt.java:65) ~[?:?]
        at org.openhab.persistence.jdbc.internal.JdbcConfiguration.updateConfig(JdbcConfiguration.java:92) ~[?:?]
        at org.openhab.persistence.jdbc.internal.JdbcConfiguration.<init>(JdbcConfiguration.java:73) ~[?:?]
        at org.openhab.persistence.jdbc.internal.JdbcPersistenceService.updateConfig(JdbcPersistenceService.java:218) ~[?:?]
        at org.openhab.persistence.jdbc.internal.JdbcPersistenceService.activate(JdbcPersistenceService.java:83) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod.invokeMethod(BaseMethod.java:228) ~[bundleFile:?]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod.access$500(BaseMethod.java:41) ~[bundleFile:?]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod$Resolved.invoke(BaseMethod.java:664) ~[bundleFile:?]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod.invoke(BaseMethod.java:510) [bundleFile:?]
        at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:317) [bundleFile:?]
        at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:307) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:340) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:114) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:982) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:955) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:900) [bundleFile:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212) [org.eclipse.osgi-3.12.100.jar:?]
        at java.security.AccessController.doPrivileged(Native Method) [?:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:508) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:624) [org.eclipse.osgi-3.12.100.jar:?]
        at org.apache.felix.scr.impl.manager.SingleRefPair.getServiceObject(SingleRefPair.java:86) [bundleFile:?]
        at org.apache.felix.scr.impl.inject.BindParameters.getServiceObject(BindParameters.java:47) [bundleFile:?]
        at org.apache.felix.scr.impl.inject.methods.BindMethod.getServiceObject(BindMethod.java:664) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.DependencyManager.getServiceObject(DependencyManager.java:2308) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1805) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:1788) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeBindMethod(SingleComponentManager.java:435) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:325) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:294) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1216) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1137) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:944) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:880) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1168) [bundleFile:?]
        at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:125) [bundleFile:?]
        at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:920) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:469) [org.eclipse.osgi-3.12.100.jar:?]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:906) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:892) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:128) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:959) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:732) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:666) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:432) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:665) [bundleFile:?]
        at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:338) [bundleFile:?]
        at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:382) [bundleFile:?]
        at org.apache.felix.scr.impl.Activator.access$200(Activator.java:49) [bundleFile:?]
        at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:264) [bundleFile:?]
        at org.apache.felix.scr.impl.AbstractExtender.createExtension(AbstractExtender.java:196) [bundleFile:?]
        at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:169) [bundleFile:?]
        at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:49) [bundleFile:?]
        at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482) [osgi.core-6.0.0.jar:?]
        at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415) [osgi.core-6.0.0.jar:?]
        at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232) [osgi.core-6.0.0.jar:?]
        at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444) [osgi.core-6.0.0.jar:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:908) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:213) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:120) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:112) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:168) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.container.Module.publishEvent(Module.java:476) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.container.Module.start(Module.java:467) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1634) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1614) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1585) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1528) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [org.eclipse.osgi-3.12.100.jar:?]
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340) [org.eclipse.osgi-3.12.100.jar:?]

I downloaded the driver bundle and it’s showing up when I do a bundle:list

263 │ Active  │  80 │ 9.4.1209.jre7           │ PostgreSQL JDBC Driver JDBC41

Doing my best to get comfortable with working with Ubuntu (I even used wget to download the bundle; quite the accomplishment for me ), but I’m stymied at this point. Any kind soul want to point me to the error of my ways?

wborn · April 8, 2021, 10:57pm

What configuration are you using? It seems to have issues parsing the JDBC URL in the configuration.

Bruce_Osborne · April 8, 2021, 11:04pm

The current JDBC 4.1 driver is 42.2.19 9.4.1209 is very old.

auzick · April 9, 2021, 12:39pm

Thanks @Bruce_Osborne was going by the list here: JDBC - Persistence Services | openHAB

I’ll try the latest driver and see what happens.

auzick · April 9, 2021, 12:44pm

Thanks @wborn.

My connection string looks like this: jdbc:postgresql://ha.myserver.com:5432. The hostname resolves in DNS.

I was having an issue where I was appending /OpenHAB to the connection string, but the driver threw an error that the database didn’t already exist, which suggests that openHab successfully connected to the database server. I removed the /OpenHAB from the connection string, which got me to the current state of afffairs.

auzick · April 9, 2021, 1:11pm

I extended the openhab user’s privileges to include superuser, which caused the driver to throw a new error

Failed to initialize pool: FATAL: database "openhab" does not exist

I manually created the database (The docs say “If no database is available it will be created”) and now it seems to be OK.

2021-04-09 08:09:59.445 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::openConnection: Driver is available::Yank setupDataSource
2021-04-09 08:09:59.911 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'pingDB':
 afterAccess     = 466 ms
 timeAverage50  = 466 ms
 timeAverage100 = 466 ms
 timeAverage200 = 466 ms
 afterAccessMin  = 466 ms
 afterAccessMax  = 466 ms
 1000Statements = 0 sec
 statementCount = 1

2021-04-09 08:09:59.922 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'doCreateItemsTableIfNot':
 afterAccess     = 6 ms
 timeAverage50  = 236 ms
 timeAverage100 = 236 ms
 timeAverage200 = 236 ms
 afterAccessMin  = 6 ms
 afterAccessMax  = 466 ms
 1000Statements = 0 sec
 statementCount = 2

2021-04-09 08:09:59.929 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'getItemIDTableNames':
 afterAccess     = 7 ms
 timeAverage50  = 159 ms
 timeAverage100 = 159 ms
 timeAverage200 = 159 ms
 afterAccessMin  = 6 ms
 afterAccessMax  = 466 ms
 1000Statements = 0 sec
 statementCount = 3