search

arendst / Tasmota

Alternative firmware for ESP8266 and ESP32 based devices with easy configuration using webUI, OTA updates, automation using timers or rules, expandability and entirely local control over MQTT, HTTP, Serial or KNX. Full documentation at
https://tasmota.github.io/docs
GNU General Public License v3.0
22.04k stars 4.78k forks source link

Unknown PowerState MqTT Reconnect = OFF #1250

Closed Scoobler closed 6 years ago

Scoobler commented 6 years ago

I have recently switched to Tasmota so may have missed something, but I have been testing the stability with a simple install on a POW. Uptime is around 24 hours, with no restarts showing. However last night I left the POW switched on, this morning it was switched off.

When viewing the logs, the reason seems to be a lost connection to the MqTT server (RiPi, openHAB). When the POW reconnected it didn't seem to know the power state (or it requested it from MqTT and as it was not retained), then turned the relay off.

Currently the MqTT retain's are all set to 0. Am I missing something obvious - I didn't wan't to rely on the MqTT broker to store the state of the relay - or is that currently the best option?

Program Version | 5.9.1

22:03:39 MQT: Connect failed to 10.0.0.5:1883, rc -2. Retry in 10 sec
22:03:50 MQT: Attempting connection...
22:03:50 MQT: Connected
22:03:50 MQT: tele/sonoff-pow/LWT = Online (retained)
22:03:50 MQT: cmnd/sonoff-pow/POWER = 
22:03:50 MQT: stat/sonoff-pow/RESULT = {"POWER":"OFF"}
22:03:50 MQT: stat/sonoff-pow/POWER = OFF
22:03:50 MQT: stat/sonoff-pow/STATUS8 = {"StatusPWR":{"Total":0.016, "Yesterday":0.000, "Today":0.015, "Power":0, "Factor":0.00, "Voltage":0, "Current":0.000}}
davidelang commented 6 years ago

read the wiki page on poweronstate and retained messages, i think that will give you the info you need to figure out what's happening in your case.

Scoobler commented 6 years ago

Thank-you for the pointer, I have had another read, but just want to clarify; I have PowerOnState 3 (last set state), which is what I’d expect to see maybe after a power cut whilst the MqTT server is rebooting for example. What I am seeing though is the relay change state if connection to the server has been lost, not a reboot. For that it is recommended to use the retain feature? So it’s a bit of a double backup to hopefully get the last set state?

davidelang commented 6 years ago

read the section on retained commands

Scoobler commented 6 years ago

Hi David, I did and it doesn’t clarify the problem, hence the question above to clarify.

https://github.com/arendst/Sonoff-Tasmota/wiki/PowerOnState-Configuration

Sorry if I’m reading the wrong section, but that makes it seem like you use one or the other.

However the PowerOnState option seems to be for reboots, NOT reconnects to the MqTT server?

davidelang commented 6 years ago

If the mqtt server is retaining a message, it will send it to the device every time it reconnects (no matter what poweronstate is set to)

so check and see if there are any retained messages for that device, and if needed, clear them.

Scoobler commented 6 years ago

Hi David,

So I checked and there were no retained messages. I actually got out a fresh new Sonoff and flashed Tasmota, switched it on then pulled the network plug from the MqTT server waited a moment and replugged the network cable. Once the Sonoff reconnected it turned the relay off. Again no retained messages, and checked all retain commands set to 0.

This seems unusual behaviour - I would expect the Sonoff to retain its state and on reconnecting simply push its current state - this way if the connection is down for any reason and the device has been operated via a manual switch it is the latest state that is maintained.

Imagine if you will, bedside lamp turned on while everything is up and working, connection to MqTT is lost so lamp is switched off with a manual button press. In a fresh setup when it reconnects (no retain settings enabled) it would switch the relay off - not a problem in this example. (However I’d retain was enabled, I would be woken up by a light coming on in the night as the last message on the server was ON).

Now imagine similar, power socket by the bed controlled by a Sonoff, come to bed switch on the socket via MqTT, plug phone/alarm in to wake me up in the morning, connection to the server is lost, now when it reconnects (no retains enabled) it switches off power, phone stops charging and alarm fails to go off. In this example enabling retain will mean the last message would turn the socket on as desired, but if it had been turned on manually with a switch due to no connection to the server, it would turn off on reconnecting.

This is why I was hoping not to have to rely on retained messages, it would be nice if when retain isn’t enabled, on reconnecting simply push the current state of the relays.

