[tahoe-lafs-trac-stream] [Tahoe-LAFS] #2954: Magic-folder status sometimes displays "percent_done" values that exceed 100%

[Tahoe-LAFS]

#2954: Magic-folder status sometimes displays "percent_done" values that exceed
100%
-------------------------------------------------+-------------------------
 Reporter:  cypher                               |          Owner:
     Type:  defect                               |         Status:  new
 Priority:  normal                               |      Milestone:
                                                 |  undecided
Component:  unknown                              |        Version:  1.12.1
 Keywords:  magic-folder reliability             |  Launchpad Bug:
  transparency                                   |
-------------------------------------------------+-------------------------
 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).

--
Ticket URL: <https://tahoe-lafs.org/trac/tahoe-lafs/ticket/2954>
Tahoe-LAFS <https://Tahoe-LAFS.org>
secure decentralized storage