Magic-folder status sometimes displays "percent_done" values that exceed 100%

[cypher]

Sometimes, when uploading cat pictures via a magic-folder, I see operations listed in the magic-folder status whose 'percent_done' value exceeds 100%. Here is some real output (of operations exceeding 100%, pprinted) that I observe while querying the status API:

2019-01-21 12:23:26-0500 [-] --------------------------
2019-01-21 12:23:26-0500 [-] {'kind': 'upload',
2019-01-21 12:23:26-0500 [-]  'path': 'Garfield.jpg',
2019-01-21 12:23:26-0500 [-]  'percent_done': 130.04722784458465,
2019-01-21 12:23:26-0500 [-]  'queued_at': 1548091314.064463,
2019-01-21 12:23:26-0500 [-]  'size': 201576,
2019-01-21 12:23:26-0500 [-]  'started_at': 1548091401.799752,
2019-01-21 12:23:26-0500 [-]  'status': 'success',
2019-01-21 12:23:26-0500 [-]  'success_at': 1548091402.292193}
2019-01-21 12:23:26-0500 [-] --------------------------
2019-01-21 12:23:26-0500 [-] {'kind': 'upload',
2019-01-21 12:23:26-0500 [-]  'path': 'Grumpy Cat.jpg',
2019-01-21 12:23:26-0500 [-]  'percent_done': 141.80984117367032,
2019-01-21 12:23:26-0500 [-]  'queued_at': 1548091314.06508,
2019-01-21 12:23:26-0500 [-]  'size': 277284,
2019-01-21 12:23:26-0500 [-]  'started_at': 1548091402.292445,
2019-01-21 12:23:26-0500 [-]  'status': 'success',
2019-01-21 12:23:26-0500 [-]  'success_at': 1548091402.826781}
2019-01-21 12:23:26-0500 [-] --------------------------
2019-01-21 12:23:26-0500 [-] {'kind': 'upload',
2019-01-21 12:23:26-0500 [-]  'path': 'Kitler.png',
2019-01-21 12:23:26-0500 [-]  'percent_done': 104.88822736238981,
2019-01-21 12:23:26-0500 [-]  'queued_at': 1548091314.147688,
2019-01-21 12:23:26-0500 [-]  'size': 1249635,
2019-01-21 12:23:26-0500 [-]  'started_at': 1548091402.826878,
2019-01-21 12:23:26-0500 [-]  'status': 'success',
2019-01-21 12:23:26-0500 [-]  'success_at': 1548091403.592652}
2019-01-21 12:23:26-0500 [-] --------------------------
2019-01-21 12:23:26-0500 [-] {'kind': 'upload',
2019-01-21 12:23:26-0500 [-]  'path': 'lolcat.jpg',
2019-01-21 12:23:26-0500 [-]  'percent_done': 115.43617068122771,
2019-01-21 12:23:26-0500 [-]  'queued_at': 1548091314.148422,
2019-01-21 12:23:26-0500 [-]  'size': 340635,
2019-01-21 12:23:26-0500 [-]  'started_at': 1548091403.592772,
2019-01-21 12:23:26-0500 [-]  'status': 'success',
2019-01-21 12:23:26-0500 [-]  'success_at': 1548091404.125816}
2019-01-21 12:23:26-0500 [-] --------------------------
2019-01-21 12:23:26-0500 [-] {'kind': 'upload',
2019-01-21 12:23:26-0500 [-]  'path': 'Nala.jpg',
2019-01-21 12:23:26-0500 [-]  'percent_done': 106.56476757657676,
2019-01-21 12:23:26-0500 [-]  'queued_at': 1548091314.148859,
2019-01-21 12:23:26-0500 [-]  'size': 245995,
2019-01-21 12:23:26-0500 [-]  'started_at': 1548091404.125934,
2019-01-21 12:23:26-0500 [-]  'status': 'success',
2019-01-21 12:23:26-0500 [-]  'success_at': 1548091404.608149}
2019-01-21 12:23:26-0500 [-] --------------------------
2019-01-21 12:23:26-0500 [-] {'kind': 'upload',
2019-01-21 12:23:26-0500 [-]  'path': 'Venus.jpg',
2019-01-21 12:23:26-0500 [-]  'percent_done': 104.41183108913678,
2019-01-21 12:23:26-0500 [-]  'queued_at': 1548091314.149489,
2019-01-21 12:23:26-0500 [-]  'size': 376601,
2019-01-21 12:23:26-0500 [-]  'started_at': 1548091404.608228,
2019-01-21 12:23:26-0500 [-]  'status': 'success',
2019-01-21 12:23:26-0500 [-]  'success_at': 1548091405.090866}
2019-01-21 12:23:26-0500 [-] --------------------------
2019-01-21 12:23:26-0500 [-] {'kind': 'upload',
2019-01-21 12:23:26-0500 [-]  'path': 'Waffles.jpg',
2019-01-21 12:23:26-0500 [-]  'percent_done': 100.13207797014154,
2019-01-21 12:23:26-0500 [-]  'queued_at': 1548091314.15018,
2019-01-21 12:23:26-0500 [-]  'size': 1178092,
2019-01-21 12:23:26-0500 [-]  'started_at': 1548091405.090958,
2019-01-21 12:23:26-0500 [-]  'status': 'success',
2019-01-21 12:23:26-0500 [-]  'success_at': 1548091406.289995}

I originally thought that the excesses might have been caused by failing to take into account erasure coding overhead when calculating percent_done, however, the 141% instance seems to invalidate this hypothesis, as it occurred on a single-node grid with N, K, and H params of 1, 1, and 1 (where erasure coding overhead would be less than that).

[exarkun]

magic-folder has been split out into a separate project - ​https://github.com/leastauthority/magic-folder