davidelang commented 6 years ago

what is your poweronstate setting? especially on the brand new one.

set logging to 'more debugging' and post the full log from bootup through the device switching it's state.

Scoobler commented 6 years ago

Unfortunately I have been doing some testing - I enabled all the Retain settings on the 6 devices, before thinking of the use case posted above - now after disabling the Retain settings again and clearing the retained messages from Mosquitto I can't replicate the issue. I have got 3 more Sonoffs on the way so will test when they arrive.

On a side note, the POW I am using won't pick up the NTP time - settings are there, it just won't get the time. I have loaded the exact same firmware on a Basic and on the POW - the Basic picks up the time, the POW doesn't seem to try:

The Basic:

 2017-11-29T12:19:57.230184+00:00 sonoff-basic-5-5110 ESP-MQT: tele/sonoff-basic-5/LWT = Online (retained)
2017-11-29T12:19:57.236925+00:00 sonoff-basic-5-5110 ESP-MQT: cmnd/sonoff-basic-5/POWER =
2017-11-29T12:19:57.237122+00:00 sonoff-basic-5-5110 ESP-MQT: Subscribe to cmnd/sonoff-basic-5/#
2017-11-29T12:19:57.242168+00:00 sonoff-basic-5-5110 ESP-MQT: Subscribe to cmnd/sonoffs/#
2017-11-29T12:19:57.289617+00:00 sonoff-basic-5-5110 ESP-MQT: Subscribe to cmnd/DVES_3C13F6/#
2017-11-29T12:19:57.301956+00:00 sonoff-basic-5-5110 ESP-MQT: tele/sonoff-basic-5/INFO1 = {"Module":"Sonoff Basic","Version":"5.9.1j","FallbackTopic":"DVES_3C13F6","GroupTopic":"sonoffs"}
2017-11-29T12:19:57.363545+00:00 sonoff-basic-5-5110 ESP-MQT: tele/sonoff-basic-5/INFO2 = {"WebServerMode":"Admin","Hostname":"sonoff-basic-5-5110","IPAddress":"10.0.0.39"}
2017-11-29T12:19:57.370229+00:00 sonoff-basic-5-5110 ESP-MQT: tele/sonoff-basic-5/INFO3 = {"RestartReason":"Software/System restart"}
2017-11-29T12:19:57.975801+00:00 sonoff-basic-5-5110 ESP-APP: (UTC) Wed Nov 29 12:19:57 2017
2017-11-29T12:19:57.976047+00:00 sonoff-basic-5-5110 ESP-APP: (DST) Sun Mar 26 02:00:00 2017
2017-11-29T12:19:57.978150+00:00 sonoff-basic-5-5110 ESP-APP: (STD) Sun Oct 29 03:00:00 2017
2017-11-29T12:19:58.557034+00:00 sonoff-basic-5-5110 ESP-MQT: stat/sonoff-basic-5/RESULT = {"POWER":"ON"}
2017-11-29T12:19:58.561826+00:00 sonoff-basic-5-5110 ESP-MQT: stat/sonoff-basic-5/POWER = ON

The POW:

2017-11-29T12:23:37.479646+00:00 sonoff-outlet-2450 ESP-MQT: tele/sonoff-outlet/LWT = Online (retained)
2017-11-29T12:23:37.484732+00:00 sonoff-outlet-2450 ESP-MQT: cmnd/sonoff-outlet/POWER =
2017-11-29T12:23:37.484957+00:00 sonoff-outlet-2450 ESP-MQT: Subscribe to cmnd/sonoff-outlet/#
2017-11-29T12:23:37.488717+00:00 sonoff-outlet-2450 ESP-MQT: Subscribe to cmnd/sonoffs/#
2017-11-29T12:23:37.538737+00:00 sonoff-outlet-2450 ESP-MQT: Subscribe to cmnd/DVES_922992/#
2017-11-29T12:23:37.550095+00:00 sonoff-outlet-2450 ESP-MQT: tele/sonoff-outlet/INFO1 = {"Module":"Sonoff Dev","Version":"5.9.1j","FallbackTopic":"DVES_922992","GroupTopic":"sonoffs"}
2017-11-29T12:23:37.599870+00:00 sonoff-outlet-2450 ESP-MQT: tele/sonoff-outlet/INFO2 = {"WebServerMode":"Admin","Hostname":"sonoff-outlet-2450","IPAddress":"10.0.0.30"}
2017-11-29T12:23:37.606606+00:00 sonoff-outlet-2450 ESP-MQT: tele/sonoff-outlet/INFO3 = {"RestartReason":"Software/System restart"}
2017-11-29T12:23:40.179343+00:00 sonoff-outlet-2450 ESP-HTP: Configure Module
2017-11-29T12:23:45.970912+00:00 sonoff-outlet-2450 ESP-MQT: tele/sonoff-outlet/STATE = {"Time":"1970-01-01T00:00:16","Uptime":0,"Vcc":3.163,"Wifi":{"AP":1,"SSId":"NetStarPro","RSSI":48,"APMac":"30:5A:3A:CE:48:38"}}
arendst commented 6 years ago

