sgupta999 / mqtt-bridge-smartthings

MQTT Bridge To SmartThings [MBS]
MIT License
27 stars 15 forks source link

ST not responding to Bridge, Duplicate Events? #26

Closed Epidurality closed 4 years ago

Epidurality commented 4 years ago

So the bridge is up and running. Updates from the ST app (or from whatever else controls the actual device) are correctly being sent to MQTT. However, I'm having problems giving commands to ST from MQTT. The bridge appears to be doing most of its job as the messages are being received and handled, but the command isn't being sent to ST.

Here's the log from when I set the Brightness of my light to 100% from the ST app, then tried to set it to 32% from my MQTT client.

Live Logging:

9:49:10 PM: debug Duplicate of last event, ignoring 'mbs-server' event '32' on attribute 'level' for device 'Desk Light' 9:49:10 PM: debug Duplicate of last event, ignoring 'mbs-server' event '32' on attribute 'level' for device 'Desk Light' 9:49:10 PM: debug Received device event from bridge: [command:false, name:Desk Light, type:level, value:32] 9:49:10 PM: debug Parsed '{"command":false,"name":"Desk Light","type":"level","value":"32"}' 9:49:05 PM: debug Received device event from bridge: [status:OK] 9:49:05 PM: debug Parsed '{"status":"OK"}' 9:49:05 PM: debug Parsed '{"status":"OK"}' 9:49:03 PM: debug Forwarding device event to bridge: {"path":"/push","body":{"name":"Desk Light","value":"100","type":"level"}} 9:49:03 PM: debug Received event 100 on attribute level for device Desk Light for BRIDGE 9:49:03 PM: debug Sending '{"path":"/push","body":{"name":"Desk Light","value":"100","type":"level"}}' to server 9:49:03 PM: debug Received event 100 on attribute level for device Desk Light for BRIDGE>

Same happens if I try publishing "../switch/set_state , 'off' " etc. I can see in the bridge's console that the messages are going through. Seems like it's handling the message, but throwing it out as a duplicate for some reason? The message shows in the console but not the error, I only see that in the Live Logging. Even if I wait several minutes between sending/receiving commands, the same behavior happens.

I checked for duplicate subscriptions that might have been confusing the bridge, but the console shows no duplicates under "ACTUAL SUBSCRIPTIONS". I am not using a devices.yml.

For reference I'm using a Tuya smart bulb for these tests (connected via Globe's new ST integration, not tasmota flashed). I also tried making a virtual device, same results. Ultimately plan to use some ESP8266 based projects communicating with MQTT, with this bridge being the connecting point to the rest of the system so I can control the ESPs from ST. I really appreciate your work and the work of stjohn.

sgupta999 commented 4 years ago

its only removing a duplicate if the last event received from either bridge to ST OR ST to bridge had the same attribute and value - otherwise we would get in a nasty loop. The duplicated check is being done in the MBS smartapp

from what your log shows it is doing exactly what it is supposed to do. so after you get duplicate for 32 try sending a 50 or something - i am sure that should work.

same thing with off / on - typically ST has its own engine where it will not trigger a new event for a duplicate event but if ST initiates an event say switch on - it then goes to server, asks MQTT to turn switch on.

When MQTT broker actually turns switch on then the MBS-server gets an on event (since we are listening to all on events on the devices) and that gets sent to ST and it has to ignore it because otherwise it would be an infinite loop.

Epidurality commented 4 years ago

Understood, but I'm not sending it duplicate events. The first events from the log stamped 09:49:03 were from me changing the light brightness to 100% in ST. At 09:49:10, I tried sending a new brightness level of 30 via mqtt. It did not change the brightness.

The same behaviour happens no matter what is sent before, any valid command I send to the bridge from the MQTT client results in this "duplicate event" message, and nothing happening to the bulb.

sgupta999 commented 4 years ago

can you send me some log from mbs-server side not the ST log

sgupta999 commented 4 years ago

what do you mean you are sending command to bridge from MQTT client? are you using another MQTT client to create an MQTT command

sgupta999 commented 4 years ago

I think i see what you might be doing - remember ST device is the virtual device. So if you are sending an MQTT command to MBS-server that command should be changing the brightness in the bulb, then reaches MBS-server which sends it to ST bridge to make sure the change is reflected in ST virtual device. As the ST virtual devices brightness is changed it generates the event that is being captured as the duplicate event i think.

