WEEWXtags.php $time is 1 hour off (slow)

[ktrue]

Very strange. The RPi is using America/Los_Angeles as local timezone. A date command shows current time in the shell. The WEEWXtags.php?sce=view shows the $time field as exactly 1 hour slow.

https://saratoga-weather.org/weewx/wxstatus.php https://saratoga-weather.org/weewx/WEEWXtags.php?sce=view

Weewx 4.10.2, WeewxSaratoga 0.1.7

[gjr80]

Ken, I'm a little puzzled. Doesn't WEEWXtags.php?sce=view show the WEEWXtags.php source so you can read $time directly, and wxstatus.php displays the time as read from $time in WEEWXtags.php. So they should be displaying identical times. I looked at those two links just now and I am guessing something has crashed as your site is showing it is 3:46am 15 September but your WEEWXtags.php?sce=view and wxstaus.php are both showing 8:40pm 14 September (at least they both agree!).

I'm interstate at the moment and not home until 25 September so a little difficult to do much troubleshooting.

[ktrue]

It looks like it stopped collecting and updating. I've restarted weewx and now the times are better.

I checked the /var/log/syslog and found

Sep 15 06:39:31 TRP3WX weewx[782] INFO __main__: Starting up weewx version 4.10.2
Sep 15 06:39:53 TRP3WX weewx[782] ERROR weewx.drivers.vantage: ip-read error: timed out
Sep 15 06:39:55 TRP3WX weewx[782] INFO weewx.engine: Clock error is -3554.81 seconds (positive is fast)
Sep 15 06:39:58 TRP3WX weewx[782] INFO weewx.drivers.vantage: Clock set to 2023-09-15 06:39:58 PDT (1694785198)
Sep 15 06:39:58 TRP3WX weewx[782] INFO weewx.engine: Using binding 'wx_binding' to database 'weewx.sdb'
Sep 15 06:39:58 TRP3WX weewx[782] INFO weewx.manager: Starting backfill of daily summaries
Sep 15 06:39:58 TRP3WX weewx[782] INFO weewx.manager: Daily summaries up to date
Sep 15 06:40:01 TRP3WX weewx[782] INFO weewx.manager: Added record 2023-09-14 20:45:00 PDT (1694749500) to database 'weewxwd.sdb'
Sep 15 06:40:01 TRP3WX weewx[782] INFO weewx.manager: Added record 2023-09-14 20:45:00 PDT (1694749500) to daily summary in 'weewxwd.sdb'

I used WeatherLink Setup to reset the time on the console (it was off by -2 minutes from current) and restarted weewx. Now the times are much better matched.

[gjr80]

Sep 15 06:39:55 TRP3WX weewx[782] INFO weewx.engine: Clock error is -3554.81 seconds (positive is fast)

Hmm, 3554 seconds will be the source of your one hour difference. With that sort of time difference WeeWX would have had issues saving records to database, exactly what the outcome would be I am not sure but the archive records would not have been saved with the correct timestamp and there would have been flow on problems for WEEWXtags.php generation.

By default (and provided the station hardware maintains a clock) WeeWX will check the station hardware clock drift every four hours and if it is more than (the default) five seconds the station hardware clock is updated to match the WeeWX PC clock. That is what occurred at startup and is recorded in the above log extract.

I'm thinking the original one hour problem was due to an out of date WEEWXtags.php (indirectly due to the one station hardware clock error) and wxstatus.php picking up the current time from clientraw.txt (or somewhere else, don't have the Saratoga source handy to confirm).

All that being said there is still something screwy, looking at wxstatus.php just now I am seeing WEEWXtags.php is always 'not current', typically 5-10 minute old. Would be interesting to see about 10-15 minutes of WeeWX log to see when WEEWXtags.php is generated and when it is uploaded to your web server.

[ktrue]

Yes, the wxstatus shows both the FTP filemtime() of the WEEWXtags.php and the internal $date $time values.
I did a shutdown of Weewx, used wee_device --set-time to force the console time set. At startup, the clock only showed 0.34sec out of 'current' Restarted weewx, and it still seems to be 5 minutes behind in the actual data posted in WEEWXtags.php. Clientraw.txt is showing current date/time, so that part works fine; only WEEWXtags.php seems to be 5 minutes behind.

[gjr80]