Compare the output of Status 5 regarding DNS server.

Scoobler commented 6 years ago

Hi Theo,

Here are the syslog's from the two devices (remote sysloging set to LOG_LEVEL_ALL) - the entry times are the remote server times - if viewed in the web console, each line also starts with the wrong time on the POW.

I have just flashed the firmware onto the basic followed by a status 5 (fresh download from Github 30 minutes ago (development branch)):

2017-11-29T14:29:58.924729+00:00 sonoff-basic-5-5110 ESP-WIF: Connected
2017-11-29T14:29:58.924950+00:00 sonoff-basic-5-5110 ESP-DNS: Initialized
2017-11-29T14:29:58.927988+00:00 sonoff-basic-5-5110 ESP-HTP: Web server active on sonoff-basic-5-5110.local with IP address 10.0.0.39
2017-11-29T14:29:59.774262+00:00 sonoff-basic-5-5110 ESP-CFG: Saved to flash at F9, Count 3, Bytes 1648
2017-11-29T14:30:00.126164+00:00 sonoff-basic-5-5110 ESP-MQT: Attempting connection...
2017-11-29T14:30:00.182636+00:00 sonoff-basic-5-5110 ESP-MQT: Connected
2017-11-29T14:30:00.229742+00:00 sonoff-basic-5-5110 ESP-MQT: tele/sonoff-basic-5/LWT = Online (retained)
2017-11-29T14:30:00.236862+00:00 sonoff-basic-5-5110 ESP-MQT: cmnd/sonoff-basic-5/POWER =
2017-11-29T14:30:00.238296+00:00 sonoff-basic-5-5110 ESP-MQT: Subscribe to cmnd/sonoff-basic-5/#
2017-11-29T14:30:00.245979+00:00 sonoff-basic-5-5110 ESP-MQT: Subscribe to cmnd/sonoffs/#
2017-11-29T14:30:00.302695+00:00 sonoff-basic-5-5110 ESP-MQT: Subscribe to cmnd/DVES_3C13F6/#
2017-11-29T14:30:00.314746+00:00 sonoff-basic-5-5110 ESP-MQT: tele/sonoff-basic-5/INFO1 = {"Module":"Sonoff Basic","Version":"5.9.1j","FallbackTopic":"DVES_3C13F6","GroupTopic":"sonoffs"}
2017-11-29T14:30:00.369497+00:00 sonoff-basic-5-5110 ESP-MQT: tele/sonoff-basic-5/INFO2 = {"WebServerMode":"Admin","Hostname":"sonoff-basic-5-5110","IPAddress":"10.0.0.39"}
2017-11-29T14:30:00.379701+00:00 sonoff-basic-5-5110 ESP-MQT: tele/sonoff-basic-5/INFO3 = {"RestartReason":"Software/System restart"}
2017-11-29T14:30:01.638282+00:00 sonoff-basic-5-5110 ESP-MQT: stat/sonoff-basic-5/RESULT = {"POWER":"OFF"}
2017-11-29T14:30:01.643641+00:00 sonoff-basic-5-5110 ESP-MQT: stat/sonoff-basic-5/POWER = OFF
2017-11-29T14:30:02.061766+00:00 sonoff-basic-5-5110 ESP-APP: (UTC) Wed Nov 29 14:30:01 2017
2017-11-29T14:30:02.061985+00:00 sonoff-basic-5-5110 ESP-APP: (DST) Sun Mar 26 02:00:00 2017
2017-11-29T14:30:02.061985+00:00 sonoff-basic-5-5110 ESP-APP: (STD) Sun Oct 29 03:00:00 2017
2017-11-29T14:30:04.763239+00:00 sonoff-basic-5-5110 ESP-HTP: Console
2017-11-29T14:30:08.742562+00:00 sonoff-basic-5-5110 ESP-MQT: tele/sonoff-basic-5/STATE = {"Time":"2017-11-29T14:30:08","Uptime":0,"Vcc":3.177,"POWER":"OFF","Wifi":{"AP":1,"SSId":"GetYourOwn","RSSI":84,"APMac":"38:5A:3A:CE:48:48"}}
2017-11-29T14:30:19.471352+00:00 sonoff-basic-5-5110 ESP-WIF: Checking connection...
2017-11-29T14:30:19.471556+00:00 sonoff-basic-5-5110 ESP-WIF: Connected
2017-11-29T14:30:33.411291+00:00 sonoff-basic-5-5110 ESP-CMD: status 5
2017-11-29T14:30:33.411496+00:00 sonoff-basic-5-5110 ESP-RSL: Received Topic /status, Data Size 1, Data 5
2017-11-29T14:30:33.411496+00:00 sonoff-basic-5-5110 ESP-RSL: Group 0, Index 1, Command STATUS, Data 5
2017-11-29T14:30:33.472437+00:00 sonoff-basic-5-5110 ESP-MQT: stat/sonoff-basic-5/STATUS5 = {"StatusNET":{"Hostname":"sonoff-basic-5-5110","IPAddress":"10.0.0.39","Gateway":"10.0.0.1","Subnetmask":"255.255.0.0","DNSServer":"10.0.0.1","Mac":"2C:3A:E8:3C:13:F6","Webserver":2,"WifiConfig":3}}