If that is not the case i am not sure what you mean by

At 09:49:10, I tried sending a new brightness level of 30 via mqtt. It did not change the brightness.

that would only be sent to via MQTT if the actual physical devices brightness has been change to 30 - because thats the topic that the MBS-server is subscribed to

Epidurality commented 4 years ago

Eventually it will be a virtual device reflecting the status of my ESP devices, but right now I'm getting things set up and working with an actual Tuya bulb set up natively (through the Globe Suite integration) in SmartThings. It's a light bulb above me, fully controlled and working through ST. What I'm attempting to do is send commands to that bulb from MQTT, through the bridge, through ST, to the bulb.

Here is an example. I first turned the light on, and set it to 100% (using the ST app). My room got brighter. Then, I used an MQTT client to publish to the set_state topic as follows:

smartthings/Desk Light/level/set_state, 25 smartthings/Desk Light/switch/set_state, off

The expected behavior is that my room should have gotten darker, then gone dark as the light turns off; but my bulb did not change. It's still on at full brightness. SmartThings also shows the bulb ON at 100%. The topics for switch/state and level/state did not change (still show 100, on). From what I can tell, the command isn't being processed by ST; the bridge seems to be throwing out any message sent to it from MQTT, despite receiving and handling the message.

Below is the bridge log:

2020-04-02 08:10:11 AM info: ===================================ACTUAL SUBSCRIPTIONS REQUESTED FROM SMARTAPP ============================================ 2020-04-02 08:10:11 AM info: Currently subscribed to smartthings/Desk Light/color/cmd, smartthings/Desk Light/color/set_state, smartthings/Desk Light/colorTemperature/cmd, smartthings/Desk Light/colorTemperature/set_state, smartthings/Desk Light/hue/cmd, smartthings/Desk Light/hue/set_state, smartthings/Desk Light/level/cmd, smartthings/Desk Light/level/set_state, smartthings/Contacts/notify/cmd, smartthings/Contacts/notify/set_state, smartthings/System/notify/cmd, smartthings/System/notify/set_state, smartthings/Desk Light/saturation/cmd, smartthings/Desk Light/saturation/set_state, smartthings/Desk Light/switch/cmd, smartthings/Desk Light/switch/set_state 2020-04-02 08:10:11 AM info: ============================================================================================================================ 2020-04-02 08:10:11 AM info: Saving current state 2020-04-02 08:10:11 AM info: Connecting to MQTT at mqtt://192.168.1.45 2020-04-02 08:10:11 AM info: Subscribing to - [ 'smartthings/Desk Light/color/cmd', 'smartthings/Desk Light/color/set_state', 'smartthings/Desk Light/colorTemperature/cmd', 'smartthings/Desk Light/colorTemperature/set_state', 'smartthings/Desk Light/hue/cmd', 'smartthings/Desk Light/hue/set_state', 'smartthings/Desk Light/level/cmd', 'smartthings/Desk Light/level/set_state', 'smartthings/Contacts/notify/cmd', 'smartthings/Contacts/notify/set_state', 'smartthings/System/notify/cmd', 'smartthings/System/notify/set_state', 'smartthings/Desk Light/saturation/cmd', 'smartthings/Desk Light/saturation/set_state', 'smartthings/Desk Light/switch/cmd', 'smartthings/Desk Light/switch/set_state' ] 2020-04-02 08:10:11 AM info: Configuring autosave 2020-04-02 08:10:11 AM info: Configuring API 2020-04-02 08:10:11 AM info: Listening at http://localhost:8080 2020-04-02 08:10:15 AM debug: From ST: - switch - on 2020-04-02 08:10:15 AM debug: Device from SmartThings: smartthings/Desk Light/switch/state = on 2020-04-02 08:10:15 AM info: ST --> MQTT: [Desk Light][switch][on] [smartthings/Desk Light/switch/state][on] 2020-04-02 08:10:20 AM debug: From ST: - level - 100 2020-04-02 08:10:20 AM debug: Device from SmartThings: smartthings/Desk Light/level/state = 100 2020-04-02 08:10:20 AM info: ST --> MQTT: [Desk Light][level][100] [smartthings/Desk Light/level/state][100] 2020-04-02 08:10:58 AM debug: From MQTT: smartthings/Desk Light/level/set_state = 25 2020-04-02 08:10:58 AM info: MQTT --> ST - Topic: [smartthings/Desk Light/level/set_state][25] [Desk Light][level][25] 2020-04-02 08:11:12 AM debug: From MQTT: smartthings/Desk Light/switch/set_state = off 2020-04-02 08:11:12 AM info: MQTT --> ST - Topic: [smartthings/Desk Light/switch/set_state][off] [Desk Light][switch][off]

