set 'group_time' to 'unix_epoch_ms' causes crash in weewx.almanac

[Graham Eddy]

my upgrade from 4.4.0 to 4.5.1 was not as clean as i indicated earlier. it crashed on test system every time it tried to generate reports but i fixed that, and production system update was clean. so, reporting the error:

cheetah crashed apparently inside weewx.almanac, so i inserted a print() - logging not being used in weewx.almanac - the line before the apparent error on line 370:

        # Calculate and store the start-of-day in Dublin Julian Days. 

#        self.sod_djd = timestamp_to_djd(weeutil.weeutil.startOfDay(self.time_ts))

        print(f"********self.time_ts={self.time_ts}")

        (y,m,d) = time.localtime(self.time_ts)[0:3]

        self.sod_djd = timestamp_to_djd(time.mktime((y,m,d,0,0,0,0,0,-1)))

i ran it in foreground to get output, it crashed as usual, see log extract:

Apr 11 23:05:17 stringybark weewx[15861] INFO weewx.manager: Added record 2021-04-11 23:05:00 AEST (1618146300) to database 'weewx.sdb'

Apr 11 23:05:17 stringybark weewx[15861] INFO weewx.manager: Added record 2021-04-11 23:05:00 AEST (1618146300) to daily summary in 'weewx.sdb'

Apr 11 23:05:17 stringybark weewx[15861] DEBUG user.forecast: MainThread: OWM: not yet time to do the forecast

Apr 11 23:05:17 stringybark weewx[15861] DEBUG weewx.reportengine: Running reports for latest time in the database.

Apr 11 23:05:17 stringybark weewx[15861] DEBUG weewx.reportengine: Running report 'GEReport'

Apr 11 23:05:17 stringybark weewx[15861] DEBUG weewx.reportengine: Found configuration file /home/weewx/skins/GE/skin.conf for report 'GEReport'

Apr 11 23:05:17 stringybark weewx[15861] DEBUG weewx.cheetahgenerator: Using search list ['weewx.cheetahgenerator.Almanac', 'weewx.cheetahgenerator.Station', 'weewx.cheetahgenerator.Current', 'weewx.cheetahgenerator.Stats', 'weewx.cheetahgenerator.UnitInfo', 'weewx.cheetahgenerator.Extras', 'weewx.cheetahgenerator.JSONHelpers', 'user.since.Since', 'user.forecast.ForecastVariables']

Apr 11 23:05:17 stringybark weewx[15861] DEBUG weewx.manager: Daily summary version is 4.0

Apr 11 23:05:29 stringybark weewx[15861] ERROR weewx.cheetahgenerator: Generate failed with exception '<class 'OverflowError'>'

Apr 11 23:05:29 stringybark weewx[15861] ERROR weewx.cheetahgenerator: **** Ignoring template /home/weewx/skins/GE/forecast-frag.html.tmpl

Apr 11 23:05:29 stringybark weewx[15861] ERROR weewx.cheetahgenerator: **** Reason: timestamp out of range for platform time_t

Apr 11 23:05:29 stringybark weewx[15861] ERROR weewx.cheetahgenerator: ****  Traceback (most recent call last):

Apr 11 23:05:29 stringybark weewx[15861] ERROR weewx.cheetahgenerator: ****    File "/home/weewx/bin/weewx/cheetahgenerator.py", line 326, in generate

Apr 11 23:05:29 stringybark weewx[15861] ERROR weewx.cheetahgenerator: ****      unicode_string = compiled_template.respond()

Apr 11 23:05:29 stringybark weewx[15861] ERROR weewx.cheetahgenerator: ****    File "_home_weewx_skins_GE_forecast_frag_html_tmpl.py", line 94, in respond

Apr 11 23:05:29 stringybark weewx[15861] ERROR weewx.cheetahgenerator: ****    File "/usr/local/lib/python3.7/dist-packages/Cheetah/Template.py", line 1708, in _handleCheetahInclude

Apr 11 23:05:29 stringybark weewx[15861] ERROR weewx.cheetahgenerator: ****      self._CHEETAH__cheetahIncludes[_includeID].respond(trans)

Apr 11 23:05:29 stringybark weewx[15861] ERROR weewx.cheetahgenerator: ****    File "_home_weewx_skins_GE_forecast_strip_inc.py", line 952, in respond

Apr 11 23:05:29 stringybark weewx[15861] ERROR weewx.cheetahgenerator: ****    File "/home/weewx/bin/weewx/almanac.py", line 267, in sunrise

Apr 11 23:05:29 stringybark weewx[15861] ERROR weewx.cheetahgenerator: ****      return self.sun.rise if self.hasExtras else self._sunrise

Apr 11 23:05:29 stringybark weewx[15861] ERROR weewx.cheetahgenerator: ****    File "/home/weewx/bin/weewx/almanac.py", line 343, in __getattr__

Apr 11 23:05:29 stringybark weewx[15861] ERROR weewx.cheetahgenerator: ****      return AlmanacBinder(self, attr)