Now for a flash on the POW (followed by Status 5):

2017-11-29T14:37:17.340059+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/UPGRADE = Successful. Restarting
2017-11-29T14:37:34.146045+00:00 sonoff-outlet-2450 ESP-WIF: Connected
2017-11-29T14:37:34.146299+00:00 sonoff-outlet-2450 ESP-DNS: Initialized
2017-11-29T14:37:34.146299+00:00 sonoff-outlet-2450 ESP-HTP: Web server active on sonoff-outlet-2450.local with IP address 10.0.0.30
2017-11-29T14:37:35.010720+00:00 sonoff-outlet-2450 ESP-CFG: Saved to flash at F9, Count 3, Bytes 1648
2017-11-29T14:37:35.362869+00:00 sonoff-outlet-2450 ESP-MQT: Attempting connection...
2017-11-29T14:37:35.383807+00:00 sonoff-outlet-2450 ESP-MQT: Connected
2017-11-29T14:37:35.440213+00:00 sonoff-outlet-2450 ESP-MQT: tele/sonoff-outlet/LWT = Online (retained)
2017-11-29T14:37:35.451441+00:00 sonoff-outlet-2450 ESP-MQT: cmnd/sonoff-outlet/POWER =
2017-11-29T14:37:35.451653+00:00 sonoff-outlet-2450 ESP-MQT: Subscribe to cmnd/sonoff-outlet/#
2017-11-29T14:37:35.455212+00:00 sonoff-outlet-2450 ESP-MQT: Subscribe to cmnd/sonoffs/#
2017-11-29T14:37:35.508805+00:00 sonoff-outlet-2450 ESP-MQT: Subscribe to cmnd/DVES_922992/#
2017-11-29T14:37:35.517700+00:00 sonoff-outlet-2450 ESP-MQT: tele/sonoff-outlet/INFO1 = {"Module":"Sonoff Basic","Version":"5.9.1j","FallbackTopic":"DVES_922992","GroupTopic":"sonoffs"}
2017-11-29T14:37:35.570760+00:00 sonoff-outlet-2450 ESP-MQT: tele/sonoff-outlet/INFO2 = {"WebServerMode":"Admin","Hostname":"sonoff-outlet-2450","IPAddress":"10.0.0.30"}
2017-11-29T14:37:35.576214+00:00 sonoff-outlet-2450 ESP-MQT: tele/sonoff-outlet/INFO3 = {"RestartReason":"Software/System restart"}
2017-11-29T14:37:36.780098+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/RESULT = {"POWER":"OFF"}
2017-11-29T14:37:36.786684+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/POWER = OFF
2017-11-29T14:37:43.899802+00:00 sonoff-outlet-2450 ESP-MQT: tele/sonoff-outlet/STATE = {"Time":"1970-01-01T00:00:16","Uptime":0,"Vcc":3.162,"POWER":"OFF","Wifi":{"AP":1,"SSId":"GetYourOwn","RSSI":50,"APMac":"38:5A:3A:CE:48:48"}}
2017-11-29T14:37:51.271486+00:00 sonoff-outlet-2450 ESP-CMD: status 5
2017-11-29T14:37:51.271741+00:00 sonoff-outlet-2450 ESP-RSL: Received Topic /status, Data Size 1, Data 5
2017-11-29T14:37:51.271741+00:00 sonoff-outlet-2450 ESP-RSL: Group 0, Index 1, Command STATUS, Data 5
2017-11-29T14:37:51.333782+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS5 = {"StatusNET":{"Hostname":"sonoff-outlet-2450","IPAddress":"10.0.0.30","Gateway":"10.0.0.1","Subnetmask":"255.255.0.0","DNSServer":"10.0.0.1","Mac":"5C:CF:7F:92:29:92","Webserver":2,"WifiConfig":3}}
Scoobler commented 6 years ago

