Missing console values when backfilling from console takes longer than archiveInterval?

[Michi Kaa]

Yesterday I had some odd console to USB-Dongle connection Problems for some hours, so I decided to take the daily db-Snapshot and to backfill the whole day. Since I read electricity data from my photovoltaic inverter throug its REST interface every archive cycle, it takes some time to backfill all these values, becaus every REST call takes a second or two.

Here is the log:

Dec 10 17:41:47 weewxPi weewx[10099]: ws28xx: RFComm: console is paired to device with ID 0171
Dec 10 17:41:49 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: request records since 2019-12-09 23:55:00 CET (1575932100)
Dec 10 17:41:54 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 195 != 194
Dec 10 17:41:56 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 199 != 198
Dec 10 17:42:03 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 203 != 202
Dec 10 17:42:07 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 210 != 209
Dec 10 17:42:08 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 211 != 210
Dec 10 17:42:09 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 212 != 211
Dec 10 17:42:11 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 215 != 214
Dec 10 17:42:15 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 216 != 215
Dec 10 17:42:24 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 217 != 216
Dec 10 17:42:37 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 218 != 217
Dec 10 17:42:43 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 220 != 219
Dec 10 17:42:44 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 221 != 220
Dec 10 17:42:45 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 223 != 222
Dec 10 17:42:46 weewxPi weewx[10099]: ws28xx: MainThread: Scanned 36 records: current=222 latest=404 remaining=182
Dec 10 17:42:49 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 224 != 223
Dec 10 17:42:50 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 226 != 225
Dec 10 17:43:00 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 228 != 227
Dec 10 17:43:07 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 231 != 230
Dec 10 17:43:09 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 233 != 232
Dec 10 17:43:11 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 238 != 237
Dec 10 17:43:20 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 243 != 242
Dec 10 17:43:21 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 244 != 243
Dec 10 17:43:22 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 246 != 245
Dec 10 17:43:33 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 254 != 253
Dec 10 17:43:37 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 260 != 259
Dec 10 17:43:41 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 268 != 267
Dec 10 17:43:42 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 269 != 268
Dec 10 17:43:46 weewxPi weewx[10099]: ws28xx: MainThread: Scanned 83 records: current=269 latest=404 remaining=135
Dec 10 17:43:53 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 283 != 282
Dec 10 17:43:54 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 284 != 283
Dec 10 17:43:58 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 287 != 286
Dec 10 17:43:58 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 288 != 287
Dec 10 17:44:01 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 292 != 291
Dec 10 17:44:06 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 295 != 294
Dec 10 17:44:12 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 297 != 296
Dec 10 17:44:15 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 303 != 302
Dec 10 17:44:26 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 312 != 311
Dec 10 17:44:29 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 316 != 315
Dec 10 17:44:34 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 318 != 317
Dec 10 17:44:42 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 319 != 318
Dec 10 17:44:46 weewxPi weewx[10099]: ws28xx: MainThread: Scanned 132 records: current=318 latest=404 remaining=86
Dec 10 17:45:09 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 353 != 352
Dec 10 17:45:09 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 354 != 353
Dec 10 17:45:17 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 363 != 362
Dec 10 17:45:30 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 382 != 381
Dec 10 17:45:39 weewxPi weewx[10099]: ws28xx: RFComm: handleHistoryData: index mismatch: 397 != 396
Dec 10 17:45:46 weewxPi weewx[10099]: ws28xx: MainThread: Scanned 218 records: current=404 latest=405 remaining=1
Dec 10 17:46:46 weewxPi weewx[10099]: ws28xx: MainThread: Scanned 219 records: current=405 latest=405 remaining=0
Dec 10 17:46:46 weewxPi weewx[10099]: ws28xx: MainThread: Found 215 historical records
Dec 10 17:46:46 weewxPi weewx[10099]: Fronius timeZone: Z
Dec 10 17:46:46 weewxPi weewx[10099]: http://10.0.1.91/solar_api/v1/GetArchiveData.cgi?Scope=System&StartDate=2019-12-09T23:00:00Z&EndDate=2019-12-09T23:05:00Z&Channel=Enereal_WAC_Sum_Produced&Channel=TimeSpanInSec
Dec 10 17:46:49 weewxPi weewx[10099]: Radiation: 0.0 at 2019-12-10 00:00:00 CET (1575932400)
Dec 10 17:46:50 weewxPi weewx[10099]: manager: Added record 2019-12-10 00:00:00 CET (1575932400) to database 'weewx.sdb'
Dec 10 17:46:50 weewxPi weewx[10099]: manager: Added record 2019-12-10 00:00:00 CET (1575932400) to daily summary in 'weewx.sdb'
Dec 10 17:46:50 weewxPi weewx[10099]: Fronius timeZone: Z
Dec 10 17:46:50 weewxPi weewx[10099]: http://10.0.1.91/solar_api/v1/GetArchiveData.cgi?Scope=System&StartDate=2019-12-09T23:05:00Z&EndDate=2019-12-09T23:10:00Z&Channel=Enereal_WAC_Sum_Produced&Channel=TimeSpanInSec
Dec 10 17:46:50 weewxPi weewx[10099]: restx: StationRegistry: Published record 2019-12-10 00:00:00 CET (1575932400)
Dec 10 17:46:53 weewxPi weewx[10099]: Radiation: 0.0 at 2019-12-10 00:05:00 CET (1575932700)
Dec 10 17:46:53 weewxPi weewx[10099]: manager: Added record 2019-12-10 00:05:00 CET (1575932700) to database 'weewx.sdb'
Dec 10 17:46:53 weewxPi weewx[10099]: manager: Added record 2019-12-10 00:05:00 CET (1575932700) to daily summary in 'weewx.sdb'
Dec 10 17:46:53 weewxPi weewx[10099]: Fronius timeZone: Z
Dec 10 17:46:53 weewxPi weewx[10099]: http://10.0.1.91/solar_api/v1/GetArchiveData.cgi?Scope=System&StartDate=2019-12-09T23:10:00Z&EndDate=2019-12-09T23:15:00Z&Channel=Enereal_WAC_Sum_Produced&Channel=TimeSpanInSec