Apr 11 23:05:29 stringybark weewx[15861] ERROR weewx.cheetahgenerator: ****    File "/home/weewx/bin/weewx/almanac.py", line 371, in __init__

Apr 11 23:05:29 stringybark weewx[15861] ERROR weewx.cheetahgenerator: ****      (y,m,d) = time.localtime(self.time_ts)[0:3]

Apr 11 23:05:29 stringybark weewx[15861] ERROR weewx.cheetahgenerator: ****  OverflowError: timestamp out of range for platform time_t

Apr 11 23:05:30 stringybark weewx[15861] INFO weewx.cheetahgenerator: Generated 12 files for report GEReport in 12.83 seconds

and here is stdout from running it 

********self.time_ts=1618146328

LOOP:   2021-04-11 23:05:28 AEST (1618146328) altimeter: 32.04764416490144, altInHumidity: 29.99981453133538, altInTemp: 63.00009273433231, altOutHumidity: 79.99986089817905, altOutTemp: 32.74071750761992, altPressure: 31.099995363272637, altRain: 0, altWindDir: 359.9991653890743, altWindGust: 11.99997217963581, altWindGustDir: 359.9991653890743, altWindSpeed: 9.999976816363175, appTemp: 28.239945905002337, barometer: 31.156899552089076, cloudbase: 2079.910023167021, consBatteryVoltage: 12.0103145468851, dateTime: 1618146328, dewpoint: 27.011613223247195, extraTemp1: 64.99981453133537, heatindex: 32.48210581363077, heatingVoltage: 12.0, humidex: 32.48210581363077, inDewpoint: 31.078747988997634, inHumidity: 29.997982134462838, inTemp: 63.001008932768585, inTempBatteryStatus: 0, luminosity: 0, maxSolarRad: 0.0, outHumidity: 79.99848656267226, outTemp: 32.48210581363077, outTempBatteryStatus: 0, pm2_5: 7.999810081003261, pm2_52: 39.999050405016305, pressure: 31.099949552089075, radiation: 0, rain: 0.0, rainBatteryStatus: 0, rainRate: 0.0, referenceVoltage: 11.697710682506875, riverLevel: 18.99986811148892, rxCheckPercent: 41.62595866132666, soilMoist1: 25.999851625068306, soilMoist2: 43.99988871880123, solarEnergy: 0, supplyVoltage: 12.207248248692489, txBatteryStatus: 0, usUnits: 1, UV: 0, wh40_batt: 0.5999679514863168, wh41_ch1_batt: 5.600678278888725, wh41_ch2_batt: 4.590165517053528, wh51_ch1_batt: 0.20313443800380582, wh51_ch2_batt: 0.054743400792768654, wh57_batt: 2.000213656757888, windBatteryStatus: 0, windchill: 32.48210581363077, windDir: 359.9909193760335, windGust: 0.0003026874655489564, windGustDir: 359.9909193760335, windSpeed: 0.0002522395546247225, ws80_batt: 3.0197965163333826

********self.time_ts=1618153200010

********self.time_ts=1618153200010

********self.time_ts=1618153200010

********self.time_ts=1618146330

********self.time_ts=1618146330

LOOP:   2021-04-11 23:05:30 AEST (1618146330) altimeter: 32.04764322508599, altInHumidity: 29.99982543879473, altInTemp: 63.000087280602635, altOutHumidity: 79.99986907881038, altOutTemp: 32.738880596764616, altPressure: 31.099995635960347, altRain: 0, altWindDir: 359.99921447286226, altWindGust: 11.999973815762075, altWindGustDir: 359.99921447286226, altWindSpeed: 9.99997817980173, appTemp: 28.237979208496572, barometer: 31.156898634880964, cloudbase: 2079.9017969833885, consBatteryVoltage: 11.190169452286101, dateTime: 1618146330, dewpoint: 27.00989528014634, extraTemp1: 64.99982543879473, heatindex: 32.48035167532193, heatingVoltage: 11.84431174998325, humidex: 32.48035167532193, inDewpoint: 31.078733700462994, inHumidity: 29.99794544800604, inTemp: 63.00102727599698, inTempBatteryStatus: 0, luminosity: 0, maxSolarRad: 0.0, outHumidity: 79.99845904642889, outTemp: 32.48035167532193, outTempBatteryStatus: 0, pm2_5: 7.999821250137079, pm2_52: 39.999106250685394, pressure: 31.099948634880963, radiation: 0, rain: 0.0, rainBatteryStatus: 0, rainRate: 0.0, referenceVoltage: 12.833850966518101, riverLevel: 18.999875867868255, rxCheckPercent: 32.44272171697512, soilMoist1: 25.99986035103578, soilMoist2: 43.99989526327684, solarEnergy: 0, supplyVoltage: 12.631453821071197, txBatteryStatus: 0, usUnits: 1, UV: 0, wh40_batt: 0.5999698362414574, wh41_ch1_batt: 5.601201330435272, wh41_ch2_batt: 4.590999267199438, wh51_ch1_batt: 0.20325833568295498, wh51_ch2_batt: 0.05481880892687266, wh57_batt: 2.0002010917236173, windBatteryStatus: 0, windchill: 32.48035167532193, windDir: 359.9907542785734, windGust: 0.0003081907142208351, windGustDir: 359.9907542785734, windSpeed: 0.00025682559518358516, ws80_batt: 3.0196396008694184

