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

[mqttembeddedbroker] File lock during upgrade causes broker to be offline #6186

Closed MyRaceData closed 5 years ago

MyRaceData commented 5 years ago

During an upgrade from OpenHAB 2.4 stable to 2.5M3, the Moquette broker when offline with the message configuration error. The log indicated the error was caused by a file lock on /var/lib/openhab2/mqttembedded.bin file. Uninstalling the broker, deleting the file and reinstalling the broker fixed the problem. OS is Debian 9 running on desktop PC

Expected Behavior

expected behavior would be for broker to continue to work after upgrade

Current Behavior

Current behavior is upgrade caused broker to go offline with error message 'offline - configuration error' log entry indicating cause of error:

18:35:06.527 [ERROR] [org.openhab.io.mqttembeddedbroker    ] - bundle org.openhab.io.mqttembeddedbroker:2.5.0.M3 (321)[org.openhab.io.mqttembeddedbroker.internal.EmbeddedBrokerService(365)] : The activate method has thrown an exception
java.lang.IllegalArgumentException: Could not deserialize [-84, -19, 0, 5, 115, 114, 0, 45, 105, 111, 46, 109, 111, 113, 117, 101, 116, 116, 101, 46, 98, 114, 111, 107, 101, 114, 46, 115, 117, 98, 115, 99, 114, 105, 112, 116, 105, 111, 110, 115, 46, 83, 117, 98, 115, 99, 114, 105, 112, 116, 105, 111, 110, -47, 11, -117, 54, 80, -6, 26, -58, 2, 0, 3, 76, 0, 8, 99, 108, 105, 101, 110, 116, 73, 100, 116, 0, 18, 76, 106, 97, 118, 97, 47, 108, 97, 110, 103, 47, 83, 116, 114, 105, 110, 103, 59, 76, 0, 12, 114, 101, 113, 117, 101, 115, 116, 101, 100, 81, 111, 115, 116, 0, 37, 76, 105, 111, 47, 110, 101, 116, 116, 121, 47, 104, 97, 110, 100, 108, 101, 114, 47, 99, 111, 100, 101, 99, 47, 109, 113, 116, 116, 47, 77, 113, 116, 116, 81, 111, 83, 59, 76, 0, 11, 116, 111, 112, 105, 99, 70, 105, 108, 116, 101, 114, 116, 0, 40, 76, 105, 111, 47, 109, 111, 113, 117, 101, 116, 116, 101, 47, 98, 114, 111, 107, 101, 114, 47, 115, 117, 98, 115, 99, 114, 105, 112, 116, 105, 111, 110, 115, 47, 84, 111, 112, 105, 99, 59, 120, 112, 116, 0, 20, 101, 109, 98, 101, 100,... [1.4.199/0]
    at org.h2.mvstore.DataUtils.newIllegalArgumentException(DataUtils.java:857) ~[?:?]
    at org.h2.mvstore.type.ObjectDataType.deserialize(ObjectDataType.java:376) ~[?:?]
    at org.h2.mvstore.type.ObjectDataType$SerializedObjectType.read(ObjectDataType.java:1547) ~[?:?]
    at org.h2.mvstore.type.ObjectDataType.read(ObjectDataType.java:231) ~[?:?]
    at org.h2.mvstore.type.ObjectDataType.read(ObjectDataType.java:114) ~[?:?]
    at org.h2.mvstore.Page$Leaf.readPayLoad(Page.java:1551) ~[?:?]
    at org.h2.mvstore.Page.read(Page.java:695) ~[?:?]
    at org.h2.mvstore.Page.read(Page.java:238) ~[?:?]
    at org.h2.mvstore.MVStore.readPage(MVStore.java:2187) ~[?:?]
    at org.h2.mvstore.MVMap.readPage(MVMap.java:554) ~[?:?]
    at org.h2.mvstore.MVMap.readOrCreateRootPage(MVMap.java:570) ~[?:?]
    at org.h2.mvstore.MVMap.setRootPos(MVMap.java:564) ~[?:?]
    at org.h2.mvstore.MVStore.openMap(MVStore.java:548) ~[?:?]
    at org.h2.mvstore.MVStore.openMap(MVStore.java:507) ~[?:?]
    at org.h2.mvstore.MVStore.openMap(MVStore.java:488) ~[?:?]
    at io.moquette.persistence.H2SubscriptionsRepository.<init>(H2SubscriptionsRepository.java:22) ~[?:?]
    at io.moquette.persistence.H2Builder.subscriptionsRepository(H2Builder.java:51) ~[?:?]
    at io.moquette.broker.Server.startServer(Server.java:167) ~[?:?]
    at org.openhab.io.mqttembeddedbroker.internal.EmbeddedBrokerService.startEmbeddedServer(EmbeddedBrokerService.java:310) ~[?:?]
    at org.openhab.io.mqttembeddedbroker.internal.EmbeddedBrokerService.initialize(EmbeddedBrokerService.java:195) ~[?:?]
    at org.openhab.io.mqttembeddedbroker.internal.EmbeddedBrokerService.activate(EmbeddedBrokerService.java:159) ~[?:?]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
    at org.apache.felix.scr.impl.inject.methods.BaseMethod.invokeMethod(BaseMethod.java:228) ~[?:?]
    at org.apache.felix.scr.impl.inject.methods.BaseMethod.access$500(BaseMethod.java:41) ~[?:?]
    at org.apache.felix.scr.impl.inject.methods.BaseMethod$Resolved.invoke(BaseMethod.java:664) ~[?:?]
    at org.apache.felix.scr.impl.inject.methods.BaseMethod.invoke(BaseMethod.java:510) ~[?:?]
    at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:317) ~[?:?]
    at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:307) ~[?:?]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:340) ~[?:?]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:114) ~[?:?]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:982) ~[?:?]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:955) ~[?:?]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:900) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212) ~[?:?]
    at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:508) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) ~[?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:624) ~[?:?]
    at com.eclipsesource.jaxrs.publisher.internal.ResourceTracker.addingService(ResourceTracker.java:39) ~[?:?]
    at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941) ~[?:?]
    at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870) ~[?:?]
    at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) ~[?:?]
    at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229) ~[?:?]
    at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:901) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) ~[?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:920) ~[?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) ~[?:?]
    at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225) ~[?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:469) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:906) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:892) ~[?:?]
    at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:128) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:959) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:732) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:666) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:432) ~[?:?]
    at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:665) ~[?:?]
    at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:338) ~[?:?]
    at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:382) ~[?:?]
    at org.apache.felix.scr.impl.Activator.access$200(Activator.java:49) ~[?:?]
    at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:264) ~[?:?]
    at org.apache.felix.scr.impl.AbstractExtender.createExtension(AbstractExtender.java:196) ~[?:?]
    at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:169) ~[?:?]
    at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:49) ~[?:?]
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482) ~[?:?]
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415) ~[?:?]
    at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232) ~[?:?]
    at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444) ~[?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:908) ~[?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) ~[?:?]
    at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) ~[?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:213) ~[?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:120) ~[?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:112) ~[?:?]
    at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:168) ~[?:?]
    at org.eclipse.osgi.container.Module.publishEvent(Module.java:476) ~[?:?]
    at org.eclipse.osgi.container.Module.start(Module.java:467) ~[?:?]
    at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:383) ~[?:?]
    at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:402) ~[?:?]
    at org.apache.karaf.features.internal.service.BundleInstallSupportImpl.startBundle(BundleInstallSupportImpl.java:165) ~[?:?]
    at org.apache.karaf.features.internal.service.FeaturesServiceImpl.startBundle(FeaturesServiceImpl.java:1153) ~[?:?]
    at org.apache.karaf.features.internal.service.Deployer.deploy(Deployer.java:1036) ~[?:?]
    at org.apache.karaf.features.internal.service.FeaturesServiceImpl.doProvision(FeaturesServiceImpl.java:1062) ~[?:?]
    at org.apache.karaf.features.internal.service.FeaturesServiceImpl.lambda$doProvisionInThread$13(FeaturesServiceImpl.java:998) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
    at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: java.lang.ClassNotFoundException: io.moquette.broker.subscriptions.Subscription cannot be found by com.h2database.mvstore_1.4.199
    at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:484) ~[?:?]
    at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:395) ~[?:?]
    at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:387) ~[?:?]
    at org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:150) ~[?:?]
    at java.lang.ClassLoader.loadClass(ClassLoader.java:357) ~[?:?]
    at java.lang.Class.forName0(Native Method) ~[?:?]
    at java.lang.Class.forName(Class.java:348) ~[?:?]
    at java.io.ObjectInputStream.resolveClass(ObjectInputStream.java:686) ~[?:?]
    at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1868) ~[?:?]
    at java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1751) ~[?:?]
    at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:2042) ~[?:?]
    at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1573) ~[?:?]
    at java.io.ObjectInputStream.readObject(ObjectInputStream.java:431) ~[?:?]
    at org.h2.mvstore.type.ObjectDataType.deserialize(ObjectDataType.java:374) ~[?:?]
    ... 96 more

the solution was given to me in this forum thread https://community.openhab.org/t/solved-mqtt-broker-moquette-offline-after-upgrade-to-2-5m3/83074/4

Steps to Reproduce (for Bugs)

  1. upgrade from 2.4 stable to 2.5M3 ???

Context

the affected was to causethe upgrade to break a working mqtt installation

Your Environment

MyRaceData commented 5 years ago

I have had a second incident with this issue caused by restarting OpenHAB. Stopping OpenHAB, deleting the bin file, clearing the cache and restarting OpenHAB caused my broker to be back online

wborn commented 5 years ago

Thanks for reporting the issue! After looking at the stack trace it seems to be a duplicate of #5527. So I'll close this issue now so we can keep the discussion going in a single issue.