Solid red, wifi ok, no RTC

[brettbeeson]

Hiya! I have the same problem on 4 devices I recently ordered.

There is the rundown:

• power on and connect to AP; set wifi
• unit restarts and connects to wifi (I see it on my network)
• solid (not flashing) red light
• can access the webpage and see in the log “Real Time Clock not initialized.”

The log file is below. I encountered this before. So I tested connecting via a different gateway IP in case the NTP was blocking my network IP. No difference.

I figure the RTC module / battery is the problem, but as new units I wouldn’t expect the battery to be flat.

How should I proceed? Happy to test battery voltage, usb debug, etc.

Cheers, Brett

`** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: Software/System restart
Trace: 255:21[69], 196:11[172], 239:75[69], 54:9[247], 103:45[95], 199:125[252], 218:81[128], 90:166[249], 170:13[181], 1:239[31], 104:59[62], 4:122[234], 242:194[80], 28:102[115], 203:164[224], 177:246[249], 252:196[51], 51:60[235], 63:31[235], 167:255[182], 107:228[231], 145:182[190], 127:29[84], 70:231[233], 150:164[202], 165:66[115], 55:1[35], 137:239[85], 90:22[72], 34:62[61], 169:162[176], 14:50[159]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 255:21[68], 196:11[172], 239:75[68], 54:9[247], 39:47[95], 199:125[254], 242:81[136], 90:166[248], 170:15[181], 1:207[31], 104:59[62], 4:122[234], 243:194[80], 12:98[115], 203:164[224], 164:247[249], 252:196[51], 51:188[235], 191:31[235], 167:255[182], 106:228[231], 145:246[190], 127:29[84], 64:247[233], 150:36[202], 169:70[115], 55:129[99], 136:239[85], 90:22[72], 34:62[61], 169:162[176], 14:50[191]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -55db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt`

[overeasy]

Sounds like it can’t find the time server at time.Google.com to set the clock. Is the lan connected to the internet?

[brettbeeson]

Yes it’s connected. The mobile AP I used as a double check is connected too.

[overeasy]

If it was one unit, I’d entertain that the battery might be defective, but these are new units and both the manufacturing tests and the firmware flashing before shipping tests the battery state and RTC for communication, setting and keeping time. So I think it’s related to obtaining the time from the internet NTP server.

I read over the previous post linked to above, and while I can’t argue that the solution apparently worked, I would say that I don’t believe all of the steps necessarily contributed.

One thing that may be happening is that NTP is a UDP protocol, so while HTTP may be working, there may be something restricting UDP or obstructing resolution of the (sub)domain.

Couple of questions:

Is this environment hostile to only these four devices and working OK for others? That is to say, if you were to power down an otherwise working IoTaWatt, remove the battery for a few seconds, then reinsert and power up on that network, does it work ok?

I have to say that throughout the world there are really no issues with internet except in Australia, where there are some unexplained issues. What would probably be most helpful would be a wire-shark trace of UDP communication to/from one of these units.

[brettbeeson]

Hiya. Assuming it’s a connection to time.google.com (UDP) problem here are some debugging results.

UDP ‘ping’ from a machine on the local network

pi@phisaver:~$ nc -z -v -u time.google.com 123
Connection to time.google.com 123 port [udp/ntp] succeeded!

tested setting linux timesyncd on same machine to time.google.com and checked syslog

this worked too

usb log

** Restart **
SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:4, 8:6, 8:8, 8:9, 8:4
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
HTTP server started

wireshark log from 192.168.0.215 (iotawatt on wifi)

I haven’t use wireshark before, so it’s possible I missed a setting but this seems to be all the packets in the first 60s. (I did this on windows with latest wireshark and npcap, using a usb wifi adapter.)

That’s all I can think of at the moment. Let me know of other debugging I can do.

[overeasy]

Any feedback on this?

@overeasy

Is this environment hostile to only these four devices and working OK for others? That is to say, if you were to power down an otherwise working IoTaWatt, remove the battery for a few seconds, then reinsert and power up on that network, does it work ok?

Looking at the USB log, I don’t see the WiFi connected message, yet the wireshark trace is showing packets from 192.169.0.215. None of those packets appear to be NTP related. They seem to be related to zeroconf services MDNS and LLMNR.

