DST change problem for CEST -> CET

[kobuki]

I have an interesting problem with my installation. DST change occurred here last week at Sunday morning, when the clock has been moved back from 3:00AM to 2:00AM (CEST -> CET). The one-hour slur of duplicate key warnings are logged in weewx.log, and it's deemed normal in case of the Davis console/Envoy as I've gathered from earlier forum threads here. Uploads to WU and another Hungarian site (Idokep) were happening normally even in the period when the warnings were logged. But today morning I looked at my curves and saw a gap from 2:00AM to 3:00AM and again, duplicates are logged for every archive record in that period. All archive logs are missing there.

Here's the log extract from the beginning and the end of the problematic period:

Nov  2 01:59:20 weather weewx[5289]: restx: Wunderground-PWS: Published record 2014-11-02 01:59:00 CET (1414889940)
Nov  2 01:59:20 weather weewx[5289]: cheetahgenerator: generated 12 'ToDate' files for StandardReport in 0.17 seconds
Nov  2 01:59:20 weather weewx[5289]: genimages: Generated 0 images for StandardReport in 0.03 seconds
Nov  2 02:00:20 weather weewx[5289]: archive: unable to add record 2014-11-02 01:00:00 CET (1414886400) to database 'weewx': (1062, "Duplicate entry '1414886400' for key 'PRIMARY'")
Nov  2 02:00:20 weather weewx[5289]: cheetahgenerator: generated 1 'SummaryByMonth' files for StandardReport in 0.05 seconds
Nov  2 02:00:20 weather weewx[5289]: cheetahgenerator: generated 1 'SummaryByYear' files for StandardReport in 0.24 seconds
Nov  2 02:00:20 weather weewx[5289]: cheetahgenerator: generated 12 'ToDate' files for StandardReport in 0.17 seconds
Nov  2 02:00:20 weather weewx[5289]: genimages: Generated 0 images for StandardReport in 0.03 seconds
Nov  2 02:00:20 weather weewx[5289]: restx: Wunderground-PWS: Published record 2014-11-02 01:00:00 CET (1414886400)
Nov  2 02:01:20 weather weewx[5289]: archive: unable to add record 2014-11-02 01:00:00 CET (1414886400) to database 'weewx': (1062, "Duplicate entry '1414886400' for key 'PRIMARY'")
Nov  2 02:01:20 weather weewx[5289]: archive: unable to add record 2014-11-02 01:01:00 CET (1414886460) to database 'weewx': (1062, "Duplicate entry '1414886460' for key 'PRIMARY'")

... similar content repeating ...

Nov  2 02:58:43 weather weewx[5289]: restx: Wunderground-PWS: Published record 2014-11-02 01:55:00 CET (1414889700)
Nov  2 02:58:44 weather weewx[5289]: restx: Wunderground-PWS: Published record 2014-11-02 01:56:00 CET (1414889760)
Nov  2 02:58:44 weather weewx[5289]: restx: Wunderground-PWS: Published record 2014-11-02 01:57:00 CET (1414889820)
Nov  2 02:58:44 weather weewx[5289]: restx: Wunderground-PWS: Published record 2014-11-02 01:58:00 CET (1414889880)
Nov  2 02:59:19 weather weewx[5289]: cheetahgenerator: generated 1 'SummaryByMonth' files for StandardReport in 0.02 seconds
Nov  2 02:59:19 weather weewx[5289]: cheetahgenerator: generated 1 'SummaryByYear' files for StandardReport in 0.13 seconds
Nov  2 02:59:19 weather weewx[5289]: cheetahgenerator: generated 12 'ToDate' files for StandardReport in 0.09 seconds
Nov  2 02:59:19 weather weewx[5289]: genimages: Generated 0 images for StandardReport in 0.02 seconds
Nov  2 03:00:20 weather weewx[5289]: archive: added record 2014-11-02 02:00:00 CET (1414890000) to database 'weewx'; table 'archive'
Nov  2 03:00:20 weather weewx[5289]: cheetahgenerator: generated 1 'SummaryByMonth' files for StandardReport in 0.05 seconds
Nov  2 03:00:20 weather weewx[5289]: restx: IDOKEP: Published record 2014-11-02 02:00:00 CET (1414890000)
Nov  2 03:00:20 weather weewx[5289]: cheetahgenerator: generated 1 'SummaryByYear' files for StandardReport in 0.24 seconds
Nov  2 03:00:20 weather weewx[5289]: restx: Wunderground-PWS: Published record 2014-11-02 02:00:00 CET (1414890000)