Here is also and NTPServer & Status 7 command for the basic:

2017-11-29T14:59:02.991397+00:00 sonoff-basic-5-5110 ESP-CMD: NTPServer
2017-11-29T14:59:02.991617+00:00 sonoff-basic-5-5110 ESP-RSL: Received Topic /ntpserver, Data Size 0, Data
2017-11-29T14:59:02.991617+00:00 sonoff-basic-5-5110 ESP-RSL: Group 0, Index 1, Command NTPSERVER, Data
2017-11-29T14:59:03.044268+00:00 sonoff-basic-5-5110 ESP-MQT: stat/sonoff-basic-5/RESULT = {"NtpServer1":"0.uk.pool.ntp.org"}
2017-11-29T14:59:03.825279+00:00 sonoff-basic-5-5110 ESP-WIF: Checking connection...
2017-11-29T14:59:03.825493+00:00 sonoff-basic-5-5110 ESP-WIF: Connected
2017-11-29T14:59:09.548623+00:00 sonoff-basic-5-5110 ESP-CMD: status 7
2017-11-29T14:59:09.548831+00:00 sonoff-basic-5-5110 ESP-RSL: Received Topic /status, Data Size 1, Data 7
2017-11-29T14:59:09.548831+00:00 sonoff-basic-5-5110 ESP-RSL: Group 0, Index 1, Command STATUS, Data 7
2017-11-29T14:59:09.558062+00:00 sonoff-basic-5-5110 ESP-MQT: stat/sonoff-basic-5/STATUS7 = {"StatusTIM":{"UTC":"Wed Nov 29 14:59:09 2017","Local":"Wed Nov 29 14:59:09 2017","StartDST":"Sun Mar 26 02:00:00 2017","EndDST":"Sun Oct 29 03:00:00 2017","Timezone":0}}

And for the POW:

2017-11-29T14:56:05.252282+00:00 sonoff-outlet-2450 ESP-CMD: NTPServer
2017-11-29T14:56:05.252509+00:00 sonoff-outlet-2450 ESP-RSL: Received Topic /NTPServer, Data Size 0, Data
2017-11-29T14:56:05.252509+00:00 sonoff-outlet-2450 ESP-RSL: Group 0, Index 1, Command NTPSERVER, Data
2017-11-29T14:56:05.257945+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/RESULT = {"NtpServer1":"0.uk.pool.ntp.org"}
2017-11-29T14:56:11.545525+00:00 sonoff-outlet-2450 ESP-WIF: Checking connection...
2017-11-29T14:56:11.545762+00:00 sonoff-outlet-2450 ESP-WIF: Connected
2017-11-29T14:56:12.245924+00:00 sonoff-outlet-2450 ESP-CMD: status 7
2017-11-29T14:56:12.246150+00:00 sonoff-outlet-2450 ESP-RSL: Received Topic /status, Data Size 1, Data 7
2017-11-29T14:56:12.246150+00:00 sonoff-outlet-2450 ESP-RSL: Group 0, Index 1, Command STATUS, Data 7
2017-11-29T14:56:12.302655+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS7 = {"StatusTIM":{"UTC":"Thu Jan 01 00:18:44 1970","Local":"Thu Jan 01 00:18:44 1970","StartDST":"Thu Jan 01 00:00:00 1970","EndDST":"Thu Jan 01 00:00:00 1970","Timezone":0}}
arendst commented 6 years ago

Do you use DHCP for IP Addresses? Pls check the other two ntpservers too as the first might not be the one in use.

Scoobler commented 6 years ago