[...]and so on [...]

Dec 10 17:58:50 weewxPi weewx[10099]: manager: Added record 2019-12-10 17:40:00 CET (1575996000) to daily summary in 'weewx.sdb'
Dec 10 17:58:50 weewxPi weewx[10099]: Fronius timeZone: Z
Dec 10 17:58:50 weewxPi weewx[10099]: http://10.0.1.91/solar_api/v1/GetArchiveData.cgi?Scope=System&StartDate=2019-12-10T16:45:00Z&EndDate=2019-12-10T16:50:00Z&Channel=EnergyReal_WAC_Sum_Produced&Channel=TimeSpanInSec
Dec 10 17:58:53 weewxPi weewx[10099]: Radiation: 0.0 at 2019-12-10 17:45:00 CET (1575996300)
Dec 10 17:58:53 weewxPi weewx[10099]: manager: Added record 2019-12-10 17:45:00 CET (1575996300) to database 'weewx.sdb'
Dec 10 17:58:53 weewxPi weewx[10099]: manager: Added record 2019-12-10 17:45:00 CET (1575996300) to daily summary in 'weewx.sdb'
Dec 10 17:58:53 weewxPi weewx[10099]: engine: Starting main packet loop.
Dec 10 18:00:23 weewxPi weewx[10099]: Fronius timeZone: Z
Dec 10 18:00:23 weewxPi weewx[10099]: http://10.0.1.91/solar_api/v1/GetArchiveData.cgi?Scope=System&StartDate=2019-12-10T17:00:00Z&EndDate=2019-12-10T17:05:00Z&Channel=EnergyReal_WAC_Sum_Produced&Channel=TimeSpanInSec
Dec 10 18:00:26 weewxPi weewx[10099]: Radiation: 0.0 at 2019-12-10 18:00:00 CET (1575997200)
Dec 10 18:00:26 weewxPi weewx[10099]: Uploading Windguru data: http://www.windguru.cz/upload/upload_custom.php?uid=AT_SALZBURG_HALLEIN_RIF&wind_avg=2.00864503238&wind_max=3.49893005641&wind_direction=172.642792918&temperature=1.5&rh=82.2180553639&mslp=1029.1641871&precip=0.0
Dec 10 18:00:26 weewxPi weewx[10099]: manager: Added record 2019-12-10 18:00:00 CET (1575997200) to database 'weewx.sdb'
Dec 10 18:00:26 weewxPi weewx[10099]: manager: Added record 2019-12-10 18:00:00 CET (1575997200) to daily summary in 'weewx.sdb'
Dec 10 18:00:39 weewxPi weewx[10099]: cheetahgenerator: Generated 14 files for report StandardReport in 11.63 seconds
Dec 10 18:00:58 weewxPi weewx[10099]: imagegenerator: Generated 39 images for StandardReport in 19.22 seconds
Dec 10 18:00:58 weewxPi weewx[10099]: copygenerator: copied 14 files to /var/www/weewx
Dec 10 18:01:01 weewxPi weewx[10099]: GaugeGenerator: Generated 7 images for HTMLPages in 2.13 seconds
Dec 10 18:01:01 weewxPi weewx[10099]: translategenerator.pyc: Language is german

