3 Iotawatts not reading data at the same time

billt · July 6, 2022, 7:38am

There are 3 Iotawatts here, in separate buildings. They have worked reliably for some time, but a couple of days ago they stopped sending data intermittently. On looking closely at the graphs I see that all three have data gaps at the same times.

They continue to send updates to EmonCMS. They are each connected to a different AP on the same network. One was installed last month, one May last year and the third the year before that.

As the data is logged internally and shouldn’t be affected by external factors, I am mystified to why three devices should be failing at the same time.

There is a 4th Iotawatt installed in a different part of the country that doesn’t appear to suffer the same issue.

overeasy · July 6, 2022, 11:23am

Can you post the message logs covering the period of time in those graphs?

billt · July 6, 2022, 12:43pm

The relevant parts of the message logs -

** Restart **

SD initialized.
6/30/22 07:19:22z Real Time Clock is running. Unix time 1656573562
6/30/22 07:19:22z Reset reason: Exception
6/30/22 07:19:22z Trace: 31:2[6], 31:90, 21:110, 21:110, 31:91, 31:9, 31:1, 1:6[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:3, 1:6[1], 1:6[3], 1:5[31], 1:6[4], 31:0, 31:1, 31:2[4], 3:91, 15:0[32]
6/30/22 07:19:22z ESP8266 ID: 15907426, RTC PCF8523 (68)
6/30/22 07:19:22z IoTaWatt 5.0, Firmware version 02_07_05
6/30/22 07:19:22z SPIFFS mounted.
6/30/22 08:19:22z Local time zone: +0:00, using DST/BST when in effect.
6/30/22 08:19:22z device name: GarageIW
6/30/22 08:19:22z HTTP server started
6/30/22 08:19:22z emoncms: Starting, interval:10, url:http://192.168.0.199
6/30/22 08:19:22z timeSync: service started.
6/30/22 08:19:22z statService: started.
6/30/22 08:19:22z dataLog: service started.
6/30/22 08:19:22z dataLog: Last log entry 06/30/22 08:19:20
6/30/22 08:19:26z WiFi connected. SSID=HML-GGE, IP=192.168.0.65, channel=3, RSSI -60db
6/30/22 08:19:26z MDNS responder started for hostname GarageIW
6/30/22 08:19:26z LLMNR responder started for hostname GarageIW
6/30/22 08:19:26z Updater: service started. Auto-update class is MINOR
6/30/22 08:19:26z emoncms: Start posting at 06/30/22 08:18:50
6/30/22 08:19:27z historyLog: service started.
6/30/22 08:19:27z historyLog: Last log entry 06/30/22 08:19:00
6/30/22 08:19:28z Updater: Auto-update is current for class MINOR.
7/06/22 13:12:05z dataLog: datalog WDT - restarting

** Restart **

SD initialized.
7/06/22 12:12:07z Real Time Clock is running. Unix time 1657109527
7/06/22 12:12:07z Reset reason: Software/System restart
7/06/22 12:12:07z Trace: 9:5, 9:9, 1:2, 1:3, 10:13, 1:3, 1:1[5], 1:2, 9:0, 9:0, 8:4, 8:6, 8:8, 8:9, 1:2, 1:3, 10:13, 10:20, 1:3, 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
7/06/22 12:12:07z ESP8266 ID: 15907426, RTC PCF8523 (68)
7/06/22 12:12:07z IoTaWatt 5.0, Firmware version 02_07_05
7/06/22 12:12:07z SPIFFS mounted.
7/06/22 13:12:07z Local time zone: +0:00, using DST/BST when in effect.
7/06/22 13:12:07z device name: GarageIW
7/06/22 13:12:07z HTTP server started
7/06/22 13:12:07z emoncms: Starting, interval:10, url:http://192.168.0.199
7/06/22 13:12:07z timeSync: service started.
7/06/22 13:12:07z statService: started.
7/06/22 13:12:07z dataLog: service started.
7/06/22 13:12:07z dataLog: Last log entry 07/06/22 13:07:05
7/06/22 13:12:11z WiFi connected. SSID=HML-GGE, IP=192.168.0.65, channel=3, RSSI -61db
7/06/22 13:12:11z MDNS responder started for hostname GarageIW
7/06/22 13:12:11z LLMNR responder started for hostname GarageIW
7/06/22 13:12:11z Updater: service started. Auto-update class is MINOR
7/06/22 13:12:11z emoncms: Start posting at 07/06/22 13:07:00
7/06/22 13:12:12z historyLog: service started.
7/06/22 13:12:12z historyLog: Last log entry 07/06/22 13:07:00
7/06/22 13:12:12z Updater: Auto-update is current for class MINOR.

SD initialized.
7/04/22 19:54:55z Real Time Clock is running. Unix time 1656964495
7/04/22 19:54:55z Reset reason: Software/System restart
7/04/22 19:54:55z Trace: 9:2, 1:2, 1:3, 1:3, 1:1[7], 1:2, 9:0, 9:0, 8:4, 8:6, 8:8, 8:9, 8:4, 8:6, 8:8, 8:9, 8:4, 8:6, 8:8, 8:9, 8:4, 8:6, 8:8, 8:9, 8:4, 8:6, 8:8, 8:9, 1:2, 1:3, 10:2, 10:3
7/04/22 19:54:55z ESP8266 ID: 12686222, RTC PCF8523 (68)
7/04/22 19:54:56z IoTaWatt 5.0, Firmware version 02_07_05
7/04/22 19:54:56z SPIFFS mounted.
7/04/22 19:54:56z Local time zone: +0:00
7/04/22 19:54:56z device name: IotaHML
7/04/22 19:54:56z HTTP server started
7/04/22 19:54:56z emoncms: Starting, interval:10, url:http://192.168.0.199/emoncms
7/04/22 19:54:57z timeSync: service started.
7/04/22 19:54:57z statService: started.
7/04/22 19:54:57z dataLog: service started.
7/04/22 19:55:00z dataLog: Last log entry 07/04/22 19:54:50
7/04/22 19:55:01z SB1200wh: Started
7/04/22 19:55:01z SB1200wh: Last log entry 07/04/22 19:54:50
7/04/22 19:55:01z SB4000kWh: Started
7/04/22 19:55:01z SB4000kWh: Last log entry 07/04/22 19:54:50
7/04/22 19:55:02z historyLog: service started.
7/04/22 19:55:02z historyLog: Last log entry 07/04/22 19:54:00
7/04/22 19:55:03z SB5000WH: Started
7/04/22 19:55:03z SB5000WH: Last log entry 07/04/22 19:54:50
7/04/22 19:55:06z WiFi connected. SSID=Ubiquiti HML, IP=192.168.0.54, channel=11, RSSI -46db
7/04/22 19:55:06z MDNS responder started for hostname IotaHML
7/04/22 19:55:06z LLMNR responder started for hostname IotaHML
7/04/22 19:55:06z Updater: service started. Auto-update class is MINOR
7/04/22 19:55:07z emoncms: Start posting at 07/04/22 19:54:50
7/04/22 19:55:10z Updater: Auto-update is current for class MINOR.
7/06/22 05:58:45z dataLog: datalog WDT - restarting

** Restart **

SD initialized.
7/06/22 05:58:47z Real Time Clock is running. Unix time 1657087127
7/06/22 05:58:47z Reset reason: Software/System restart
7/06/22 05:58:47z Trace: 1:3, 10:13, 1:3, 1:1[2], 1:2[4], 9:0[4], 9:0, 9:1, 8:4, 8:6, 8:8, 8:9, 9:3, 9:5, 9:9, 1:2, 1:3, 10:13, 1:3, 1:1[4], 1:2[5], 9:0[5], 9:0, 9:1, 8:4, 8:6, 8:8, 8:9, 9:3, 9:5, 9:9, 1:2
7/06/22 05:58:47z ESP8266 ID: 12686222, RTC PCF8523 (68)
7/06/22 05:58:48z IoTaWatt 5.0, Firmware version 02_07_05
7/06/22 05:58:48z SPIFFS mounted.
7/06/22 05:58:48z Local time zone: +0:00
7/06/22 05:58:48z device name: IotaHML
7/06/22 05:58:48z HTTP server started
7/06/22 05:58:48z emoncms: Starting, interval:10, url:http://192.168.0.199/emoncms
7/06/22 05:58:49z timeSync: service started.
7/06/22 05:58:49z statService: started.
7/06/22 05:58:49z dataLog: service started.
7/06/22 05:58:52z dataLog: Last log entry 07/06/22 05:53:45
7/06/22 05:58:54z historyLog: service started.
7/06/22 05:58:55z historyLog: Last log entry 07/06/22 05:53:00
7/06/22 05:58:55z WiFi connected. SSID=Ubiquiti HML, IP=192.168.0.54, channel=11, RSSI -45db
7/06/22 05:58:55z MDNS responder started for hostname IotaHML
7/06/22 05:58:56z LLMNR responder started for hostname IotaHML
7/06/22 05:58:56z Updater: service started. Auto-update class is MINOR
7/06/22 05:58:56z emoncms: Start posting at 07/06/22 05:53:40
7/06/22 05:58:57z Updater: Auto-update is current for class MINOR.
7/06/22 05:58:58z SB1200wh: Started
7/06/22 05:58:58z SB1200wh: Last log entry 07/06/22 05:53:45
7/06/22 05:58:58z SB4000kWh: Started
7/06/22 05:58:59z SB4000kWh: Last log entry 07/06/22 05:53:45
7/06/22 05:58:59z SB5000WH: Started
7/06/22 05:58:59z SB5000WH: Last log entry 07/06/22 05:53:45

** Restart **

SD initialized.
7/04/22 19:46:21z Real Time Clock is running. Unix time 1656963981
7/04/22 19:46:21z Reset reason: Software/System restart
7/04/22 19:46:21z Trace: 8:4, 8:6, 8:8, 8:9, 9:2, 1:2, 1:3, 1:3, 1:1[2], 1:2[3], 9:0[3], 9:0, 9:1, 8:4, 8:6, 8:8, 8:9, 9:2, 1:2, 1:3, 1:3, 1:1[3], 1:2[4], 9:0[4], 9:0, 9:1, 8:4, 8:6, 8:8, 8:9, 9:2, 1:2
7/04/22 19:46:21z ESP8266 ID: 9109337, RTC PCF8523 (68)
7/04/22 19:46:21z IoTaWatt 5.0, Firmware version 02_07_05
7/04/22 19:46:21z SPIFFS mounted.
7/04/22 20:46:21z Local time zone: +0:00, using DST/BST when in effect.
7/04/22 20:46:21z device name: PumpHse
7/04/22 20:46:21z HTTP server started
7/04/22 20:46:21z emoncms: Starting, interval:10, url:http://192.168.0.199/emoncms
7/04/22 20:46:22z timeSync: service started.
7/04/22 20:46:22z statService: started.
7/04/22 20:46:22z dataLog: service started.
7/04/22 20:46:24z dataLog: Last log entry 07/04/22 20:41:20
7/04/22 20:46:27z historyLog: service started.
7/04/22 20:46:28z historyLog: Last log entry 07/04/22 20:41:00
7/04/22 20:46:30z WiFi connected. SSID=HML-PumpHouse, IP=192.168.0.55, channel=9, RSSI -48db
7/04/22 20:46:30z MDNS responder started for hostname PumpHse
7/04/22 20:46:30z LLMNR responder started for hostname PumpHse
7/04/22 20:46:30z Updater: service started. Auto-update class is MINOR
7/04/22 20:46:31z emoncms: Start posting at 07/04/22 20:41:20
7/04/22 20:46:31z Updater: Auto-update is current for class MINOR.
7/05/22 08:49:25z dataLog: datalog WDT - restarting

** Restart **

SD initialized.
7/05/22 07:49:26z Real Time Clock is running. Unix time 1657007366
7/05/22 07:49:26z Reset reason: Software/System restart
7/05/22 07:49:26z Trace: 9:0, 9:1, 8:4, 8:6, 8:8, 8:9, 9:2, 1:2, 1:3, 10:13, 1:3, 1:6[1], 1:6[2], 1:6[2], 1:6[2], 1:6[2], 1:6[2], 1:6[3], 1:5[19], 1:6[4], 1:6[6], 1:1[3], 1:2[4], 9:0[4], 9:0, 9:1, 8:4, 8:6, 8:8, 8:9, 9:2, 1:2
7/05/22 07:49:26z ESP8266 ID: 9109337, RTC PCF8523 (68)
7/05/22 07:49:26z IoTaWatt 5.0, Firmware version 02_07_05
7/05/22 07:49:26z SPIFFS mounted.
7/05/22 08:49:26z Local time zone: +0:00, using DST/BST when in effect.
7/05/22 08:49:26z device name: PumpHse
7/05/22 08:49:26z HTTP server started
7/05/22 08:49:26z emoncms: Starting, interval:10, url:http://192.168.0.199/emoncms
7/05/22 08:49:27z timeSync: service started.
7/05/22 08:49:27z statService: started.
7/05/22 08:49:27z dataLog: service started.
7/05/22 08:49:29z dataLog: Last log entry 07/05/22 08:44:30
7/05/22 08:49:32z historyLog: service started.
7/05/22 08:49:33z historyLog: Last log entry 07/05/22 08:44:00
7/05/22 08:49:33z WiFi connected. SSID=HML-PumpHouse, IP=192.168.0.55, channel=9, RSSI -47db
7/05/22 08:49:33z MDNS responder started for hostname PumpHse
7/05/22 08:49:33z LLMNR responder started for hostname PumpHse
7/05/22 08:49:33z Updater: service started. Auto-update class is MINOR
7/05/22 08:49:33z emoncms: Start posting at 07/05/22 08:44:20
7/05/22 08:49:35z Updater: Auto-update is current for class MINOR.

These are taken from the web page. I don’t seem to be able to download files from the Iotawatts, they always fail.

overeasy · July 7, 2022, 1:29am

Assuming the graphs are from July 6, I don’t see anything in the logs to explain the problem. These appear to be three separate units and one appears to be on a different voltage supply (HML). The only thing they have in common is the WiFi. I’ve seen where WiFi can cause the TCP stack to essentially freeze the processor, but it’s rare and usually not for more than a few seconds. That said, has anything changed with your WiFi?

The only other thing that comes to mind is that IoTaWatt does not sample while servicing queries. These would need to be very long queries, with a lines= override, issued to all three units at the same time. Is that a possibility?

billt · July 7, 2022, 12:46pm

The graphs are from the 5th of July.
They are on the same supply, although with different cable lengths.

As you can see they all track voltage variations when viewed over a longer period.

They are not on the same WiFi network, they each are connected to a different AP. (The house WiFi doesn’t give a strong enough signal in the outbuildings for an ESP to work reliably.) No, nothing has changed.

It crossed my mind that RF interference could be an issue, but we have no very close neighbours and there is no high level WiFi signals visible. Don’t have the means to check for other RF sources.

It seems that this started on the 28th of June with the newest Iotawatt being affected first.

The Iotawatts just record their inputs and send the data to a local EmonCMS instance, nothing else is happening. I don’t even look at the web interface (until something goes wrong!). Queries are an unknown subject to me, so I’m pretty sure that they’re not involved.

overeasy · July 7, 2022, 2:11pm

This new graph appears to be from the EmonPi. One thing to note is that the default mode of plotting with Emoncms is to plot the value of the 10 second interval at each point, whereas the IoTaWatt will plot the average of all of the datapoints of each interval. So you see a lot more apparent fluctuation with Emoncms. You can check a box in Emoncms graph to get averages, and that IMO is a better way to plot this data.

If this is also July 5th, the period 7:00-8:40 is unremarkable. Assuming the EmonPI voltage is sampled with the EmonPI, it pretty much matches the IoTaWatt. That makes the initial three plots all the more puzzling. Can you replicate the above plot with the same time period as the first three plots?

The message logs show nothing for the period in question for any of the three units. I do see some datalog WDT restarts outside that period. Those are unusual and suggest a problem with the voltage. I’d like to see a couple of more things:

Could you reproduce one of the first three plots, click “CSV Data” and post all of the CSV.

Where I’m going with this is that IoTaWatt will datalog WDT if it doesn’t post to the datalog for 5 minutes. Your gaps are longer than that and there is no WDT restart. That suggests that it is posting to the datalog, but isn’t successfully sampling to get new data. That could happen if there is excessive asymmetry in the voltage signal. After sampling a voltage cycle, IoTaWatt will look at how many samples were in the positive and negative half-cycles, and throw out the sample if they differ excessively. That would suggest either a bias in the voltage signal (unlikely) or a very asymmetrical load that uses only half of the voltage cycle, as can happen with some types of dimmers and speed controls. Lets see the CSV to see if I’m on the right track.

billt · July 8, 2022, 10:17am

The graph was from a time before the errors started appearing and was just to show that they are on the same supply.

this is an EmonCMS grah of the same period as the first graphs.

These are the CSV filees from the same period.

iotawatt_2022-07-08_1111.csv (16.3 KB)
iotawatt_2022-07-08_1112.csv (16.4 KB)
iotawatt_2022-07-08_1113.csv (16.3 KB)

overeasy · July 8, 2022, 1:13pm

As I suspected, the CSV indicate that the units were logging data but rejecting the samples during the outage periods. Without getting into the possible causes for that, suffice to say that they suggest abnormalities in the voltage signal. In support of that theory is the EmonPI voltage record. EmonPI uses a completely different algorithm to sample the voltage and as far as I know does not subsequently do any quality checks on the signal. For the outage periods, the EmonPi voltage definitely changes consistent with the freeze of the IoTaWatt sampling.

The rejection of samples by IoTaWatt is intended to detect incidences where processor interrupts may have occurred during sampling. It has worked well for years. I’m curious as to what may be going on to cause this. My best guess is that somehow there is a bias on the voltage causing the cycles to be asymmetrical. I confess that I don’t understand how that could happen.

The cycle symmetry test may need rethinking. The primary method of detecting interrupts, looking at the gross number of samples, should be sufficient.

In the meantime, you might look for any patterns as to when this occurs, looking for things like time-of-day, PV activity (does it ever happen at night?), or operation of large loads.

billt · July 8, 2022, 3:35pm

You might find this graph interesting, it show fairly large loads switching and causing noticeable voltage changes.

And this is from the early morning of the 4th of July, showing lack of logging on 2 of the Iotawatts. The changes inn power consumption are the fridge and freezer compressors switching.

The Emonpi doesn’t measure anything apart from mains volts, it runs the EmonCMS instance. Most of the logging is done with a Brultech Gem with the Iotawatts supplementing it. An OpenEVSE EV charge controller has recently been added, but that doesn’t coincide with any of the Iotawatt logging errors.

FYI the electrical system is non standard. It is off grid using an SMA Sunny Island SB8.0 inverter charger with about 14kW of PV panels, the PV inverters AC coupled to the SB8.0. That shouldn’t be relevant; it has been working with no issues for over 2 years.

overeasy · July 8, 2022, 4:12pm

This is a double standard. Reliable historic operation is no guarantee of current integrity.

I think I’ve made the case that there is a voltage quality issue. Whether it effects any appliances or electronics isn’t the issue. Without a doubt you have identified a vulnerability in the IoTaWatt logic for validating voltage signals. At first I was puzzled about how that can happen in the ordinary world. As usual, the off-grid power source was not mentioned in the initial problem definition.

The IoTaWatt is logging to Emoncms throughout the events, but the same data as it is unable to accumulate new samples. I think it is due to a malformed voltage signal, which is now much more likely that it is an inverter created signal. Without a doubt the IoTaWatt should be able to measure the malformed voltage, and it does, but integrity checks cause the measurements to be rejected. This does not happen with grid power. It’s interesting that above the problem does not happen at the PV inverter, only further down the line. I don’t think it’s a motor switching, as that would not continue to cause problems for several minutes. I think it’s more likely something causing the AC voltage signal to cross zero early or late during every AC cycle. That it happens in remote units would indicate that it has to do with the resistance of the feeds and/or the inability of the inverter to provide enough power.

As previously stated, I can look at the logic for detecting a balanced voltage signal, and probably eliminate it or make it more liberal, but that will not happen until the next release due out in the Fall.