In the previous message log, it got further along with WiFi connecting and the MDNS and LLMNR responders starting. The next service that should run is timesync, which should do the NTP request. I don’t see that starting. So I’m curious about another unit that might run on that network and what it’s log shows if it does run.

These are new units, so maybe you could upload the entire /iotawatt/iotamsgs.txt file?

[brettbeeson]

This is the same network I’ve setup heaps of units on, so I don’t think it’s hostile to others.

I just took one of the units to a new network. It worked on this new network.

I’ll paste the log of this (‘new’) unit below. Note the change of network for the last entry when it succeeded.

Hence it seem related to my network. It seems consistent with time.google.com blocking excess requests, but this is contra-indicated by another machine on the network connecting ok. Not sure. I’m probably one of the few with a ‘production line’ of iotawatts where I configure in 5 minutes and do multiple units. But that’s not many requests (I do reboot the units during config) to NTP. Still not sure. Maybe you can shed some light (e.g. does iotawatt repeatedly access NTP or is it “try and give up”).

For completeness, I then returned to the original (troublesome) network and…

• plugged in, set wifi details and rebooted. I connected ok (visible in log)
• removed RTC battery for 10s and rebooted.
• Observed same problem was before (i.e. cannot set RTC) and the same first 2 packets (mDNS/avahi)

For extra completeness, I then tested a previously an old working unit on the original network. It’s a v5 which was configured ok previously:

• plugged in, set wifi details and reboot. I connected ok as expected
• removed RTC battery rebooted - I see in the log “no real time clock” as expected
• replace RTC battery and reboot
• it connected to wifi and has green light - I see it got the NTP time
• (I didn’t see any UDP packets to the NTP server so I think my wiresharking is not perfect)

I don’t know what to make of that - it all seems inconsistent!

Log of old unit - works ok (last few connections)

** Restart **

SD initialized.
7/04/21 07:24:02z Real Time Clock is running. Unix time 1625383442
7/04/21 07:24:02z Power failure detected.
7/04/21 07:24:02z Reset reason: External System
7/04/21 07:24:02z ESP8266 ChipID: 2517414
7/04/21 07:24:02z IoTaWatt 5.0, Firmware version 02_05_02
7/04/21 07:24:02z SPIFFS mounted.
7/04/21 17:24:04 Local time zone: +10:00
7/04/21 17:24:04 device name: rc480b
7/04/21 17:24:07 MDNS responder started for hostname rc480b
7/04/21 17:24:07 LLMNR responder started for hostname rc480b
7/04/21 17:24:07 HTTP server started
7/04/21 17:24:07 WiFi connected. SSID=NetComm 0405, IP=192.168.0.208, channel=1, RSSI -61db
7/04/21 17:24:08 timeSync: service started.
7/04/21 17:24:08 statService: started.
7/04/21 17:24:08 Updater: service started. Auto-update class is MAJOR
7/04/21 17:24:08 dataLog: service started.
7/04/21 17:24:12 dataLog: Last log entry 07/04/21 17:23:50
7/04/21 17:24:12 Updater: Auto-update is current for class MAJOR.
7/04/21 17:24:12 influxDB: started, url:8086=live2.phisaver.com, db=phisaver, interval=60
7/04/21 17:24:14 influxDB: Start posting at 07/04/21 17:24:00
7/04/21 17:25:09 historyLog: service started.
7/04/21 17:25:10 historyLog: Last log entry 03/03/21 04:54:00

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 17:121[96], 130:221[192], 3:68[41], 200:123[164], 197:13[62], 3:235[213], 75:133[84], 110:251[231], 204:195[2], 68:82[219], 93:27[151], 205:43[4], 181:38[50], 228:16[29], 13:8[141], 62:237[175], 84:211[101], 162:233[55], 119:11[116], 55:221[146], 58:7[190], 18:110[191], 83:48[64], 192:247[235], 214:31[95], 229:206[176], 181:224[150], 146:246[245], 216:190[16], 145:202[219], 243:233[210], 0:8[171]
ESP8266 ChipID: 2517414
IoTaWatt 5.0, Firmware version 02_05_02
SPIFFS mounted.
Local time zone: +10:00
device name: rc480b
MDNS responder started for hostname rc480b
LLMNR responder started for hostname rc480b
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.208, channel=1, RSSI -61db
timeSync: service started.
statService: started.
Updater: service started. Auto-update class is MAJOR
7/04/21 17:29:32 timeSync: RTC initalized to NTP time
7/04/21 17:29:32 Real Time Clock battery is low.
7/04/21 17:29:32 dataLog: service started.
7/04/21 17:29:36 dataLog: Last log entry 07/04/21 17:28:20
7/04/21 17:29:36 Updater: Auto-update is current for class MAJOR.
7/04/21 17:29:37 influxDB: started, url:8086=live2.phisaver.com, db=phisaver, interval=60
7/04/21 17:29:38 influxDB: Start posting at 07/04/21 17:29:00

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 17:121[112], 130:220[208], 3:68[41], 204:122[196], 197:141[62], 11:235[213], 75:133[118], 110:123[239], 204:195[2], 196:82[219], 125:19[151], 221:59[4], 181:38[178], 236:24[93], 13:8[143], 54:239[175], 84:211[101], 162:235[55], 119:11[124], 53:237[146], 58:7[158], 50:111[175], 87:16[64], 192:247[235], 214:26[93], 229:206[176], 181:162[150], 146:246[229], 209:190[18], 145:206[219], 241:233[194], 0:12[187]
ESP8266 ChipID: 2517414
IoTaWatt 5.0, Firmware version 02_05_02
SPIFFS mounted.
Local time zone: +10:00
device name: rc480b
MDNS responder started for hostname rc480b
LLMNR responder started for hostname rc480b
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.208, channel=1, RSSI -57db
timeSync: service started.
statService: started.
Updater: service started. Auto-update class is MAJOR
7/04/21 17:30:07 timeSync: RTC initalized to NTP time
7/04/21 17:30:07 dataLog: service started.
7/04/21 17:30:11 dataLog: Last log entry 07/04/21 17:29:45
7/04/21 17:30:11 influxDB: started, url:8086=live2.phisaver.com, db=phisaver, interval=60
7/04/21 17:30:11 historyLog: service started.
7/04/21 17:30:12 historyLog: Last log entry 03/08/21 07:04:00
7/04/21 17:30:14 Updater: Auto-update is current for class MAJOR.
7/04/21 17:30:15 influxDB: Start posting at 07/04/21 17:30:00