clientraw.txt is generated via a WeeWX service that runs/generates each time a loop packet arrives from the station using loop packet data, whereas WEEWXtags.php is generated via the WeeWX report service which runs after each archive record arrives/is generated (and saved to archive) using archive record data.

Depending on the number of reports WeeWX is producing and where WEEWXtags.php is in that list, WEEWXtags.php may be produced anywhere from 20 to 60 (or even up to 90) seconds after the archive record timestamp. If you are then uploading to a web server using the WeeWX FTP or Rsync reports that can add seconds as well. Of course the usual speed and load on the processor factors apply as well, but you generally need to be doing some significant processing/loading of the machine for those to be significant. Seeing consistent five+ minute delays really sounds like something fundamental is amiss. The next thing I would do is edit weewx.conf, set debug = 1 and restart WeeWX. Once WeeWX has been running for a 15 minutes or so take an extract from the WeeWX log showing at least three full report cycles. We should be able to see when archive records arrive (and their timestamps), when they are saved to archive, when WEEWXtags.php is generated and when it is uploaded to your web server. I doubt this is a WeeWX config issue, but it is probably also worthwhile capturing and posting the full WeeWX start log (through until the first archive record is saved), this will give us details of exactly how WeeWX is configured.

[ktrue]

Here's the 3 cycles of weewx from /var/log/syslog with startup. Thanks! weewx.debug.log

[gjr80]

Sorry, been travelling!

Well here is the cause:

Sep 16 17:40:15 TRP3WX weewx[5287] DEBUG weewx.drivers.vantage: Getting archive packets since 2023-09-16 17:30:00 PDT (1694910600)
Sep 16 17:40:17 TRP3WX weewx[5287] DEBUG weewx.drivers.vantage: Successfully woke up Vantage console
Sep 16 17:40:18 TRP3WX weewx[5287] DEBUG weewx.drivers.vantage: Retrieving 1 page(s); starting index= 3
Sep 16 17:40:18 TRP3WX weewx[5287] INFO weewx.manager: Added record 2023-09-16 17:35:00 PDT (1694910900) to database 'weewxwd.sdb'
Sep 16 17:40:18 TRP3WX weewx[5287] INFO weewx.manager: Added record 2023-09-16 17:35:00 PDT (1694910900) to daily summary in 'weewxwd.sdb'
Sep 16 17:40:18 TRP3WX weewx[5287] DEBUG weewx.manager: Daily summary version is 4.0
Sep 16 17:40:18 TRP3WX weewx[5287] DEBUG weewx.drivers.vantage: DMPAFT complete: page timestamp 2023-09-07 19:10:00 PDT (1694139000) less than final timestamp 2023-09-16 17:35:00 PDT (1694910900)
Sep 16 17:40:18 TRP3WX weewx[5287] DEBUG weewx.drivers.vantage: Catch up complete.
Sep 16 17:40:18 TRP3WX weewx[5287] DEBUG weewx.reportengine: Running reports for latest time in the database.

At 17:40:15 WeeWX asks the console/logger for all archive records since the last archive record in the database (17:30). With a five minute archive interval I would expect the logger would provide two archive records (17:35 and 17:40) but it only provides one (17:35). WeeWX saves this record to the database and runs the reports; however, the reports are run using the 17:35 archive record as the current record. Consequently the WEEWXtags.php generated at 17:40 uses the 17:35 record and straight away we are five minutes behind. WEEWXtags.php is uploaded at 17:40:27 so the youngest age wxstatus.php will report for WEEWXtags.php is 5:27, and it just gets worse from there until the next archive record when the age goes back to (around) 5:27 (actually 5:35 this time).

The real question is why does the logger only provide a five minute old archive record? I have no experience with the IP logger but I can't say I have seen any posts in weewx-user with the IP logger and the same problem. One thing that did come to mind: I guess you are running more than just WeeWX off your VP Pro, are other systems also accessing the IP logger or is it shared through software (Virtual VP is it?).

If you look at the end of the WeeWX startup when WeeWX starts it's catchup it manages to get the 17:30 archive record at (around) 17:30:56, so it may be a case of for some reason the archive record is not being made available until after WeeWX retrieves any new archive records.

