MQTT 2.0 - Error Updating Integer types using Homie Convention

broconne · January 12, 2019, 6:38pm

I am running into an error updating integer types in the new MQTT 2.0 binding with a device using the homie convention. I have no problems with string types.

Rule looks like this:

rule "Track Time Changed"
when
    Item ChromecastStatusCurrentTime changed
then
    val trackPosition = (ChromecastStatusCurrentTime.state as DecimalType).intValue
    logInfo("Nuvo", "Sending new track position {}", trackPosition)
    //Nuvo_Source_5_Track_Position.sendCommand(new Integer(trackPosition))
    Nuvo_Source_5_Track_Position.sendCommand(50)
end

note I simplified it to just send 50, in case my conversion was an issue.

Item is defined like this:

Number                 Nuvo_Source_5_Track_Position      {channel="mqtt:homie300:mosquitto:nuvo:source5#position"}

I see the following in the log when an update happens:

2019-01-12 13:34:33.943 [DEBUG] [eneric.internal.generic.ChannelState] - Format pattern incorrect for mqtt:homie300:mosquitto:nuvo:source5#position

java.util.IllegalFormatConversionException: d != java.lang.String

	at java.util.Formatter$FormatSpecifier.failConversion(Formatter.java:4302) ~[?:?]

	at java.util.Formatter$FormatSpecifier.printInteger(Formatter.java:2793) ~[?:?]

	at java.util.Formatter$FormatSpecifier.print(Formatter.java:2747) ~[?:?]

	at java.util.Formatter.format(Formatter.java:2520) ~[?:?]

	at java.util.Formatter.format(Formatter.java:2455) ~[?:?]

	at org.eclipse.smarthome.binding.mqtt.generic.internal.generic.ChannelState.publishValue(ChannelState.java:312) [230:org.eclipse.smarthome.binding.mqtt.generic:0.10.0.oh240]

	at org.eclipse.smarthome.binding.mqtt.generic.internal.handler.AbstractMQTTThingHandler.handleCommand(AbstractMQTTThingHandler.java:119) [230:org.eclipse.smarthome.binding.mqtt.generic:0.10.0.oh240]

	at sun.reflect.GeneratedMethodAccessor121.invoke(Unknown Source) ~[?:?]

	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]

	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]

	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [102:org.eclipse.smarthome.core:0.10.0.oh240]

	at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [102:org.eclipse.smarthome.core:0.10.0.oh240]

	at com.sun.proxy.$Proxy222.handleCommand(Unknown Source) [230:org.eclipse.smarthome.binding.mqtt.generic:0.10.0.oh240]

	at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [109:org.eclipse.smarthome.core.thing:0.10.0.oh240]

	at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [109:org.eclipse.smarthome.core.thing:0.10.0.oh240]

	at sun.reflect.GeneratedMethodAccessor120.invoke(Unknown Source) ~[?:?]

	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]

	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]

	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [102:org.eclipse.smarthome.core:0.10.0.oh240]

	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [102:org.eclipse.smarthome.core:0.10.0.oh240]

	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]

	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]

	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]

	at java.lang.Thread.run(Thread.java:748) [?:?]

2019-01-12 13:34:33.949 [DEBUG] [nal.handler.AbstractMQTTThingHandler] - Successfully published value 50 to topic homie/nuvo/source5/position

Looking at the code, it seems to indicate that it is trying to convert a number placeholder in a format with a string value… The value does actually get published, after the exception.

@David_Graeff Is this working as designed, or is this an issue?

vzorglub · January 12, 2019, 6:56pm

mqtt:homie300:mosquitto:nuvo:source5#position

Is that a number channel?

broconne · January 12, 2019, 6:58pm

Yep

vzorglub · January 12, 2019, 7:22pm

rule "Track Time Changed"
when
    Item ChromecastStatusCurrentTime changed
then
    val Number trackPosition = (ChromecastStatusCurrentTime.state as DecimalType).intValue
    logInfo("Nuvo", "Sending new track position {}", trackPosition)
    Nuvo_Source_5_Track_Position.sendCommand(trackPosition)
    //Nuvo_Source_5_Track_Position.sendCommand(50)
end

broconne · January 12, 2019, 7:40pm

No change when explicitly setting the val to be a number.

vzorglub · January 12, 2019, 7:43pm

    Nuvo_Source_5_Track_Position.sendCommand(trackPosition.toString)

broconne · January 12, 2019, 7:46pm

Tried that one before… no dice.

vzorglub · January 12, 2019, 7:55pm

What does the logInfo say?

broconne · January 13, 2019, 11:25am

 [INFO ] [.eclipse.smarthome.model.script.Nuvo] - Sending new track position 42

vzorglub · January 13, 2019, 12:15pm

Question:
Does it work with:

    Nuvo_Source_5_Track_Position.sendCommand(50)

broconne · January 13, 2019, 12:32pm

Nope. Same exception. It works, in that it sends the message. But it throws the exception every time.

vzorglub · January 13, 2019, 12:37pm

Ok, well, it seems like a bug.
Report it to:

broconne · January 13, 2019, 12:57pm

@vzorglub - thanks for the help.

@David_Graeff - Do you agree this is a defect and should be submitted?

David_Graeff · January 13, 2019, 5:15pm

I agree that the error message should be a better one instead of showing the exception stack trace.

You have changed the formatter parameter from “%s” to something else apparently, I have no other explanation.
The formatter takes an input and does what ever the “format” arguments tells him to do. And “%s” basically says, make a string out of everything. And that works in Java via the implicit .toString() method on every object.

There is an automated test suite that checks publish/receive of string and number channels and that test suite almost guarantees that this functionality works and no developer can break it on accident.

broconne · January 13, 2019, 6:12pm

I have not modified the formatter.

It appears to me that “%d” is specified as the formatter in the code:

github.com

eclipse/smarthome/blob/6a81231cda79d3812e8ff9868868190cf142be95/extensions/binding/org.eclipse.smarthome.binding.mqtt.generic/src/main/java/org/eclipse/smarthome/binding/mqtt/generic/internal/convention/homie300/Property.java#L200


    case unknown:
    default:
        value = new TextValue();
        break;
}


ChannelConfigBuilder b = ChannelConfigBuilder.create().makeTrigger(!attributes.retained)
        .withStateTopic(stateTopic);


if (isDecimal != null && !isDecimal) {
    b = b.withFormatter("%d"); // Apply formatter to only publish integers
}


if (attributes.settable) {
    b = b.withCommandTopic(commandTopic);
}


final ChannelState channelState = new ChannelState(b.build(), channelUID, value, callback);
this.channelState = channelState;


final ChannelType type = createChannelType(attributes, channelState);

Maybe I am looking in the wrong place, but I only see test for float and boolean? https://github.com/eclipse/smarthome/blob/master/extensions/binding/org.eclipse.smarthome.binding.mqtt.generic.test/src/test/java/org/eclipse/smarthome/binding/mqtt/generic/HomieImplementationTests.java

I am not sure why the automated tests would fail, since the exception is swallowed:

github.com

eclipse/smarthome/blob/6a81231cda79d3812e8ff9868868190cf142be95/extensions/binding/org.eclipse.smarthome.binding.mqtt.generic/src/main/java/org/eclipse/smarthome/binding/mqtt/generic/internal/generic/ChannelState.java#L314


String mqttCommandValue = cachedValue.getMQTTpublishValue();


final MqttBrokerConnection connection = this.connection;


if (!readOnly && connection != null) {
    // Formatter: Applied before the channel state value is published to the MQTT broker.
    if (config.formatBeforePublish.length() > 0) {
        try (Formatter formatter = new Formatter()) {
            Formatter format = formatter.format(config.formatBeforePublish, mqttCommandValue);
            mqttCommandValue = format.toString();
        } catch (IllegalFormatException e) {
            logger.debug("Format pattern incorrect for {}", channelUID, e);
        }
    }
    // Send retained messages if this is a stateful channel
    return connection.publish(config.commandTopic, mqttCommandValue.getBytes(), 1, config.retained)
            .thenRun(() -> {
            });
} else {
    CompletableFuture<@Nullable Void> f = new CompletableFuture<>();
    f.completeExceptionally(new IllegalStateException("No connection or readOnly channel!"));

David_Graeff · January 13, 2019, 6:45pm

I think that should be made an explicit exception, especially for the test suite to correctly fail if a formatter string is incorrect.

And yes, for integers it is correct to use the “%d” formatter, I guess. But why on earth is it failing here.

broconne · January 13, 2019, 6:49pm

It is failing because the format is of type “%d” which means: “I only accept integers”, and on line 304 the value is being stored in a String which is then passed to the format command.

David_Graeff · January 13, 2019, 6:57pm

Nah, the input is always a string. The formatter pattern “%d” should be more like “output an integer”. Otherwise the entire formatter API wouldn’t make sense.

broconne · January 13, 2019, 7:15pm

I don’t think that is correct

public class MyClass {
    public static void main(String args[]) {
       java.util.Formatter formatter = new java.util.Formatter();
       System.out.println(formatter.format("%d",5));
       System.out.println("=============");
       System.out.println(formatter.format("%d",Integer.toString(5)));
    }
}

5
=============

Exception in thread "main" java.util.IllegalFormatConversionException: d != java.lang.String
	at java.base/java.util.Formatter$FormatSpecifier.failConversion(Formatter.java:4421)
	at java.base/java.util.Formatter$FormatSpecifier.printInteger(Formatter.java:2936)
	at java.base/java.util.Formatter$FormatSpecifier.print(Formatter.java:2890)
	at java.base/java.util.Formatter.format(Formatter.java:2671)
	at java.base/java.util.Formatter.format(Formatter.java:2607)
	at MyClass.main(MyClass.java:6)
Command exited with non-zero status 1

A large part of what the formatter does is convert objects into string representations of those objects.

David_Graeff · January 13, 2019, 7:51pm

Oh. So I had a full black-out while coding that piece of the binding and actually need a parse-and-output like API, that complies to what I have written in the binding documentation.