Red-Red-Red LED code

[frogmore]

I noticed that I could ping one of my IoTaWatt devices, but could not see the web UI. It was showing the 3 reds code on the LED. I restarted it, but it was the same. I took out the SD card and see this:

10/06/18 11:21:55 Updater: Release downloaded 12359ms, size 631848
10/06/18 11:22:04 Updater: Update downloaded and signature verified
10/06/18 11:22:14 Updater: firmware upgraded to version 02_03_16
10/06/18 11:22:14 Firmware updated, restarting.

** Restart **

SD initialized.
10/06/18 19:22:25z Real Time Clock is running. Unix time 1538853745 
10/06/18 19:22:25z Version 02_03_16
10/06/18 19:22:25z Updater: Installing update files for version 02_03_16
10/06/18 19:22:25z Updater: Installing EDIT.HTM
10/06/18 19:22:26z Updater: Installing GRAPH.HTM
10/06/18 19:22:26z Updater: Installing GRAPH.JS
10/06/18 19:22:26z Updater: Installing INDEX.HTM
10/06/18 19:22:28z Updater: Installing TABLES.TXT
10/06/18 19:22:28z Updater: Installing CNFSTYLE.CSS
10/06/18 19:22:28z Updater: Installation complete.
10/06/18 19:22:28z Reset reason: Software/System restart
10/06/18 19:22:28z Trace:  18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:4, 18:5, 1:6, 1:3, 1:4, 1:5[19], 1:6, 1:3, 1:4, 1:5[19], 1:6, 1:3, 1:4, 1:5[19], 1:6, 1:3, 1:4, 1:5[5]
10/06/18 19:22:28z ESP8266 ChipID: 2222239
10/06/18 19:22:38z SPIFFS mounted.
10/06/18 11:22:38 Local time zone: -8
10/06/18 11:22:38 device name: IotaWatt, version: 3
10/06/18 11:22:38 MDNS responder started
10/06/18 11:22:38 You can now connect to http://IotaWatt.local
10/06/18 11:22:38 HTTP server started
10/06/18 11:22:38 timeSync: service started.
10/06/18 11:22:38 statService: started.
10/06/18 11:22:38 WiFi connected. SSID FrogmoreN66, IP 192.168.0.38, channel 1, RSSI -68db
10/06/18 11:22:38 Updater: service started. Auto-update class is MINOR
10/06/18 11:22:38 dataLog: service started.
10/06/18 11:22:38 dataLog: New current log created.
10/06/18 11:22:40 Updater: Auto-update is current for class MINOR.
10/06/18 11:24:41 historyLog: service started.
10/06/18 11:24:41 historyLog: first entry 10/6/18 11:23:00 
10/06/18 11:26:39 timeSync: adjusting RTC by -1

<lots of entries removed, since it was working fine>
** Restart **