Sep 16 17:30:52 TRP3WX weewx[5287] DEBUG weewx.manager: Daily summary version is 4.0
Sep 16 17:30:53 TRP3WX weewx[5287] DEBUG weewx.drivers.vantage: Successfully woke up Vantage console
Sep 16 17:30:54 TRP3WX weewx[5287] INFO weewx.engine: Clock error is -0.30 seconds (positive is fast)
Sep 16 17:30:54 TRP3WX weewx[5287] INFO weewx.engine: Using binding 'wx_binding' to database 'weewx.sdb'
Sep 16 17:30:54 TRP3WX weewx[5287] INFO weewx.manager: Starting backfill of daily summaries
Sep 16 17:30:54 TRP3WX weewx[5287] INFO weewx.manager: Daily summaries up to date
Sep 16 17:30:54 TRP3WX weewx[5287] DEBUG weewx.drivers.vantage: Getting archive packets since 2023-09-16 17:25:00 PDT (1694910300)
Sep 16 17:30:55 TRP3WX weewx[5287] DEBUG weewx.drivers.vantage: Successfully woke up Vantage console
Sep 16 17:30:56 TRP3WX weewx[5287] DEBUG weewx.drivers.vantage: Retrieving 1 page(s); starting index= 2
Sep 16 17:30:57 TRP3WX weewx[5287] INFO weewx.manager: Added record 2023-09-16 17:30:00 PDT (1694910600) to database 'weewxwd.sdb'
Sep 16 17:30:57 TRP3WX weewx[5287] INFO weewx.manager: Added record 2023-09-16 17:30:00 PDT (1694910600) to daily summary in 'weewxwd.sdb'
Sep 16 17:30:57 TRP3WX weewx[5287] DEBUG weewx.manager: Daily summary version is 4.0
Sep 16 17:30:57 TRP3WX weewx[5287] DEBUG weewx.drivers.vantage: DMPAFT complete: page timestamp 2023-09-07 19:05:00 PDT (1694138700) less than final timestamp 2023-09-16 17:30:00 PDT (1694910600)

One solution might be to increase the delay used by WeeWX before requesting new archive records, by default it is 15 seconds. The other solution that comes to mind is using software archive record generation rather than hardware archive records but I don't like this approach.

I'll drop Tom Keffer (WeeWX author) a line and ask his advice, he has much more Davis experience than I.

[ktrue]

thanks.. let me know what Tom says.

Here's a dump of the info:

pi@TRP3WX:~ $ sudo /etc/init.d/weewx stop
Stopping weewx (via systemctl): weewx.service.
pi@TRP3WX:~ $ wee_device --info
Using configuration file /etc/weewx/weewx.conf
Using Vantage driver version 3.5.2 (weewx.drivers.vantage)
Querying...
Davis Vantage EEPROM settings:

    CONSOLE TYPE:                   Vantage Pro

    CONSOLE FIRMWARE:
      Date:                         Nov 20 2006
      Version:                      <Unavailable>

    CONSOLE SETTINGS:
      Archive interval:             300 (seconds)
      Altitude:                     374 (foot)
      Wind cup type:                large
      Rain bucket type:             0.01 inches
      Rain year start:              7
      Onboard time:                 2023-09-18 11:39:31

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

    CONSOLE STATION INFO:
      Latitude (onboard):           +37.3
      Longitude (onboard):          -122.0
      Use manual or auto DST?       AUTO
      DST setting:                  N/A
      Use GMT offset or zone code?  ZONE_CODE
      Time zone code:               4
      GMT offset:                   N/A
      Temperature logging:          LAST
      Retransmit channel:           ON (2)

Traceback (most recent call last):
  File "/usr/share/weewx/wee_device", line 76, in <module>
    main()
  File "/usr/share/weewx/wee_device", line 72, in main
    device.configure(config_dict)
  File "/usr/share/weewx/weewx/drivers/__init__.py", line 67, in configure
    self.do_options(options, parser, config_dict, not options.noprompt)
  File "/usr/share/weewx/weewx/drivers/vantage.py", line 2157, in do_options
    self.show_info(station)
  File "/usr/share/weewx/weewx/drivers/vantage.py", line 2281, in show_info
    transmitter_list = station.getStnTransmitters()
  File "/usr/share/weewx/weewx/drivers/vantage.py", line 1289, in getStnTransmitters
    'repeater' : Vantage.repeater_dict[repeater_id],
KeyError: 1
pi@TRP3WX:~ $ sudo /etc/init.d/weewx start
Starting weewx (via systemctl): weewx.service.
pi@TRP3WX:~ $

Odd that the wee_device --info command seems to blow up at the end.

