search

openhab / openhab-addons

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

[mqtt.homie] Integration tests fail #5905

Closed lolodomo closed 5 years ago

lolodomo commented 5 years ago

Build on Windows 10:

[INFO] --- bnd-testing-maven-plugin:4.2.0:testing (default) @ org.openhab.binding.mqtt.homie.tests ---
[INFO] Matching glob *
08:24:50.515 [main] DEBUG org.eclipse.smarthome.core.common.ThreadPoolManager - Created thread pool 'safeCall' with size 5
08:24:50.577 [main] DEBUG org.eclipse.smarthome.core.internal.i18n.I18nProviderImpl - No language set, setting locale to 'null'.
08:24:50.577 [main] DEBUG org.eclipse.smarthome.core.internal.i18n.I18nProviderImpl - Error setting measurement system for value 'null'.
08:24:50.624 [main] DEBUG org.eclipse.smarthome.core.common.ThreadPoolManager - Created scheduled thread pool 'scheduler' of size 5
08:24:50.655 [main] DEBUG org.eclipse.smarthome.core.common.ThreadPoolManager - Created thread pool 'ConfigStatusService' with size 5
08:24:50.702 [main] DEBUG org.eclipse.smarthome.core.common.ThreadPoolManager - Created scheduled thread pool 'discovery' of size 5
08:24:50.702 [main] DEBUG org.eclipse.smarthome.config.discovery.AbstractDiscoveryService - Background discovery for discovery service 'org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery' enabled.
08:24:50.702 [main] DEBUG org.eclipse.smarthome.config.discovery.AbstractDiscoveryService - Background discovery for discovery service 'org.openhab.binding.mqtt.internal.discovery.MqttServiceDiscoveryService' enabled.
08:24:50.749 [main] DEBUG org.eclipse.smarthome.core.thing.internal.firmware.FirmwareUpdateServiceImpl - Modifying the configuration of the firmware update service.
08:24:50.749 [main] DEBUG org.eclipse.smarthome.core.thing.internal.firmware.FirmwareUpdateServiceImpl - Given time unit null is not supported. Will keep current configuration.
08:24:50.765 [main] DEBUG org.eclipse.smarthome.core.transform.internal.TransformationActivator - Transformation Service has been started.
08:24:50.780 [main] DEBUG org.eclipse.smarthome.core.common.ThreadPoolManager - Created scheduled thread pool 'file-processing' of size 5
08:24:50.905 [OH-file-processing-4] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/config/number-channel-config.xml' in module 'org.openhab.binding.mqtt.generic'...
08:24:50.905 [OH-file-processing-3] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/config/i18n.xml' in module 'org.openhab.core'...
08:24:50.905 [OH-file-processing-2] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/config/config.xml' in module 'org.openhab.core.config.discovery'...
08:24:50.905 [OH-file-processing-5] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/config/homie-channel-config.xml' in module 'org.openhab.binding.mqtt.homie'...
08:24:50.905 [OH-file-processing-1] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/binding/binding.xml' in module 'org.openhab.binding.mqtt'...
08:24:50.921 [main] INFO org.openhab.io.mqttembeddedbroker.internal.EmbeddedBrokerService - Broker persistence file: mqttembedded.bin
08:24:50.921 [main] DEBUG org.openhab.io.mqttembeddedbroker.internal.EmbeddedBrokerService - Broker anonymous access enabled
08:24:50.937 [main] DEBUG io.moquette.broker.Server - Configuring Using persistent store file, path: D:\dev\openhab2\git\openhab2-addons\itests\org.openhab.binding.mqtt.homie.tests\target\test\tmp\testing\itest\userdata\mqttembedded.bin
08:24:50.937 [main] INFO io.moquette.broker.Server - Configuring message interceptors...
08:24:50.937 [main] INFO io.moquette.interception.BrokerInterceptor - Initializing broker interceptor. InterceptorIds=[]
08:24:50.937 [main] DEBUG io.moquette.broker.Server - Initialized MQTT protocol processor
08:24:50.937 [main] INFO io.moquette.broker.Server - Using default SSL context creator
08:24:50.937 [main] DEBUG io.moquette.broker.Server - Configuring MQTT authenticator
08:24:50.937 [main] INFO io.moquette.broker.Server - An io.moquette.broker.security.AcceptAllAuthenticator authenticator instance will be used
08:24:50.937 [main] DEBUG io.moquette.broker.Server - Configuring MQTT authorizator policy
08:24:50.937 [main] INFO io.moquette.broker.Server - Authorizator policy io.moquette.broker.security.PermitAllAuthorizatorPolicy instance will be used
08:24:50.937 [main] INFO io.moquette.persistence.H2Builder - Initializing H2 store
08:24:50.952 [OH-file-processing-4] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/config/string-channel-config.xml' in module 'org.openhab.binding.mqtt.generic'...
08:24:50.952 [OH-file-processing-4] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/config/switch-channel-config.xml' in module 'org.openhab.binding.mqtt.generic'...
08:24:50.952 [OH-file-processing-4] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/config/rollershutter-channel-config.xml' in module 'org.openhab.binding.mqtt.generic'...
08:24:50.968 [OH-file-processing-4] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/config/color-channel-config.xml' in module 'org.openhab.binding.mqtt.generic'...
08:24:50.968 [OH-file-processing-2] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/config/brokerConnectionInstance.xml' in module 'org.openhab.core.io.transport.mqtt'...
08:24:50.968 [OH-file-processing-3] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/config/networkinterface.xml' in module 'org.openhab.core'...
08:24:50.968 [OH-file-processing-3] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/config/config.xml' in module 'org.openhab.core.thing'...
08:24:50.983 [OH-file-processing-4] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/config/dimmer-channel-config.xml' in module 'org.openhab.binding.mqtt.generic'...
08:24:50.983 [OH-file-processing-3] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/config/offsetProfile.xml' in module 'org.openhab.core.thing'...
08:24:50.983 [main] INFO io.moquette.broker.subscriptions.CTrieSubscriptionDirectory - Initializing CTrie
08:24:50.983 [OH-file-processing-4] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/thing/thing-types.xml' in module 'org.openhab.binding.mqtt'...
08:24:50.983 [OH-file-processing-3] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/thing/generic-thing.xml' in module 'org.openhab.binding.mqtt.generic'...
08:24:50.983 [OH-file-processing-5] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/thing/homie-thing.xml' in module 'org.openhab.binding.mqtt.homie'...
08:24:50.983 [main] INFO io.moquette.broker.subscriptions.CTrieSubscriptionDirectory - Initializing subscriptions store...
08:24:50.983 [main] DEBUG io.moquette.persistence.H2SubscriptionsRepository - Retrieving existing subscriptions
08:24:50.983 [main] DEBUG io.moquette.persistence.H2SubscriptionsRepository - Loaded 0 subscriptions
08:24:50.999 [OH-file-processing-1] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/config/config.xml' in module 'org.openhab.io.mqttembeddedbroker'...
08:24:50.999 [OH-file-processing-3] DEBUG org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker - Reading the XML document '/ESH-INF/thing/channels.xml' in module 'org.openhab.binding.mqtt.generic'...
08:24:51.062 [main] DEBUG io.netty.util.internal.logging.InternalLoggerFactory - Using SLF4J as the default logging framework
08:24:51.062 [main] DEBUG io.netty.util.internal.PlatformDependent - Platform: Windows
08:24:51.062 [main] DEBUG io.netty.util.internal.PlatformDependent0 - -Dio.netty.noUnsafe: false
08:24:51.062 [main] DEBUG io.netty.util.internal.PlatformDependent0 - Java version: 8
08:24:51.062 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: unavailable
java.lang.NoClassDefFoundError: sun/misc/Unsafe
        at io.netty.util.internal.PlatformDependent0$1.run(PlatformDependent0.java:87)
        at java.security.AccessController.doPrivileged(Native Method)
        at io.netty.util.internal.PlatformDependent0.<clinit>(PlatformDependent0.java:83)
        at io.netty.util.internal.PlatformDependent.isAndroid(PlatformDependent.java:213)
        at io.netty.util.internal.PlatformDependent.<clinit>(PlatformDependent.java:81)
        at io.netty.util.ConstantPool.<init>(ConstantPool.java:32)
        at io.netty.util.AttributeKey$1.<init>(AttributeKey.java:27)
        at io.netty.util.AttributeKey.<clinit>(AttributeKey.java:27)
        at io.moquette.broker.NewNettyMQTTHandler.<clinit>(NewNettyMQTTHandler.java:37)
        at io.moquette.broker.Server.startServer(Server.java:186)
        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:341)
        at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:114)
        at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:983)
        at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:956)
        at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:756)
        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:339)
        at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:381)
        at org.apache.felix.scr.impl.Activator.access$200(Activator.java:49)
        at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:263)
        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:488)
        at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:1)
        at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232)
        at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:450)
        at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:911)
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:233)
        at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151)
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:233)
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:140)
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:132)
        at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:194)
        at org.eclipse.osgi.container.Module.publishEvent(Module.java:479)
        at org.eclipse.osgi.container.Module.start(Module.java:470)
        at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:431)
        at aQute.launcher.Launcher.startBundles(Launcher.java:528)
        at aQute.launcher.Launcher.activate(Launcher.java:427)
        at aQute.launcher.Launcher.run(Launcher.java:306)
        at aQute.launcher.Launcher.main(Launcher.java:152)