Truth be told, I set up automatic handling of DST in the Envoy a week ago after 2:00AM, before 3:00AM (still in the DST period, right before the clock went back 1 hr), saw the duplicate warnings but then everything seemed fine, till this morning. Could it be that the Envoy is misprogrammed as far as DST handling goes? It looks as if it has tried to end CEST this morning instead of the "real" one that happened a week ago. I'm pasting my "wee_config_vantage --info" output too, it might be useful. I omitted my coordinates, but they're correct in the Envoy (though IIRC they're not used for DSN handling).

Using configuration file /etc/weewx/weewx.conf.
Querying...
Davis Vantage EEPROM settings:

    CONSOLE TYPE:                   VantagePro2

    CONSOLE FIRMWARE:
      Date:                         Jun  3 2013
      Version:                      3.15

    CONSOLE SETTINGS:
      Archive interval:             60 (seconds)
      Altitude:                     574 (foot)
      Wind cup type:                large
      Rain bucket type:             0.2 MM
      Rain year start:              1
      Onboard time:                 2014-11-02 14:02:54

    CONSOLE DISPLAY UNITS:
      Barometer:                    mbar
      Temperature:                  degree_F
      Rain:                         inch
      Wind:                         mile_per_hour

    CONSOLE STATION INFO:
      Latitude (onboard):           +xx.x
      Longitude (onboard):          +xx.x
      Use manual or auto DST?       AUTO
      DST setting:                  N/A
      Use GMT offset or zone code?  ZONE_CODE
      Time zone code:               22
      GMT offset:                   N/A

    TRANSMITTERS:
      Channel 1:                    iss
      Channel 2:                    wind
      Channel 3:                    (N/A)
      Channel 4:                    (N/A)
      Channel 5:                    (N/A)
      Channel 6:                    (N/A)
      Channel 7:                    (N/A)
      Channel 8:                    (N/A)

    RECEPTION STATS:
      Total packets received:       13895
      Total packets missed:         889
      Number of resynchronizations: 5
      Longest good stretch:         45
      Number of CRC errors:         54

    BAROMETER CALIBRATION DATA:
      Current barometer reading:    30.284 inHg
      Altitude:                     574 feet
      Dew point:                    46 F
      Virtual temperature:          42 F
      Humidity correction factor:   21
      Correction ratio:             1.022
      Correction constant:          +0.039 inHg
      Gain:                         0.000
      Offset:                       -47.000

    OFFSETS:
      Wind direction:               +0 deg
      Inside Temperature:           +0.0 F
      Inside Humidity:              +0%
      Outside Temperature:          +0.0 F
      Outside Humidity:             +0%

[kobuki]

No one has an idea?

I can post more info if needed. Please help me solve this. Do I need to turn off automatic DST settings and adjust DST manually every time?

[Thomas Keffer]

I think it would help if you posted the images with the problem.

-tk

--
You received this message because you are subscribed to the Google Groups "weewx-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to weewx-user+...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[kobuki]

Sorry, I don't follow. What kind of images would you need?

[Thomas Keffer]

I'm trying to understand what the problem is. You said, "But today morning I looked at my curves and saw a gap..." 

I assume that is the problem? If so, I'd like to see the gap.

If that is not the problem, what is?

-tk

[kobuki]

Well, I'm pretty certain I described the problem as thoroughly as I could, and provided a small fragment of the log so you see how and when the problem appeared. But it might be that I wasn't thorough enough so let me rephrase it.

I'm missing a one-hour part of the archive and thus a small one-hour fragment of the graphs are missing. And yes, if we want to visualize the problem, there is a gap on all the daily curves. I cannot provide you with one that shows the gap visibly, because the daily graphs are rolled out and on the weekly graphs you cannot see it.

From the logs my idea of the problem is that the Envoy mishandles CET/CEST DST changes - it appears to handle them a week later than expected. Could that be right?

I can send you an SQL dump of the problematic day and the full logs for that day if that helps.

Thank you in advance.

[Thomas Keffer]

The Davis consoles suffer from an unfortunate design decision to store records internally in local time. That means that during the fall transition period, you cannot tell the difference between, say, 1:30am CET and 1:30am CEST. As data comes off the logger, it will simply jump backwards an hour with no other explanation. Unless weewx were to become locale aware, it can't know why the time went backwards. For it to become locale aware would require installing pytz and a whole new set of headaches that come with that.

The net result is that weewx complains about one hours worth of "PRIMARY KEY must be unique" errors.  

I have tried many ways of working around this problem, and they all seem to make things worse. 

Is this the problem you were trying to describe?

-tk

--

[kobuki]

I have already read the answer you pasted, and this is close, yes. As I've already mentioned in the first paragraph of my opening message, I am aware of that behavior (duplicate keys around DST). However, this should have happened on 26 Oct, not last Sunday morning, 2 Nov. So from what you have just written I can conclude that you're not aware of bugs in the Envoy firmware, nor in WeeWx to cause DST change a week later. I'll take my bets on a buggy firmware. DST change happened in my Envoy when it's supposed to be happening in North America. I guess Davis devs just assumed it happens at the same time around the world or something. I'll prolly switch back to manual DST settings. I'm a little surprised though, that no one else noticed this problem.

[Thomas Keffer]

That's probably right. 

You're probably better off going with manual DST setting, then let weewx manage the clock through StdTimeSync.

-tk

[kobuki]

Okay, thanks. In any case I'll attempt to reach Davis with my problem.

[Thomas Keffer]

Here's a nice example of the problem. This is a data dump from one of my loggers. 

The first time stamp is the time as it comes off the logger. The second is weewx's best guess as to what it represents. The blue colors are the records affected by the DST transition. Note how there are two, say, "2014-11-02 01:30" timestamps (highlighted) with no way of telling them apart.

I'm sure open to ideas how to solve this.

-tk

781 156 1 | 2014-11-02 00:45 | 2014-11-02 00:45:00 PDT (1414914300)
782 156 2 | 2014-11-02 00:50 | 2014-11-02 00:50:00 PDT (1414914600)
783 156 3 | 2014-11-02 00:55 | 2014-11-02 00:55:00 PDT (1414914900)
784 156 4 | 2014-11-02 01:00 | 2014-11-02 01:00:00 PDT (1414915200)
785 157 0 | 2014-11-02 01:05 | 2014-11-02 01:05:00 PDT (1414915500)
786 157 1 | 2014-11-02 01:10 | 2014-11-02 01:10:00 PDT (1414915800)
787 157 2 | 2014-11-02 01:15 | 2014-11-02 01:15:00 PDT (1414916100)
788 157 3 | 2014-11-02 01:20 | 2014-11-02 01:20:00 PDT (1414916400)
789 157 4 | 2014-11-02 01:25 | 2014-11-02 01:25:00 PDT (1414916700)
790 158 0 | 2014-11-02 01:30 | 2014-11-02 01:30:00 PDT (1414917000)
791 158 1 | 2014-11-02 01:35 | 2014-11-02 01:35:00 PDT (1414917300)
792 158 2 | 2014-11-02 01:40 | 2014-11-02 01:40:00 PDT (1414917600)
793 158 3 | 2014-11-02 01:45 | 2014-11-02 01:45:00 PDT (1414917900)
794 158 4 | 2014-11-02 01:50 | 2014-11-02 01:50:00 PDT (1414918200)
795 159 0 | 2014-11-02 01:55 | 2014-11-02 01:55:00 PDT (1414918500)
796 159 1 | 2014-11-02 01:00 | 2014-11-02 01:00:00 PDT (1414915200)
797 159 2 | 2014-11-02 01:05 | 2014-11-02 01:05:00 PDT (1414915500)
798 159 3 | 2014-11-02 01:10 | 2014-11-02 01:10:00 PDT (1414915800)
799 159 4 | 2014-11-02 01:15 | 2014-11-02 01:15:00 PDT (1414916100)
800 160 0 | 2014-11-02 01:20 | 2014-11-02 01:20:00 PDT (1414916400)
801 160 1 | 2014-11-02 01:25 | 2014-11-02 01:25:00 PDT (1414916700)
802 160 2 | 2014-11-02 01:30 | 2014-11-02 01:30:00 PDT (1414917000)
803 160 3 | 2014-11-02 01:35 | 2014-11-02 01:35:00 PDT (1414917300)
804 160 4 | 2014-11-02 01:40 | 2014-11-02 01:40:00 PDT (1414917600)
805 161 0 | 2014-11-02 01:45 | 2014-11-02 01:45:00 PDT (1414917900)
806 161 1 | 2014-11-02 01:50 | 2014-11-02 01:50:00 PDT (1414918200)
807 161 2 | 2014-11-02 01:55 | 2014-11-02 01:55:00 PDT (1414918500)
808 161 3 | 2014-11-02 02:00 | 2014-11-02 02:00:00 PST (1414922400)
809 161 4 | 2014-11-02 02:05 | 2014-11-02 02:05:00 PST (1414922700)
810 162 0 | 2014-11-02 02:10 | 2014-11-02 02:10:00 PST (1414923000)

[kobuki]

Yeah, I got that the first time when I read about it a week ago at CET DST transition. There's no easy way around it, really. The buggy FW with the one-week-late DST adjustment is just the icing on the cake. I'm an SW dev too (used to be for ~20 years) and a lot of info is missing for solving it in a robust way. One can't just assume DST has changed when the console/envoy is suddenly back an hour, even when it's expected. Too many variables can be changing outside of the control of the program or the programmer. Not even mentioning stored archive records in the console.

One might be able to handle the problem by disregarding timestamps from the console and using the local system time of weewx. But then what about reading the backlog with DMPAFT? The records should be put somewhere on the timeline. If records happen to be stored before and after the DST change then we're back to square one.

Another idea is to have the user disable automatic DST changes. Then the most difficult piece of the puzzle can be solved and weewx would be able to take care of the problem, but then what about the time displayed on the console? For an envoy it's largely irrelevant, though.

If the records are always generated by software, and only catch-ups are read with DMPAFT, then the problem is 99.9% mitigated (there's a very thin chance of a catch-up happening at DST transitions), but not solved. I'm going to switch to software record generation for other reasons I mentioned in another post, anyway.

And then, even if the problem is mitigated succesfully, there's the problem of the number of hours in a day. At DST start, the day is one hour shorter; at DST end, it is one hour longer. It should somehow be reflected on the graphs.

Well, take it as if I was thinking out loud :) You most probably have given a lot of thought at solving this and I for one, can fully understand why this isn't solved. I can live with one hour of missed records, of course, as everyone else. It only hurts my programmer side... It might be beneficial to study how other software authors handled this same problem. At least I have a habit of gathering working ideas instead of reinventing the wheel.

[Andrew Milner]

My graphs DID have an extra hour in them as the clock went back - so all praise to the team!!  Especially as the clock on the fo systems is ignored - so even more praise to Mathew!!  It worked like a dream.  Now I have a wee dilemma as my console clock is showing the correct time without me having adjusted anything - and I do not know if I had it right or wrong before the time change!!  If it can be done for the crappy FO systems then as sure as eggs is eggs it can be done for the more sophisticated Davis systems - surely ...!!!

Now back to getting meso working again ....

[kobuki]

Yeah, if you can completely ignore hardware/console time, it might be a win. But well, that's just a workaround for Davis hardware... Maybe Tom could add an option to ignore the HW-provided timestamps for the Vantage driver?