Log of new unit

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: Software/System restart
Trace: 255:21[69], 196:11[172], 239:75[69], 54:9[247], 103:45[95], 199:125[252], 218:81[128], 90:166[249], 170:13[181], 1:239[31], 104:59[62], 4:122[234], 242:194[80], 28:102[115], 203:164[224], 177:246[249], 252:196[51], 51:60[235], 63:31[235], 167:255[182], 107:228[231], 145:182[190], 127:29[84], 70:231[233], 150:164[202], 165:66[115], 55:1[35], 137:239[85], 90:22[72], 34:62[61], 169:162[176], 14:50[159]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 255:21[68], 196:11[172], 239:75[68], 54:9[247], 39:47[95], 199:125[254], 242:81[136], 90:166[248], 170:15[181], 1:207[31], 104:59[62], 4:122[234], 243:194[80], 12:98[115], 203:164[224], 164:247[249], 252:196[51], 51:188[235], 191:31[235], 167:255[182], 106:228[231], 145:246[190], 127:29[84], 64:247[233], 150:36[202], 169:70[115], 55:129[99], 136:239[85], 90:22[72], 34:62[61], 169:162[176], 14:50[191]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -55db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt
Disconnect command received.
timeSync: service started.
statService: started.
WiFi disconnected.
WiFi disconnected more than 60 minutes, restarting.

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: Software/System restart
Trace: 8:2, 1:2, 1:3, 1:3, 1:6[1], 1:6[2], 1:6[2], 1:6[2], 1:6[2], 1:6[3], 1:5[5], 1:6[4], 5:0, 1:6[6], 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:6[1], 1:6[2], 1:6[2], 1:6[2], 1:6[3], 1:5[21], 1:6[4], 21:0, 21:2
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.
RTC not running, waiting for WiFi.
RTC not running, waiting for WiFi.
RTC not running, waiting for WiFi.
RTC not running, waiting for WiFi.
RTC not running, waiting for WiFi.
RTC not running, waiting for WiFi.
RTC not running, waiting for WiFi.
RTC not running, waiting for WiFi.
RTC not running, waiting for WiFi.
RTC not running, waiting for WiFi.
RTC not running, waiting for WiFi.
RTC not running, waiting for WiFi.
RTC not running, waiting for WiFi.
RTC not running, waiting for WiFi.
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -60db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 228:21[68], 196:11[172], 239:75[85], 62:9[247], 103:47[95], 199:245[252], 250:81[136], 94:166[248], 170:141[181], 1:223[31], 104:59[62], 4:122[234], 242:194[80], 28:98[115], 203:164[232], 160:247[249], 252:212[51], 19:188[235], 63:15[235], 135:253[182], 107:224[231], 145:182[254], 127:29[86], 68:119[249], 146:36[202], 173:70[115], 55:129[3], 137:239[213], 88:22[72], 34:190[61], 169:34[176], 14:50[159]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -45db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 239:21[196], 196:11[172], 239:75[85], 62:9[247], 39:47[95], 199:253[252], 250:81[232], 94:166[248], 170:79[181], 65:223[31], 104:63[62], 4:122[234], 243:194[80], 28:98[115], 203:164[224], 160:247[249], 248:212[51], 17:60[235], 63:15[235], 167:255[182], 106:228[231], 145:246[254], 119:29[212], 64:119[225], 150:36[202], 161:70[114], 55:1[67], 137:239[197], 90:22[72], 34:190[61], 169:34[176], 14:50[191]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -48db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 254:21[69], 196:11[172], 239:75[85], 54:9[247], 103:47[95], 199:125[254], 250:80[192], 94:166[248], 170:13[181], 65:223[31], 104:59[62], 4:122[234], 242:194[80], 12:98[115], 203:164[224], 160:247[249], 248:196[51], 17:44[251], 191:31[235], 167:255[182], 106:196[231], 145:182[190], 127:29[84], 68:103[249], 150:36[202], 173:70[115], 55:129[67], 137:238[197], 88:20[72], 34:190[61], 169:162[176], 14:50[191]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.
HTTP server started

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 252:21[68], 192:11[172], 239:75[69], 54:9[247], 103:47[95], 199:253[252], 250:81[136], 90:166[248], 170:79[181], 65:223[31], 104:59[62], 4:122[234], 243:194[80], 12:98[115], 203:164[224], 160:231[248], 250:196[51], 17:56[235], 191:15[235], 7:255[182], 107:228[231], 145:246[158], 127:29[84], 68:119[233], 150:36[202], 169:70[115], 55:129[35], 137:239[197], 90:22[73], 34:190[61], 169:34[176], 14:50[191]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
HTTP server started

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -57db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -56db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -55db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 229:21[69], 196:11[172], 239:75[69], 54:9[247], 39:47[95], 199:253[252], 250:81[160], 94:166[249], 170:143[181], 65:207[31], 104:51[62], 4:122[234], 242:194[80], 28:98[115], 203:164[224], 161:247[249], 254:84[51], 17:60[235], 191:13[235], 167:255[182], 106:224[231], 145:182[190], 127:29[214], 64:115[225], 146:36[202], 173:70[115], 55:129[19], 137:239[197], 90:22[72], 34:190[60], 169:162[176], 14:50[191]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -56db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -54db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 246:21[197], 196:11[172], 239:75[85], 54:9[247], 39:47[95], 199:253[252], 250:81[160], 94:166[248], 42:143[181], 65:223[31], 104:59[62], 4:122[234], 242:194[80], 28:98[115], 203:164[224], 160:247[249], 254:196[51], 17:40[235], 63:15[235], 167:255[182], 122:224[231], 145:182[191], 127:29[214], 64:247[233], 150:52[202], 169:70[115], 55:129[67], 137:239[197], 90:22[72], 34:190[52], 169:162[176], 14:50[191]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -55db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt
timeSync: service started.

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:4, 8:6, 8:8, 8:9, 8:4
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
HTTP server started

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -54db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 247:21[69], 196:11[172], 239:75[85], 54:9[247], 103:47[95], 199:253[252], 234:81[128], 90:166[249], 42:141[181], 65:223[31], 104:59[62], 4:122[234], 242:194[80], 28:102[115], 203:132[224], 160:230[249], 250:68[51], 51:44[251], 191:15[235], 167:254[182], 106:224[231], 145:246[190], 127:29[84], 68:119[233], 150:36[200], 161:70[115], 55:129[3], 137:239[197], 90:22[73], 34:190[61], 169:162[176], 14:50[159]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -61db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt
timeSync: service started.

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 228:21[68], 196:11[172], 239:75[69], 62:9[247], 39:47[95], 199:253[254], 250:81[140], 90:166[248], 42:15[181], 1:255[31], 104:59[62], 5:122[234], 242:194[80], 28:98[115], 219:36[224], 160:247[249], 252:196[51], 81:104[235], 191:15[235], 167:255[182], 106:196[231], 145:182[222], 127:29[86], 64:103[233], 150:36[200], 173:70[115], 55:129[3], 137:239[197], 90:22[72], 34:190[61], 169:162[176], 14:50[159]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -70db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 244:21[69], 196:11[172], 239:75[85], 54:9[247], 39:47[95], 199:245[254], 242:81[224], 94:166[248], 42:79[181], 1:223[31], 104:63[62], 4:122[234], 242:194[80], 28:98[115], 203:164[224], 160:247[248], 250:196[51], 17:40[235], 127:31[235], 167:255[182], 122:224[231], 145:247[190], 127:29[92], 68:115[233], 150:36[202], 165:70[115], 55:129[83], 136:239[85], 90:22[72], 50:190[61], 169:162[176], 14:50[31]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -66db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 246:21[69], 196:11[172], 239:75[69], 54:9[247], 103:47[95], 199:245[252], 250:81[128], 94:166[248], 42:143[149], 65:239[31], 104:59[62], 4:122[234], 242:194[80], 28:98[115], 203:165[224], 160:247[249], 248:212[51], 17:124[235], 191:15[239], 167:255[182], 106:196[231], 145:246[158], 127:29[84], 68:243[249], 150:36[202], 161:70[115], 55:129[51], 136:238[213], 90:22[105], 38:190[61], 169:162[176], 14:50[63]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -64db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 246:21[69], 68:11[172], 239:75[69], 54:9[247], 103:47[95], 199:125[252], 242:81[160], 94:166[185], 42:143[181], 65:223[31], 104:59[62], 4:122[234], 242:194[80], 28:98[115], 219:164[224], 160:247[248], 252:196[51], 113:60[235], 191:31[235], 167:255[182], 123:196[231], 145:182[254], 127:157[84], 64:119[233], 150:38[202], 165:70[115], 55:129[115], 137:239[197], 88:22[72], 38:62[189], 169:162[176], 14:50[159]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -67db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 230:21[69], 192:11[172], 239:75[69], 62:9[247], 103:47[95], 199:245[254], 250:81[128], 90:166[248], 42:143[181], 65:255[31], 104:59[62], 4:122[234], 242:194[80], 28:98[115], 203:164[224], 161:231[249], 248:84[51], 51:40[235], 191:31[239], 167:253[182], 107:228[231], 145:182[223], 127:29[86], 64:231[233], 150:36[200], 161:70[115], 55:129[3], 137:239[197], 90:22[72], 34:190[60], 169:162[144], 14:50[191]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -69db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 246:21[68], 64:11[172], 239:75[85], 62:9[247], 103:47[95], 199:253[252], 250:81[168], 90:166[249], 42:13[181], 65:255[31], 104:59[62], 4:122[234], 242:194[80], 28:98[115], 203:36[232], 160:247[249], 252:84[51], 49:40[235], 191:29[235], 167:255[182], 107:228[231], 145:182[158], 127:29[214], 64:119[241], 150:36[202], 161:70[115], 55:129[67], 137:239[229], 88:22[104], 34:190[189], 169:162[176], 14:50[63]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.
HTTP server started
WiFi connected. SSID=TelstraD8065D, IP=192.168.0.94, channel=5, RSSI -44db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt
timeSync: service started.
statService: started.
Updater: service started. Auto-update class is MINOR
7/04/21 03:30:12z timeSync: RTC initalized to NTP time
7/04/21 03:30:40z dataLog: service started.
7/04/21 03:30:40z dataLog: New current log created.