Yes I am using DHCP.

The three time servers for the POW:

00:23:36 CMD: ntpserver1
00:23:36 MQT: stat/sonoff-outlet/RESULT = {"NtpServer1":"0.uk.pool.ntp.org"}
00:23:45 CMD: ntpserver2
00:23:45 MQT: stat/sonoff-outlet/RESULT = {"NtpServer2":"1.uk.pool.ntp.org"}
00:23:49 CMD: ntpserver3
00:23:49 MQT: stat/sonoff-outlet/RESULT = {"NtpServer3":"2.uk.pool.ntp.org"}

The three time servers for the basic:

15:29:39 CMD: ntpserver1
15:29:39 MQT: stat/sonoff-basic-5/RESULT = {"NtpServer1":"0.uk.pool.ntp.org"}
15:29:49 CMD: ntpserver2
15:29:49 MQT: stat/sonoff-basic-5/RESULT = {"NtpServer2":"1.uk.pool.ntp.org"}
15:29:53 CMD: ntpserver3
15:29:53 MQT: stat/sonoff-basic-5/RESULT = {"NtpServer3":"2.uk.pool.ntp.org"}

Testing access from a Windows computer on the same network:

C:\Users\jamie>w32tm /stripchart /computer:0.uk.pool.ntp.org /dataonly /samples:5
Tracking 0.uk.pool.ntp.org [195.219.205.9:123].
Collecting 5 samples.
The current time is 29/11/2017 15:39:15.
15:39:15, +00.5000772s
15:39:17, +00.5005166s
15:39:19, +00.4998758s
15:39:21, +00.4996351s
15:39:23, +00.4958310s

C:\Users\jamie>w32tm /stripchart /computer:1.uk.pool.ntp.org /dataonly /samples:5
Tracking 1.uk.pool.ntp.org [129.250.35.251:123].
Collecting 5 samples.
The current time is 29/11/2017 15:39:31.
15:39:31, +00.4998696s
15:39:33, +00.4958908s
15:39:35, +00.4991125s
15:39:37, +00.5001067s
15:39:39, +00.4988010s

C:\Users\jamie>w32tm /stripchart /computer:2.uk.pool.ntp.org /dataonly /samples:5
Tracking 2.uk.pool.ntp.org [178.79.160.57:123].
Collecting 5 samples.
The current time is 29/11/2017 15:39:46.
15:39:46, +00.5003789s
15:39:48, +00.4969663s
15:39:50, +00.5004719s
15:39:52, +00.4995961s
15:39:54, +00.5002562s

IP details of the PC:

IPv4 Address. . . . . . . . . . . : 10.0.0.178
Subnet Mask . . . . . . . . . . . : 255.255.0.0
Default Gateway . . . . . . . . . : 10.0.0.1
arendst commented 6 years ago

I'm lost unless you have a firewall rule on ntp for your pow in your gateway...

Scoobler commented 6 years ago

Nope definitely no firewall rules in place for the devices. I have also tried setting the DNS to 8.8.8.8 - no luck there either.

When I am home, I will try attaching the POW to a hotspot on my mobile to see if that helps.

It is a little odd as I have also tried putting the same firmware on each device with a fresh CFG_Header to force the same settings - the POW still doesn't pick up time!

Scoobler commented 6 years ago

So I have done a little digging tonight, I added a load of debugging code, and tracked the error on the POW to the function RtcSecond, specifically the call to ntp_time = sntp_get_current_timestamp(); - this just returns continously on the home WiFi, on the basic with the same debugging, as soon as ESP-MQT: tele/sonoff-basic-5/LWT = Online (retained), the basic rsntp_get_current_timestamp() returned a value. Very odd as both devices with the same compiled bin loaded seem to act differently!

arendst commented 6 years ago

What if you enter the ip address of a NTP server for ntpserver1 to eliminate DNS problems? I've tested it and it works for me.

If this works and your MQTT server address was also entered as an IP address it means something is wrong with DNS config on your Pow.

Pls provide output of command status 0.

Scoobler commented 6 years ago

Hi Theo,

So I did as you suggested, and the POW picked up the time - so I have just put the domain names back in for NTPServer1, 2 & 3 and it has stayed working - still with the same DNS server details served by the DHCP - seems very odd!

With NTPServer1 as it's IP address (NTPServer 2 & 3 empty):

