v2 deduplication logic is blocking legitimate MQTT messages

[airdrummingfool]

This is going to be a bit involved, and I apologize in advance. I have just updated to v2, and the MQTT message deduplication logic seems overly aggressive - it is blocking legitimate messages from my device.

The Situation

I have a curtain operating device (basically, a slow dimmer) that I have connected to ST through the bridge. When ST issues a dim command, it is sent to the read_suffix topic, which my device is subscribed to. The device then performs the command as requested, and sends progress updates to the write_suffix topic. A typical operation looks something like this (assume dimmer starts at 100):

1. ST sends level=0 to read_suffix.
2. Dimmer starts to dim. After a few seconds, it has dimmed 50%, so it sends level=50 to write_suffix.
3. After a few more seconds, the dimmer has finished, and it sends level=0 to write_suffix.

Enter the deduplication logic

Prior to 2.0, the deduplication logic was (for better or worse) simple:

if (history[topicState] === contents) {
    winston.info('Skipping duplicate message from: %s = %s', topic, contents);
    return;
}
history[topic] = contents;

Now, with the introduction of write and read suffixes, it has grown a bit more complex:

if (history[topicWriteState] === contents) {
    history[topicReadState] = contents;
    winston.info('Skipping duplicate message from: %s = %s', topic, contents);
    return;
}
if (history[topicReadState] === contents) {
    history[topicWriteState] = contents;
    winston.info('Skipping duplicate message from: %s = %s', topic, contents);
    return;
}
history[topic] = contents;

What happens

With the new logic, "duplicate" messages can be blocked even if there are other messages in between. Here's my device's operation again, this time annotated with the behavior of the deduplication code:

1. ST sends level=0 to read_suffix.

   history[read_suffix] = undefined
   history[write_suffix] = undefined

2. Dimmer starts to dim. After a few seconds, it has dimmed 50%, and it sends a status update level=50 to write_suffix.

   history[read_suffix] = 0
   history[write_suffix] = undefined

3. After a few more seconds, the dimmer has finished, and it sends level=0 to write_suffix.

   history[read_suffix] = 0 # Duplicate detected, blocking message!
   history[write_suffix] = 50

Discussion

The deduplication code in question is in the parseMQTTMessage method, which means it is only deduplicating messages coming from the MQTT broker. The bridge is only subscribed to two topics per device property (command_suffix and write_suffix).

It seems to me that if the incoming message is from the write_suffix topic, we should be okay with it possibly being a reflection (duplicate) of the last read_suffix state, because it would just be the device verifying that it's state transitioned the way ST commanded it to. Plus, the write_suffix message isn't a command, so it shouldn't trigger any actions in Smart Things (just setStatus).

What deduplication scenarios does the logic need to handle? I don't yet use HASS and only have one device running through the bridge, so there may be some of scenarios I haven't thought of yet. That being said, the basic duplication (preventing two identical messages from the same topic) would work well for my use.

If we did want to make sure we didn't reflect messages from an outgoing ST message back into the write_suffix, I'd like to propose a more limited scope, so that deduplication is only run when the incoming message is from the write_suffix topic. Also, we should only compare the very next message across topics (e.g. comparing an incoming write_suffix to previously sent read_suffix). Example:

// Make sure it's not a raw duplicate
if (history[topic] === contents) {
    winston.info('Skipping duplicate message from: %s = %s', topic, contents);
    return;
}

// Make sure we don't reflect state from ST > device
if (topicWriteState === topic) {
    if (history[topicReadState] === contents || history[topicWriteState] === contents) {
        winston.info('Skipping duplicate message from: %s = %s', topic, contents);
        return;
    }
    // If this (the very next message) is a non-duplicated state read/write, clear history so we don't skip future messages
    history[topicReadState] = undefined;
    history[topicWriteState] = undefined;
}
history[topic] = contents;

I'm happy to write up a PR if that would make discussion/testing easier, once I get a bit of input on what kind of duplication needs to be handled.

@gandazgul you wrote the new deduplication code (PR #84), can you take a look at this?

[stjohnjohnson]

Wow. Great catch. Yes, this is incorrectly matching write commands and read commands. The write topic should not be de-duped.

Can you provide a PR to fix that?

Also, excellent write up

[airdrummingfool]

I'd be happy to provide a PR. Can you clarify this statement:

The write topic should not be de-duped.

Do you mean at all? As in, we shouldn't even do the naïve if (history[topic] === contents) check for the write topic? In that case, only messages coming from the command topic will be checked at all.

Or do you want to just go back to the naïve if (history[topic] === contents) raw duplicate check for all incoming messages?

[stjohnjohnson]

If the write and read topics are different (meaning they are two distinct topic channels), then any commands being sent to the write topic are from the user. The reason we did the de-dupe in the beginning was that when we sent a write message, it would be sent to SmartThings, the update would happen, the bridge would be notified of the new state, it would write back to mqtt, and the bridge would read the value again (loop!).

But imagine the scenario:

• Light is off
• User sends command to turn light on to write topic
• Light is turned on and read topic reflects light is on
• User turns off light manually
• Light is turned off and read topic reflects light is off
• User sends command to turn light on to write topic

We don't want to de-dupe that command.

[airdrummingfool]

Ah, thanks, that makes a lot of sense. Since we're subscribed to up to two channels the user may write to (write and command), both need to be deduped IFF they are equivalent to the read topic. I've implemented this in my PR #136.

[gandazgul]

I see, I've actually seen this problem once but didn't pay attention to it. I don't have any devices that need a level so I dont hit your scenario at all. I can see how the 2 histories separated as I had them are not good in that scenario. I think the way you have it in the PR should be ok.

I'm sorry for breaking this :(. I will have a dimmer custom device soon so this is perfect timing :).

Thank you for catching and fixing this @airdrummingfool.

[airdrummingfool]

@gandazgul thanks for taking a look!

[digiblur]

Anything new on this? I seem to be in the same boat as many others with the dedupe kill legit messages.

[gandazgul]

@stjohnjohnson can you merge this PR?

[gandazgul]

thank you! @stjohnjohnson for merging.

@airdrummingfool @digiblur Let us know how is working for you.

[stjohnjohnson]

Of course, package version is smartthings-mqtt-bridge@2.1.0

[digiblur]

Unfortunately for testing and fortunately for my sanity, my Zwave/Zigbee USB stick finally arrived and I have pulled the plug on Smartthings.

[airdrummingfool]

@gandazgul I've been using this code since I originally sent the PR (almost 2 months ago) and I haven't seen any issues.