SD initialized.
5/10/20 12:19:29z Real Time Clock is running. Unix time 1589113169 
5/10/20 12:19:29z Reset reason: Software/System restart
5/10/20 12:19:29z Trace:  1:5[21], 21:0, 21:1, 21:10, 21:20, 21:21, 21:21[1], 21:30, 21:99, 1:6, 1:3, 1:4, 1:5[19], 1:6, 1:1, 1:2[1], 9:0[1], 9:0, 9:1, 8:4, 8:6, 8:8, 8:9, 9:3, 9:5, 9:9, 1:2, 1:3, 1:4, 1:5[5], 5:0, 5:7
5/10/20 12:19:29z ESP8266 ChipID: 2222239
5/10/20 12:19:29z IoTaWatt 4.x, Firmware version 02_05_09
5/10/20 12:19:29z Updater: Installing update files for version 02_05_09
5/10/20 12:19:29z Updater: Installing EDIT.HTM
5/10/20 12:19:30z Updater: Installing GRAPH.HTM
5/10/20 12:19:30z Updater: Installing GRAPH.JS
5/10/20 12:19:31z Updater: Installing GRAPH2.HTM
5/10/20 12:19:31z Updater: Installing GRAPH2.JS
5/10/20 12:19:31z Updater: Installing INDEX.HTM
5/10/20 12:19:33z Updater: Installing TABLES.TXT
5/10/20 12:19:33z Updater: Installing CNFSTYLE.CSS
5/10/20 12:19:33z Updater: Installation complete.
5/10/20 12:19:33z SPIFFS mounted.
5/10/20 05:19:33 Local time zone: -8:00
5/10/20 05:19:33 Using Daylight Saving Time (BST) when in effect.
5/10/20 05:19:33 device name: IotaWatt
5/10/20 05:19:33 HTTP server started
5/10/20 05:19:33 timeSync: service started.
5/10/20 05:19:34 statService: started.
5/10/20 05:19:34 dataLog: service started.
5/10/20 05:19:38 dataLog: Last log entry 05/10/20 05:18:50
5/10/20 05:19:39 Updater: service started. Auto-update class is ALPHA
5/10/20 05:19:39 WiFi connected. SSID=FrogmoreN66, IP=192.168.0.38, channel=5, RSSI -66db
5/10/20 05:19:39 MDNS responder started for hostname IotaWatt
5/10/20 05:19:39 LLMNR responder started for hostname IotaWatt
5/10/20 05:19:40 Updater: Auto-update is current for class ALPHA.
5/10/20 05:20:34 historyLog: service started.
5/10/20 05:20:34 historyLog: Last log entry 05/10/20 05:18:00
5/11/20 12:23:04 Updater: Invalid response from server. HTTPcode: -4
5/13/20 13:27:52 Updater: Invalid response from server. HTTPcode: -11
5/20/20 02:28:46 WiFi disconnected.
5/20/20 02:28:50 WiFi connected. SSID=FrogmoreN66, IP=192.168.0.38, channel=5, RSSI -66db
5/20/20 02:38:47 WiFi disconnected.
5/20/20 02:38:50 WiFi connected. SSID=FrogmoreN66, IP=192.168.0.38, channel=5, RSSI -65db
5/20/20 02:43:11 Updater: Invalid response from server. HTTPcode: -4

<lots oft WiFi connect/disconnects removed from when I was working on the system>

6/05/20 22:53:13 WiFi disconnected.
6/05/20 23:00:27 WiFi connected. SSID=FrogmoreN66, IP=192.168.1.38, channel=11, RSSI -67db
6/06/20 00:19:08 Updater: Invalid response from server. HTTPcode: -4
6/11/20 18:08:27 WiFi disconnected.
6/11/20 18:08:30 WiFi connected. SSID=FrogmoreN66, IP=192.168.1.38, channel=1, RSSI -76db
6/15/20 21:40:02 historyLog: primary log file read failure. Service suspended.

** Restart **

SD initialized.
6/17/20 00:31:44z Real Time Clock is running. Unix time 1592353904 
6/17/20 00:31:44z Reset reason: Software Watchdog
6/17/20 00:31:44z Trace:  25:56, 25:41, 25:42, 25:41, 25:50, 25:51, 25:53, 25:54, 25:60, 25:61, 25:61, 25:63, 25:55, 25:56, 25:41, 25:42, 25:41, 25:50, 25:51, 25:53, 25:54, 25:60, 25:61, 25:61, 25:63, 25:55, 25:56, 25:41, 25:42, 25:41, 25:50, 25:51
6/17/20 00:31:44z ESP8266 ChipID: 2222239
6/17/20 00:31:44z IoTaWatt 4.x, Firmware version 02_05_09
6/17/20 00:31:44z SPIFFS mounted.
6/16/20 17:31:45 Local time zone: -8:00
6/16/20 17:31:45 Using Daylight Saving Time (BST) when in effect.
6/16/20 17:31:45 device name: IotaWatt
6/16/20 17:31:45 HTTP server started
6/16/20 17:31:45 timeSync: service started.
6/16/20 17:31:45 statService: started.
6/16/20 17:31:45 dataLog: service started.
6/16/20 17:31:46 dataLog: Log file open failed. 2
6/16/20 17:31:46 Program halted.