So now I am missing 17:50 and 17:55 CET values. Not a problem compared to the hour-long missing values before, but still :) As a fist workaround i will save circular 4-hour snapshot of the current day also.

[Michi Kaa]

Is this a known limitation or intended or just my issue because of the slow reading of the REST API?

[gjr80]

Hi,

Short answer is it depends.

Long answer. When WeeWX starts it will attempt to download any archive records since the timestamp of the last good record in the archive. Not all drivers support this feature; if it is not supported then the catchup is skipped and WeeWX continues and starts receiving loop packets/archive records from the driver as per normal. If there was a gap between the last good record and the current time then those records have been lost and the gap will remain. If the driver does support catchup WeeWX will attempt to download any archive records timestamped after the timestamp of the last good archive record in the archive. Once the catchup is complete WeeWX continues and starts receiving loop packets/archive records from the driver as per normal. In this case what happens to the archive records that would have been generated during the time the catchup was running depends on several factors. If the driver emits loop packets only then WeeWX will never see these loop packets nor will any archive records be generated from these loop packets. If the catchup takes less than an archive period and WeeWX subsequently receives at least one loop packet in that archive period, then the archive record will be generated but only based on the loop packet(s) actually received by WeeWX. If the driver/station supports hardware record generation (ie the station provides the archive records) then the behaviour will depend on the station and driver. If the station uses some form of logger to store historical archive records then you may be able to get the archive records produced during the catchup, you may need to restart WeeWX to perform another catchup to pickup these records, then again they may not be stored. If there is no logger then in all likelihood you will have lost the records, or at best you might get the most recent one.

How to minimise lost records. Start WeeWX as early as possible in the archive period (eg for a 5 minute archive period start as soon as possible after a 5 minute boundary) so as to give WeeWX the maximum amount of time to complete the catchup. Perform a restart in the archive period after the catchup is complete, it may help, it may not. Consider your architecture, if you have more than one source for data and preventing data loss is important maybe running multiple WeeWX instances may help; that way a slow performing source will not necessarily drag down other faster sources during a catchup.

Gary

[Michi Kaa]

Thanks Gary.

For my particular situation, I might ask the author (which is myself, haha) of the weewx extension that is getting the inverter data from the REST interface, if he could implement in a way so that it is not backfilled in the usual way. Maybe an approach could be to only retrieve single values if the timestamp for the requested value is not older than x-times an interval and let it check for gaps afterwards. A call for all the values in the last 24 hours in a 5-min interval only take another second or so longer than it takes for a single reading.

With this approach I have to take care of getting things right with the corresponding archive_day_-table.

Or I could implement a cache which holds all the values since the latest good record up until now and return the cached value, if cached, if not, it asks for all values since the newest good record, and caches it. Should work with some kind of static key-value-pairs variable.