Created attachment 373211 [details] exerpt Wish to ping gjanssens to try elucidate this mandelbug. The issue is the old p.broadbery test (test-account-get-trans-type-splits-interval) created by p.broadbery. The original commit was https://github.com/Gnucash/gnucash/commit/516b3025b10b9cb43f4a26b1a19e6465872444ba and the comment " report-utilities: Add a very small test to show that splits are unique for account-get-trans-type-splits-interval" -- I have no idea what this test is meant to confirm. It created transactions from 10 days ago until today, then calls (gnc:account-get-trans-type-splits-interval ... ACCT-TYPE-ASSET 5-days-ago today). ----[By the way]---- The ACCT-TYPE-ASSET is completely wrong: the tree at that time was as follows, and the definition (gnc:account-get-trans-type-splits-interval account-list type start-date-tp end-date-tp) assumed type was an association list rather than an account-type.... but this is beside the point https://github.com/Gnucash/gnucash/blob/901c89dffad9fa9ee19960b91a585fc90a67e29e/src/report/report-system/report-utilities.scm#L897 ----[END]---- The output of (gnc:account-get-trans-type-splits-interval ... ACCT-TYPE-ASSET 5-days-ago today) was originally confirmed to be 8 splits. Why 8? I have no idea... the qof-query spanned 5 full days [from (decdate end-date (NDayDelta 5)) to end-date] yet produced 4 txns = 8 splits. Then bug 771617 was filed (whole lot of issues found) and gjanssens fixed it until I started to add more tests to test-report-utilities.scm The test was running successfully (although I suspect it would fail in a time window from 10-March to a few weeks later). ----[My mistake]---- I made a little mistake in https://github.com/Gnucash/gnucash/commit/4102e7007e0ac1f6cdc9bead7189c6caedcc3b30 in October 2018. I'd added (test-gnc-pk) to test gnc:pk and gnc:strify but forgot to close the (test-begin "debugging tools") with an appropriate (test-end "debugging tools"); this caused srfi-64 to miscount test any preceding failures. I realised this last night and added the (test-end) but this awakened the (test-account-get-trans-type-splits-interval) section which had started to officially fail on 10-March. ----[END]---- I managed to recreate the failure state as follows: TZ=America/Los_Angeles faketime='MM/DD/YY' ctest -V -R test-report-utilities Both TZ and faketime seem important to recreate the test failure on my ubuntu 19.04 en_AU AWST timezone. Setting MM/DD/YY to 10/08/2018 (when introducing test-gnc-pk) passes Setting MM/DD/YY to 03/10/2019 (before DST) passes Setting MM/DD/YY to 03/13/2019 (today after DST) fails Setting MM/DD/YY to 03/29/2019 (at least 10 days after 10-march??) passes I've added more tracers in test-report-utilities to dump the splitlist retrieved, results for the failing test as follows. I still can't figure out why the query retrieving 5 transactions is meant to be correct. The log below states txns were created (start-date and end-date) 2-march to 12-march all at 2:59 or 3:59, and the account was queried (q-start-date to q-end-date) 6-march 23:00 to 12-march 23:59 which should retrieve 12 txns. Perhaps in 8 days' time it'll become clearer.
Is this still an issue ? If I run TZ=America/Los_Angeles faketime='03/13/19' ctest -V -R test-report-utilities in current maint, the test passes.
The actual test required that the (test-begin "debugging tools") is closed with (test-end "debugging tools"). So, as of today, the 'debugging-tools' section is, in practice, disabled (*) Therefore the real test is as follows: 1. patch test-report-utilities with modified gnucash/report/report-system/test/test-report-utilities.scm @@ -131,7 +131,8 @@ (gnc:strify (cons 'a 2))) (test-equal "gnc:strify cons" "Proc<cons>" - (gnc:strify cons))) + (gnc:strify cons)) + (test-end "debugging tools")) (define (test-commodity-collector) (test-group-with-cleanup "test-commodity-collector" 2. TZ=America/Los_Angeles faketime='03/13/19' ctest -V -R test-report-utilities (*) We can reinstate the (test-end) which will genuinely re-enable the test, however I wouldn't be surprised if next March the test fails again. We can try.
I did the change, reran the test, with all dates you suggest. Works fine on my system. Can you reproduce this on your system ?
I cannot reproduce anymore. Perhaps we should re-enable the test but remember that next March 2020 the failure may reactivate. I still don't really understand why (test-account-get-trans-type-splits-interval) would generate either 10 or 8 splits in March 2019.
Go ahead and re-enable the test. As an extra experiment I reset my computer's date to 03/13/19 and reran all tests. It continues to work. If it happens again next year we'll have another window to experiment, though I suspect other fixes in the gnucash data-time handling have solved this as well.
It appeared today again: https://travis-ci.org/Gnucash/gnucash/builds/660024487?utm_source=github_status&utm_medium=notification Just a stupi idea: "März" is the only month in German with umlaut - non-ASCII.
Created attachment 373601 [details] travis log 9-mar-2020 this bug woke up again! see log output attached. i've also augmented test-report-utilities.scm to dump the 12 splits obtained *and* their time64 posted_date, via this patch: =-=-=- modified gnucash/report/report-system/test/test-report-utilities.scm @@ -64,6 +64,10 @@ (let ((splits (gnc:account-get-trans-type-splits-interval (list bank-account wallet) ACCT-TYPE-ASSET q-start-date q-end-date))) + ;; temporarily increase test output to help debug 797139 + (for-each (lambda (s) + (gnc:pk 'split (xaccTransGetDate (xaccSplitGetParent s)) s)) + splits) =-=-=- On my machine - 10 splits obtained: 108: Created transactions for each day from Fri Feb 28 18:59:00 2020 to Mon Mar 09 18:59:00 2020 108: d26.0326 t26.033: ('split 1583319540 Split<d:03/04/20,acc:Wallet,amt:-$4.00,val:-$4.00>) 108: d0.0020 t26.035: ('split 1583319540 Split<d:03/04/20,acc:Bank Account,amt:$4.00,val:$4.00>) 108: d0.0006 t26.035: ('split 1583405940 Split<d:03/05/20,acc:Wallet,amt:-$5.00,val:-$5.00>) 108: d0.0006 t26.036: ('split 1583405940 Split<d:03/05/20,acc:Bank Account,amt:$5.00,val:$5.00>) 108: d0.0006 t26.036: ('split 1583492340 Split<d:03/06/20,acc:Wallet,amt:-$6.00,val:-$6.00>) 108: d0.0006 t26.037: ('split 1583492340 Split<d:03/06/20,acc:Bank Account,amt:$6.00,val:$6.00>) 108: d0.0007 t26.038: ('split 1583578740 Split<d:03/07/20,acc:Wallet,amt:-$7.00,val:-$7.00>) 108: d0.0006 t26.038: ('split 1583578740 Split<d:03/07/20,acc:Bank Account,amt:$7.00,val:$7.00>) 108: d0.0007 t26.039: ('split 1583665140 Split<d:03/08/20,acc:Wallet,amt:-$8.00,val:-$8.00>) 108: d0.0007 t26.040: ('split 1583665140 Split<d:03/08/20,acc:Bank Account,amt:$8.00,val:$8.00>) 108: [pass] line:72, test: length splits = 10 108: [pass] line:83, test: list-ref-safe normal 108: [pass] line:86, test: list-ref-safe out of bounds 108: [pass] line:95, test: list-set-safe normal 108: [pass] line:99, test: list-set-safe out-of-bounds On travis - 12 splits obtained -- note 2 extra splits tacked on at the end: Created transactions for each day from Fri Feb 28 02:59:00 2020 to Mon Mar 09 03:59:00 2020 d7.2493 t7.249: ('split 1583319540 Split<d:03/04/20,acc:Wallet,amt:-$4.00,val:-$4.00>) d0.0006 t7.250: ('split 1583319540 Split<d:03/04/20,acc:Bank Account,amt:$4.00,val:$4.00>) d0.0002 t7.250: ('split 1583405940 Split<d:03/05/20,acc:Wallet,amt:-$5.00,val:-$5.00>) d0.0002 t7.250: ('split 1583405940 Split<d:03/05/20,acc:Bank Account,amt:$5.00,val:$5.00>) d0.0002 t7.251: ('split 1583492340 Split<d:03/06/20,acc:Wallet,amt:-$6.00,val:-$6.00>) d0.0002 t7.251: ('split 1583492340 Split<d:03/06/20,acc:Bank Account,amt:$6.00,val:$6.00>) d0.0002 t7.251: ('split 1583578740 Split<d:03/07/20,acc:Wallet,amt:-$7.00,val:-$7.00>) d0.0002 t7.251: ('split 1583578740 Split<d:03/07/20,acc:Bank Account,amt:$7.00,val:$7.00>) d0.0002 t7.251: ('split 1583665140 Split<d:03/08/20,acc:Wallet,amt:-$8.00,val:-$8.00>) d0.0002 t7.251: ('split 1583665140 Split<d:03/08/20,acc:Bank Account,amt:$8.00,val:$8.00>) d0.0002 t7.252: ('split 1583751540 Split<d:03/09/20,acc:Wallet,amt:-$9.00,val:-$9.00>) d0.0003 t7.252: ('split 1583751540 Split<d:03/09/20,acc:Bank Account,amt:$9.00,val:$9.00>) [fail] line:72, test: length splits = 10 report-utilities/test-account-get-trans-type-splits-interval -> expected: 10 -> obtained: 12 [pass] line:83, test: list-ref-safe normal [pass] line:86, test: list-ref-safe out of bounds [pass] line:95, test: list-set-safe normal [pass] line:99, test: list-set-safe out-of-bounds
(In reply to Geert Janssens from comment #1) > Is this still an issue ? > If I run > TZ=America/Los_Angeles faketime='03/13/19' ctest -V -R test-report-utilities > in current maint, the test passes. Currently (9 March) this test fails in my machine (TZ=AWST).
And I think we can predict on which days the test will fail :) https://en.wikipedia.org/wiki/Daylight_saving_time_in_the_United_States
We did indeed go to DST yesterday and that could explain why it fails on CI and for me, but how does it affect you? Is that test set to run in Z-8 somewhere?
(In reply to John Ralls from comment #10) > We did indeed go to DST yesterday and that could explain why it fails on CI > and for me, but how does it affect you? Is that test set to run in Z-8 > somewhere? You're right it doesn't fail on my machine. Are you referring to my test failure in comment 8 ? I meant that running [TZ=America/Los_Angeles faketime='03/13/19' ctest -V -R test-report-utilities] on my machine currently fails.
... and the answer lies in the definition of start-date and end-date in the report. in travis/USA: start-date Fri Feb 28 02:59:00 2020 end-date Mon Mar 09 03:59:00 2020 so, imho is simply a bad test rather than an API issue. everyone agrees?
Ah, you tricked me by saying TZ=AWST. I'm not sure that I agree the test is messed up. It might be date-utilities.scm. I changed your patch to print time64 instead of converting it to a local date and instrumented gnc:make-date-list. The TZ=Australia/Perth results: 106: Next time64: 1582973940 106: Next time64: 1583060340 106: Next time64: 1583146740 106: Next time64: 1583233140 106: Next time64: 1583319540 106: Next time64: 1583405940 106: Next time64: 1583492340 106: Next time64: 1583578740 106: Next time64: 1583665140 106: Next time64: 1583751540 106: Next time64: 1583837940 106: Created transactions for each day from 1582973940 to 1583837940 And for TZ=America/Los_Angeles (though I don't need to set that explicitly) 106: Next time64: 1582887540 106: Next time64: 1582973940 106: Next time64: 1583060340 106: Next time64: 1583146740 106: Next time64: 1583233140 106: Next time64: 1583319540 106: Next time64: 1583405940 106: Next time64: 1583492340 106: Next time64: 1583578740 106: Next time64: 1583665140 106: Next time64: 1583747940 106: Next time64: 1583834340 106: Created transactions for each day from 1582887540 to 1583751540 The time64s should be the same because time64 is supposed to be UTC. That they're different means that local times are getting interpreted as UTC instead of converted to UTC. Consequently what should be the last time is an hour short of the end-time when the shift to DST is in the period so an extra date is generated. Changing the termination condition in gnc:make-date-list as follows resolves the problem. It's a band-aid fix as the real problem is the time64s being wrong. --- a/libgnucash/app-utils/date-utilities.scm 2019-12-27 16:53:21.000000000 -0800 +++ b/libgnucash/app-utils/date-utilities.scm 2020-03-09 19:53:52.000000000 -0700 @@ -283,7 +283,7 @@ (date startdate) (idx 0)) (cond - ((>= date enddate) + ((<= (- enddate date) 3600) (reverse (cons enddate result))) (month-delta (let* ((curr (incdate-months startdate (* month-delta idx)))
If end-date is defined as (gnc-dmy2time64-neutral test-day test-month test-year) and start-date is 10 days exactly before that, and gnc-dmy2time64-neutral is giving you different time64 numbers according to your TZ, doesn't it mean gnc-dmy2time64-neutral is flawed? (See my log in comment 7 - my time64 are identical whichever TZ)
OOPS. pie onto face. My log was split->dates in time64, your log was date-utilities.scm output.
The root cause likely is at least partly in gnc-dmy2time64-neutral. The symptom, of course, is that 10 days exactly in local time is not 864000 seconds because of the short day but the increment code in gnc:make-date-list doesn't take that into account.
Ah yes. gnc:make-date-list has been like that since forever; this is its original definition: (define (gnc:make-date-list startdate enddate incr) (cond ((gnc:timepair-later startdate enddate) (cons startdate (gnc:make-date-list (incdate startdate incr) enddate incr))) (else (list enddate)))) My opinion would be to omit gnc-dmy2time64-neutral; reports use gnc-dmy2time64 and then typically normalised with time64CanonicalDayTime. To fix it, I think is fine to just fix the start and end definition to be normalised with time64CanonicalDayTime. I don't really know if/why gnc-dmy2time64-neutral is useful; not used anywhere apart from test code.
The C implementation, gnc_dmy2time64-neutral is used to set a transaction's posted_date to 10:59:00Z so that it's the same calendar day in nearly all timezones. That might explain why it returns a local time instead of UTC; otherwise the UI date-handling code might have to be rewritten to take UTC and convert it to local. Tracking all of that down would be a bit of work. The result of (gnc-dmy2time64-neutral) and (time64CanonicalDayTime (gnc-dmy2time64)) will be the same, so that won't fix anything. Did the old timepair code work in UTC or local time?
(In reply to John Ralls from comment #18) > The C implementation, gnc_dmy2time64-neutral is used to set a transaction's > posted_date to 10:59:00Z so that it's the same calendar day in nearly all > timezones. That might explain why it returns a local time instead of UTC; > otherwise the UI date-handling code might have to be rewritten to take UTC > and convert it to local. Tracking all of that down would be a bit of work. > > The result of (gnc-dmy2time64-neutral) and (time64CanonicalDayTime > (gnc-dmy2time64)) will be the same, so that won't fix anything. Did the old > timepair code work in UTC or local time? Don't understand the question. From memory there was always 3 ways to convert: see https://github.com/Gnucash/gnucash/blob/2.6.18/src/app-utils/date-utilities.scm timepair time64 localtime gnc:timepair->date => gnc-localtime gnc:date->timepair => gnc-mktime (cons secs 0) secs y/m/d/h/m/s From my understanding localtime is TZ sensitive. Don't really know/understand much about time otherwise.
Time is a dimension of spacetime affected by the velocity of the reference frame and the gravity field in which it's measured. Oh, not what you meant? ;-) In POSIX-compliant operating systems, time is the number of seconds from midnight 1 January 1970 Universal Coordinated Time or UTC, which is more-or-less the same as Greenwich Mean Time/British Standard Time. Local time is time plus an offset for the locality's time zone. (Microsoft does things a bit differently but GncDateTime has code that converts to the POSIX standard.) time is expressed as a time_t, generally typedeffed from either int32_t (BSD-based systems including Apple's OSes and Linux before ~2012) or int64_t (more recent Linuxes). Depending on the function used that time_t may be interpreted as either UTC or local time, and that is a frequent source of errors. Because int32_t runs out of seconds in late January 2038 (https://en.wikipedia.org/wiki/Year_2038_problem) I rewrote GnuCash's time library to provide a consistent int64_t time called time64. Because so much of GnuCash's code uses the POSIX functions for time manipulation I was compelled to furnish time64 implementation of those functions so time64 suffers from the same UTC/localtime ambiguity that time_t does. Since accounting rules operate on days as the minimum time period it would have made more sense for GnuCash to use a Julian day scheme (https://en.wikipedia.org/wiki/Julian_day); I can't begin to understand what Sled was thinking when he copied the Unix struct timespec into GnuCash's time system. There's no need at all for nanoseconds and the fact that the tv_nsec component was always 0 proves it. Nevertheless we're stuck with seconds until someone has time to rewrite pretty much everything to use days. Not bleeping likely. There's another way of expressing time in POSIX, struct tm. You'll find a description in ctime(3), and on most systems that man page also describes a variety of functions for converting back-and-forth between time and struct tm. On some versions of UNIX struct tm can carry timezone and DST information; on systems that don't have that extension struct tm suffers from the same ambiguity that time_t does. And that's what gets us to this bug: The increment is computed from a struct tm that's all 0 except for tm_mday, which produces 86400 seconds. The span is computed from a pair of localtime time64s spanning 10 days. If that 10-day period includes a standard->daylight transition it's 3600 seconds short and we get an extra iteration leading to an extra day and 2 extra splits.
What a mess. All these related to bug 771617 are a conversation for another day. Reports *could* be modified to use Julian Day. Meanwhile I'd just fix this test to avoid -neutral and use time64CanonicalDayTime instead.
This simplistic patch will just avoid -neutral for now and allow this test to pass. Maybe we can deprecate -neutral? modified gnucash/report/report-system/test/test-report-utilities.scm @@ -46,7 +46,7 @@ (test-day (tm:mday ts-now)) (test-month (+ 1 (tm:mon ts-now))) (test-year (+ 1900 (tm:year ts-now))) - (end-date (gnc-dmy2time64-neutral test-day test-month test-year)) + (end-date (gnc-dmy2time64 test-day test-month test-year)) (start-date (NDayDelta end-date 10)) (q-end-date (gnc-dmy2time64-end test-day test-month test-year)) (q-start-date (gnc-dmy2time64 test-day test-month test-year))
That shouldn't fix the problem because even if the neutral calculation is messing up (which it seems to be) gnc-dmy2time64 is supposed to return midnight local in UTC. Midnight 28 Feb in California is 0800 UTC but midnight March 9 is 0700 so the 10 days is still short the 3600 seconds. Neutral is supposed to avoid that problem because it's supposed to be 10:59 UTC regardless of the local TZ, and the date times displayed in comment 7 show that to be true, but the time64 output is coming as if the local time was the UTC time. That means something's not right somewhere in gnc-datetime.cpp.
Here's log output for: (gnc:pk 1 1 1970) (gnc:pk 'gnc-dmy2time64 (gnc-dmy2time64 1 1 1970)) (gnc:pk 'gnc-dmy2time64-neutral (gnc-dmy2time64-neutral 1 1 1970)) (gnc:pk 'gnc-dmy2time64-end (gnc-dmy2time64-end 1 1 1970)) (gnc:pk 'gnc-dmy2time64 (gnc-dmy2time64 1 1 1970)) (gnc:pk 'gnc:time64-end-day-time (gnc:time64-end-day-time 100)) (gnc:pk 'gnc:time64-start-day-time (gnc:time64-start-day-time 100)) -in my timezone:- d0.0000 t0.000: (1 1 1970) d0.0008 t0.001: ('gnc-dmy2time64 -28800) d0.0002 t0.001: ('gnc-dmy2time64-neutral 39540) d0.0002 t0.001: ('gnc-dmy2time64-end 57599) d0.0002 t0.001: ('gnc-dmy2time64 -28800) d0.0003 t0.002: ('gnc:time64-end-day-time 57599) d0.0003 t0.002: ('gnc:time64-start-day-time -28800) -TZ=America/Los_Angeles- d0.0000 t0.000: (1 1 1970) d0.0010 t0.001: ('gnc-dmy2time64 28800) d0.0004 t0.001: ('gnc-dmy2time64-neutral 39540) d0.0003 t0.002: ('gnc-dmy2time64-end 115199) d0.0003 t0.002: ('gnc-dmy2time64 28800) d0.0005 t0.002: ('gnc:time64-end-day-time 28799) d0.0004 t0.003: ('gnc:time64-start-day-time -57600) Conclusion: gnc_dmy2time64 and gnc-dmy2time64-end are TZ-sensitive, whereas gnc-dmy2time64-neutral is not. This is not incompatible with their comments in gnc-date.h. gnc:time64-start|end-day-time in date-utilities.scm are also TZ-sensitive. What would you suggest we do for now?
The problem isn't covered by the tests. I see that as a bit obvious since they all pass but test-report-utilities fails. The next step is to add tests to GncDateTime that expose the error, then fix what that test reveals as the source of the problem.
I added some tests for time neutral and they pass, so I went back and looked at the day-by-day values in comment 13 again and noticed that the time difference is 1 day: California W. Australia Diff 29: 1582887540 1: 1582973940 1582973940 2: 1583060340 1583060340 3: 1583146740 1583146740 4: 1583233140 1583233140 5: 1583319540 1583319540 6: 1583405940 1583405940 7: 1583492340 1583492340 8: 1583578740 1583578740 9: 1583665140 1583665140 10: 1583747940 1583751540 3600 11: 1583834340 1583837940 3600 It's not neutral time that's messed up after all, the error is because (modtime) at date-utilities.scm line 193, which operates on localtime and takes dst transitions into account, is inserting a 23-hour transition for March 9 - 10. Your patch in comment 22 (with a comment explaining why you're using start instead of neutral) seems better than the alternative of changing modtime to work in UTC as the latter would impact most Scheme code involving dates.
(In reply to John Ralls from comment #26) > It's not neutral time that's messed up after all, the error is because > (modtime) at date-utilities.scm line 193, which operates on localtime and > takes dst transitions into account, is inserting a 23-hour transition for > March 9 - 10. > > Your patch in comment 22 (with a comment explaining why you're using start > instead of neutral) seems better than the alternative of changing modtime to > work in UTC as the latter would impact most Scheme code involving dates. Good one! As a quick test I've removed the set-tm:isdst statement in moddate, and there's still test failure in test-report-utilities. I'll point the commit message to this bug report instead of writing a long and likely imprecise explanation.