7/04/21 04:41:12z dataLog: datalog WDT - restarting

** Restart **

SD initialized.
7/04/21 04:41:13z Real Time Clock is running. Unix time 1625373673
7/04/21 04:41:13z Reset reason: Software/System restart
7/04/21 04:41:13z Trace: 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:4, 8:6, 8:8, 8:9, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:4, 8:2, 8:2, 1:2, 1:3, 1:3, 1:1, 1:2, 9:0, 9:0, 8:4, 8:6, 8:8, 8:9, 1:2
7/04/21 04:41:13z ESP8266 ChipID: 8559155
7/04/21 04:41:13z IoTaWatt 5.0, Firmware version 02_06_02
7/04/21 04:41:13z SPIFFS mounted.
7/04/21 04:41:13z Local time zone: +0:00
7/04/21 04:41:13z device name: IotaWatt
7/04/21 04:41:13z HTTP server started
7/04/21 04:41:13z timeSync: service started.
7/04/21 04:41:13z statService: started.

** Restart **

SD initialized.
7/04/21 07:03:59z Real Time Clock is running. Unix time 1625382239
7/04/21 07:03:59z Power failure detected.
7/04/21 07:03:59z Reset reason: External System
7/04/21 07:03:59z ESP8266 ChipID: 8559155
7/04/21 07:03:59z IoTaWatt 5.0, Firmware version 02_06_02
7/04/21 07:03:59z SPIFFS mounted.
7/04/21 07:03:59z Local time zone: +0:00
7/04/21 07:03:59z device name: IotaWatt
7/04/21 07:04:02z Connecting with WiFiManager.
7/04/21 07:04:46z HTTP server started
7/04/21 07:04:46z WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -60db
7/04/21 07:04:46z MDNS responder started for hostname IotaWatt
7/04/21 07:04:46z LLMNR responder started for hostname IotaWatt

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 255:21[69], 196:11[172], 239:75[85], 54:9[247], 39:47[95], 199:245[254], 242:81[160], 90:166[248], 42:143[181], 65:223[31], 104:59[62], 4:122[234], 242:194[80], 28:98[115], 219:165[228], 177:247[248], 252:84[51], 17:44[235], 63:29[235], 167:255[182], 107:228[231], 145:246[191], 127:29[212], 64:247[233], 150:36[202], 161:70[119], 55:129[19], 137:239[213], 90:22[104], 34:190[61], 169:162[176], 14:50[31]
ESP8266 ChipID: 8559155
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.215, channel=1, RSSI -65db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt

[brettbeeson]

And finally, to try to pin down the problem, I tested a brand new unit (i.e. from the box) with a brand new 4G router (i.e. a wifi hotspot with a new sim card). These should be independent of my network. Log is below. It initially showed red (log point noted) then, after a few minutes (didn’t see it exactly) timeSync started and … voila… we’re good.

Given this appears to be a problem specific to my network and/or multiple iotawatts in rapid succession, I’ll just work around it. Unfortunately I still don’t know the exact problem.

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: Software/System restart
Trace: 40:182[27], 41:185[133], 244:222[210], 3:14[218], 251:181[161], 181:93[61], 52:113[45], 147:30[170], 223:107[189], 240:171[144], 46:191[11], 50:156[66], 2:70[173], 103:149[196], 250:94[71], 119:163[242], 123:177[193], 23:220[211], 186:239[71], 218:47[148], 92:178[178], 98:218[226], 38:118[152], 237:202[255], 112:140[147], 244:100[132], 230:110[96], 6:120[229], 148:183[122], 80:200[136], 53:188[219], 80:249[215]
ESP8266 ChipID: 4312010
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 40:182[27], 169:185[133], 244:222[210], 19:14[218], 255:181[160], 164:127[153], 52:117[45], 147:30[171], 223:19[125], 240:43[144], 46:63[11], 18:220[67], 2:86[173], 103:149[196], 250:94[71], 119:163[210], 123:177[193], 23:212[215], 184:236[71], 218:47[152], 212:178[178], 98:219[226], 38:242[153], 237:202[255], 112:172[139], 212:100[132], 230:110[96], 70:120[229], 148:183[58], 16:72[136], 52:188[91], 80:221[215]
ESP8266 ChipID: 4312010
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.
HTTP server started
WiFi connected. SSID=router, IP=192.168.0.74, channel=1, RSSI -52db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt
*** about 10 minutes pass ***
timeSync: service started.
statService: started.
Updater: service started. Auto-update class is MINOR
7/04/21 09:52:12z timeSync: RTC initalized to NTP time
7/04/21 09:52:12z Updater: Auto-update is current for class MINOR.
7/04/21 09:52:12z dataLog: service started.
7/04/21 09:52:12z dataLog: New current log created.
7/04/21 09:53:15z historyLog: service started.
7/04/21 09:53:15z historyLog: first entry 07/04/21 09:53:00

