Bug in Sonoff S31

[swilson86]

There seems to be a bug in Sonoff S31 running Espurna 1.12.6 The JSON energy is always reported by MQTT as 2147483647 which is in binary a pile of exactly 1111111's.

I just made a pot of coffee for example and here are the beginning and ending results.

{"current":"6.025","voltage":"119","power":"707","energy":"2147483647",
"time":"2018-05-11 19:46:04","mac":"5C:CF:7F:7D:2A:F1","host":"Coffee",
"ip":"192.168.0.58","id":3023}

{"current":"0.000","voltage":"123","power":"0","energy":"2147483647",
"time":"2018-05-11 19:57:05","mac":"5C:CF:7F:7D:2A:F1","host":"Coffee",
"ip":"192.168.0.58","id":3038}

Resetting energy still results in that same exact number. It never changes!

[swilson86]

Hmmmm. The S31 is new and programmed it yesterday. For some reason it initialized with that huge energy number. Using the "energy reset to 0" didn't work, but unplugging it physically and plugging in again set the energy counter to zero. Strange... but the fix is to just unplug it and try it again checking that it reset to zero.

[swilson86]

I have programmed 2 of the S31 units with Espurna 1.12.6 setting them up with joules for energy units. One S31 is on a 600W coffee pot and the other on a washing machine. Both S31 units will suddenly jump to 2147483647 joules and stay there. That number is about 595 kW or enough energy to make coffee for an entire city! But I've only made 3 pots of coffee.

There is an overflow situation going on in your code I suspect. The clue is that 2147483647 in Hex is 7FFFFFFF

Here are a few lines from the debug module on the washing machine.

{"current":"0.000","voltage":"122","power":"0","energy":"2147483647","time":"2018-05-16 18:40:49","mac":"5C:CF:7F:7D:1C:4E","host":"Washing Machine","ip":"192.168.0.57","id":13766} (PID 1)
[958718] [MQTT] Sending Washing Machine/status => 1 (PID 1)
[958824] [MQTT] Sending Washing Machine/data => {"app":"ESPURNA","version":"1.12.6","board":"ITEAD_SONOFF_S31","host":"Washing Machine","ip":"192.168.0.57","mac":"5C:CF:7F:7D:1C:4E","rssi":"-80","uptime":"488958","datetime":"2018-05-16 18:41:08","freeheap":"20392","relay/0":"1","vcc":"3196","loadavg":"1","time":"2018-05-16 18:41:08","id":13767} (PID 1)

[swilson86]

I have captured the error on the debug window today. This time I setup the S31 using Espurna to display kWh for energy rather than joules. The washing machine starts and the watts display increases... the kWh start to move up slowly as it should and then.. BAM... a huge jump of over 6,000 kWh shows up in a matter of 2 minutes. Then it continues normally increasing as it should.

Both of my S31's do a similar thing. And eventually they reach a number that is out of range. I have 4 more S31's on the way and I have just setup MariaDB to capture and study this phenomenon further.

Here is the critical section of the debug display just as Espurna goes crazy...

[625023] [MQTT] Sending Washing Machine/status => 1 (PID 1)
[625129] [MQTT] Sending Washing Machine/data => {"app":"ESPURNA","version":"1.12.6","board":"ITEAD_SONOFF_S31","host":"Washing Machine","ip":"192.168.0.57","mac":"5C:CF:7F:7D:1C:4E","rssi":"-80","uptime":"89625","datetime":"2018-05-18 20:49:01","freeheap":"20672","relay/0":"1","vcc":"3196","loadavg":"1","time":"2018-05-18 20:49:01","id":18656} (PID 1)
[663922] [MQTT] Sending Washing Machine/data => {"current":"0.635","voltage":"124","power":"34","energy":"0.077","time":"2018-05-18 20:49:40","mac":"5C:CF:7F:7D:1C:4E","host":"Washing Machine","ip":"192.168.0.57","id":18657} (PID 1)
[723960] [MQTT] Sending Washing Machine/data => {"current":"1.734","voltage":"123","power":"169","energy":"0.078","time":"2018-05-18 20:50:40","mac":"5C:CF:7F:7D:1C:4E","host":"Washing Machine","ip":"192.168.0.57","id":18658} (PID 1)
[784027] [MQTT] Sending Washing Machine/data => {"current":"2.812","voltage":"123","power":"271","energy":"3426.725","time":"2018-05-18 20:51:40","mac":"5C:CF:7F:7D:1C:4E","host":"Washing Machine","ip":"192.168.0.57","id":18659} (PID 1)
[844065] [MQTT] Sending Washing Machine/data => {"current":"3.766","voltage":"122","power":"367","energy":"6168.045","time":"2018-05-18 20:52:40","mac":"5C:CF:7F:7D:1C:4E","host":"Washing Machine","ip":"192.168.0.57","id":18660} (PID 1)
[904120] [MQTT] Sending Washing Machine/data => {"current":"1.530","voltage":"123","power":"124","energy":"6168.049","time":"2018-05-18 20:53:40","mac":"5C:CF:7F:7D:1C:4E","host":"Washing Machine","ip":"192.168.0.57","id":18661} (PID 1)
[925032] [MQTT] Sending Washing Machine/status => 1 (PID 1)

[xoseperez]

I have been able to reproduce the issue but I still don't know the reason. I'm monitoring a S31 trying to find out when that happens.

[swilson86]

You may find you'll be drinking a lot of coffee!! My wife says "Why are you making so much coffee and asking me when I am doing the laundry again?" Bug analysis I tell her. "You're a geek" she says. Mmmm... ya! :)

[xoseperez]

LOL. I've been trying to trigger the issue again. I have it connected to a heater but so far I have not seen it again...

[xoseperez]

Got it. You were right and it was an overflow, I just didn't noticed it since I thought the variable will do the maths automatically, but apparently it doesn't...