Caused by: java.lang.ClassNotFoundException: sun.misc.Unsafe cannot be found by io.netty.common_4.1.34.Final
        at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:511)
        at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:422)
        at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:414)
        at org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:153)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
        ... 56 common frames omitted
08:24:51.062 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.DirectByteBuffer.<init>(long, int): unavailable
08:24:51.062 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.tmpdir: C:\Users\Laurent\AppData\Local\Temp (java.io.tmpdir)
08:24:51.062 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
08:24:51.062 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.maxDirectMemory: -1 bytes
08:24:51.062 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1
08:24:51.062 [main] DEBUG io.netty.util.internal.CleanerJava6 - java.nio.ByteBuffer.cleaner(): available
08:24:51.062 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false
08:24:51.062 [main] DEBUG io.moquette.broker.NewNettyAcceptor - Initializing Netty acceptor
08:24:51.062 [main] INFO io.moquette.broker.NewNettyAcceptor - Netty is using NIO
08:24:51.062 [main] DEBUG io.netty.channel.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 8
08:24:51.077 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.noKeySetOptimization: false
08:24:51.077 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
08:24:51.077 [main] DEBUG io.netty.util.internal.PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: unavailable
08:24:51.108 [main] DEBUG io.moquette.broker.NewNettyAcceptor - Configuring TCP MQTT transport
08:24:51.108 [main] DEBUG io.moquette.broker.NewNettyAcceptor - Initializing integration. Protocol=TCP MQTT
08:24:51.108 [main] DEBUG io.moquette.broker.NewNettyAcceptor - Binding integration. host=0.0.0.0, port=1883
08:24:51.108 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.processId: 16148 (auto-detected)
08:24:51.124 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv4Stack: false
08:24:51.124 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv6Addresses: false
08:24:51.233 [main] DEBUG io.netty.util.NetUtil - Loopback interface: lo (Software Loopback Interface 1, 127.0.0.1)
08:24:51.233 [main] DEBUG io.netty.util.NetUtil - Failed to get SOMAXCONN from sysctl and file \proc\sys\net\core\somaxconn. Default: 200
08:24:51.358 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.machineId: 9c:5c:8e:ff:fe:20:3a:21 (auto-detected)
08:24:51.358 [main] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
08:24:51.358 [main] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
08:24:51.358 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.level: simple
08:24:51.358 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.targetRecords: 4
08:24:51.374 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 8
08:24:51.374 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 8
08:24:51.374 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192
08:24:51.374 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11
08:24:51.374 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216
08:24:51.374 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.tinyCacheSize: 512
08:24:51.374 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256
08:24:51.374 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64
08:24:51.374 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
08:24:51.374 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192
08:24:51.374 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: true
08:24:51.374 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
08:24:51.390 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: pooled
08:24:51.390 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 0
08:24:51.390 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384
08:24:51.390 [main] INFO io.moquette.broker.NewNettyAcceptor - Server bound to host=0.0.0.0, port=1883, protocol=TCP MQTT
08:24:51.390 [main] DEBUG io.moquette.broker.NewNettyAcceptor - Configuring Websocket MQTT transport
08:24:51.390 [main] INFO io.moquette.broker.NewNettyAcceptor - Property websocket_port has been setted to disabled. Websocket MQTT will be disabled
08:24:51.390 [main] INFO io.moquette.broker.Server - Moquette integration has been started successfully in 453 ms
08:24:51.390 [main] INFO io.moquette.broker.Server - Adding MQTT message interceptor. InterceptorId=logger
08:24:51.390 [main] INFO io.moquette.interception.BrokerInterceptor - Adding MQTT message interceptor. InterceptorId=logger, handledMessageTypes=[class io.moquette.interception.messages.InterceptConnectMessage, class io.moquette.interception.messages.InterceptDisconnectMessage]
08:24:51.390 [nioEventLoopGroup-2-1] DEBUG io.moquette.broker.NewNettyAcceptor - bound TCP MQTT port: 1883
08:24:51.405 [main] DEBUG org.openhab.io.mqttembeddedbroker.internal.EmbeddedBrokerService - Embedded broker connection still connecting
08:24:51.405 [nioEventLoopGroup-3-1] DEBUG io.moquette.broker.AutoFlushHandler - Initializing autoflush handler on channel [id: 0x022f55af, L:/127.0.0.1:1883 - R:/127.0.0.1:49680] Cid: null
08:24:51.436 [main] INFO org.eclipse.smarthome.io.transport.mqtt.MqttBrokerConnection - Starting MQTT broker connection to 'localhost' with clientid embedded-mqtt-broker and file store 'D:\dev\openhab2\git\openhab2-addons\itests\org.openhab.binding.mqtt.homie.tests\target\test\tmp\testing\itest\userdata\mqtt\localhost'
08:24:51.436 [nioEventLoopGroup-3-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxCapacityPerThread: 4096
08:24:51.436 [nioEventLoopGroup-3-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxSharedCapacityFactor: 2
08:24:51.436 [nioEventLoopGroup-3-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.linkCapacity: 16
08:24:51.436 [nioEventLoopGroup-3-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.ratio: 8
08:24:51.436 [nioEventLoopGroup-3-2] DEBUG io.moquette.broker.AutoFlushHandler - Initializing autoflush handler on channel [id: 0x213ec1a7, L:/127.0.0.1:1883 - R:/127.0.0.1:49681] Cid: null
08:24:51.452 [nioEventLoopGroup-3-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.checkAccessible: true
08:24:51.452 [nioEventLoopGroup-3-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.checkBounds: true
08:24:51.452 [nioEventLoopGroup-3-1] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@626f14df
08:24:51.546 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.internal.items.ManagedMetadataProviderImpl" has been added.
08:24:51.546 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.items.ManagedItemProvider" has been added.
08:24:51.546 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.thing.ManagedThingProvider" has been added.
08:24:51.546 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.thing.link.ManagedItemChannelLinkProvider" has been added.
08:24:51.561 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.thing.internal.ChannelItemProvider" has been added.
08:24:51.577 [main] DEBUG org.eclipse.smarthome.core.common.ThreadPoolManager - Created scheduled thread pool 'thingManager' of size 5
08:24:51.577 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' added
08:24:51.577 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' added
08:24:51.577 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttBrokerHandlerFactory' added
08:24:51.577 [main] DEBUG org.eclipse.smarthome.core.common.ThreadPoolManager - Created scheduled thread pool 'thingLinkManager' of size 5
08:24:51.593 [main] INFO org.eclipse.smarthome.config.discovery.internal.PersistentInbox - Added new thing 'mqtt:systemBroker:embedded-mqtt-broker' to inbox.
08:24:51.780 [nioEventLoopGroup-3-2] INFO io.moquette.broker.metrics.MQTTMessageLogger - C->B CONNECT <null>
08:24:51.780 [nioEventLoopGroup-3-2] DEBUG io.moquette.broker.MQTTConnection - Received MQTT message, type: CONNECT, channel: [id: 0x213ec1a7, L:/127.0.0.1:1883 - R:/127.0.0.1:49681]
08:24:51.780 [nioEventLoopGroup-3-2] DEBUG io.moquette.broker.metrics.MQTTMessageLogger - C<-B CONNACK <null>
08:24:51.796 [nioEventLoopGroup-3-2] DEBUG io.moquette.broker.MQTTConnection - Connection has been configured CId=embedded-mqtt-broker, keepAlive=60, removeTemporaryQoS2=true, idleTime=90
08:24:51.796 [nioEventLoopGroup-3-2] DEBUG io.moquette.broker.InflightResender - Initializing autoflush handler on channel [id: 0x213ec1a7, L:/127.0.0.1:1883 - R:/127.0.0.1:49681]
08:24:51.796 [nioEventLoopGroup-3-2] DEBUG io.moquette.interception.BrokerInterceptor - Sending MQTT CONNECT message to interceptor. CId=embedded-mqtt-broker, interceptorId=logger
08:24:51.796 [pool-3-thread-1] DEBUG org.openhab.io.mqttembeddedbroker.internal.EmbeddedBrokerService - MQTT Client connected: embedded-mqtt-broker
08:24:51.796 [MQTT Call: embedded-mqtt-broker] DEBUG org.openhab.io.mqttembeddedbroker.internal.EmbeddedBrokerService - Embedded broker connection connected
08:24:51.968 [main] WARN org.openhab.binding.mqtt.EmbeddedBrokerTools - waitForConnection CONNECTED
08:24:51.968 [main] INFO org.eclipse.smarthome.io.transport.mqtt.MqttBrokerConnection - Starting MQTT broker connection to 'localhost' with clientid homie and file store 'userdata\mqtt\localhost'
08:24:51.968 [nioEventLoopGroup-3-3] DEBUG io.moquette.broker.AutoFlushHandler - Initializing autoflush handler on channel [id: 0x784cf99c, L:/127.0.0.1:1883 - R:/127.0.0.1:49682] Cid: null
08:24:52.186 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ManagedMetadataProviderImpl" has been removed.
08:24:52.186 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ManagedItemProvider" has been removed.
08:24:52.202 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ManagedThingProvider" has been removed.
08:24:52.202 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' removed
08:24:52.202 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' removed
08:24:52.202 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttBrokerHandlerFactory' removed
08:24:52.202 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' removed
08:24:52.202 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' removed
08:24:52.202 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttBrokerHandlerFactory' removed
08:24:52.218 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ChannelItemProvider" has been removed.
08:24:52.218 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ManagedItemChannelLinkProvider" has been removed.
TEST retrieveOneAttribute(org.openhab.binding.mqtt.HomieImplementationTest) <<< ERROR: null
java.util.concurrent.TimeoutException
        at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1771)
        at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
        at org.openhab.binding.mqtt.HomieImplementationTest.setUp(HomieImplementationTest.java:108)
        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.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
        at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:24)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
        at junit.framework.TestSuite.runTest(TestSuite.java:252)
        at junit.framework.TestSuite.run(TestSuite.java:247)
        at aQute.junit.Activator.test(Activator.java:340)
        at aQute.junit.Activator.automatic(Activator.java:236)
        at aQute.junit.Activator.run(Activator.java:177)
        at aQute.launcher.Launcher.lambda$serviceChanged$0(Launcher.java:1385)
        at aQute.launcher.Launcher.run(Launcher.java:352)
        at aQute.launcher.Launcher.main(Launcher.java:152)
TEST retrieveOneAttribute(org.openhab.binding.mqtt.HomieImplementationTest) <<< ERROR: null
java.lang.NullPointerException
        at org.openhab.binding.mqtt.HomieImplementationTest.tearDown(HomieImplementationTest.java:162)
        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.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:33)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
        at junit.framework.TestSuite.runTest(TestSuite.java:252)
        at junit.framework.TestSuite.run(TestSuite.java:247)
        at aQute.junit.Activator.test(Activator.java:340)
        at aQute.junit.Activator.automatic(Activator.java:236)
        at aQute.junit.Activator.run(Activator.java:177)
        at aQute.launcher.Launcher.lambda$serviceChanged$0(Launcher.java:1385)
        at aQute.launcher.Launcher.run(Launcher.java:352)
        at aQute.launcher.Launcher.main(Launcher.java:152)
08:24:52.233 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.internal.items.ManagedMetadataProviderImpl" has been added.
08:24:52.233 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.items.ManagedItemProvider" has been added.
08:24:52.233 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.thing.ManagedThingProvider" has been added.
08:24:52.233 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.thing.link.ManagedItemChannelLinkProvider" has been added.
08:24:52.249 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.thing.internal.ChannelItemProvider" has been added.
08:24:52.249 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' added
08:24:52.249 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' added
08:24:52.249 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttBrokerHandlerFactory' added
08:24:52.249 [main] INFO org.eclipse.smarthome.config.discovery.internal.PersistentInbox - Added new thing 'mqtt:systemBroker:embedded-mqtt-broker' to inbox.
08:24:52.249 [main] WARN org.openhab.binding.mqtt.EmbeddedBrokerTools - waitForConnection CONNECTED
08:24:52.249 [main] INFO org.eclipse.smarthome.io.transport.mqtt.MqttBrokerConnection - Starting MQTT broker connection to 'localhost' with clientid homie and file store 'userdata\mqtt\localhost'
08:24:52.249 [nioEventLoopGroup-3-4] DEBUG io.moquette.broker.AutoFlushHandler - Initializing autoflush handler on channel [id: 0x177c6025, L:/127.0.0.1:1883 - R:/127.0.0.1:49683] Cid: null
08:24:52.296 [nioEventLoopGroup-3-3] INFO io.moquette.broker.metrics.MQTTMessageLogger - C->B CONNECT <null>
08:24:52.296 [nioEventLoopGroup-3-3] DEBUG io.moquette.broker.MQTTConnection - Received MQTT message, type: CONNECT, channel: [id: 0x784cf99c, L:/127.0.0.1:1883 - R:/127.0.0.1:49682]
08:24:52.296 [nioEventLoopGroup-3-3] DEBUG io.moquette.broker.metrics.MQTTMessageLogger - C<-B CONNACK <null>
08:24:52.311 [nioEventLoopGroup-3-3] DEBUG io.moquette.broker.MQTTConnection - Connection has been configured CId=homie, keepAlive=60, removeTemporaryQoS2=true, idleTime=90
08:24:52.311 [nioEventLoopGroup-3-3] DEBUG io.moquette.broker.InflightResender - Initializing autoflush handler on channel [id: 0x784cf99c, L:/127.0.0.1:1883 - R:/127.0.0.1:49682]
08:24:52.311 [nioEventLoopGroup-3-3] DEBUG io.moquette.interception.BrokerInterceptor - Sending MQTT CONNECT message to interceptor. CId=homie, interceptorId=logger
08:24:52.311 [nioEventLoopGroup-3-3] INFO io.moquette.broker.metrics.MQTTMessageLogger - Channel closed <homie>
08:24:52.311 [nioEventLoopGroup-3-3] INFO io.moquette.broker.MQTTConnection - Notifying connection lost event. CId: homie, channel: [id: 0x784cf99c, L:/127.0.0.1:1883 ! R:/127.0.0.1:49682]
08:24:52.311 [pool-3-thread-1] DEBUG org.openhab.io.mqttembeddedbroker.internal.EmbeddedBrokerService - MQTT Client connected: homie
08:24:52.311 [nioEventLoopGroup-3-5] DEBUG io.moquette.broker.AutoFlushHandler - Initializing autoflush handler on channel [id: 0xd88ead35, L:/127.0.0.1:1883 - R:/127.0.0.1:49684] Cid: null
08:24:52.468 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ManagedMetadataProviderImpl" has been removed.
08:24:52.468 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ManagedItemProvider" has been removed.
08:24:52.468 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ManagedThingProvider" has been removed.
08:24:52.468 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' removed
08:24:52.468 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' removed
08:24:52.468 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttBrokerHandlerFactory' removed
08:24:52.468 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' removed
08:24:52.468 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' removed
08:24:52.468 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttBrokerHandlerFactory' removed
08:24:52.468 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ChannelItemProvider" has been removed.
08:24:52.483 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ManagedItemChannelLinkProvider" has been removed.
TEST parseHomieTree(org.openhab.binding.mqtt.HomieImplementationTest) <<< ERROR: null
java.util.concurrent.TimeoutException
        at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1771)
        at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
        at org.openhab.binding.mqtt.HomieImplementationTest.setUp(HomieImplementationTest.java:108)
        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.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
        at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:24)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
        at junit.framework.TestSuite.runTest(TestSuite.java:252)
        at junit.framework.TestSuite.run(TestSuite.java:247)
        at aQute.junit.Activator.test(Activator.java:340)
        at aQute.junit.Activator.automatic(Activator.java:236)
        at aQute.junit.Activator.run(Activator.java:177)
        at aQute.launcher.Launcher.lambda$serviceChanged$0(Launcher.java:1385)
        at aQute.launcher.Launcher.run(Launcher.java:352)
        at aQute.launcher.Launcher.main(Launcher.java:152)
TEST parseHomieTree(org.openhab.binding.mqtt.HomieImplementationTest) <<< ERROR: null
java.lang.NullPointerException
        at org.openhab.binding.mqtt.HomieImplementationTest.tearDown(HomieImplementationTest.java:162)
        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.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:33)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
        at junit.framework.TestSuite.runTest(TestSuite.java:252)
        at junit.framework.TestSuite.run(TestSuite.java:247)
        at aQute.junit.Activator.test(Activator.java:340)
        at aQute.junit.Activator.automatic(Activator.java:236)
        at aQute.junit.Activator.run(Activator.java:177)
        at aQute.launcher.Launcher.lambda$serviceChanged$0(Launcher.java:1385)
        at aQute.launcher.Launcher.run(Launcher.java:352)
        at aQute.launcher.Launcher.main(Launcher.java:152)