Yes, the TCP connection is to VirtualVP which is driving multiple software programs with the weather data, and none of them are having the issue with lagging data being displayed. This is a very ancient console (from 2004) with the last firmware update applied ages ago to support the change in dates for DST. It is connected via a serial port (and opto-isolator) to the wired VP1+ ISS.

[gjr80]

That is odd about wee_device --info. The error indicates that WeeWX received a repeater ID of 1 from the console, I'm not sure, but the way I read the Davis Serial Communications Reference is that allowable values are 0, 8, 9,10, 11, 12, 13, 14 and 15. Could be due to the age of the console, but I am guessing here. Does not appear to be Virtual VP related as the command used to obtain data from the console EEPROM works fine for altitude, archive interval, rain year start etc.

I have a theory on why only WeeWX exhibits this problem. WeeWX continuously receives and accumulates loop packet data from the console/logger. By default, at the end of an archive interval WeeWX attempts to obtain an archive record from the console/logger (known as hardware record generation). If a record is provided it is saved to database. If WeeWX is set to software record generation, WeeWX does not attempt obtain an archive record from the console/logger, rather WeeWX synthesises an archive record from the loop packets accumulated in the current archive interval. This synthesised archive record is saved to database. I think why other programs do not exhibit this problem is that they only use hardware archive records for catchup/history download on startup. When running steady state they only use loop packet data. My C knowledge is pretty limited, but looking at the Cumulus source on GitHub it appears that Cumulus behaves in this manner. I must drop Mark Crossly a line to confirm. WeatherDisplay is closed source, but I suspect it operates in a similar manner.

Tom did not have much info to add, he has seen similar behaviour before, but it is usually associated with a long period of catchup on startup and during this catchup an archive record arrives. That is quite different to what you are seeing.

We know that Virtual VP is passing on archive record from the console/logger, but I wonder if there is some delay in there that means the archive record is not available when WeeWX asks for it. Such behaviour would not impact programs that download archive records either as a catchup or history download, and of course has no impact on program that use loop packets only for steady state operation. I mentioned earlier that by default WeeWX waits 15 seconds after the time the console/logger should produce an archive record, let's try extending that period. Could you try editing weewx.conf and under [StdArchive] set archive_delay = 30 (suspect you will need to add the setting, it is not normally included in weewx.conf). Save weewx.conf and restart. See if that improves things, it should be fairly evident in the log and of course visible in wxstatus.php. If 30 seconds does not fix it you could try something longer. The downside with increasing archive_delay is that you will be delaying the update of data on your site, the site will still be updated every five minutes, but there will now be extra delay before the web site receives the updated files (this will affect all WeeWX generated files not just WEEWXtags.php).

If archive_delay needs to be set to an unacceptably large number, it might be worth switching to software record generation (ie under [StdArchive] set record_generation = software then save and restart). I will need to check the downside on using software record generation, it was the case in the past that this meant the loss of the catchup facility on loss of power or WeeWX crashing, but I have an inkling that was fixed. Need to check.

[ktrue]

I've set archive_delay = 20 and it seems to work. I tried archive_delay = 10 but it didn't fix it, so backed-off to 20 seconds.

I'm leaving it there overnight. Thanks for all your help with this issue!

[gjr80]

That is good news and I'm glad to help. I expect 10 would fail, the default was 15 and it was not working and if my theory was correct we just needed to wait a little longer for the archive record to be available. The archive_delay setting should be set as low was possible, but high enough to ensure reliable operation. If 20 is stable that will be good, you will not notice the five seconds difference, though maybe wxstatus.php might need to be told to allow a little more time before considering WEEWXtags.php stale. Now you will be seeing WEEWXtags.php that are at least 5:20 old, so maybe 5:15 should be increased to 5:20.

One thing I did notice looking at your wxstatus.php just now is your NOAA data is old, it's currently at 21+ minutes.

[gjr80]

The wee_device --info error you experienced is a known error. It's fixed in the vantage driver to be included in WeeWX v5 (when released). The v5 vantage driver is fully compatible with v4.10.2, so you can install it now if you wish using:

wget -O /usr/share/weewx/weewx/drivers/vantage.py https://raw.githubusercontent.com/weewx/weewx/V5/bin/weewx/drivers/vantage.py

WeeWX will need to be restarted to use the new driver (wee_device --info will use the new driver irrespective).