[GNC] postpone reconciliation broken: ignores my changes

[Michael Hendry]

> On 8 Feb 2019, at 17:37, John Ralls <jralls at ceridwen.us> wrote:
> 
> 
> 
>> On Feb 8, 2019, at 8:11 AM, Michael Hendry <hendry.michael at gmail.com> wrote:
>> 
>> PS Looking at the log files, I’m reminded that a number of scheduled transactions took place during the session. Inspecting these it seems that each one is recorded four times - here’s an example extracted from the larger of the two log file:
>> 
>> ===== START
>> B	aefe075a22d466826d4735afb8159c08	cd4cb60c1e5a5294eb4e7d2623dbaebe	2019-02-08 00:03:46 +0000	2018-08-05 12:20:04 +0100	2018-08-05 11:59:00 +0100	9768413066e3e0d1272ba7839ea5f1cc	b0e28c7d097d448b29f193895c973d63		Amazon Prime Subscription				n	0/1	0/100	1970-01-01 01:00:00 +0100
>> B	aefe075a22d466826d4735afb8159c08	f9d8cacc6b99135677ccc97ce6f4887d	2019-02-08 00:03:46 +0000	2018-08-05 12:20:04 +0100	2018-08-05 11:59:00 +0100	9768413066e3e0d1272ba7839ea5f1cc	b0e28c7d097d448b29f193895c973d63		Amazon Prime Subscription				n	0/1	0/100	1970-01-01 01:00:00 +0100
>> ===== END
>> ===== START
>> R	aefe075a22d466826d4735afb8159c08	cd4cb60c1e5a5294eb4e7d2623dbaebe	2019-02-08 00:03:46 +0000	2018-08-05 12:20:04 +0100	2018-08-05 11:59:00 +0100	9768413066e3e0d1272ba7839ea5f1cc	b0e28c7d097d448b29f193895c973d63		Amazon Prime Subscription				n	0/1	0/100	1970-01-01 01:00:00 +0100
>> R	aefe075a22d466826d4735afb8159c08	f9d8cacc6b99135677ccc97ce6f4887d	2019-02-08 00:03:46 +0000	2018-08-05 12:20:04 +0100	2018-08-05 11:59:00 +0100	9768413066e3e0d1272ba7839ea5f1cc	b0e28c7d097d448b29f193895c973d63		Amazon Prime Subscription				n	0/1	0/100	1970-01-01 01:00:00 +0100
>> ===== END
>> ===== START
>> B	aefe075a22d466826d4735afb8159c08	cd4cb60c1e5a5294eb4e7d2623dbaebe	2019-02-08 00:03:46 +0000	2018-08-05 12:20:04 +0100	2018-08-05 11:59:00 +0100	9768413066e3e0d1272ba7839ea5f1cc	b0e28c7d097d448b29f193895c973d63		Amazon Prime Subscription				n	0/1	0/100	1970-01-01 01:00:00 +0100
>> B	aefe075a22d466826d4735afb8159c08	f9d8cacc6b99135677ccc97ce6f4887d	2019-02-08 00:03:46 +0000	2018-08-05 12:20:04 +0100	2018-08-05 11:59:00 +0100	9768413066e3e0d1272ba7839ea5f1cc	b0e28c7d097d448b29f193895c973d63		Amazon Prime Subscription				n	0/1	0/100	1970-01-01 01:00:00 +0100
>> ===== END
>> ===== START
>> R	aefe075a22d466826d4735afb8159c08	cd4cb60c1e5a5294eb4e7d2623dbaebe	2019-02-08 00:03:46 +0000	2018-08-05 12:20:04 +0100	2018-08-05 11:59:00 +0100	9768413066e3e0d1272ba7839ea5f1cc	b0e28c7d097d448b29f193895c973d63		Amazon Prime Subscription				n	0/1	0/100	1970-01-01 01:00:00 +0100
>> R	aefe075a22d466826d4735afb8159c08	f9d8cacc6b99135677ccc97ce6f4887d	2019-02-08 00:03:46 +0000	2018-08-05 12:20:04 +0100	2018-08-05 11:59:00 +0100	9768413066e3e0d1272ba7839ea5f1cc	b0e28c7d097d448b29f193895c973d63		Amazon Prime Subscription				n	0/1	0/100	1970-01-01 01:00:00 +0100
>> ===== END
>> 
>> I don’t know what the significance of “B” and “R” is in the first column, but the pairs of lines appear to be record the guids of the each transaction and the accounts the split refers to. I don’t suppose the appearance of Unix zero time (1970-01-01 01:00:00 +0100) at the end of each line is of any significance.
> 
> There's a header at the top of the log file titling the columns. It's
> 
> "mod|trans_guid|split_guid|time_now|date_entered|date_posted|acc_guid|acc_name|num|description|notes|memo|action|reconciled|amount|value|date_reconciled"
> 
> The codes for the mod field are:
> 
> 'B' for 'begin edit' (followed by the transaction as it looks before any changes, i.e. the 'old value')
> 'D' for delete (i.e. delete the previous B; echoes the data in the 'old B')
> 'C' for commit (i.e. accept a previous B; data that follows is the 'new value')
> 'R' for rollback (i.e. revert to previous B; data that follows should be identical to old B)
> 
> So GnuCash tried twice to create the two splits of the Amazon Prime Subscription transaction only to roll them back for some reason.
> 
> Regards,
> John Ralls
> 
> 


Morning, John.

Armed with the information above, I’ve been comparing the latest before-crash log file with that created when I forced GC to open this morning.

Here’s how the tops of these files look in MacVim’s split-diff mode:

https://www.dropbox.com/s/tlk9xy7vstb7i0o/Screenshot%202019-02-09%2010.50.19.png?dl=0

and here’s how the bottom of the file looks:

https://www.dropbox.com/s/8y5w0p8c7mf3oxq/Screenshot%202019-02-09%2010.52.17.png?dl=0

My guess is that GC is setting up all of my Scheduled transactions (“B” lines) and then rolling them back (“R” lines) without committing them.

There follows a series of four empty START-END pairs at line 643.

This is then following at line 651 in the earlier file (on the right of the screenshot) the one transaction scheduled to take place on the 8th of February - but involving a Commit, then a Begin then a Commit.

Today’s file (on the right) starts at line 651 with the same transaction and the same Commit-Begin-Commit sequence, and then goes on to record the scheduled transaction due for today.

Each file ends with an orphaned “D” line, whose UID doesn’t appear earlier in the file.

This may be the expected behaviour, but it seems odd to me!

Michael