MQTT Connections

🚧 Developers Coding Questions
1

Hey all!

I've written a driver that successfully gets values from my MQTT server (Mosquitto), but after a day or two loses connection. I know the server is still running because another device is publishing messages that NodeRED is subscribed to, and it is processing the data and publishing messages correctly. I foolishly log the mqqtClientStatus conditionally to debug, so I haven't actually seen the disconnect reason yet. Next on the list...

My question is, is the MQTT client supposed to be handling reconnects? Or am I supposed to write code in mqttClientStatus(String message) that watches for disconnects and attempts to reconnect?

Thanks!

1 Like
2

You’ll need to write that code..

Also worth working out why the disconnects are happening...

3

I initially made the mistake of using the same clientid for multiple instances of my driver. Once they were unique my disconnect issues stopped.

4

Yeah, I did that too, I'm past that.

I changed my current driver to log all MQTT status messages to figure out what is going on, and am writing a new driver to retry reconnects.

5

I used to have issues with mqtt, not had a problem for some time now though.
My main issue was with the version of moquitto I had .. it used to leak memory and freeze for several seconds while writing its DB, but a version upgrade got rid of that ..

The version Ive been running for a few months now is 1.6.4

6

Watch out that you don’t get duplicate driver code running.. it’s quite easy to do.

7

@andrew.rowbottom Good tip. I am running 1.6.7 in a Docker container, hopefully that isn't it.

8

@Kevin
Would this show as multiple entries in the list of devices? Or is it trickier than that? How would I know if I have duplicates running?

I have only created one virtual devices, and hit Configure on it after saving code changes.

9

It is most easily apparent if you have log messages in the code and they appear multiple times or interleaved. My main issue was in my app but I saw it in the driver too. Initially I created the problem by calling initialize in the app again after a reconnect in the driver that still had some runin methods scheduled. I needed to run initialize again to recreate the MQTT subscriptions.

10

OK, probably very stupid question, but I've wasted too much time on something probably very, very simple.

I've read that I should save state in the state map. However when the MQTT library calls back in def mqttClientStatus(String message), there is no state or atomicState variable, and as expected if I set any values on those variables, they do not make it out of that function. I added logging to def refresh(), so I can see if the value made it out, and they do not. They are still the values I had set in configure().

If I am going to manage reconnections, I need to keep state like connected and retryCount, am I trying to access the state variable incorrectly? Should I be doing this another way?

Thanks

11

Assuming the state variable is defined somewhere earlier within the same driver (or app) and assigned a value before it is again referenced, and not reinitialized again for example in configure() .

def state.myVar = "fred"

later in code

state.myVar="john"

log.info "State myVar is $state.myVar"   
log.info "State myVar is " + state.myVar

outputs to the log

State myVar is john
State myVar is john

Do check configure() is not running more often than you expect... maybe in initialize() is a better place.

state variables and their current values show in the device's Hubitat webpage too. You will have to refresh [F5] on that page to see changes

image

12

I believe I have the syntax correct. The problem appears to be that state isn't defined inside mqttClientStatus(String message)?

For example, here is my log output:

Blockquote
dev:1622019-12-18 08:03:17.342 pm debug refresh: state is [connected:false, retryCount:0]
dev:1622019-12-18 08:03:13.366 pm debug Configured
dev:1622019-12-18 08:03:13.358 pm debug mqttClientStatus: finish state: [connected:true, lastMQTTStatus:Status: Connection succeeded]
dev:1622019-12-18 08:03:13.356 pm debug mqttClientStatus: start state: [connected:false]
dev:1622019-12-18 08:03:13.332 pm debug Connecting...
dev:1622019-12-18 08:03:13.330 pm debug configure: state is [connected:false, retryCount:0]

For the following code:

def refresh() {
    log.debug "refresh: state is ${state}"
}

def configure() {
    if (interfaces.mqtt.isConnected()) {
        interfaces.mqtt.disconnect()
    }
    state.connected = false
    state.retryCount = 0
    log.debug "configure: state is ${state}"
    connect()
    
    log.debug "Configured"
}


def connect() {
    log.debug "Connecting..."
    try {
        interfaces.mqtt.connect("tcp://127.0.01:1883", "hubitat-washerdryer", "hubitat",     "hubitatpwd")
    } catch (Exception e) {
        log.error "Can not connect: ${e}"
    }
}

def parse(String message) {
    def map = interfaces.mqtt.parseMessage(message)
	if (logEnable) log.debug "message is ${map}"
}

def mqttClientStatus(String message) {
    log.debug "mqttClientStatus: start state: ${state}"
    
    state.lastMQTTStatus = message
    
    if (message == "Status: Connection succeeded") {
        state.connected = true
    } else {
        log.warn "unknown mqttClientStatus: ${message}"
    }

    log.debug "mqttClientStatus: finish state: ${state}"
}

You can see that the state logs as expected at the end of configure, but at the start of mqttClientStatus(String) retryCount is missing. The values I add do log at the end of mqqtClientStatus(String), but when I click refresh to trigger logging of state, connected is back to false, retryCount reappears, and the added lastMQTTStatus is gone.

Edit: I changed the MQTT server IP address, not really using localhost

13

Is that line throwing an error maybe as ${state} isn't what you want. if so no later lines will be executed.

add this line right at the end - does it log correctly ?

log.debug "mqttClientStatus: state is now: ${state.connected} / ${state.lastMQTTStatus}"

14

The method already has a log of state at the end, and the output has what I would expect. It is after the method completes and I trigger refresh that the values no longer print. If there was an exception inside mqttClientStatus(String), I would not expect the logging at the start and end of that function to be in the log.

15

I agree but you are using ${state} not a specific variable like ${state.connected}

Here is my method - ignore the events.. and the unusual log variant

void mqttClientStatus(String message) {
    status=message.take(6)
    if (status=="Error:") {
        try {
            interfaces.mqtt.disconnect()  // clears buffers
        }
        catch (e)
        {
        }
        state.connected=false
        log ("Broker: ${message} Will restart in 5 seconds","ERROR")
        runIn (4,"adviseStatus")
        runIn (5,"reset")  
    }
    else {
        log ("Broker: ${message}","INFO")
        state.connected=true
        sendEvent (name: "presence", value: "present")
        sendEvent(name: "MQTTStatus", value: status, data: [message:message], isStateChange: true)  // allow continue
        // need to advise app have a connection to allow it to continue.
    }
}
16

I was previously logging the individual values, but found that logging the entire state map was easier. Same result though. That mqttClientStatus(String) starts out missing the retryCount value makes me think this is a different context of state.

With the timestamps removed, might be easier to see what comes and goes from the state map:

[debug] refresh: state is [connected:false, retryCount:0]
[debug] Configured
[debug] mqttClientStatus: finish state: [connected:true, lastMQTTStatus:Status: Connection succeeded]
[debug] mqttClientStatus: start state: [connected:false]
[debug] Connecting...
[debug] configure: state is [connected:false, retryCount:0]

I wrapped the previous content of the method in:

try {
} catch (Exception e) {
    log.warn "exception in mqttClientStatus: ${e}"
}

No exception was logged.

17

Does the finish state have state.connected within .. and is it correct ?
I wonder from the dev page ... "Just remember that all modifications done to state within a SmartApp or Device Handler are only written to external storage after the execution completes".

18

Interesting.

And you are using the changed value of state.connected outside of that method? Or is the state of the device driven by the runIn calls?

19

I use state.connected outside of that method and it is correct.. It updates correctly on the device page too. I assume you set state.connected = false prior to that method ?

20

I can get it to change in both logs and the device page when I change it anywhere but that callback. Very strange...