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

Closed
opened 2019-01-21 17:50:25 +00:00 by crwood · 1 comment

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).

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%, `pprint`ed) 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).
crwood added the
unknown
normal
defect
1.12.1
labels 2019-01-21 17:50:25 +00:00
crwood added this to the undecided milestone 2019-01-21 17:50:25 +00:00
crwood added
code-frontend-magic-folder
and removed
unknown
labels 2019-01-29 15:59:30 +00:00

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

magic-folder has been split out into a separate project - <https://github.com/leastauthority/magic-folder>
exarkun added the
somebody else's problem
label 2020-06-30 13:49:09 +00:00
Sign in to join this conversation.
No Milestone
No Assignees
2 Participants
Notifications
Due Date
The due date is invalid or out of range. Please use the format 'yyyy-mm-dd'.

No due date set.

Reference: tahoe-lafs/trac-2024-07-25#2954
No description provided.