And the corresponding ST Live Logging for the same events:

8:11:13 AM: debug Duplicate of last event, ignoring 'mbs-server' event 'off' on attribute 'switch' for device 'Desk Light' 8:11:13 AM: debug Duplicate of last event, ignoring 'mbs-server' event 'off' on attribute 'switch' for device 'Desk Light' 8:11:13 AM: debug Received device event from bridge: [command:false, name:Desk Light, type:switch, value:off] 8:11:13 AM: debug Parsed '{"command":false,"name":"Desk Light","type":"switch","value":"off"}' 8:10:59 AM: debug Duplicate of last event, ignoring 'mbs-server' event '25' on attribute 'level' for device 'Desk Light' 8:10:59 AM: debug Duplicate of last event, ignoring 'mbs-server' event '25' on attribute 'level' for device 'Desk Light' 8:10:59 AM: debug Received device event from bridge: [command:false, name:Desk Light, type:level, value:25] 8:10:58 AM: debug Parsed '{"command":false,"name":"Desk Light","type":"level","value":"25"}' 8:10:20 AM: debug Received device event from bridge: [status:OK] 8:10:20 AM: debug Parsed '{"status":"OK"}' 8:10:20 AM: debug Forwarding device event to bridge: {"path":"/push","body":{"name":"Desk Light","value":"100","type":"level"}} 8:10:20 AM: debug Received event 100 on attribute level for device Desk Light for BRIDGE 8:10:20 AM: debug Sending '{"path":"/push","body":{"name":"Desk Light","value":"100","type":"level"}}' to server 8:10:20 AM: debug Sending '{"path":"/push","body":{"name":"Desk Light","value":"100","type":"level"}}' to server 8:10:15 AM: debug Received device event from bridge: [status:OK] 8:10:15 AM: debug Parsed '{"status":"OK"}' 8:10:14 AM: debug Forwarding device event to bridge: {"path":"/push","body":{"name":"Desk Light","value":"on","type":"switch"}} 8:10:14 AM: debug Received event on on attribute switch for device Desk Light for BRIDGE 8:10:14 AM: debug Sending '{"path":"/push","body":{"name":"Desk Light","value":"on","type":"switch"}}' to server 8:10:14 AM: debug Sending '{"path":"/push","body":{"name":"Desk Light","value":"on","type":"switch"}}' to server

sgupta999 commented 4 years ago

[command:false, name:Desk Light, type:switch, value:off]

this tells me that you are not using the devices.yml but the legacy hass.io implementation that I am supporting in this form without modification.

that has some weird logic around level and switch.

are you using devices.yml - if you are send me a version but the log is telling me the hass.io legacy implementation is doing something weird. Another person had a somewhat similar issue - check one of the closed issues.

My suggestion would be to use devices.yml - as that offers a lot more functionality and flexibility

Epidurality commented 4 years ago

Correct, I currently have deviceconfig: false in my config.yml. When I try to set up a simple device.yml (see below) and set deviceconfig: true, this is the output I get from the bridge console:

Device.yml (indents get lost with the formatting of quote, but it's indented properly I think based on the examples)

Desk Light: subscribe: switch:
smartthings/Desk Light/set_switch_state: command: 'OFF': 'off' 'ON': 'on' publish: switch: smartthings/Desk Light/switch_state: command: 'off': 'OFF' 'on': 'ON' retain: 'false'

Bridge console:

2020-04-02 09:42:24 AM info: Loading Device configuration 2020-04-02 09:42:24 AM debug: Loading config for Device 2020-04-02 09:42:24 AM debug: Subscription smartthings/Desk Light/set_switch_state [Desk Light],[switch],[{ OFF: 'off', ON: 'on' }] 2020-04-02 09:42:24 AM debug: Subscription: smartthings/Desk Light/set_switch_state - Device { 'Desk Light': [Object] } 2020-04-02 09:42:24 AM info: ============================ALL POSSIBLE SUBSCRIPTIONS FROM ALL EXTERNAL DEVICES =========================================== 2020-04-02 09:42:24 AM info: Subscription smartthings/Desk Light/set_switch_state [Desk Light],[switch],[{"OFF":"off","ON":"on"}] 2020-04-02 09:42:24 AM info: ============================================================================================================================ 2020-04-02 09:42:24 AM info: ===================================ACTUAL SUBSCRIPTIONS REQUESTED FROM SMARTAPP ============================================ 2020-04-02 09:42:24 AM info: Currently subscribed to 2020-04-02 09:42:24 AM info: ============================================================================================================================ 2020-04-02 09:42:24 AM info: Saving current state 2020-04-02 09:42:24 AM info: Connecting to MQTT at mqtt://192.168.1.45 2020-04-02 09:42:24 AM info: Configuring autosave 2020-04-02 09:42:24 AM info: Configuring API 2020-04-02 09:42:24 AM info: Listening at http://localhost:8080

The bridge still publishes fine, but as you can see it's not actually subscribing to anything for some reason, so it isn't even getting MQTT messages. I'm not sure how to make the smartapp request this subscription?

I'm not sure the default Hass.io implementation of switch/level is the issue though. ColorTemperature, Hue, and Saturation attributes all responded the same: no commands being handled by ST because the Bridge is throwing them out as duplicates.

sgupta999 commented 4 years ago

for indent begin and close with the ``` (the ~ key without the shift) delete your state,json file. restart mbs-server save settings in ST app for the mbs-smartapp.

You also have to make that on MBS smartapp the default capability is there

"switches": [
    name: "Switch",
    capability: "capability.switch",
    attributes: [
        "switch"
    ],
    action: "actionOnOff"
],

and then from the smartapp config you have to select the switch (which I am assuming you aready did).

some redundant steps but just makes sure you follow it. Notice the default capability does not include level you can either add that to the switch capability or add the level capability from the mbs-smartapp-full

"levels": [
    name: "Switch Level",
    capability: "capability.switchLevel",
    attributes: [
        "level"
    ],
    action: "actionLevel"
],
sgupta999 commented 4 years ago

and the file is devices.yml not device.yml

Epidurality commented 4 years ago

Ah, thanks for the tip for formatting. Opening the SmartApp and clicking Save to get it to update was the trick to get the subscription. However it's having the same problem.

EDIT: I'm using the MBS SmartApp Full, so Switch and Level are both in there. For that bulb, the SmartApp has Switch, Switch Level, Color, and Color Temp as selected attributes (which I'm assuming is why they all populated using the hass.io style implementation). No other devices are set up on the bridge device, just this "Desk Light". I only added "switch" to the devices.yml as a simple test; I understand that level will not work with my current devices.yml, only switch. Trying to get the first blocks working before building on them.

ST Log:

10:37:44 AM: debug Duplicate of last event, ignoring 'mbs-server' event 'off' on attribute 'switch' for device 'Desk Light'
10:37:44 AM: debug Duplicate of last event, ignoring 'mbs-server' event 'off' on attribute 'switch' for device 'Desk Light'
10:37:44 AM: debug Duplicate of last event, ignoring 'mbs-server' event 'off' on attribute 'switch' for device 'Desk Light'
10:37:44 AM: debug Duplicate of last event, ignoring 'mbs-server' event 'off' on attribute 'switch' for device 'Desk Light'
10:37:44 AM: debug Received device event from bridge: [command:true, name:Desk Light, type:switch, value:off]
10:37:44 AM: debug Parsed '{"command":true,"name":"Desk Light","type":"switch","value":"off"}'

Bridge console:

2020-04-02 10:37:40 AM info: ===================================ACTUAL SUBSCRIPTIONS REQUESTED FROM SMARTAPP ============================================
2020-04-02 10:37:40 AM info: Currently subscribed to smartthings/Contacts/notify, smartthings/System/notify, smartthings/Desk Light/set_switch_state
2020-04-02 10:37:40 AM info: ============================================================================================================================
2020-04-02 10:37:40 AM info: Saving current state
2020-04-02 10:37:40 AM info: Connecting to MQTT at mqtt://192.168.1.45
2020-04-02 10:37:40 AM info: Subscribing to - [
  'smartthings/Contacts/notify',
  'smartthings/System/notify',
  'smartthings/Desk Light/set_switch_state'
]
2020-04-02 10:37:40 AM info: Configuring autosave
2020-04-02 10:37:40 AM info: Configuring API
2020-04-02 10:37:40 AM info: Listening at http://localhost:8080
2020-04-02 10:37:44 AM debug: From MQTT: smartthings/Desk Light/set_switch_state = OFF
2020-04-02 10:37:44 AM info: MQTT --> ST - Topic: [smartthings/Desk Light/set_switch_state][OFF]        [Desk Light][switch][off]

devices.yml

Desk Light:
  subscribe:
      switch:     
        smartthings/Desk Light/set_switch_state:
          command:
            'OFF': 'off'
            'ON': 'on'
  publish:
    switch:
      smartthings/Desk Light/switch_state:
        command:
          'off': 'OFF'
          'on': 'ON'
  retain: 'false'

Message sent from MQTT:

Topic: smartthings/Desk Light/set_switch_state
Payload: OFF
sgupta999 commented 4 years ago

pretty odd that you are getting the duplicate command 4 times. Just for the heck of this try replacing the switches section with this

"switches": [ name: "Switch", capability: "capability.switch", attributes: [ "switch" ], action: "actionOnOff", duplicate: "allow" ],

This will allow duplicates but could create other problems lets see. confused why you have only one MQTT->ST on server but in ST IDE you are seeing four duplicate commands. should only happen once - something funky going on.

Is this only happening with the 'off' event or also with the 'on' event?

this

Epidurality commented 4 years ago

Excerpt from modified MBS SmartApp Full in ST IDE:

    "stepSensor": [
        name: "Step Sensor",
        capability: "capability.stepSensor",
        attributes: [
            "steps",
            "goal"
        ]
    ],
    // These could be standardized Smartthings virtual switches or any other device that has MQTT functionality implemented
    "switches": [
        name: "Switch",
        capability: "capability.switch",
        attributes: [
            "switch"
        ],
        action: "actionOnOff",
        duplicate: "allow" // ==================Added to test duplicate message error============.
    ],
    "soundPressureLevel": [
        name: "Sound Pressure Level",

I then Updated the SmartApp through the IDE, Saved the SmartApp in the ST classic phone app, and restarted the bridge. Same result (though only 3 duplicate messages this time). Same result happens when sending the payloads "ON", "OFF", "GARBAGE" - literally anything I send which gets picked up by the bridge is resulting in the duplicate event messages, and nothing happening to the light bulb.

Just for the hell of it I commented out the return on the duplicate check completely under the bridgeHandler function:

                        if (capability.containsKey("action")) {                     
                            if (!eventCheck(device.displayName,json.type, json.value)) {
                                log.debug "Duplicate of last event, ignoring 'mbs-server' event '${json.value}' on attribute '${json.type}' for device '${device.displayName}'. BUT WE'RE IGNORING IT."
                                //log.debug "Duplicate of last event, ignoring 'mbs-server' event '${json.value}' on attribute '${json.type}' for device '${device.displayName}'"   
                                //return;
                            } 

Did the same update routine. IT WORKED! Sort of. The light can now be controlled, "OFF" turned it off and "ON" turned it on. However, this is still the log I'm getting from ST Live Logging:

11:43:07 AM: debug Duplicate of last event from device 'Desk Light', ignoring event 'off' on attribute 'switch' for device 'Desk Light'
11:43:07 AM: debug Received event off on attribute switch for device Desk Light for BRIDGE
11:43:07 AM: debug Calling action method actionOnOff, for attribute switch, for device Desk Light with payload off
11:43:07 AM: debug Duplicate of last event, ignoring 'mbs-server' event 'off' on attribute 'switch' for device 'Desk Light'. BUT WE'RE IGNORING IT.
911:43:07 AM: debug Duplicate of last event, ignoring 'mbs-server' event 'off' on attribute 'switch' for device 'Desk Light'
11:43:07 AM: debug Duplicate of last event, ignoring 'mbs-server' event 'off' on attribute 'switch' for device 'Desk Light'
11:43:07 AM: debug Received device event from bridge: [command:true, name:Desk Light, type:switch, value:off]
11:43:06 AM: debug Parsed '{"command":true,"name":"Desk Light","type":"switch","value":"off"}'

So it seems like there's something about the duplicate checking that isn't playing nicely with my setup.

sgupta999 commented 4 years ago

this could be an ST issue. Try replacing "state." with"atomicState." and "state?" with "atomicState?" in mbs-smartapp. (matchcase while replacing)

ST sometime corrupts state - i want to eliminate that as the issue

Epidurality commented 4 years ago

With state. and state? changed, I'm no longer getting duplicate errors, but it's also not actually performing any functions. I've got log.debugs set up in a few places in the SmartApp (like in eventCheck()) so it's clearly just not getting to certain points in the code now. Below is the eventCheck function, but "state." was changed to "atomicState." in several other places as well (11 places total, 2 places total for state? both in eventCheck below).

def eventCheck(device, attribute, value){
    // If last event was same return false, else store event and return true
    if ((atomicState?.events[device][attribute] == null) ||  (atomicState?.events[device][attribute]  != value)){
        log.debug "eventCheck returning TRUE";
        atomicState.events[device][attribute] = value;
        return true;
    }
    else {
        log.debug "eventCheck returning FALSE";
        return false;
    }
}

Entire ST log from an MQTT send: 12:32:14 PM: debug Parsed '{"command":true,"name":"Desk Light","type":"switch","value":"off"}'

So now it's not even getting to the point of checking for duplicates it seems.

sgupta999 commented 4 years ago

Yeah -atomicState is not a map so that is going to be an issue. Sorry for debugging this by hit and trial but perhaps you can try this.

revert back to state and in intialize()

add state.remove(events) before state.events = [:]; ST is corrupting state object that is why you are getting four duplicates instead of just one.

sgupta999 commented 4 years ago

sometime just deleting and re-adding the smartapp might help. But be careful sometime ST screws up on that too where smartapp is not completely deleted. Its a know issue with ST. Some state somewhere has gotten corrupted.

Epidurality commented 4 years ago
def initialize() {
    state.remove(events);
    state.events = [:];

Same behavior. Log now shows my extra debug logs:

12:59:31 PM: debug Duplicate of last event, ignoring 'mbs-server' event 'off' on attribute 'switch' for device 'Desk Light'
12:59:31 PM: debug eventCheck returning FALSE
12:59:31 PM: debug Running eventCheck under bridgeHandler on event 'off' on attribute 'switch' for device 'Desk Light'
12:59:31 PM: debug Duplicate of last event, ignoring 'mbs-server' event 'off' on attribute 'switch' for device 'Desk Light'
12:59:31 PM: debug eventCheck returning FALSE
12:59:31 PM: debug Running eventCheck under bridgeHandler2 on event 'off' on attribute 'switch' for device 'Desk Light'
12:59:31 PM: debug Duplicate of last event, ignoring 'mbs-server' event 'off' on attribute 'switch' for device 'Desk Light'
12:59:31 PM: debug eventCheck returning FALSE
12:59:31 PM: debug Running eventCheck under bridgeHandler2 on event 'off' on attribute 'switch' for device 'Desk Light'
12:59:30 PM: debug eventCheck returning TRUE
12:59:30 PM: debug Running eventCheck under bridgeHandler2 on event 'off' on attribute 'switch' for device 'Desk Light'
12:59:30 PM: debug Received device event from bridge: [command:true, name:Desk Light, type:switch, value:off]
12:59:30 PM: debug Parsed '{"command":true,"name":"Desk Light","type":"switch","value":"off"}'

I'll "start fresh" by uninstalling and reinstalling the app. I was having issues earlier where new apps and devices were essentially getting frozen in ST, not updating, not saving, not being able to be uninstalled. Seems like it takes a few hours for that to fix itself (rebooting the hub didn't help). Maybe me tinkering while it was in that stuck state caused some issues on the back end. I'll update when it re-installs and starts functioning again.

sgupta999 commented 4 years ago

somewhat surprised by your log.

11:43:07 AM: debug Duplicate of last event, ignoring 'mbs-server' event 'off' on attribute 'switch' for device 'Desk Light'. BUT WE'RE IGNORING IT. 911:43:07 AM: debug Duplicate of last event, ignoring 'mbs-server' event 'off' on attribute 'switch' for device 'Desk Light' 11:43:07 AM: debug Duplicate of last event, ignoring 'mbs-server' event 'off' on attribute 'switch' for device 'Desk Light'

the first two do not seem to be showing "BUT WE'RE IGNORING IT'.

Is it possible that a couple of orphan instances of mbs-smartapp are running - that would explain a lot.

Something weird going on with that - somewhere multiple instances are corrupting state.

Epidurality commented 4 years ago

The "BUT WE'RE IGNORING IT" was only placed on the first eventCheck call fail under bridgeHandler. I didn't add that text or any modifications beyond that point. The last log I posted is where I've put "Running eventCheck under [where the log.debug is placed] on event...." so it's clear which check is being performed from where. It's still possible that extra instances of this app are running due to the **ckery that ST was handing me yesterday and the day before. I'll see what I can do.

sgupta999 commented 4 years ago

you symptoms are consistent with what had happened to me and several others. i had to call ST to manually remove some apps.

One are to go and do this from is go to hubs under location and there is another menu for smartapp - uninstall from there.

I don't know where this log would surface under your current code Duplicate of last event, ignoring 'mbs-server' event 'off' on attribute 'switch' for device 'Desk Light'

that should happen only once each bridgehandler event is handled. its iterating through it at least 3 times and for two times it is not hitting your IGNORE debug

Epidurality commented 4 years ago

Apologies, I removed the "IGNORE" part in favor of the log.debug "Running eventCheck under bridgeHandler on event '${json.value}' on attribute '${json.type}' for device '${device.displayName}'". "bridgeHandler2" is right before the second eventCheck in bridgeHandler, and inputHandler is just before the eventCheck in inputHandler().

Basically anytime we see "bridgeHandler", it's because if (capability["attributes"].contains(json.type)) evaluated TRUE. If we see "bridgeHandler2" then it evaluated FALSE, and went to the else statement instead. I've also included one for inputHandler but we don't see that since we're working in the opposite direction.

The behavior of the reinstalled app is the same as it was yesterday; when I try to update the SmartApp from the phone app it just says "Sorry, but there was an unexpected error". The new MBS Device can't be updated with the ip/mac info until whatever this issue is goes away (also just spin-loops and comes up with a vague error); last 2 times it happened, it just took time to fix itself and start working properly.

sgupta999 commented 4 years ago

yeah unfortunately its going to take you at least a day or maybe more to do a clean uninstall and reinstall - happened to me with another app too ...

difficult to debug without that - check the bridge specific log in IDE too - may be add some debug statement there - if bridge is only sending event to smartapp once and its is processing it 3-4 times something is messed up with environment.

Epidurality commented 4 years ago

That did the trick! Created a new SmartApp instance with a new name, new device with a new name, and once the "Update" actually worked (took about 2 hours), this is now the log I get, and the light reacts correctly:

2:50:45 PM: debug Duplicate of last event from device 'Desk Light', ignoring event 'off' on attribute 'switch' for device 'Desk Light'
2:50:45 PM: debug eventCheck returning FALSE
2:50:45 PM: debug Potentially running eventCheck under inputHandler on event 'off' on attribute 'switch' for device 'Desk Light'
2:50:45 PM: debug Received event off on attribute switch for device Desk Light for BRIDGE
2:50:44 PM: debug Calling action method actionOnOff, for attribute switch, for device Desk Light with payload off
2:50:44 PM: debug eventCheck returning TRUE
2:50:44 PM: debug Running eventCheck under bridgeHandler on event 'off' on attribute 'switch' for device 'Desk Light'
2:50:44 PM: debug Received device event from bridge: [command:true, name:Desk Light, type:switch, value:off]
291560e0-8bb8-451d-9ff9-9540bf0c5ab1 2:50:44 PM: debug Parsed '{"command":true,"name":"Desk Light","type":"switch","value":"off"}'

When I remove my debugging (go back to a copy+paste of your original groovy code):

2:53:51 PM: debug Duplicate of last event from device 'Desk Light'; ignoring event 'off' on attribute 'switch' for device 'Desk Light'
2:53:51 PM: debug Received event off on attribute switch for device Desk Light for BRIDGE
2:53:51 PM: debug Calling action method actionOnOff, for attribute switch, for device Desk Light with payload off
2:53:51 PM: debug Received device event from bridge: [command:true, name:Desk Light, type:switch, value:off]
2:53:51 PM: debug Parsed '{"command":true,"name":"Desk Light","type":"switch","value":"off"}'

Thank you again for all your help! This would have been a pain to track down. I had already uninstalled and reinstalled the app, but I used the same Names when I did... so I'm guessing ST still has some ghost apps sitting somewhere I can't see that were still responding and screwing with the eventChecks, but not doing useful work.

I really appreciate the time you've put into this, both in creating the apps and helping the common folk to use them.