[overeasy]

Hmmm . I need to analyze this information better. Right now it’s Sunday and the 4th of July. We’ve got a houseful of people. So working around for a few days is the best strategy. I’ll dig in Tues or Wed.

One thing I notice with the older units is that they are running a quite older firmware, possibly predating the switch to google time servers. I have to research.

Another change is that the newer release has a different ESP8266/Arduino core,

The NTP protocol has a provision for rate limiting requests. I didn’t think the Google servers use it, but it’s possible. That was one of the reasons for switching.

But also, these logs suggest there maybe something else going on that is delaying or inhibiting the timesync service from running. In one place I saw the datalog WDT went off and in that last log where you note a ten minute gap, timesync starts after that gap, which indicates a potential problem someplace else.

I’ll probably ask you to do more experiments as I research this

[brettbeeson]

No worries. Have fun!

More info: If I leave the units powered up (solid red light) overnight, they eventually connect and get a NTP time. In the log it connects ~16hours after power up:

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 13:128[145], 108:97[195], 14:115[108], 109:63[33], 38:193[144], 249:51[139], 69:10[4], 192:33[184], 232:18[8], 233:80[176], 60:111[204], 212:63[172], 151:227[136], 214:88[55], 145:13[229], 190:123[55], 25:35[52], 167:101[122], 175:115[217], 146:241[175], 162:95[245], 115:171[165], 46:167[151], 249:115[145], 128:119[251], 211:12[197], 148:109[15], 247:173[29], 55:182[242], 75:20[111], 165:25[231], 92:211[220]
ESP8266 ChipID: 4307718
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.214, channel=1, RSSI -53db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt

** Restart **

SD initialized.
Real Time Clock not initialized.
Reset reason: External System
Trace: 15:128[147], 108:113[211], 14:115[108], 109:63[161], 54:192[144], 121:49[139], 85:10[196], 64:36[184], 232:50[8], 233:208[176], 60:111[204], 212:59[164], 147:226[136], 214:88[55], 145:13[164], 190:251[53], 25:43[36], 167:101[122], 175:123[217], 146:241[191], 166:93[253], 115:171[165], 46:39[22], 249:112[17], 129:117[251], 211:12[197], 148:109[14], 245:237[29], 103:182[242], 75:16[103], 164:16[231], 92:211[220]
ESP8266 ChipID: 4307718
IoTaWatt 5.0, Firmware version 02_06_02
SPIFFS mounted.
Local time zone: +0:00
device name: IotaWatt
Connecting with WiFiManager.
HTTP server started
WiFi connected. SSID=NetComm 0405, IP=192.168.0.214, channel=1, RSSI -64db
MDNS responder started for hostname IotaWatt
LLMNR responder started for hostname IotaWatt
timeSync: service started.
statService: started.
Updater: service started. Auto-update class is MINOR
*** This is 14:00 local time, about 16 hours after power on ***
7/05/21 04:39:51z timeSync: RTC initalized to NTP time
7/05/21 04:39:51z Updater: Auto-update is current for class MINOR.
7/05/21 04:39:51z dataLog: service started.
7/05/21 04:39:51z dataLog: New current log created.
7/05/21 04:40:55z historyLog: service started.
7/05/21 04:40:55z historyLog: first entry 07/05/21 04:40:00

[overeasy]

Hi Brett,

Still looking at the NTP server issue, but wanted first to start a separate effort to resolve another looming problem. You posted a message log from an older system that was auto-update class MAJOR and running on release 02_05_02. That is very old release but there is a problem upgrading it in Australia.

When attempting to auto-update the installed base there was an issue with internet timeout on the download - only in Australia. Units were repeatedly attempting the download and failing for days and weeks. Eventually, when the rest of the world was upgraded to a new release with increased download timeout times, I essentially abandoned those units that could not download the new release.

Your system may have been one of those, or may simply not have been active at that time. There is a manual update procedure to bring those units past the timeout issue. So I’m wondering if you have many units still running a release prior to 02_05_09? If so, we will need to come up with a strategy to move those forward.

First I’d like to see if the internet problem is still there. Could you try to update that old system by switching to auto-update class MINOR?