S20 and basic switching on/off at MQTT reconnect

[sebastianlorenzen]

Hello all,

I'm having issues with my Sonoff devices on an unreliable connection to my MQTT broker.
Every time connection to the broker is lost ,regardless if Wifi is down or just something on the wire the Sonoff devices are switching unexpected on and off or vice versa.
Firmware used: 4.1.2
(There is an issue #314 for the old firmware with the same symptoms)

Snippet from the log (loglevel 3)

log from a S20: (Switches itself off after reconnect)
21:17:20 RSLT: DataCb Topic s20_01, Group 0, Index 1, Type POWER, Data ON (ON)
21:17:20 MQTT: stat/s20_01/RESULT = {"POWER":"ON"}
21:17:20 MQTT: stat/s20_01/POWER = ON (retained)
21:17:20 Config: Saved configuration (1364 bytes) to flash at F7 and count 594
21:18:35 MQTT: Attempting connection...
21:18:36 mDNS: Query done with 0 mqtt services found
21:18:36 MQTT: Connect FAILED to 192.168.x.x:1883, rc -2. Retry in 10 seconds
21:18:48 MQTT: Attempting connection...
21:18:49 mDNS: Query done with 0 mqtt services found
21:18:55 MQTT: Connect FAILED to 192.168.x.x:1883, rc -2. Retry in 10 seconds
-- snip ---
21:20:39 MQTT: Connected
21:20:39 MQTT: tele/s20_01/LWT = Online (retained)
21:20:39 MQTT: cmnd/s20_01/POWER =
21:20:39 RSLT: DataCb Topic s20_01, Group 0, Index 1, Type POWER, Data TOGGLE (TOGGLE)
21:20:39 MQTT: stat/s20_01/RESULT = {"POWER":"OFF"}
21:20:39 MQTT: stat/s20_01/POWER = OFF (retained)

the same from a basic: (Switches itself off and on after reconnect)
21:18:04 RSLT: DataCb Topic basic_02, Group 0, Index 1, Type POWER, Data TOGGLE (TOGGLE)
21:18:04 MQTT: stat/basic_02/RESULT = {"POWER":"ON"}
21:18:04 MQTT: stat/basic_02/POWER = ON (retained)
21:18:05 Config: Saved configuration (1364 bytes) to flash at F7 and count 466
21:18:36 MQTT: Attempting connection...
21:18:37 mDNS: Query done with 0 mqtt services found
21:18:37 MQTT: Connect FAILED to 192.168.x.x:1883, rc -2. Retry in 10 seconds
21:18:48 MQTT: Attempting connection...
21:18:49 mDNS: Query done with 0 mqtt services found
21:18:55 MQTT: Connect FAILED to 192.168.x.x:1883, rc -2. Retry in 10 seconds
-- snip --
21:20:39 MQTT: Connected
21:20:39 MQTT: tele/basic_02/LWT = Online (retained)
21:20:39 MQTT: cmnd/basic_02/POWER =
21:20:39 RSLT: DataCb Topic basic_02, Group 0, Index 1, Type POWER, Data TOGGLE (TOGGLE)
21:20:39 MQTT: stat/basic_02/RESULT = {"POWER":"OFF"}
21:20:39 MQTT: stat/basic_02/POWER = OFF (retained)
21:20:39 RSLT: DataCb Topic basic_02, Group 0, Index 1, Type POWER, Data TOGGLE (TOGGLE)
21:20:39 MQTT: stat/basic_02/RESULT = {"POWER":"ON"}
21:20:39 MQTT: stat/basic_02/POWER = ON (retained)

[davidelang]

can you increase the debugging level so we can see what's generating the command to change the state. you may have just cnipped a little too much here

[sebastianlorenzen]

To debug level 4? It is already set to level3.

Here another incident.
Copied from my syslog host I installed last night to monitor this.

08:02:00 S20_01 MQTT: tele/s20_01/UPTIME = {"Time":"2017-04-25T07:02:00", "Uptime":10}
08:03:40 S20_01 MQTT: Connected
08:03:40 S20_01 MQTT: tele/s20_01/LWT = Online (retained)
08:03:40 S20_01 MQTT: cmnd/s20_01/POWER =
08:03:40 S20_01 RSLT: DataCb Topic s20_01, Group 0, Index 1, Type POWER, Data TOGGLE (TOGGLE)
08:03:40 S20_01 MQTT: stat/s20_01/RESULT = {"POWER":"ON"}
08:03:40 S20_01 MQTT: stat/s20_01/POWER = ON (retained)

[davidelang]

On Tue, 25 Apr 2017, sebastianlorenzen wrote: To debug level 4?

yes.

Here another incident. Copied from my syslog host I installed last night to monitor this. 08:02:00 S20_01 MQTT: tele/s20_01/UPTIME = {"Time":"2017-04-25T07:02:00", "Uptime":10} 08:03:40 S20_01 MQTT: Connected 08:03:40 S20_01 MQTT: tele/s20_01/LWT = Online (retained) 08:03:40 S20_01 MQTT: cmnd/s20_01/POWER =

This is showing a request for the status

08:03:40 S20_01 RSLT: DataCb Topic s20_01, Group 0, Index 1, Type POWER, Data TOGGLE (TOGGLE)

but this then seems to indicate that it's processing a command to toggle the status. we need to see the most detailed logs between them (this may be a bug that's snuck in, but we need to eliminate any possibility that something external is issuing the toggle command)

…

08:03:40 S20_01 MQTT: stat/s20_01/RESULT = {"POWER":"ON"} 08:03:40 S20_01 MQTT: stat/s20_01/POWER = ON (retained)

[sebastianlorenzen]

Ok, set to level 4.

I switch the snonoffs with toggle command from my home automation (FHEM)
Thus I just need to define one action for a push button. -> send toggle.

[sebastianlorenzen]

Small update:
double checked my Mosquitto MQTT configuration. Persistence was set to true. Disabled it.
Wondering why this was enabled as this is not the default.

since then no more issues. I saw reconnects in the log, but no toggle or on/off

[davidelang]

glad you solved your problem

[dariosm]

@sebastianlorenzen I'm discussing in another thread about persistence in mosquitto.conf and other "power state" staff.
I saw you disabled persistence in order to solve on/off issues, I'm wondering if you experienced any side effect, like losing track of the sonoff state in other mqtt clients subscribed to the topics to be aware of and show the sonoff state (like Home Assistant).

[garymcleanuk]

I still have the same on going issue..
It seems when setting the relay on or off on the sonoff it sends the stat message to mqtt broker

When using hass, homeassisstant sends the cmnd command to the sonoff. This is retained on mqtt and takes priority over that stat status that the sonoff reports to mqtt and in tele

When the sonoff looses the connection to mqtt and comes back online, it always sets the relay on/off based on the last set cmnd command. Not the lasts stat message sent to the broker.