** Restart **

SD initialized.
6/18/20 20:31:49z Real Time Clock is running. Unix time 1592512309 
6/18/20 20:31:49z Reset reason: Exception
6/18/20 20:31:49z Trace:  1:3, 1:4, 1:5[19], 1:6, 1:3, 1:4, 1:5[19], 1:6, 1:3, 1:4, 1:5[19], 1:6, 1:3, 1:4, 1:5[19], 1:6, 1:3, 1:4, 1:5[19], 1:6, 1:1[14], 1:2, 9:0, 9:0, 8:4, 8:6, 8:8, 8:9, 1:2, 1:3, 1:4, 1:5[19]
6/18/20 20:31:49z ESP8266 ChipID: 2222239
6/18/20 20:31:49z IoTaWatt 4.x, Firmware version 02_05_09
6/18/20 20:31:49z SPIFFS mounted.
6/18/20 13:31:50 Local time zone: -8:00
6/18/20 13:31:50 Using Daylight Saving Time (BST) when in effect.
6/18/20 13:31:50 device name: IotaWatt
6/18/20 13:31:50 HTTP server started
6/18/20 13:31:50 timeSync: service started.
6/18/20 13:31:50 statService: started.
6/18/20 13:31:50 dataLog: service started.
6/18/20 13:31:51 dataLog: Log file open failed. 2
6/18/20 13:31:51 Program halted.

** Restart **

SD initialized.
6/20/20 23:02:08z Real Time Clock is running. Unix time 1592694128 
6/20/20 23:02:08z Reset reason: Exception
6/20/20 23:02:08z Trace:  1:4, 1:5[19], 1:6, 1:1[13], 1:2[14], 9:0[14], 9:0, 9:1, 8:4, 8:6, 8:8, 8:9, 9:3, 9:5, 9:9, 1:2, 1:3, 1:4, 1:5[19], 1:6, 1:1[14], 1:2, 9:0, 9:0, 8:4, 8:6, 8:8, 8:9, 1:2, 1:3, 1:4, 1:5[19]
6/20/20 23:02:08z ESP8266 ChipID: 2222239
6/20/20 23:02:08z IoTaWatt 4.x, Firmware version 02_05_09
6/20/20 23:02:08z SPIFFS mounted.
6/20/20 16:02:08 Local time zone: -8:00
6/20/20 16:02:08 Using Daylight Saving Time (BST) when in effect.
6/20/20 16:02:08 device name: IotaWatt
6/20/20 16:02:08 HTTP server started
6/20/20 16:02:08 timeSync: service started.
6/20/20 16:02:08 statService: started.
6/20/20 16:02:09 dataLog: service started.
6/20/20 16:02:09 dataLog: Log file open failed. 2
6/20/20 16:02:09 Program halted.

** Restart **

SD initialized.
6/22/20 17:47:44z Real Time Clock is running. Unix time 1592848064 
6/22/20 17:47:44z Reset reason: Exception
6/22/20 17:47:44z Trace:  1:3, 1:4, 1:5[19], 1:6, 1:3, 1:4, 1:5[19], 1:6, 1:3, 1:4, 1:5[19], 1:6, 1:3, 1:4, 1:5[19], 1:6, 1:3, 1:4, 1:5[19], 1:6, 1:1[14], 1:2, 9:0, 9:0, 8:4, 8:6, 8:8, 8:9, 1:2, 1:3, 1:4, 1:5[19]
6/22/20 17:47:44z ESP8266 ChipID: 2222239
6/22/20 17:47:44z IoTaWatt 4.x, Firmware version 02_05_09
6/22/20 17:47:44z SPIFFS mounted.
6/22/20 10:47:44 Local time zone: -8:00
6/22/20 10:47:44 Using Daylight Saving Time (BST) when in effect.
6/22/20 10:47:44 device name: IotaWatt
6/22/20 10:47:44 HTTP server started
6/22/20 10:47:45 timeSync: service started.
6/22/20 10:47:45 statService: started.
6/22/20 10:47:45 dataLog: service started.
6/22/20 10:47:45 dataLog: Log file open failed. 2
6/22/20 10:47:45 Program halted.

