MQTT error on 2.5.0.M2: Error processing protocol message: SUBSCRIBE

Hi,

after upgrading my OH system to 2.5.0.M2 - Docker container on Synology NAS - my MQTT things worked fine. Yet out of the blue one of the things (ESPEasy powered WemosD1) is causing an error - see below. Any advice how to get this resolved? Do I need to delete and setup the thing and items again?

2019-09-05 07:42:07.721 [ERROR] [.moquette.broker.NewNettyMQTTHandler] - Error processing protocol message: SUBSCRIBE
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) ~[203:com.h2database.mvstore:1.4.199]
        at org.h2.mvstore.type.ObjectDataType.deserialize(ObjectDataType.java:376) ~[203:com.h2database.mvstore:1.4.199]
        at org.h2.mvstore.type.ObjectDataType$SerializedObjectType.read(ObjectDataType.java:1547) ~[203:com.h2database.mvstore:1.4.199]
        at org.h2.mvstore.type.ObjectDataType.read(ObjectDataType.java:231) ~[203:com.h2database.mvstore:1.4.199]
        at org.h2.mvstore.type.ObjectDataType.read(ObjectDataType.java:114) ~[203:com.h2database.mvstore:1.4.199]
        at org.h2.mvstore.Page$Leaf.readPayLoad(Page.java:1551) ~[203:com.h2database.mvstore:1.4.199]
        at org.h2.mvstore.Page.read(Page.java:695) ~[203:com.h2database.mvstore:1.4.199]
        at org.h2.mvstore.Page.read(Page.java:238) ~[203:com.h2database.mvstore:1.4.199]
        at org.h2.mvstore.MVStore.readPage(MVStore.java:2187) ~[203:com.h2database.mvstore:1.4.199]
        at org.h2.mvstore.MVMap.readPage(MVMap.java:554) ~[203:com.h2database.mvstore:1.4.199]
        at org.h2.mvstore.Page$NonLeaf.getChildPage(Page.java:1086) ~[203:com.h2database.mvstore:1.4.199]
        at org.h2.mvstore.MVMap.traverseDown(MVMap.java:1877) ~[203:com.h2database.mvstore:1.4.199]
        at org.h2.mvstore.MVMap.operate(MVMap.java:1664) ~[203:com.h2database.mvstore:1.4.199]
        at org.h2.mvstore.MVMap.put(MVMap.java:151) ~[203:com.h2database.mvstore:1.4.199]
        at io.moquette.persistence.H2SubscriptionsRepository.addNewSubscription(H2SubscriptionsRepository.java:41) ~[204:io.moquette.moquette-broker:0.12.1]
        at io.moquette.broker.subscriptions.CTrieSubscriptionDirectory.add(CTrieSubscriptionDirectory.java:88) ~[204:io.moquette.moquette-broker:0.12.1]
        at io.moquette.broker.PostOffice.subscribeClientToTopics(PostOffice.java:81) ~[204:io.moquette.moquette-broker:0.12.1]
        at io.moquette.broker.MQTTConnection.processSubscribe(MQTTConnection.java:306) ~[204:io.moquette.moquette-broker:0.12.1]
        at io.moquette.broker.MQTTConnection.handleMessage(MQTTConnection.java:70) ~[204:io.moquette.moquette-broker:0.12.1]
        at io.moquette.broker.NewNettyMQTTHandler.channelRead(NewNettyMQTTHandler.java:58) [204:io.moquette.moquette-broker:0.12.1]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337) [211:io.netty.transport:4.1.34.Final]
        at io.moquette.broker.metrics.MQTTMessageLogger.channelRead(MQTTMessageLogger.java:46) [204:io.moquette.moquette-broker:0.12.1]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337) [211:io.netty.transport:4.1.34.Final]
        at io.moquette.broker.metrics.MessageMetricsHandler.channelRead(MessageMetricsHandler.java:50) [204:io.moquette.moquette-broker:0.12.1]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337) [211:io.netty.transport:4.1.34.Final]
        at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:323) [206:io.netty.codec:4.1.34.Final]
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:297) [206:io.netty.codec:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337) [211:io.netty.transport:4.1.34.Final]
        at io.moquette.broker.metrics.BytesMetricsHandler.channelRead(BytesMetricsHandler.java:51) [204:io.moquette.moquette-broker:0.12.1]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337) [211:io.netty.transport:4.1.34.Final]
        at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286) [209:io.netty.handler:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1408) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:930) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:677) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:612) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:529) [211:io.netty.transport:4.1.34.Final]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:491) [211:io.netty.transport:4.1.34.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905) [208:io.netty.common:4.1.34.Final]
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [208:io.netty.common:4.1.34.Final]
        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) ~[?:?]
        ... 66 more

Thanks!

The message seems to come from the broker (moquette) so there’s no point fiddling with openHAB things.

I missed the clue that led you to finger a particular device? But googling the moquette error message seems to link this kind of error to heavy load e.g. MQTT message spammimg. In his case I would restart your your suspect device at least.

Hi rossko57,

thanks for your advise. Restarting the ESPEasy device was the first thing I tried - w/o any change. I’ll restart the openhab system next.

I point to a particular device as I have multiple ESPEasy device sending MQTT messages. Only one of them is causing the issue while the remaining ones continue to work just fine. The problematic device send different messages (different sensors) than the working ones. Yet the error came out of the blue as the problematic one was working just fine before.

Regards

Perhaps if you use a monitor tool like mqtt.fx you might see if anything makes bursts of messages, overloading moquette. That might include an openHAB rule, of course.
There’s nothing in what you’ve shown us that points to a suspect, perhaps you can see more. Maybe you have screwy values in openHAB for your suspect device as well.

I guess I’m back in business :grinning:

The issue got resolved by doing those steps:

  1. stop OH
  2. rm -rf userdata/tmp userdata/cache
  3. rm userdata mqttembedded.bin
  4. start OH

There is a (known?) issue with mqttembedded.bin file staying locked after OH shutdown. Just removing that file while keeping tmp and cache folders seems to create some confusion on the system. Cleaning up is solving the issue.

Those are the error messages from locked mqttembedded.bin file:

2019-09-05 20:13:21.478 [ERROR] [org.openhab.io.mqttembeddedbroker   ] - bundle org.openhab.io.mqttembeddedbroker:2.5.0.M2 (241)[org.openhab.io.mqttembeddedbroker.internal.Embe
ddedBrokerService(223)] : The activate method has thrown an exception
2019-09-05 20:13:21.651 [INFO ] [roker.internal.EmbeddedBrokerService] - Broker persistence file: mqttembedded.bin
2019-09-05 20:13:21.650 [WARN ] [org.openhab.io.mqttembeddedbroker   ] - FrameworkEvent WARNING - org.openhab.io.mqttembeddedbroker
org.osgi.framework.ServiceException: org.apache.felix.scr.impl.manager.SingleComponentManager.getService() returned a null service object
2019-09-05 20:13:21.751 [ERROR] [org.openhab.io.mqttembeddedbroker   ] - bundle org.openhab.io.mqttembeddedbroker:2.5.0.M2 (241)[org.openhab.io.mqttembeddedbroker.internal.Embe
ddedBrokerService(223)] : The activate method has thrown an exception
java.lang.IllegalStateException: The file is locked: nio:/openhab/userdata/mqttembedded.bin [1.4.199/7]

Case closed?! Will monitor and report back if things go south again…

Thanks & Regards!

So the problem reoccurred. It is very hard to debug as the issue comes very sudden.

Anyhow it turned out the ESPEasy device got somehow corrupt and hence delivered invalid data. I did a firmware update on the device to latested release version (20190903) and since then no further issue.

Yet even after firmware update the MQTT service was not recovering. I had to restart OH to make it work again. Will see how 2.5.0.M3 behaves…

… well, the very same error occurred again - this time using OH 2.5.0-M3 docker image while a different of my ESPEasy powered Wemos D1 devices is affected. Everything was running fine for almost 20h and then boom. Seems like Moquette does not like some certain message. I don’t see anything special happening or reported when the error occurs.

With the error occurring, mqtt.fx is of no help as the device is gone from the broker. I may have to monitor all traffic until it happens again?!

Also I have to restart OH to get out of the error condition. Trying to suspend the broker and restart it creates even more java errors. Any advise?

Thanks!

Same error here. For me it is just enough to delete mqttembedded.bin and then restart openhab. It works for about 1-2 Days and then the error appears again. Would an external mosquitto server be a solution until the embedded is fixed again?

Yeah, the issue persist - independent of any optimization I tried on the ESPEasy devices messing with the send queue parameters to slow down the message rate. I don’t see any pattern in what is triggering the Moquette error.

I’m willing to debug if someone would send instructions what to monitor.

Thanks!

Hi,

the issue is still present in OH 2.5.0-M5. Every 1…2 days the very same error occurs from one of the MQTT sensor devices so I have to restart the OH server - very annoying! Any advise on how to debug that error? I was not able to catch anything using mqtt.fx which just stops reporting the messages when the error occurs. Nothing unusal seen before that.

How to prevent the error? Do I have to switch to mosquitto MQTT server?

Thanks!

As I replied on the 2.5 M5 issues thread, the error is coming from Moquette code, not openHAB code. It has been reported that Moquette has been abandoned by its developer so a fix is unlikely to be coming down the line. If you experience any errors with Moquette, your best bet is to switch to using Mosquitto or some other external and well supported broker.

1 Like

Hi Rich,

ok, understand. This is a pitty as “Embedded MQTT broker” was announced as a unique feature in OH2 and has been working reasonable well in 2.4. What is the plan forward on this?

I’m OH 2.5.0-M5 from docker container on Synology NAS. I understand Mosquitto has to be installed as a separate server / container - its not part of the docker image, correct?

For Synology NAS I see a native Mosquitto package from synocommunity or a docker container to run in parallel to OH2 instance. Any advise?

Thanks!

sounds like 6 of one and half a dozen of the other… either should work

Find some other embedded broker, hope someone picks back up the development, it remove the embedded broker entirely. It seems to work in a lot of use cases and for all lot of users. There is something about your environment that makes it not will workable.

As with everything in oh, it will take sometime to volunteer to do something about it.

Correct, and that is how containers should be. One container had one service.

I don’t run on Synology but I do run the official mosquito Docker image and have no complaints.

Thanks to all. I switched to Mosquitto (Docker container) and since then no issues.