08:24:52.483 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.internal.items.ManagedMetadataProviderImpl" has been added.
08:24:52.483 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.items.ManagedItemProvider" has been added.
08:24:52.483 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.thing.ManagedThingProvider" has been added.
08:24:52.483 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.thing.link.ManagedItemChannelLinkProvider" has been added.
08:24:52.499 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.thing.internal.ChannelItemProvider" has been added.
08:24:52.499 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' added
08:24:52.499 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' added
08:24:52.499 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttBrokerHandlerFactory' added
08:24:52.499 [main] INFO org.eclipse.smarthome.config.discovery.internal.PersistentInbox - Added new thing 'mqtt:systemBroker:embedded-mqtt-broker' to inbox.
08:24:52.499 [main] WARN org.openhab.binding.mqtt.EmbeddedBrokerTools - waitForConnection CONNECTED
08:24:52.499 [main] INFO org.eclipse.smarthome.io.transport.mqtt.MqttBrokerConnection - Starting MQTT broker connection to 'localhost' with clientid homie and file store 'userdata\mqtt\localhost'
08:24:52.514 [nioEventLoopGroup-3-6] DEBUG io.moquette.broker.AutoFlushHandler - Initializing autoflush handler on channel [id: 0x17a32dbd, L:/127.0.0.1:1883 - R:/127.0.0.1:49685] Cid: null
08:24:52.577 [nioEventLoopGroup-3-4] INFO io.moquette.broker.metrics.MQTTMessageLogger - C->B CONNECT <null>
08:24:52.577 [nioEventLoopGroup-3-4] DEBUG io.moquette.broker.MQTTConnection - Received MQTT message, type: CONNECT, channel: [id: 0x177c6025, L:/127.0.0.1:1883 - R:/127.0.0.1:49683]
08:24:52.577 [nioEventLoopGroup-3-4] DEBUG io.moquette.broker.metrics.MQTTMessageLogger - C<-B CONNACK <null>
08:24:52.608 [nioEventLoopGroup-3-4] DEBUG io.moquette.broker.MQTTConnection - Connection has been configured CId=homie, keepAlive=60, removeTemporaryQoS2=true, idleTime=90
08:24:52.608 [nioEventLoopGroup-3-4] DEBUG io.moquette.broker.InflightResender - Initializing autoflush handler on channel [id: 0x177c6025, L:/127.0.0.1:1883 - R:/127.0.0.1:49683]
08:24:52.608 [nioEventLoopGroup-3-4] DEBUG io.moquette.interception.BrokerInterceptor - Sending MQTT CONNECT message to interceptor. CId=homie, interceptorId=logger
08:24:52.608 [nioEventLoopGroup-3-4] INFO io.moquette.broker.metrics.MQTTMessageLogger - Channel closed <homie>
08:24:52.608 [nioEventLoopGroup-3-4] INFO io.moquette.broker.MQTTConnection - Notifying connection lost event. CId: homie, channel: [id: 0x177c6025, L:/127.0.0.1:1883 ! R:/127.0.0.1:49683]
08:24:52.608 [pool-3-thread-1] DEBUG org.openhab.io.mqttembeddedbroker.internal.EmbeddedBrokerService - MQTT Client connected: homie
08:24:52.608 [nioEventLoopGroup-3-7] DEBUG io.moquette.broker.AutoFlushHandler - Initializing autoflush handler on channel [id: 0x5b4dd471, L:/127.0.0.1:1883 - R:/127.0.0.1:49686] Cid: null
08:24:52.639 [nioEventLoopGroup-3-5] INFO io.moquette.broker.metrics.MQTTMessageLogger - C->B CONNECT <null>
08:24:52.639 [nioEventLoopGroup-3-5] DEBUG io.moquette.broker.MQTTConnection - Received MQTT message, type: CONNECT, channel: [id: 0xd88ead35, L:/127.0.0.1:1883 - R:/127.0.0.1:49684]
08:24:52.639 [nioEventLoopGroup-3-5] DEBUG io.moquette.broker.metrics.MQTTMessageLogger - C<-B CONNACK <null>
08:24:52.655 [nioEventLoopGroup-3-5] DEBUG io.moquette.broker.MQTTConnection - Connection has been configured CId=homie, keepAlive=60, removeTemporaryQoS2=true, idleTime=90
08:24:52.655 [nioEventLoopGroup-3-5] DEBUG io.moquette.broker.InflightResender - Initializing autoflush handler on channel [id: 0xd88ead35, L:/127.0.0.1:1883 - R:/127.0.0.1:49684]
08:24:52.655 [nioEventLoopGroup-3-5] DEBUG io.moquette.interception.BrokerInterceptor - Sending MQTT CONNECT message to interceptor. CId=homie, interceptorId=logger
08:24:52.655 [pool-3-thread-1] DEBUG org.openhab.io.mqttembeddedbroker.internal.EmbeddedBrokerService - MQTT Client connected: homie
08:24:52.717 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ManagedMetadataProviderImpl" has been removed.
08:24:52.717 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ManagedItemProvider" has been removed.
08:24:52.717 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ManagedThingProvider" has been removed.
08:24:52.717 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' removed
08:24:52.717 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' removed
08:24:52.717 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttBrokerHandlerFactory' removed
08:24:52.717 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' removed
08:24:52.717 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' removed
08:24:52.717 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttBrokerHandlerFactory' removed
08:24:52.717 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ChannelItemProvider" has been removed.
08:24:52.717 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ManagedItemChannelLinkProvider" has been removed.
TEST retrieveAttributes(org.openhab.binding.mqtt.HomieImplementationTest) <<< ERROR: null
java.util.concurrent.TimeoutException
        at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1771)
        at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
        at org.openhab.binding.mqtt.HomieImplementationTest.setUp(HomieImplementationTest.java:108)
        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.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
        at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:24)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
        at junit.framework.TestSuite.runTest(TestSuite.java:252)
        at junit.framework.TestSuite.run(TestSuite.java:247)
        at aQute.junit.Activator.test(Activator.java:340)
        at aQute.junit.Activator.automatic(Activator.java:236)
        at aQute.junit.Activator.run(Activator.java:177)
        at aQute.launcher.Launcher.lambda$serviceChanged$0(Launcher.java:1385)
        at aQute.launcher.Launcher.run(Launcher.java:352)
        at aQute.launcher.Launcher.main(Launcher.java:152)