2017-11-30T11:14:15.504274+00:00 sonoff-outlet-2450 ESP-CMD: status 0
2017-11-30T11:14:15.504442+00:00 sonoff-outlet-2450 ESP-RSL: Received Topic /status, Data Size 1, Data 0
2017-11-30T11:14:15.504442+00:00 sonoff-outlet-2450 ESP-RSL: Group 0, Index 1, Command STATUS, Data 0
2017-11-30T11:14:15.638145+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS = {"Status":{"Module":1,"FriendlyName":"Sonoff Outlet","Topic":"sonoff-outlet","ButtonTopic":"0","Power":0,"PowerOnState":3,"LedState":1,"SaveData":1,"SaveState":1,"ButtonRetain":0,"PowerRetain":0}}
2017-11-30T11:14:15.657916+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS1 = {"StatusPRM":{"Baudrate":115200,"GroupTopic":"sonoffs","OtaUrl":"http://10.0.0.3:80/api/platformio/firmware.bin","Uptime":0,"Sleep":0,"BootCount":5,"SaveCount":10,"SaveAddress":"FA000"}}
2017-11-30T11:14:15.672171+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS2 = {"StatusFWR":{"Version":"5.9.1j","BuildDateTime":"2017-11-30T11:07:27","Boot":31,"Core":"2_3_0","SDK":"1.5.3(aec24ac9)"}}
2017-11-30T11:14:15.694540+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"SysLog":5,"LogHost":"10.0.0.3","LogPort":514,"SSId1":"GetYourOwn","SSId2":"GotOneThanks","TelePeriod":60,"SetOption":"00000009"}}
2017-11-30T11:14:15.704649+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS4 = {"StatusMEM":{"ProgramSize":447,"Free":556,"Heap":25,"ProgramFlashSize":1024,"FlashSize":4096,"FlashMode":3}}
2017-11-30T11:14:15.725138+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS5 = {"StatusNET":{"Hostname":"sonoff-outlet-2450","IPAddress":"10.0.0.30","Gateway":"10.0.0.1","Subnetmask":"255.255.255.0","DNSServer":"10.0.0.1","Mac":"5C:CF:7F:92:29:92","Webserver":2,"WifiConfig":3}}
2017-11-30T11:14:15.745309+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS6 = {"StatusMQT":{"MqttHost":"10.0.0.5","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_922992","MqttUser":"scoobler","MAX_PACKET_SIZE":512,"KEEPALIVE":15}}
2017-11-30T11:14:15.763215+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS7 = {"StatusTIM":{"UTC":"Thu Nov 30 11:14:15 2017","Local":"Thu Nov 30 11:14:15 2017","StartDST":"Sun Mar 26 02:00:00 2017","EndDST":"Sun Oct 29 03:00:00 2017","Timezone":0}}
2017-11-30T11:14:15.773304+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS10 = {"StatusSNS":{"Time":"2017-11-30T11:14:15"}}
2017-11-30T11:14:15.792595+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS11 = {"StatusSTS":{"Time":"2017-11-30T11:14:15","Uptime":0,"Vcc":3.160,"POWER":"OFF","Wifi":{"AP":1,"SSId":"GetYourOwn","RSSI":46,"APMac":"38:5A:3A:CE:48:48"}}}

With NTPServer 1, 2 & 3 back to the domain names:

2017-11-30T11:30:21.079162+00:00 sonoff-outlet-2450 ESP-CMD: status 0
2017-11-30T11:30:21.079401+00:00 sonoff-outlet-2450 ESP-RSL: Received Topic /status, Data Size 1, Data 0
2017-11-30T11:30:21.079401+00:00 sonoff-outlet-2450 ESP-RSL: Group 0, Index 1, Command STATUS, Data 0
2017-11-30T11:30:21.132624+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS = {"Status":{"Module":1,"FriendlyName":"Sonoff Outlet","Topic":"sonoff-outlet","ButtonTopic":"0","Power":0,"PowerOnState":3,"LedState":1,"SaveData":1,"SaveState":1,"ButtonRetain":0,"PowerRetain":0}}
2017-11-30T11:30:21.139079+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS1 = {"StatusPRM":{"Baudrate":115200,"GroupTopic":"sonoffs","OtaUrl":"http://10.0.0.3:80/api/platformio/firmware.bin","Uptime":0,"Sleep":0,"BootCount":9,"SaveCount":18,"SaveAddress":"FA000"}}
2017-11-30T11:30:21.144564+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS2 = {"StatusFWR":{"Version":"5.9.1j","BuildDateTime":"2017-11-30T11:07:27","Boot":31,"Core":"2_3_0","SDK":"1.5.3(aec24ac9)"}}
2017-11-30T11:30:21.151177+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"SysLog":5,"LogHost":"10.0.0.3","LogPort":514,"SSId1":"GetYourOwn","SSId2":"GotOneThanks","TelePeriod":60,"SetOption":"00000009"}}
2017-11-30T11:30:21.156798+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS4 = {"StatusMEM":{"ProgramSize":447,"Free":556,"Heap":24,"ProgramFlashSize":1024,"FlashSize":4096,"FlashMode":3}}
2017-11-30T11:30:21.161511+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS5 = {"StatusNET":{"Hostname":"sonoff-outlet-2450","IPAddress":"10.0.0.30","Gateway":"10.0.0.1","Subnetmask":"255.255.255.0","DNSServer":"10.0.0.1","Mac":"5C:CF:7F:92:29:92","Webserver":2,"WifiConfig":3}}
2017-11-30T11:30:21.166894+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS6 = {"StatusMQT":{"MqttHost":"10.0.0.5","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_922992","MqttUser":"scoobler","MAX_PACKET_SIZE":512,"KEEPALIVE":15}}
2017-11-30T11:30:21.171791+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS7 = {"StatusTIM":{"UTC":"Thu Nov 30 11:30:21 2017","Local":"Thu Nov 30 11:30:21 2017","StartDST":"Sun Mar 26 02:00:00 2017","EndDST":"Sun Oct 29 03:00:00 2017","Timezone":0}}
2017-11-30T11:30:21.181100+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS10 = {"StatusSNS":{"Time":"2017-11-30T11:30:21"}}
2017-11-30T11:30:21.190965+00:00 sonoff-outlet-2450 ESP-MQT: stat/sonoff-outlet/STATUS11 = {"StatusSTS":{"Time":"2017-11-30T11:30:21","Uptime":0,"Vcc":3.160,"POWER":"OFF","Wifi":{"AP":1,"SSId":"GetYourOwn","RSSI":46,"APMac":"38:5A:3A:CE:48:48"}}}
arendst commented 6 years ago

Well the status messages look fine to me.

At least the time is back but why... Beats me.

BTW just to ease my mind what features did you disable to get a ProgramSize of 447?

Scoobler commented 6 years ago

It is an odd one - I was trying to look into the Arduino time function, but that doesn't appear to have been touched since 2015 so I'm guessing that is rock solid, it must have been a glitch somewhere, it's just annoying not to have been able to pin point it one way or another! I have a few more Sonoff devices on order so will see if any do the same and carry on digging into them if they exhibit the fault.

I have dissabled:

//#define USE_MQTT_TLS
//#define USE_DOMOTICZ  
//#define USE_DS18x20 
//#define USE_DS18x20_LEGACY 
//#define USE_I2C 
//  #define USE_SHT
//  #define USE_HTU
//  #define USE_BMP
//  #define USE_BH1750
//  #define USE_VEML6070
//  #define USE_ADS1115
//  #define USE_ADS1115_I2CDEV
//  #define USE_INA219
//#define USE_IR_REMOTE
//  #define USE_IR_HVAC
//  #define USE_IR_RECEIVE
//#define USE_WS2812
//  #define USE_WS2812_CTYPE
//  #define USE_WS2812_DMA
//#define USE_ARILUX_RF
//#define BE_MINIMAL

In platformio.ini I have: env_default = sonoff And:

upload_port = 10.0.0.3:80/api/upload-arduino.php
extra_scripts = pio/http-uploader.py

Then just use the firmware update via the web interface. One little request here would be for the script to add the project name to the uploaded file. When platformio builds the firmware and the script uploads it to the webserver it is just called firmware.bin - it would be good if it could pick up on the project name for example and upload the file as that, not a major thing but I was doing some testing and ended up flashing the wrong firmware to the wrong device because the filename is the same and platformio had failed uploading the file, my knowledge of python and time are very limited at the moment so haven't been able to take a look into finding if that is possible.

Got to say a massive thanks for the software Theo - it works really well, I am very impressed! I have been using Homie for some of my ESP8266 projects which I quite liked, but I have found a port of Homie for the Sonoff's to be very unreliable.

stale[bot] commented 6 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

stale[bot] commented 6 years ago

This issue will be auto-closed because there hasn't been any activity for a few months. Feel free to open a new one if you still experience this problem.