** Restart **

SD initialized.
6/22/20 17:53:05z Real Time Clock is running. Unix time 1592848385 
6/22/20 17:53:05z Power failure detected.
6/22/20 17:53:05z Reset reason: External System
6/22/20 17:53:05z ESP8266 ChipID: 2222239
6/22/20 17:53:05z IoTaWatt 4.x, Firmware version 02_05_09
6/22/20 17:53:05z SPIFFS mounted.
6/22/20 10:53:05 Local time zone: -8:00
6/22/20 10:53:05 Using Daylight Saving Time (BST) when in effect.
6/22/20 10:53:05 device name: IotaWatt
6/22/20 10:53:08 Connecting with WiFiManager.
6/22/20 10:53:11 HTTP server started
6/22/20 10:53:11 WiFi connected. SSID=FrogmoreN66, IP=192.168.1.38, channel=1, RSSI -73db
6/22/20 10:53:11 MDNS responder started for hostname IotaWatt
6/22/20 10:53:12 LLMNR responder started for hostname IotaWatt
6/22/20 10:53:12 timeSync: service started.
6/22/20 10:53:12 statService: started.
6/22/20 10:53:12 Updater: service started. Auto-update class is ALPHA
6/22/20 10:53:12 dataLog: service started.
6/22/20 10:53:12 dataLog: Log file open failed. 2
6/22/20 10:53:12 Program halted.

This the device that I reformatted the SD card on a long time ago, since there was some corruption. Windows is happy to read the SD card and the files.

[frogmore]

Corrupted SD card (resolved)

I took the SD card out of my device, and it looks interesting. there is this file: tables.TP dated: 8/22/2082 7:20PM PDT There is another one: EFIV.HTM from: 8/22/2034 (also at 7:20PM PDT) I was unable to delete the tables.TP* file, so I copied all the content from the SD card and then slow formatted the SD card. It is a very slow card (Kingston, class 4) with a write speed of ~5MB/sec, so that took a long time. And putting the card back in and booted and get red-red-red. Looks like the …

[overeasy]

@frogmore

<lots oft WiFi connect/disconnects removed from when I was working on the system>

What do mean by “working on the system”? Are you compiling and loading your own version of the firmware? Not that there’s anything wrong with that, but you have to agree that would open up a universe of possibilities.

Your problems seem to have started right after you did this work on the system, and after the deleted log entries.

Yes, the SDcard is slow. There is no point in using fast cards when the data-width is 1 bit as in the ESP8266 SPI. (The ESP32 has SDMMC with 4 bit path and I use faster cards). The format should be standard fat-32 as with a windows machine. Most new SD cards come preformatted that way. The best way to ruin an SDcard is to remove or insert it while the unit is powered on. I don’t do that anymore, and I no longer have problems with SD cards.

So I would recommend getting a new or clean reformatted SD card, loading the core files from the SD direectory on github, and loading a binary from the same release on github. It’s possible your history file is OK, and you might want to try preloading that as well before startup.

[frogmore]

Working on system means the WiFi system. I did not touch the IotaWatt. It is running the alpha channel, but I have not made any modifications to the code. I was modifying the graphing code and web UI, but that was a long time ago and I am pretty sure that it got overwritten with one of the changes over the last more than a year or so.

Since I had the SD card out and the FW was complaining about the data log file, I renamed the file (IOTALOG.LOG). I replaced the card in the device and it started up fine (and created a new log) looks like it still has history, but the period from 6/15 to now is missing.