TEST retrieveAttributes(org.openhab.binding.mqtt.HomieImplementationTest) <<< ERROR: null
java.lang.NullPointerException
        at org.openhab.binding.mqtt.HomieImplementationTest.tearDown(HomieImplementationTest.java:162)
        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.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:33)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
        at junit.framework.TestSuite.runTest(TestSuite.java:252)
        at junit.framework.TestSuite.run(TestSuite.java:247)
        at aQute.junit.Activator.test(Activator.java:340)
        at aQute.junit.Activator.automatic(Activator.java:236)
        at aQute.junit.Activator.run(Activator.java:177)
        at aQute.launcher.Launcher.lambda$serviceChanged$0(Launcher.java:1385)
        at aQute.launcher.Launcher.run(Launcher.java:352)
        at aQute.launcher.Launcher.main(Launcher.java:152)
08:24:52.733 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.internal.items.ManagedMetadataProviderImpl" has been added.
08:24:52.733 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.items.ManagedItemProvider" has been added.
08:24:52.733 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.thing.ManagedThingProvider" has been added.
08:24:52.733 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.thing.link.ManagedItemChannelLinkProvider" has been added.
08:24:52.749 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "org.eclipse.smarthome.core.thing.internal.ChannelItemProvider" has been added.
08:24:52.749 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' added
08:24:52.749 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' added
08:24:52.749 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttBrokerHandlerFactory' added
08:24:52.749 [main] INFO org.eclipse.smarthome.config.discovery.internal.PersistentInbox - Added new thing 'mqtt:systemBroker:embedded-mqtt-broker' to inbox.
08:24:52.749 [main] WARN org.openhab.binding.mqtt.EmbeddedBrokerTools - waitForConnection CONNECTED
08:24:52.749 [main] INFO org.eclipse.smarthome.io.transport.mqtt.MqttBrokerConnection - Starting MQTT broker connection to 'localhost' with clientid homie and file store 'userdata\mqtt\localhost'
08:24:52.749 [nioEventLoopGroup-3-8] DEBUG io.moquette.broker.AutoFlushHandler - Initializing autoflush handler on channel [id: 0xad1ad7c8, L:/127.0.0.1:1883 - R:/127.0.0.1:49687] Cid: null
08:24:52.952 [nioEventLoopGroup-3-6] INFO io.moquette.broker.metrics.MQTTMessageLogger - C->B CONNECT <null>
08:24:52.952 [nioEventLoopGroup-3-6] DEBUG io.moquette.broker.MQTTConnection - Received MQTT message, type: CONNECT, channel: [id: 0x17a32dbd, L:/127.0.0.1:1883 - R:/127.0.0.1:49685]
08:24:52.952 [nioEventLoopGroup-3-7] INFO io.moquette.broker.metrics.MQTTMessageLogger - C->B CONNECT <null>
08:24:52.952 [nioEventLoopGroup-3-7] DEBUG io.moquette.broker.MQTTConnection - Received MQTT message, type: CONNECT, channel: [id: 0x5b4dd471, L:/127.0.0.1:1883 - R:/127.0.0.1:49686]
08:24:52.952 [nioEventLoopGroup-3-6] DEBUG io.moquette.broker.metrics.MQTTMessageLogger - C<-B CONNACK <null>
08:24:52.952 [nioEventLoopGroup-3-7] DEBUG io.moquette.broker.metrics.MQTTMessageLogger - C<-B CONNACK <null>
08:24:52.952 [nioEventLoopGroup-3-5] INFO io.moquette.broker.metrics.MQTTMessageLogger - Channel closed <homie>
08:24:52.952 [nioEventLoopGroup-3-5] INFO io.moquette.broker.MQTTConnection - Notifying connection lost event. CId: homie, channel: [id: 0xd88ead35, L:/127.0.0.1:1883 ! R:/127.0.0.1:49684]
08:24:52.952 [nioEventLoopGroup-3-6] DEBUG io.moquette.broker.MQTTConnection - Connection has been configured CId=homie, keepAlive=60, removeTemporaryQoS2=true, idleTime=90
08:24:52.952 [nioEventLoopGroup-3-7] DEBUG io.moquette.broker.MQTTConnection - Connection has been configured CId=homie, keepAlive=60, removeTemporaryQoS2=true, idleTime=90
08:24:52.952 [nioEventLoopGroup-3-7] DEBUG io.moquette.broker.InflightResender - Initializing autoflush handler on channel [id: 0x5b4dd471, L:/127.0.0.1:1883 - R:/127.0.0.1:49686]
08:24:52.952 [nioEventLoopGroup-3-6] DEBUG io.moquette.broker.InflightResender - Initializing autoflush handler on channel [id: 0x17a32dbd, L:/127.0.0.1:1883 - R:/127.0.0.1:49685]
08:24:52.952 [nioEventLoopGroup-3-7] DEBUG io.moquette.interception.BrokerInterceptor - Sending MQTT CONNECT message to interceptor. CId=homie, interceptorId=logger
08:24:52.952 [nioEventLoopGroup-3-6] DEBUG io.moquette.interception.BrokerInterceptor - Sending MQTT CONNECT message to interceptor. CId=homie, interceptorId=logger
08:24:52.952 [nioEventLoopGroup-3-6] INFO io.moquette.broker.metrics.MQTTMessageLogger - Channel closed <homie>
08:24:52.952 [nioEventLoopGroup-3-6] INFO io.moquette.broker.MQTTConnection - Notifying connection lost event. CId: homie, channel: [id: 0x17a32dbd, L:/127.0.0.1:1883 ! R:/127.0.0.1:49685]
08:24:52.952 [pool-3-thread-1] DEBUG org.openhab.io.mqttembeddedbroker.internal.EmbeddedBrokerService - MQTT Client connected: homie
08:24:52.952 [pool-3-thread-1] DEBUG org.openhab.io.mqttembeddedbroker.internal.EmbeddedBrokerService - MQTT Client connected: homie
08:24:52.952 [nioEventLoopGroup-3-6] ERROR io.moquette.broker.NewNettyMQTTHandler - Unexpected exception while processing MQTT message. Closing Netty channel. CId=homie
java.lang.NullPointerException: null
        at io.moquette.broker.MQTTConnection.handleConnectionLost(MQTTConnection.java:254)
        at io.moquette.broker.NewNettyMQTTHandler.channelInactive(NewNettyMQTTHandler.java:82)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:242)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:228)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:221)
        at io.moquette.broker.metrics.MQTTMessageLogger.channelInactive(MQTTMessageLogger.java:109)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:242)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:228)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:221)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:242)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:228)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:221)
        at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:390)
        at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:355)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:242)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:228)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:221)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
        at io.moquette.broker.AutoFlushHandler.channelInactive(AutoFlushHandler.java:90)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:242)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:228)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:221)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:242)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:228)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:221)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:242)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:228)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:221)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
        at io.netty.handler.timeout.IdleStateHandler.channelInactive(IdleStateHandler.java:277)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:242)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:228)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:221)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
        at io.moquette.broker.InflightResender.channelInactive(InflightResender.java:123)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:242)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:228)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:221)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1403)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:242)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:228)
        at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:912)
        at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:827)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:495)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.lang.Thread.run(Thread.java:748)