well, with those values for a timestamp, crashing with ‘out of range’ error is correct behaviour.

but why is the timestamp so wrong?

it looks suspiciously like it is 1000 time too big. the one significant change i had made to the test config was to change the default unit for ‘group_time' from ‘unix_epoch' to ‘unix_epoch_ms'. i changed it back to ‘unix_epoch' → problem went away. so, i think this is a defect, but i’m not sure in what module - it seemed to hit this when processing forecast module but that might be coincidence

______

[gjr80]

To understand why you are seeing this behaviour you need to understand how Almanac objects are created and how they are created within a Cheetah template/WeeWX report.

An Almanac object needs, among other things, a unix epoch timestamp when it is created. If the Almanac constructor does not include a timestamp the current system time is used. The key point here is that the timestamp is a unix epoch timestamp, ie seconds since midnight GMT/UTC 1 January 1970. When you use an $almanac.xxx tag in a CheetahGenerator template the CheetahGenerator obtains an Almanac object (to provide all of the $almanac.xxx tags) and uses the report generator timestamp (a unix epoch timestamp) to initialise the underlying Almanac object. You have not shown us the code in your GE skin, but for the purposes of the exercise I will assume it is similar to some of the existing forecast extension and clones code. The forecast variable available in the forecast skin has an almanac property (which works just like the $almanac tag) that can be used to obtain various tags, commonly sun/moon rise/set etc. The forecast extension also operates across a number of days and almanac properties for each day are obtained by initialising the almanac with a timestamp for each day (period), for example (my indentation):

#for $period in $periods
   #set $img = ''
   #set $alm = $forecast.almanac(ts=$period.event_ts.raw+10)
   #if $alm.hasExtras
     #set $moonrise_ts = $alm.moon.rise.raw #set $moonset_ts = $alm.moon.set.raw

Here the almanac is initialised not with the current epoch timestamp or generator timestamp but with a tag ($period.event_ts.raw) that is going to be in the group_time units that apply to the skin. When group_time is set to unix_epoch you get seconds since epoch, if you use unix_epoch_ms you get milliseconds since unix epoch or 1000 time the former. This is what causes the overflow and this is why changing group_time causes the error to appear/disappear.

Is it a bug, maybe, but I don't think it is. class Almanac needs a timestamp, the class says it needs to be initialised with a unix epoch timestamp but that is not what it is being given. If you ask WeeWX to convert degree C to hPa is it a bug if WeeWX throws an error?

Solutions? class Almanac could be made handle a timestamp in unix epoch seconds or milliseconds as it is generally pretty easy to tell the difference, though not for all date-times. Not sure on Tom's view on that though, does feel a little hackish to me. Alternatively, templates/SLEs etc could just force any timestamps being passed to $almanac() (or in this case $forecast.almanac()) be be in unix_epoch seconds, just like we force units in some formulae to degree C or m/s etc. So in this case something like (untested):

#for $period in $periods
   #set $img = ''
   #set $alm = $forecast.almanac(ts=$period.event_ts.unix_epoch.raw+10)
   #if $alm.hasExtras
     #set $moonrise_ts = $alm.moon.rise.raw #set $moonset_ts = $alm.moon.set.raw

should work.

Gary

[Graham Eddy]

i am using https://github.com/chaunceygardiner/weewx-forecast v.b12, which, as you say, calls almanac

i think i understand. deep in weewx (call it weewx ‘kernel’), monotonic time is a fundamental always measured in time_t. in the upper levels of weewx, in the world of weewx units, time is an observable property with transformable units. almanac is really part of the ‘kernel’, which works in time_t only, so any time values from the units space must be converted to time_t before being presented to almanac i.e. it is actually a bug in forecast, in this case [and might imply some tweaking needed in the almanac interface within cheetah]

[gjr80]

More or less. Even more simply, think of WeeWX (and python) as using timestamps the ‘units’ of which are seconds since epoch. V4.5.0 introduced a new ‘unit’ of time in the report space that is milliseconds since epoch. When the report space wants to deal with any other part of WeeWX (and python) it needs to speak in seconds since epoch. Before that v4.5.0 that was implicit as there was only one unit of time, post v4.5.0 it needs to be explicit.

Gary

[Tom Keffer]

Anything other than unix_epoch was not really intended to be used as the "unit of record," so I'm not surprised this isn't working. For example, in the template celestial.inc, you have

    #set $now = $current.dateTime.raw

With group_time set to unix_epoch_ms, this would be in milliseconds. It could be changed to

    #set $now = $current.dateTime.unix_epoch.raw

and perhaps, for completeness, it should be. There are many other places like this.

-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.
To view this discussion on the web visit https://groups.google.com/d/msgid/weewx-user/8dd1b742-8236-4db4-ab19-dc162acc213bn%40googlegroups.com.

[Tom Keffer]

It may not be as hard as I thought to get this working. Try branch `development` now.