6/22/20 10:53:12 timeSync: service started.
6/22/20 10:53:12 statService: started.
6/22/20 10:53:12 Updater: service started. Auto-update class is ALPHA
6/22/20 10:53:12 dataLog: service started.
6/22/20 10:53:12 dataLog: Log file open failed. 2
6/22/20 10:53:12 Program halted.

** Restart **

SD initialized.
6/22/20 20:45:10z Real Time Clock is running. Unix time 1592858710 
6/22/20 20:45:10z Power failure detected.
6/22/20 20:45:10z Reset reason: External System
6/22/20 20:45:10z ESP8266 ChipID: 2222239
6/22/20 20:45:10z IoTaWatt 4.x, Firmware version 02_05_09
6/22/20 20:45:10z SPIFFS mounted.
6/22/20 13:45:10 Local time zone: -8:00
6/22/20 13:45:10 Using Daylight Saving Time (BST) when in effect.
6/22/20 13:45:10 device name: IotaWatt
6/22/20 13:45:13 HTTP server started
6/22/20 13:45:13 WiFi connected. SSID=FrogmoreN66, IP=192.168.1.38, channel=1, RSSI -72db
6/22/20 13:45:13 MDNS responder started for hostname IotaWatt
6/22/20 13:45:13 LLMNR responder started for hostname IotaWatt
6/22/20 13:45:13 timeSync: service started.
6/22/20 13:45:13 statService: started.
6/22/20 13:45:13 Updater: service started. Auto-update class is ALPHA
6/22/20 13:45:14 dataLog: service started.
6/22/20 13:45:14 dataLog: New current log created.
6/22/20 13:45:14 dataLog: Last history entry: 06/15/20 21:39:00
6/22/20 13:45:15 Updater: Auto-update is current for class ALPHA.
6/22/20 13:47:13 historyLog: service started.
6/22/20 13:47:13 historyLog: Last log entry 06/15/20 21:39:00

[frogmore]

There was no indicated power failure in the log. The WiFi was stable for days before the file got corrupted. No one was even in the room where the device is located. So, it’s a mystery as to what happened.

It does appear to be working now. There is nothing that in the data that is lost that is that important, so not particularly concerned about it being gone.

If you think it will be useful, I can send you the recovered log that it can’t read.

[frogmore]

While handling failure is always hard, in this specific instance, it appears that the dataLog got corrupted somehow. While that should never happen, clearly it does. I believe in some cases it might be possible to have better behavior than what happened. When the code starts up without a datalog, it creates a new one. Ideally when faced with a datalog that doesn’t make sense, it would use the part that makes sense and ignore the rest. Depending on the structure of the log, this might be hard to implement. A perhaps easier solution would be to just rename the old log and create a new one. Has the system done that, I probably wouldn’t have even noticed the problem. Since I don’t have data from the last several nights, I will now have to wait till tonight to see how much of a difference the new landscape lights are making to power consumption.

Since file corruption doesn’t happen frequently, you might have more urgent things to address.

[overeasy]

It will remain a mystery. The damage occurred during the two-week stretch that was removed from the posted log. We’ll just never know.

There is a lot of recovery code in place for the datalogs, and it works well. These kinds of problems are very rare. The issue here is that the file could not be opened. That, along with the presence of those mystery files, suggests to me that there was directory damage. The file couldn’t be opened, but if it had simply not been there, IoTaWatt would have created one. So the SD needed to have it’s directory rebuilt. Deleting the datalog that couldn’t be opened, if that was even possible, would not have been a good solution. Directory inconsistencies have a way of causing recurring problems.

[frogmore]

All I did was rename the datalog file. I made no other changes to the SD card. I have the complete contents of the SD card saved. The event/message log stuff I deleted was just the WiFi connection/disconnection messages, maybe 20-30 of them over a week or so. I can post the log if you think that will be helpful. I can send you the datalog if you are interested in seeing what is wrong with it. I didn’t look at the data to see if it made any sense, since it is a binary file and I wasn’t sure of the format.