Closed stueble closed 1 year ago
openhab-bot
commented
1 year ago This issue has been mentioned on openHAB Community. There might be relevant details there:
https://community.openhab.org/t/oh3-mqtt-binding-not-reacting-to-incoming-payloads/142008/21
J-N-K
commented
1 year ago Do you have a set of commands (e.g. with mosquitto_pub) that can reproduce that behavior and does not depend on some external hardware that I don't own?
stueble
commented
1 year ago That was easier than expected:
I can reproduce the bug when using a thing with incoming transformation "JSONPATH:$.value"
Sending the following message changes the corresponding item
mosquitto_pub -d -h mosquittobroker -t "My/Test" -m '{"value": -6500}'
The item does not change any more after sending the following NULL message:
mosquitto_pub -d -h mosquittobroker -t "My/Test" -n
As described above, after restarting the thing everything works again. Since I could not reproduce the bug without transformation, my expectation is that the JSONPATH transformation breaks something when the null message is received. Maybe.
J-N-K
commented
1 year ago It would have been easier if someone had mentioned this exception in the log:
java.lang.IllegalArgumentException: json string can not be null or empty
at com.jayway.jsonpath.internal.Utils.notEmpty(Utils.java:383)
at com.jayway.jsonpath.internal.ParseContextImpl.parse(ParseContextImpl.java:36)
at com.jayway.jsonpath.JsonPath.read(JsonPath.java:498)
at org.openhab.transform.jsonpath.internal.JSonPathTransformationService.transform(JSonPathTransformationService.java:63)
at org.openhab.binding.mqtt.generic.ChannelStateTransformation.processValue(ChannelStateTransformation.java:91)
at org.openhab.binding.mqtt.generic.ChannelState.processMessage(ChannelState.java:176)
at org.openhab.core.io.transport.mqtt.internal.Subscription.processMessage(Subscription.java:88)
at org.openhab.core.io.transport.mqtt.internal.Subscription.lambda$1(Subscription.java:84)
at java.base/java.util.concurrent.ConcurrentHashMap$KeySpliterator.forEachRemaining(ConcurrentHashMap.java:3573)
at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:762)
at org.openhab.core.io.transport.mqtt.internal.Subscription.messageArrived(Subscription.java:84)
at org.openhab.core.io.transport.mqtt.internal.Subscription.messageArrived(Subscription.java:69)
at com.hivemq.client.internal.mqtt.mqtt3.Mqtt3AsyncClientView.lambda$callbackView$1(Mqtt3AsyncClientView.java:76)
at com.hivemq.client.internal.mqtt.MqttAsyncClient$CallbackSubscriber.onNext(MqttAsyncClient.java:303)
at com.hivemq.client.internal.mqtt.MqttAsyncClient$CallbackSubscriber.onNext(MqttAsyncClient.java:288)
at com.hivemq.client.rx.FlowableWithSingle$SingleFutureSubscriber.onNext(FlowableWithSingle.java:406)
at com.hivemq.client.internal.rx.operators.FlowableWithSingleCombine$SplitSubscriber$Default.tryOnNextActual(FlowableWithSingleCombine.java:235)
at com.hivemq.client.internal.rx.operators.FlowableWithSingleCombine$SplitSubscriber.tryOnNext(FlowableWithSingleCombine.java:200)
at io.reactivex.internal.operators.flowable.FlowableObserveOn$ObserveOnConditionalSubscriber.runAsync(FlowableObserveOn.java:649)
at io.reactivex.internal.operators.flowable.FlowableObserveOn$BaseObserveOnSubscriber.run(FlowableObserveOn.java:176)
at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66)
at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:833)
Exception in thread "RxComputationThreadPool-6" java.lang.IllegalArgumentException: json string can not be null or empty
at com.jayway.jsonpath.internal.Utils.notEmpty(Utils.java:383)
at com.jayway.jsonpath.internal.ParseContextImpl.parse(ParseContextImpl.java:36)
at com.jayway.jsonpath.JsonPath.read(JsonPath.java:498)
at org.openhab.transform.jsonpath.internal.JSonPathTransformationService.transform(JSonPathTransformationService.java:63)
at org.openhab.binding.mqtt.generic.ChannelStateTransformation.processValue(ChannelStateTransformation.java:91)
at org.openhab.binding.mqtt.generic.ChannelState.processMessage(ChannelState.java:176)
at org.openhab.core.io.transport.mqtt.internal.Subscription.processMessage(Subscription.java:88)
at org.openhab.core.io.transport.mqtt.internal.Subscription.lambda$1(Subscription.java:84)
at java.base/java.util.concurrent.ConcurrentHashMap$KeySpliterator.forEachRemaining(ConcurrentHashMap.java:3573)
at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:762)
at org.openhab.core.io.transport.mqtt.internal.Subscription.messageArrived(Subscription.java:84)
at org.openhab.core.io.transport.mqtt.internal.Subscription.messageArrived(Subscription.java:69)
at com.hivemq.client.internal.mqtt.mqtt3.Mqtt3AsyncClientView.lambda$callbackView$1(Mqtt3AsyncClientView.java:76)
at com.hivemq.client.internal.mqtt.MqttAsyncClient$CallbackSubscriber.onNext(MqttAsyncClient.java:303)
at com.hivemq.client.internal.mqtt.MqttAsyncClient$CallbackSubscriber.onNext(MqttAsyncClient.java:288)
at com.hivemq.client.rx.FlowableWithSingle$SingleFutureSubscriber.onNext(FlowableWithSingle.java:406)
at com.hivemq.client.internal.rx.operators.FlowableWithSingleCombine$SplitSubscriber$Default.tryOnNextActual(FlowableWithSingleCombine.java:235)
at com.hivemq.client.internal.rx.operators.FlowableWithSingleCombine$SplitSubscriber.tryOnNext(FlowableWithSingleCombine.java:200)
at io.reactivex.internal.operators.flowable.FlowableObserveOn$ObserveOnConditionalSubscriber.runAsync(FlowableObserveOn.java:649)
at io.reactivex.internal.operators.flowable.FlowableObserveOn$BaseObserveOnSubscriber.run(FlowableObserveOn.java:176)
at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66)
at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:833)I don't have this exception. At least not in openhab.log
stueble
commented
1 year ago Many thanks. For those who have the same problem, a possible workaround is to replace the JSONPATH transformation by a Javascript transformation, e.g.,
(function(i) {
if (i == "") {
return null;
}
var data = JSON.parse(i);
return data.value;
})(input)Please note that the above function is not 100% correct, as it seems to be impossible to send an "UNDEF" to a NumberValue in a Javascript transformation.
MQTT things stop receiving values after a null message has been send by the broker. Other clients, such as mosquitto_sub, continue working, therefore it seems to be a bug of the openhab MQTT plugin. I found several similar topics discussed by the openhab community, but none of them discussed a solution.
I tried to provide any information I have. If you need more, or have an idea how I can increase debugging output, I am happy to support.
Expected Behavior
After receiving the (truncated, invalid) message, the MQTT thing should continue receiving valid values, as other clients such as mqtt-explorer or mosquitto_sub do.
Current Behavior
Took a while to break down the problem:
I have a generic MQTT thing that expects to receive a Number in JSON format, thus it also includes a transformation pattern: JSONPATH:$.value
mosquitto_sub connecting to the same (mosquitto) broker receives outputs the following data:
First, two valid (16 byte) data are received. Then the client sends a 0 bytes balue and a 15 bytes value. After that, it continues to output the valid (16 byte) values. In contrast, openhab only outputs values until the "null" is received. From then on, the item is not updated any more. Unfortunately, I was not able to get any debug log in incoming mqtt messages, although I set all bundles with MQTT in its name to TRACE.
The only debug messages I receive are like this:
Possible Solution
The thing works again if either the MQTT thing or the MQTT broker is restarted, but it is not a realistic workaround.
Context
The bug occurs in the context of a Victron Battery Storage System connected to openhab. Openhab writes the received values to a connected OpenWB wallbox. Both data logging and wallbox stop working when the thing hangs. The invalid values are send by the Victron system when a PV inverted connected via modbus (to the victron system) is not reachable (which unfortunately resets the connection every night). But this reset is an expected behavior.
As already mentioned above, you find in the openhab community several discussions around this problem.
Your Environment
openhab 3.4.4 (docker) Victron VenusOS on Raspberry Pi