08:24:52.967 [MQTT Rec: homie] INFO org.eclipse.smarthome.io.transport.mqtt.internal.ClientCallback - MQTT connection to 'localhost' was lost
org.eclipse.paho.client.mqttv3.MqttException: Connexion perdue
        at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:189)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.io.EOFException: null
        at java.io.DataInputStream.readByte(DataInputStream.java:267)
        at org.eclipse.paho.client.mqttv3.internal.wire.MqttInputStream.readMqttWireMessage(MqttInputStream.java:92)
        at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:136)
        ... 1 common frames omitted
08:24:52.967 [nioEventLoopGroup-3-1] DEBUG io.moquette.broker.AutoFlushHandler - Initializing autoflush handler on channel [id: 0x7f50b727, L:/127.0.0.1:1883 - R:/127.0.0.1:49688] Cid: null
08:24:52.967 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ManagedMetadataProviderImpl" has been removed.
08:24:52.967 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ManagedItemProvider" has been removed.
08:24:52.967 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ManagedThingProvider" has been removed.
08:24:52.967 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' removed
08:24:52.967 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' removed
08:24:52.967 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttBrokerHandlerFactory' removed
08:24:52.967 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' removed
08:24:52.967 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttThingHandlerFactory' removed
08:24:52.967 [main] DEBUG org.eclipse.smarthome.core.thing.internal.ThingManagerImpl - Thing handler factory 'MqttBrokerHandlerFactory' removed
08:24:52.967 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ChannelItemProvider" has been removed.
08:24:52.967 [main] DEBUG org.eclipse.smarthome.core.common.registry.AbstractRegistry - Provider "ManagedItemChannelLinkProvider" has been removed.
TEST retrieveAllTopics(org.openhab.binding.mqtt.HomieImplementationTest) <<< ERROR: null
java.util.concurrent.TimeoutException
        at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1771)
        at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
        at org.openhab.binding.mqtt.HomieImplementationTest.setUp(HomieImplementationTest.java:108)
        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.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
        at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:24)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
        at junit.framework.TestSuite.runTest(TestSuite.java:252)
        at junit.framework.TestSuite.run(TestSuite.java:247)
        at aQute.junit.Activator.test(Activator.java:340)
        at aQute.junit.Activator.automatic(Activator.java:236)
        at aQute.junit.Activator.run(Activator.java:177)
        at aQute.launcher.Launcher.lambda$serviceChanged$0(Launcher.java:1385)
        at aQute.launcher.Launcher.run(Launcher.java:352)
        at aQute.launcher.Launcher.main(Launcher.java:152)
