'weewx.sdb': UNIQUE constraint failed: archive.dateTime

[Leon Shaner]

Hey WeeWX'ers...

I've been getting a series of the following error for about an hour each time I restart WeeWx since syncing to the latest development branch several weeks ago:

Dec 14 13:12:14 nixie weewx[14125] ERROR weewx.manager: Unable to add record 2019-12-14 13:12:00 EST (1576347120) to database 'weewx.sdb': UNIQUE constraint failed: archive.dateTime

The error messages occur only right after starting WeeWx and continues on every archive interval for an hour after the weewx restart, then the error is no longer shown.

Sure seems like a timezone ± 1 hour offset issue of some kind, but I can't pinpoint it.
Coincidentally we crossed into Eastern Standard time a few days before I made the upgrade.

Anyone else seeing a similar error?

Last night I sync'd to the latest development branch again and the error persists.
I had been running under the system default Python 2.7, so this morning I switched weewx to use Python 3.5, and the error still persists.

Regards,
\Leon
--
Leon Shaner :: Dearborn, Michigan (iPad)

[Thomas Keffer]

The log sure would be useful...

--
You received this message because you are subscribed to the Google Groups "weewx-development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to weewx-developm...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/weewx-development/39928361-6AFF-44EA-BC1A-3B9666C42669%40isylum.org.

[Leon Shaner]

Log attached.

Thomas Keffer wrote on 12/14/19 2:19 PM:

The log sure would be useful...

On Sat, Dec 14, 2019 at 11:19 AM Leon Shaner <le...@isylum.org> wrote:

Hey WeeWX'ers...

I've been getting a series of the following error for about an hour each time I restart WeeWx since syncing to the latest development branch several weeks ago:

Dec 14 13:12:14 nixie weewx[14125] ERROR weewx.manager: Unable to add record 2019-12-14 13:12:00 EST (1576347120) to database 'weewx.sdb': UNIQUE constraint failed: archive.dateTime

The error messages occur only right after starting WeeWx and continues on every archive interval for an hour after the weewx restart, then the error is no longer shown.

Sure seems like a timezone ± 1 hour offset issue of some kind, but I can't pinpoint it.
Coincidentally we crossed into Eastern Standard time a few days before I made the upgrade.

Anyone else seeing a similar error?

Last night I sync'd to the latest development branch again and the error persists.
I had been running under the system default Python 2.7, so this morning I switched weewx to use Python 3.5, and the error still persists.

Regards,
\Leon
--
Leon Shaner :: Dearborn, Michigan (iPad)

-- 
le...@isylum.org - Dearborn, Michigan

[Leon Shaner]

Tom,

I think I see the problem.   The wmr300 history code is adding "future" records.
Note the "disagreement" in the time of the log entry vs. the time of the record being added:

Dec 14 13:11:16 nixie weewx[14125] INFO weewx.drivers.wmr300: New historical record for 2019-12-14 14:04:00 EST (1576350240): 1813: {'dateTime': 1576350240.0, 'usUnits': 17, 'barometer': 976.3000000000001, 'windSpeed': 1.8, 'windDir': 292.0, 'windGust': 1.8, 'windGustDir': 254.0, 'inTemp': 21.1, 'outTemp': 5.7, 'extraTemp1': None, 'extraTemp2': None, 'extraTemp3': None, 'extraTemp4': None, 'extraTemp5': None, 'extraTemp6': None, 'extraTemp7': None, 'inHumidity': 39.0, 'outHumidity': 73.0, 'extraHumid1': None, 'extraHumid2': None, 'extraHumid3': None, 'extraHumid4': None, 'extraHumid5': None, 'extraHumid6': None, 'extraHumid7': None, 'dewpoint': None, 'extraDewpoint1': None, 'extraDewpoint2': None, 'extraDewpoint3': None, 'extraDewpoint4': None, 'extraDewpoint5': None, 'extraDewpoint6': None, 'extraDewpoint7': None, 'heatindex': None, 'extraHeatindex1': None, 'extraHeatindex2': None, 'extraHeatindex3': None, 'extraHeatindex4': None, 'extraHeatindex5': None, 'extraHeatindex6': None, 'extraHeatindex7': 4.2, 'windchill': 4.2, 'rainRate': 0.0, 'rainTotal': 503.17400000000004, 'rain': 0.0, 'interval': 1.0}
Dec 14 13:11:16 nixie weewx[14125] INFO weewx.manager: Added record 2019-12-14 14:04:00 EST (1576350240) to database 'weewx.sdb'

