Autoconfigured device state not visible to HA

[tari]

Describe the bug

An autodiscovered device's state isn't visible to Home Assistant, so it can be turned on but not off (because HA doesn't see a state change from the device, so assumes nothing happened).

I'm not sure if this is a Tasmota problem or HA; I updated Tasmota to 6.4.0 (the release sonoff.bin) and HA to 0.84.3 at about the same time, after which I found state reporting wasn't working; prior to that, it did work.

Status 0 output:

07:41:05 MQT: sonoff-7994/stat/STATUS = {"Status":{"Module":8,"FriendlyName":["Sonoff S26 7994"],"Topic":"sonoff-7994","ButtonTopic":"0","Power":0,"PowerOnState":3,"LedState":1,"SaveData":1,"SaveState":1,"SwitchTopic":"0","SwitchMode":[0,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0}}
07:41:05 MQT: sonoff-7994/stat/STATUS1 = {"StatusPRM":{"Baudrate":115200,"GroupTopic":"sonoffs","OtaUrl":"http://thehackbox.org/tasmota/release/sonoff.bin","RestartReason":"Software/System restart","Uptime":"0T00:18:29","StartupUTC":"2018-12-19T07:22:36","Sleep":50,"BootCount":16,"SaveCount":60,"SaveAddress":"F8000"}}
07:41:05 MQT: sonoff-7994/stat/STATUS2 = {"StatusFWR":{"Version":"6.4.0(sonoff)","BuildDateTime":"2018-12-16T14:31:02","Boot":31,"Core":"2_4_2","SDK":"2.2.1(cfd48f3)"}}
07:41:05 MQT: sonoff-7994/stat/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["Needlecast-2G","Needlecast"],"TelePeriod":300,"SetOption":["000A8009","558180C0","00000220"]}}
07:41:05 MQT: sonoff-7994/stat/STATUS4 = {"StatusMEM":{"ProgramSize":521,"Free":480,"Heap":17,"ProgramFlashSize":1024,"FlashSize":1024,"FlashChipId":"146085","FlashMode":3,"Features":["00000809","0FDAE794","000383A0","23B617CE","00003BC0"]}}
07:41:05 MQT: sonoff-7994/stat/STATUS5 = {"StatusNET":{"Hostname":"sonoff-7994-7994","IPAddress":"192.168.127.155","Gateway":"192.168.127.1","Subnetmask":"255.255.255.0","DNSServer":"192.168.127.1","Mac":"EC:FA:BC:9C:5F:3A","Webserver":2,"WifiConfig":3}}
07:41:05 MQT: sonoff-7994/stat/STATUS6 = {"StatusMQT":{"MqttHost":"hass.taricorp.net","MqttPort":1883,"MqttClientMask":"sonoff-7994","MqttClient":"sonoff-7994","MqttUser":"sonoff-7994","MqttType":1,"MAX_PACKET_SIZE":1000,"KEEPALIVE":15}}
07:41:05 MQT: sonoff-7994/stat/STATUS7 = {"StatusTIM":{"UTC":"Wed Dec 19 07:41:05 2018","Local":"Wed Dec 19 07:41:05 2018","StartDST":"Sun Mar 25 02:00:00 2018","EndDST":"Sun Oct 28 03:00:00 2018","Timezone":"+00:00","Sunrise":"07:39","Sunset":"15:54"}}
07:41:05 MQT: sonoff-7994/stat/STATUS10 = {"StatusSNS":{"Time":"2018-12-19T07:41:05"}}
07:41:05 MQT: sonoff-7994/stat/STATUS11 = {"StatusSTS":{"Time":"2018-12-19T07:41:05","Uptime":"0T00:18:29","Vcc":3.552,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER":"OFF","Wifi":{"AP":1,"SSId":"Needlecast-2G","BSSId":"32:B5:C2:09:62:01","Channel":11,"RSSI":100}}}

To Reproduce

Enable options 19 and 55 for MQTT discovery and abbreviation, connect to MQTT with HA connected to the same broker.

Expected behavior

The device is discovered by HA and its state is correctly reported.

Additional context

I suspect this may actually be a HA bug, possibly caused by home-assistant/core#19010 or another change that's new in 0.84, but haven't been able to isolate it yet. There wasn't any obvious change when I temporarily downgraded to HA 0.83, but I didn't spend long poking at that version.

A sample exchange of messages, with the two power on commands coming from HA and the power off result is me manually turning it off via the web interface:

sonoff-7994/cmnd/POWER ON
tele/sonoff-7994/STATE {"Time":"2018-12-19T07:31:13","Uptime":"0T00:08:37","Vcc":3.552,"SleepMode":"Dynamic","Sleep":
50,"LoadAvg":19,"POWER":"ON","Wifi":{"AP":1,"SSId":"Needlecast-2G","BSSId":"32:B5:C2:09:62:01","Channel":11,"RSSI":96
}}
stat/sonoff-7994/RESULT {"POWER":"ON"}
stat/sonoff-7994/POWER ON
sonoff-7994/tele/STATE {"Time":"2018-12-19T07:31:22","Uptime":"0T00:08:46","Vcc":3.552,"SleepMode":"Dynamic","Sleep":
50,"LoadAvg":19,"POWER":"OFF","Wifi":{"AP":1,"SSId":"Needlecast-2G","BSSId":"32:B5:C2:09:62:01","Channel":11,"RSSI":9
2}}
sonoff-7994/stat/RESULT {"POWER":"OFF"}
sonoff-7994/stat/POWER OFF
sonoff-7994/tele/STATE {"Time":"2018-12-19T07:32:50","Uptime":"0T00:10:14","Vcc":3.552,"SleepMode":"Dynamic","Sleep":
50,"LoadAvg":19,"POWER":"OFF","Wifi":{"AP":1,"SSId":"Needlecast-2G","BSSId":"32:B5:C2:09:62:01","Channel":11,"RSSI":9
4}}

The autoconfiguration messages look okay at a glance (all empty except this one):

homeassistant/switch/9C5F3A_RL_1/config {"name":"Sonoff S26 7994","cmd_t":"~cmnd/POWER","stat_t":"~tele/STATE","val_t
pl":"{{value_json.POWER}}","pl_off":"OFF","pl_on":"ON","avty_t":"~tele/LWT","pl_avail":"Online","pl_not_avail":"Offli
ne","uniq_id":"9C5F3A_RL_1","device":{"identifiers":["9C5F3A"],"name":"Sonoff S26 7994","model":"Sonoff S2X","sw_vers
ion":"6.4.0(sonoff)","manufacturer":"Tasmota"}, "~":"sonoff-7994/"}

[tari]

On further inspection, state responses appear to be coming back on the wrong topic. Commands are going to ~cmnd/POWER, and state responses come back on stat/#. When switched via the web interface however, the state is reported on the correct topic.

I think I didn't notice this behavior before because I had somehow enabled option 19 and kept the default fulltopic instead of it automatically switching to %topic%/%prefix%/ so it was still using the same topic for both.

[Jason2866]

Not a Tasmota issue. Check your HA configuration and/or open a issue in HA github.

[ascillato2]

Closing this issue as it has been answered.

Support Information

See Wiki for more information.
See Chat for more user experience.

[tari]

I'm confused- are you saying that it's a HA misconfiguration that it can't see state on a topic it hasn't been told about? The command comes in on sonoff-7994/cmnd/POWER and response goes back out on tele/sonoff-7994/STATE, which is different from what autoconfiguration says (sonoff-7994/tele/STATE) and what it publishes when manually actuated (which is the correct topic).

I don't see how that can possibly be a HA issue, when Tasmota is publishing on a topic it hasn't said anything about.

[ascillato]

please try SetOption59 1

[tari]

Option 59 is apparently already enabled.

[ascillato]

apparently ?

Have you tried writing SetOption59 on the console?

[tari]

Yes, that's where I got that it was enabled:

20:40:09 CMD: SetOption59
20:40:09 MQT: sonoff-7994/stat/RESULT = {"SetOption59":"ON"}

I said apparently because I didn't expect it to be; sorry for any confusion there.

[ascillato]

Ok, do the following to delete retained messages on Home Assistant:

Go to the Tasmota console and type:

setoption55 0
setoption59 0
setoption19 0
restart 1

After restart do:

setoption19 1

[tari]

Options off:

sonoff-7994/stat/RESULT {"SetOption1":"OFF"}
sonoff-7994/stat/RESULT {"SetOption59":"OFF"}
homeassistant/light/9C5F3A_LI_1/config (null)
homeassistant/switch/9C5F3A_RL_1/config (null)
homeassistant/light/9C5F3A_LI_2/config (null)
homeassistant/switch/9C5F3A_RL_2/config (null)
homeassistant/light/9C5F3A_LI_3/config (null)
homeassistant/switch/9C5F3A_RL_3/config (null)
homeassistant/light/9C5F3A_LI_4/config (null)
homeassistant/switch/9C5F3A_RL_4/config (null)
homeassistant/light/9C5F3A_LI_5/config (null)
homeassistant/switch/9C5F3A_RL_5/config (null)
homeassistant/light/9C5F3A_LI_6/config (null)
homeassistant/switch/9C5F3A_RL_6/config (null)
homeassistant/light/9C5F3A_LI_7/config (null)
homeassistant/switch/9C5F3A_RL_7/config (null)
homeassistant/light/9C5F3A_LI_8/config (null)
homeassistant/switch/9C5F3A_RL_8/config (null)
sonoff-7994/stat/RESULT {"SetOption19":"OFF"}

Restart:

sonoff-7994/stat/RESULT {"Restart":"Restarting"}
sonoff-7994/tele/LWT Online
sonoff-7994/tele/INFO1 {"Module":"Sonoff S2X","Version":"6.4.0(sonoff)","FallbackTopic":"sonoff-7994","GroupTopic":"sonoffs"}
sonoff-7994/tele/INFO2 {"WebServerMode":"Admin","Hostname":"sonoff-7994-7994","IPAddress":"192.168.127.155"}
sonoff-7994/tele/INFO3 {"RestartReason":"Software/System restart"}
sonoff-7994/stat/RESULT {"POWER":"OFF"}
sonoff-7994/stat/POWER OFF
sonoff-7994/tele/STATE {"Time":"2018-12-20T06:49:01","Uptime":"0T00:00:14","Vcc":3.560,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER":"OFF","Wifi":{"AP":1,"SSId":"Needlecast-2G","BSSId":"32:B5:C2:09:62:01","Channel":11,"RSSI":82}}

Option 19 back on:

homeassistant/light/9C5F3A_LI_1/config (null)
homeassistant/switch/9C5F3A_RL_1/config {"name":"Sonoff S26 7994","cmd_t":"~cmnd/POWER","stat_t":"~tele/STATE","val_tpl":"{{value_json.POWER}}","pl_off":"OFF","pl_on":"ON","avty_t":"~tele/LWT","pl_avail":"Online","pl_not_avail":"Offline","uniq_id":"9C5F3A_RL_1","device":{"identifiers":["9C5F3A"],"name":"Sonoff S26 7994","model":"Sonoff S2X","sw_version":"6.4.0(sonoff)","manufacturer":"Tasmota"}, "~":"sonoff-7994/"}
homeassistant/light/9C5F3A_LI_2/config (null)
homeassistant/switch/9C5F3A_RL_2/config (null)
homeassistant/light/9C5F3A_LI_3/config (null)
homeassistant/switch/9C5F3A_RL_3/config (null)
homeassistant/light/9C5F3A_LI_4/config (null)
homeassistant/switch/9C5F3A_RL_4/config (null)
homeassistant/light/9C5F3A_LI_5/config (null)
homeassistant/switch/9C5F3A_RL_5/config (null)
homeassistant/light/9C5F3A_LI_6/config (null)
homeassistant/switch/9C5F3A_RL_6/config (null)
homeassistant/light/9C5F3A_LI_7/config (null)
homeassistant/switch/9C5F3A_RL_7/config (null)
homeassistant/light/9C5F3A_LI_8/config (null)
homeassistant/switch/9C5F3A_RL_8/config (null)
sonoff-7994/stat/RESULT {"SetOption19":"ON"}

---

Turn the power on via Home Assistant again:

sonoff-7994/cmnd/POWER ON
tele/sonoff-7994/STATE {"Time":"2018-12-20T06:51:51","Uptime":"0T00:03:04","Vcc":3.552,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER":"ON","Wifi":{"AP":1,"SSId":"Needlecast-2G","BSSId":"32:B5:C2:09:62:01","Channel":11,"RSSI":82}}
stat/sonoff-7994/RESULT {"POWER":"ON"}
stat/sonoff-7994/POWER ON

State messages in response to commands over MQTT remain on the wrong topic. States reported when I use the toggle button in the web interface remain correct (and are reflected in the Home Assistant UI as expected):

sonoff-7994/tele/STATE {"Time":"2018-12-20T06:54:08","Uptime":"0T00:05:21","Vcc":3.552,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER":"ON","Wifi":{"AP":1,"SSId":"Needlecast-2G","BSSId":"32:B5:C2:09:62:01","Channel":11,"RSSI":86}}
sonoff-7994/stat/RESULT {"POWER":"ON"}
sonoff-7994/stat/POWER ON
sonoff-7994/tele/STATE {"Time":"2018-12-20T06:54:18","Uptime":"0T00:05:31","Vcc":3.552,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER":"OFF","Wifi":{"AP":1,"SSId":"Needlecast-2G","BSSId":"32:B5:C2:09:62:01","Channel":11,"RSSI":88}}
sonoff-7994/stat/RESULT {"POWER":"OFF"}
sonoff-7994/stat/POWER OFF

[ascillato]

Ok, so that is weird. I can not reproduce that. In order to solve your issue please, erase all flash with esptool.py as explained in the wiki and flash again with the precompiled bins from release.

[tari]

This device was just flashed with full erase as described and release binaries, so I don't think that will help.

I have another one of these devices that exhibits the same problem. To reproduce, I can do the following:

1. Reset configuration to defaults and reconnect to network
2. Configure MQTT, setting the client and user to sonoff-3376, topic to sonoff-3376 and full topic to %topic%/%prefix%/
3. Manually send a message to it to turn on

sonoff-3376/cmnd/POWER ON
stat/sonoff-3376/RESULT {"POWER":"ON"}
stat/sonoff-3376/POWER ON

It turns on, but the response is on the wrong topic. This doesn't seem specific to autodiscovery.

[tari]

I think I found the problem, digging through code.

The web UI and MQTT handlers both invoke ExecuteCommandPower, which calls GetTopic_P to determine what topic to publish on. GetTopic_P predicates its choice of topic on the fallback_topic_flag, which is set in MqttDataHandler at line 470 and cleared immediately after the handler calls ExecuteCommandPower.

The fallback flag is set if the received message's topic contains the client ID, and in this case I've set the Client ID and Topic (%topic%) to the same value. Turns out this has bitten other people before as well, like #4190.

---

So while I can fix this by changing the client ID back to the default, I also think it's a bug that a substring search is used to determine whether a message has been received on the fallback or regular topic; it should instead include the cmnd prefix to avoid false positives like this.