TEST retrieveAllTopics(org.openhab.binding.mqtt.HomieImplementationTest) <<< ERROR: null
java.lang.NullPointerException
        at org.openhab.binding.mqtt.HomieImplementationTest.tearDown(HomieImplementationTest.java:162)
        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.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:33)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
        at junit.framework.TestSuite.runTest(TestSuite.java:252)
        at junit.framework.TestSuite.run(TestSuite.java:247)
        at aQute.junit.Activator.test(Activator.java:340)
        at aQute.junit.Activator.automatic(Activator.java:236)
        at aQute.junit.Activator.run(Activator.java:177)
        at aQute.launcher.Launcher.lambda$serviceChanged$0(Launcher.java:1385)
        at aQute.launcher.Launcher.run(Launcher.java:352)
        at aQute.launcher.Launcher.main(Launcher.java:152)
Tests run  : 4
Passed     : -4
Errors     : 8
Failures   : 0
[INFO] 8 Error(s)
lolodomo commented 5 years ago

Similar to the other. Timeout exception at this line: https://github.com/openhab/openhab2-addons/blob/268f9149e1f573ee41069519215152f370cbabd3/itests/org.openhab.binding.mqtt.homie.tests/src/main/java/org/openhab/binding/mqtt/HomieImplementationTest.java#L108

J-N-K commented 5 years ago

Ok. I started and ran in exactly the same error.

-> increased timeout to 500 -> fixed

After that paho complains about „too many publications“

-> increased max. inflight messages (requires core patch) -> fixed

Now the tests fail because subscriptions do not return the requested values. I guess that is another timing issue. Stopping for today

J-N-K commented 5 years ago

It seems to be an issue with the embedded broker. I exchanged that with an external broker and tests succeed. No matter how far I extend the subscription I never receive topics with retained messages. It seems that under certain circumstances the embedded broker is not retaining messages (I have seen that in my test setup, too).

lolodomo commented 5 years ago

If the test is showing a bug, that is interesting ;)

J-N-K commented 5 years ago

This really seems to be a bug in moquette. I verified with Wireshark that the messages are sent with QoS 1 and retain flag set. In #5915 I added a new test for moquette, result: