MQTT related error - how to narros it down?

I am running Openhab on a Raspberry Pi4 with Docker. Containers installed are in the same n network are:

  • OpenHAB
  • Node-Red
  • Influx
  • Grafana
  • Mosquitto
  • zigbee2mqtt
  • zigbee2mqttGUI

I am trying to migrate from the Openhabian installation on a RPi3. I started now to get this error:

2019-11-24 23:34:06.182 [thome.event.ItemStateEvent] - Bathroom1_Fan updated to OFF
==> /openhab/userdata/logs/openhab.log <==
2019-11-24 23:34:07.396 [ERROR] [ansport.mqtt.internal.ClientCallback] - MQTT message received. MqttMessageSubscriber#processMessage() implementation failure
java.lang.StringIndexOutOfBoundsException: String index out of range: 10
	at java.lang.String.substring(String.java:1963) ~[?:1.8.0_222]
	at org.eclipse.smarthome.core.library.types.DateTimeType.<init>(DateTimeType.java:121) ~[?:?]
	at org.eclipse.smarthome.core.library.types.DecimalType.as(DecimalType.java:173) ~[?:?]
	at org.eclipse.smarthome.core.internal.items.ItemStateConverterImpl.convertToAcceptedState(ItemStateConverterImpl.java:64) ~[?:?]
	at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.sendUpdate(ProfileCallbackImpl.java:134) ~[?:?]
	at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onStateUpdateFromHandler(SystemDefaultProfile.java:53) ~[?:?]
	at org.eclipse.smarthome.core.thing.internal.CommunicationManager.lambda$9(CommunicationManager.java:467) ~[?:?]
	at org.eclipse.smarthome.core.thing.internal.CommunicationManager.lambda$11(CommunicationManager.java:487) ~[?:?]
	at java.lang.Iterable.forEach(Iterable.java:75) ~[?:1.8.0_222]
	at org.eclipse.smarthome.core.thing.internal.CommunicationManager.handleCallFromHandler(CommunicationManager.java:483) ~[?:?]
	at org.eclipse.smarthome.core.thing.internal.CommunicationManager.stateUpdated(CommunicationManager.java:465) ~[?:?]
	at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$1.stateUpdated(ThingManagerImpl.java:168) ~[?:?]
	at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateState(BaseThingHandler.java:257) ~[?:?]
	at org.openhab.binding.mqtt.generic.AbstractMQTTThingHandler.updateChannelState(AbstractMQTTThingHandler.java:234) ~[?:?]
	at org.openhab.binding.mqtt.generic.ChannelState.processMessage(ChannelState.java:204) ~[?:?]
	at org.eclipse.smarthome.io.transport.mqtt.internal.ClientCallback.lambda$3(ClientCallback.java:96) ~[?:?]
	at java.util.ArrayList.forEach(ArrayList.java:1257) ~[?:1.8.0_222]
	at org.eclipse.smarthome.io.transport.mqtt.internal.ClientCallback.messageArrived(ClientCallback.java:96) ~[?:?]
	at org.eclipse.smarthome.io.transport.mqtt.internal.ClientCallback.messageArrived(ClientCallback.java:71) ~[?:?]
	at com.hivemq.client.internal.mqtt.mqtt3.Mqtt3AsyncClientView.lambda$callbackView$1(Mqtt3AsyncClientView.java:73) ~[bundleFile:?]
	at com.hivemq.client.internal.mqtt.MqttAsyncClient$CallbackSubscriber.onNext(MqttAsyncClient.java:227) [bundleFile:?]
	at com.hivemq.client.internal.mqtt.MqttAsyncClient$CallbackSubscriber.onNext(MqttAsyncClient.java:212) [bundleFile:?]
	at com.hivemq.client.rx.FlowableWithSingle$SingleFutureSubscriber.onNext(FlowableWithSingle.java:377) [bundleFile:?]
	at com.hivemq.client.internal.rx.operators.FlowableWithSingleCombine$SplitSubscriber$Default.tryOnNextActual(FlowableWithSingleCombine.java:206) [bundleFile:?]
	at com.hivemq.client.internal.rx.operators.FlowableWithSingleCombine$SplitSubscriber.tryOnNext(FlowableWithSingleCombine.java:171) [bundleFile:?]
	at io.reactivex.internal.operators.flowable.FlowableObserveOn$ObserveOnConditionalSubscriber.runAsync(FlowableObserveOn.java:649) [bundleFile:?]
	at io.reactivex.internal.operators.flowable.FlowableObserveOn$BaseObserveOnSubscriber.run(FlowableObserveOn.java:176) [bundleFile:?]
	at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66) [bundleFile:?]
	at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57) [bundleFile:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_222]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_222]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_222]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
==> /openhab/userdata/logs/events.log <==

The messages do not contain information so that I understand what the real problem is. How can I narrow down what the problem is? It seems to bet triggered in the proximity of some items but I have not yet found which of them do not work.

Any help in pointing me into a direction for investigation is welcome.

I can’t be much help, but -

seems to be a clear clue the MQTT binding is struggling with an incoming message. As I’m sure you already realized :smiley:

But this looks a further clue -

which suggests you should look at any channels you have linked to DateTime type Items, I think.
Or possibly, datetime type channels even if not linked.
I’d guess it is trying to look at a non-standard string in the MQTT message for conversion.

If you can guess likely offenders (what else updates at the same time?) you should be able to temporarily make a string channel to see what arrives at openHAB

Thanks a lot. It seems I was able to identify the problem with your pointer to the DateTime item. But I do not understand why it happened.

For a generic mqtt thing I had created several channels, one of them was linked to two items

  1. the item it was really meant for (I think it was the temperature measurement)
  2. a DateTime item that I linked using the “Timestamp on update” profile so I can monitor when it was updated last time.

(I am using OH 2.5M4)

I have done this for several mqtt things and they all seem to work fine. After deleting the link I had no further error for several hours. I have now created a new link to the same time with the “Timestamp on update” profile and it does not seem to create any error.

Hi,

I experienced a simimlar error which might is related to this one therefore I post my exception here as well:

I think I started getting this error after switching to OH 2.5 M4, too.

Mine is related to KNX, not MQTT but kind of similar:


java.lang.StringIndexOutOfBoundsException: String index out of range: 10
        at java.lang.String.substring(String.java:1963) ~[?:1.8.0_222]
        at org.eclipse.smarthome.core.library.types.DateTimeType.<init>(DateTimeType.java:121) ~[?:?]
        at org.eclipse.smarthome.core.library.types.DecimalType.as(DecimalType.java:173) ~[?:?]
        at org.eclipse.smarthome.core.internal.items.ItemStateConverterImpl.convertToAcceptedState(ItemStateConverterImpl.java:64) ~[?:?]
        at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.sendUpdate(ProfileCallbackImpl.java:134) ~[?:?]
        at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onStateUpdateFromHandler(SystemDefaultProfile.java:53) ~[?:?]
        at org.eclipse.smarthome.core.thing.internal.CommunicationManager.lambda$9(CommunicationManager.java:467) ~[?:?]
        at org.eclipse.smarthome.core.thing.internal.CommunicationManager.lambda$11(CommunicationManager.java:487) ~[?:?]
        at java.lang.Iterable.forEach(Iterable.java:75) ~[?:1.8.0_222]
        at org.eclipse.smarthome.core.thing.internal.CommunicationManager.handleCallFromHandler(CommunicationManager.java:483) ~[?:?]
        at org.eclipse.smarthome.core.thing.internal.CommunicationManager.stateUpdated(CommunicationManager.java:465) ~[?:?]
        at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$1.stateUpdated(ThingManagerImpl.java:168) ~[?:?]
        at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateState(BaseThingHandler.java:257) ~[?:?]
        at org.openhab.binding.knx.internal.handler.DeviceThingHandler.processDataReceived(DeviceThingHandler.java:397) ~[?:?]
        at org.openhab.binding.knx.internal.handler.DeviceThingHandler.lambda$11(DeviceThingHandler.java:350) ~[?:?]
        at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:127) ~[?:?]
        at org.openhab.binding.knx.internal.handler.DeviceThingHandler.onGroupWrite(DeviceThingHandler.java:329) ~[?:?]
        at org.openhab.binding.knx.internal.client.AbstractKNXClient$1.lambda$0(AbstractKNXClient.java:107) ~[?:?]
        at org.openhab.binding.knx.internal.client.AbstractKNXClient.lambda$8(AbstractKNXClient.java:256) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_222]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_222]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[?:1.8.0_222]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[?:1.8.0_222]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]

I had no time to check if M6 will solve it up to now…