Then later, after the history is processed we see:

Dec 14 14:04:15 nixie weewx[14125] ERROR weewx.manager: Unable to add record 2019-12-14 14:04:00 EST (1576350240) to database 'weewx.sdb': UNIQUE constraint failed: archive.dateTime

I am headed to the station to see if it needs to be adjusted from EDT to EST.  :-/

Regards,
\Leon

Leon Shaner wrote on 12/14/19 3:47 PM:

--
You received this message because you are subscribed to the Google Groups "weewx-development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to weewx-developm...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/weewx-development/1b40f83d-3f9a-a9af-a7e0-9a374a15d64c%40isylum.org.

[Leon Shaner]

Tom,

Yep that was it.  WMR300 apparently needs to not only be manually switched from "dst" to "st" but the hour also had to decremented.
Now upon weewx restart it takes almost no time to process the very few "missed" records vs. what amounted to erroneously "replaying" an hours worth of records offset 1-hour in the future and therefore, blocking the proper insertion of the actual records as time progressed normally.
All this time since DST changed to EST, every time I've had a weewx restart I've been effectively losing an hour of data. :-(
Just too busy with work to dig into it before now.  :-/

Hoping the latest weewx changes and the move from Raspbian Stretch to Buster and from Python 2.7 to 3.5 will avoid the memory leak finally and the need for the watchdog weewx restarts.
But anyway, even if the memory leak persists at least I won't be losing data now that I figured out what was going on.

Cheers!  =D
\Leon

Leon Shaner wrote on 12/14/19 4:01 PM:

To view this discussion on the web visit https://groups.google.com/d/msgid/weewx-development/d597904f-19ec-8004-dbda-078077129f00%40isylum.org.

[Leon Shaner]

Tom,

One more thing to add...

An interesting "one-time" artifact of changing the WMR300 from EDT to EST is the history replay is adding a handful of entries added one hour in the future.
Probably a bug/RFE here that WMR 300 historical replay should refuse to insert future-dated timestamps into the weewx DB.
Would be nice to turn the presence of future-dated history records into a warning that the station is likely on the wrong side of DST/ST.
That would have alerted me to the fact this station doesn't auto-adjust for DST/ST.  That coupled with the refusal to insert the future-data records would have avoided loss of data.

An hour after weewx restart, I saw:

Dec 14 16:58:14 nixie weewx[14980] ERROR weewx.manager: Unable to add record 2019-12-14 16:58:00 EST (1576360680) to database 'weewx.sdb': UNIQUE constraint failed: archive.dateTime
Dec 14 16:59:15 nixie weewx[14980] ERROR weewx.manager: Unable to add record 2019-12-14 16:59:00 EST (1576360740) to database 'weewx.sdb': UNIQUE constraint failed: archive.dateTime
Dec 14 17:00:15 nixie weewx[14980] ERROR weewx.manager: Unable to add record 2019-12-14 17:00:00 EST (1576360800) to database 'weewx.sdb': UNIQUE constraint failed: archive.dateTime
Dec 14 17:01:14 nixie weewx[14980] ERROR weewx.manager: Unable to add record 2019-12-14 17:01:00 EST (1576360860) to database 'weewx.sdb': UNIQUE constraint failed: archive.dateTime
Dec 14 17:02:15 nixie weewx[14980] ERROR weewx.manager: Unable to add record 2019-12-14 17:02:00 EST (1576360920) to database 'weewx.sdb': UNIQUE constraint failed: archive.dateTime

And checking for those timestamps from the history replay I see that in fact right after WeeWx was restarted there were some five records inserted into the future:

pi@nixie:~ $ egrep 'Starting|1576360680|1576360740|1576360800|1576360860|1576360920' /tmp/weewx4b.log
Dec 14 16:05:55 nixie weewx[14980] INFO weewx.engine: Starting up weewx version 4.0.0b5
Dec 14 16:05:55 nixie weewx[14980] INFO weewx.manager: Starting backfill of daily summaries
Dec 14 16:05:55 nixie weewx[14980] INFO weewx.drivers.wmr300: New historical record for 2019-12-14 16:58:00 EST (1576360680): 33: {'dateTime': 1576360680.0, 'usUnits': 17, 'barometer': 976.9000000000001, 'windSpeed': 1.6, 'windDir': 282.0, 'windGust': 2.6, 'windGustDir': 248.0, 'inTemp': 20.900000000000002, 'outTemp': 5.300000000000001, 'extraTemp1': None, 'extraTemp2': None, 'extraTemp3': None, 'extraTemp4': None, 'extraTemp5': None, 'extraTemp6': None, 'extraTemp7': None, 'inHumidity': 39.0, 'outHumidity': 75.0, 'extraHumid1': None, 'extraHumid2': None, 'extraHumid3': None, 'extraHumid4': None, 'extraHumid5': None, 'extraHumid6': None, 'extraHumid7': None, 'dewpoint': None, 'extraDewpoint1': None, 'extraDewpoint2': None, 'extraDewpoint3': None, 'extraDewpoint4': None, 'extraDewpoint5': None, 'extraDewpoint6': None, 'extraDewpoint7': None, 'heatindex': None, 'extraHeatindex1': None, 'extraHeatindex2': None, 'extraHeatindex3': None, 'extraHeatindex4': None, 'extraHeatindex5': None, 'extraHeatindex6': None, 'extraHeatindex7': 3.4000000000000004, 'windchill': 3.4000000000000004, 'rainRate': 0.0, 'rainTotal': 503.17400000000004, 'rain': 0.0, 'interval': 1.0}
Dec 14 16:05:55 nixie weewx[14980] INFO weewx.manager: Added record 2019-12-14 16:58:00 EST (1576360680) to database 'weewx.sdb'
Dec 14 16:05:55 nixie weewx[14980] INFO weewx.manager: Added record 2019-12-14 16:58:00 EST (1576360680) to daily summary in 'weewx.sdb'
Dec 14 16:05:56 nixie weewx[14980] INFO weewx.drivers.wmr300: New historical record for 2019-12-14 16:59:00 EST (1576360740): 34: {'dateTime': 1576360740.0, 'usUnits': 17, 'barometer': 976.9000000000001, 'windSpeed': 1.6, 'windDir': 282.0, 'windGust': 4.3, 'windGustDir': 234.0, 'inTemp': 20.900000000000002, 'outTemp': 5.300000000000001, 'extraTemp1': None, 'extraTemp2': None, 'extraTemp3': None, 'extraTemp4': None, 'extraTemp5': None, 'extraTemp6': None, 'extraTemp7': None, 'inHumidity': 39.0, 'outHumidity': 75.0, 'extraHumid1': None, 'extraHumid2': None, 'extraHumid3': None, 'extraHumid4': None, 'extraHumid5': None, 'extraHumid6': None, 'extraHumid7': None, 'dewpoint': None, 'extraDewpoint1': None, 'extraDewpoint2': None, 'extraDewpoint3': None, 'extraDewpoint4': None, 'extraDewpoint5': None, 'extraDewpoint6': None, 'extraDewpoint7': None, 'heatindex': None, 'extraHeatindex1': None, 'extraHeatindex2': None, 'extraHeatindex3': None, 'extraHeatindex4': None, 'extraHeatindex5': None, 'extraHeatindex6': None, 'extraHeatindex7': 2.2, 'windchill': 2.2, 'rainRate': 0.0, 'rainTotal': 503.17400000000004, 'rain': 0.0, 'interval': 1.0}
Dec 14 16:05:56 nixie weewx[14980] INFO weewx.manager: Added record 2019-12-14 16:59:00 EST (1576360740) to database 'weewx.sdb'
Dec 14 16:05:56 nixie weewx[14980] INFO weewx.manager: Added record 2019-12-14 16:59:00 EST (1576360740) to daily summary in 'weewx.sdb'
Dec 14 16:05:56 nixie weewx[14980] INFO weewx.drivers.wmr300: New historical record for 2019-12-14 17:00:00 EST (1576360800): 35: {'dateTime': 1576360800.0, 'usUnits': 17, 'barometer': 976.9000000000001, 'windSpeed': 1.6, 'windDir': 282.0, 'windGust': 1.8, 'windGustDir': 319.0, 'inTemp': 20.900000000000002, 'outTemp': 5.2, 'extraTemp1': None, 'extraTemp2': None, 'extraTemp3': None, 'extraTemp4': None, 'extraTemp5': None, 'extraTemp6': None, 'extraTemp7': None, 'inHumidity': 39.0, 'outHumidity': 75.0, 'extraHumid1': None, 'extraHumid2': None, 'extraHumid3': None, 'extraHumid4': None, 'extraHumid5': None, 'extraHumid6': None, 'extraHumid7': None, 'dewpoint': None, 'extraDewpoint1': None, 'extraDewpoint2': None, 'extraDewpoint3': None, 'extraDewpoint4': None, 'extraDewpoint5': None, 'extraDewpoint6': None, 'extraDewpoint7': None, 'heatindex': None, 'extraHeatindex1': None, 'extraHeatindex2': None, 'extraHeatindex3': None, 'extraHeatindex4': None, 'extraHeatindex5': None, 'extraHeatindex6': None, 'extraHeatindex7': 3.8000000000000003, 'windchill': 3.8000000000000003, 'rainRate': 0.0, 'rainTotal': 503.17400000000004, 'rain': 0.0, 'interval': 1.0}
Dec 14 16:05:56 nixie weewx[14980] INFO weewx.manager: Added record 2019-12-14 17:00:00 EST (1576360800) to database 'weewx.sdb'
Dec 14 16:05:56 nixie weewx[14980] INFO weewx.manager: Added record 2019-12-14 17:00:00 EST (1576360800) to daily summary in 'weewx.sdb'
Dec 14 16:05:56 nixie weewx[14980] INFO weewx.drivers.wmr300: New historical record for 2019-12-14 17:01:00 EST (1576360860): 36: {'dateTime': 1576360860.0, 'usUnits': 17, 'barometer': 976.9000000000001, 'windSpeed': 2.3000000000000003, 'windDir': 270.0, 'windGust': 1.3, 'windGustDir': 224.0, 'inTemp': 20.8, 'outTemp': 5.2, 'extraTemp1': None, 'extraTemp2': None, 'extraTemp3': None, 'extraTemp4': None, 'extraTemp5': None, 'extraTemp6': None, 'extraTemp7': None, 'inHumidity': 39.0, 'outHumidity': 75.0, 'extraHumid1': None, 'extraHumid2': None, 'extraHumid3': None, 'extraHumid4': None, 'extraHumid5': None, 'extraHumid6': None, 'extraHumid7': None, 'dewpoint': None, 'extraDewpoint1': None, 'extraDewpoint2': None, 'extraDewpoint3': None, 'extraDewpoint4': None, 'extraDewpoint5': None, 'extraDewpoint6': None, 'extraDewpoint7': None, 'heatindex': None, 'extraHeatindex1': None, 'extraHeatindex2': None, 'extraHeatindex3': None, 'extraHeatindex4': None, 'extraHeatindex5': None, 'extraHeatindex6': None, 'extraHeatindex7': None, 'windchill': None, 'rainRate': 0.0, 'rainTotal': 503.17400000000004, 'rain': 0.0, 'interval': 1.0}
Dec 14 16:05:57 nixie weewx[14980] INFO weewx.manager: Added record 2019-12-14 17:01:00 EST (1576360860) to database 'weewx.sdb'
Dec 14 16:05:57 nixie weewx[14980] INFO weewx.manager: Added record 2019-12-14 17:01:00 EST (1576360860) to daily summary in 'weewx.sdb'
Dec 14 16:05:57 nixie weewx[14980] INFO weewx.drivers.wmr300: New historical record for 2019-12-14 17:02:00 EST (1576360920): 37: {'dateTime': 1576360920.0, 'usUnits': 17, 'barometer': 976.9000000000001, 'windSpeed': 2.3000000000000003, 'windDir': 270.0, 'windGust': 1.4000000000000001, 'windGustDir': 274.0, 'inTemp': 20.8, 'outTemp': 5.2, 'extraTemp1': None, 'extraTemp2': None, 'extraTemp3': None, 'extraTemp4': None, 'extraTemp5': None, 'extraTemp6': None, 'extraTemp7': None, 'inHumidity': 39.0, 'outHumidity': 75.0, 'extraHumid1': None, 'extraHumid2': None, 'extraHumid3': None, 'extraHumid4': None, 'extraHumid5': None, 'extraHumid6': None, 'extraHumid7': None, 'dewpoint': None, 'extraDewpoint1': None, 'extraDewpoint2': None, 'extraDewpoint3': None, 'extraDewpoint4': None, 'extraDewpoint5': None, 'extraDewpoint6': None, 'extraDewpoint7': None, 'heatindex': None, 'extraHeatindex1': None, 'extraHeatindex2': None, 'extraHeatindex3': None, 'extraHeatindex4': None, 'extraHeatindex5': None, 'extraHeatindex6': None, 'extraHeatindex7': None, 'windchill': None, 'rainRate': 0.0, 'rainTotal': 503.17400000000004, 'rain': 0.0, 'interval': 1.0}
Dec 14 16:05:57 nixie weewx[14980] INFO weewx.manager: Added record 2019-12-14 17:02:00 EST (1576360920) to database 'weewx.sdb'
Dec 14 16:05:57 nixie weewx[14980] INFO weewx.manager: Added record 2019-12-14 17:02:00 EST (1576360920) to daily summary in 'weewx.sdb'
Dec 14 16:05:58 nixie weewx[14980] INFO weewx.engine: Starting main packet loop.
...

(and then the timestamp matches shown at the start of this e-mail)

Regards,
\Leon

Leon Shaner wrote on 12/14/19 4:11 PM:

[mwall]

On Saturday, December 14, 2019 at 5:20:04 PM UTC-5, Leon Shaner wrote:

That coupled with the refusal to insert the future-data records would have avoided loss of data.

leon, i put in a fix at commit 10d00a23. this is on the development branch.  this will reject any historical record that has a timestamp in the future.  it won't log about the DST stuff, but it will log the rejected records.

could you try it?

m

[mwall]

tom,

i did a patch on the wmr300 driver, but perhaps this would be better done in the engine?

rejecting packets/records that have a dateTime in the future is pretty generic

doing it in the engine would prevent problems from any driver...

m

[mwall]

leon,

i put the change in engine.py instead of wmr300.py - that way it will fix this problem for every driver, not just wmr300.  changed at weewx-development commit e9962fe8

can you test it with the appropriate DST settings and historical data on your station?

m

[Thomas Keffer]

i put the change in engine.py instead of wmr300.py - that way it will fix this problem for every driver, not just wmr300.  changed at weewx-development commit e9962fe8

For stations with an internal clock, it's possible the time will drift a few seconds, maybe even archive_delay seconds ahead. We don't want to reject records just because of that.

-tk

 

[mwall]

On Saturday, December 14, 2019 at 6:57:13 PM UTC-5, Tom Keffer wrote:

For stations with an internal clock, it's possible the time will drift a few seconds, maybe even archive_delay seconds ahead. We don't want to reject records just because of that.

done at commit f0bb3259