"Fragment overlap" error with encrypted onedrive?

Ok that is working better and it confirms my theory that only part of the chunk was received 8355840 bytes out of 62914560-52428800 = 10485760

Unfortunately I forgot to adjust the Content-Length and Content-Range on the retry - hence the errors :frowning:

Here is the next version with that corrected! Thanks for testing :slight_smile:

https://beta.rclone.org/branch/v1.50.2-195-gacd1a502-fix-3131-onedrive-416-beta/ (uploaded in 15-30 mins)

Hmm, no. It still seems to be failing in the same way. Hmm, this one also says "8355840" which seems a little suspicious!

2020/01/29 06:36:11 DEBUG : rclone: Version "v1.50.2-195-gacd1a502-fix-3131-onedrive-416-beta" starting with parameters ["/home/sweh/XX/rclone" "-vv" "-c" "--stats=60s" "--max-size=40000M" "--config" "/home/sweh/.config/rclone/rclone.conf" "--size-only" "sync" "." "OneDriveTST:"]


2020/01/29 10:06:43 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Uploading segment 786432000/5370019872 size 10485760

2020/01/29 10:06:57 DEBUG : pacer: low level retry 1/10 (error generalException: General Exception While Processing)
2020/01/29 10:06:57 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2020/01/29 10:06:57 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:06:57 DEBUG : pacer: Reducing sleep to 15ms
2020/01/29 10:06:57 DEBUG : pacer: Reducing sleep to 11.25ms
2020/01/29 10:06:57 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:06:57 DEBUG : pacer: low level retry 2/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:06:57 DEBUG : pacer: Rate limited, increasing sleep to 22.5ms
2020/01/29 10:06:58 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:06:58 DEBUG : pacer: Reducing sleep to 16.875ms
2020/01/29 10:06:58 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:06:58 DEBUG : pacer: low level retry 3/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:06:58 DEBUG : pacer: Rate limited, increasing sleep to 33.75ms
2020/01/29 10:06:58 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:06:58 DEBUG : pacer: Reducing sleep to 25.3125ms
2020/01/29 10:06:58 DEBUG : pacer: Reducing sleep to 18.984375ms
2020/01/29 10:06:58 DEBUG : pacer: Reducing sleep to 14.238281ms
2020/01/29 10:06:58 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:06:58 DEBUG : pacer: low level retry 4/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:06:58 DEBUG : pacer: Rate limited, increasing sleep to 28.476562ms
2020/01/29 10:06:58 DEBUG : pacer: Reducing sleep to 21.357421ms
2020/01/29 10:06:59 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:06:59 DEBUG : pacer: Reducing sleep to 16.018065ms
2020/01/29 10:06:59 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:06:59 DEBUG : pacer: low level retry 5/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:06:59 DEBUG : pacer: Rate limited, increasing sleep to 32.03613ms
2020/01/29 10:06:59 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:06:59 DEBUG : pacer: Reducing sleep to 24.027097ms
2020/01/29 10:06:59 DEBUG : pacer: Reducing sleep to 18.020322ms
2020/01/29 10:06:59 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:06:59 DEBUG : pacer: low level retry 6/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:06:59 DEBUG : pacer: Rate limited, increasing sleep to 36.040644ms
2020/01/29 10:06:59 DEBUG : pacer: Reducing sleep to 27.030483ms
2020/01/29 10:07:00 DEBUG : pacer: Reducing sleep to 20.272862ms
2020/01/29 10:07:00 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:07:00 DEBUG : pacer: Reducing sleep to 15.204646ms
2020/01/29 10:07:00 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:07:00 DEBUG : pacer: low level retry 7/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:07:00 DEBUG : pacer: Rate limited, increasing sleep to 30.409292ms
2020/01/29 10:07:01 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:07:01 DEBUG : pacer: Reducing sleep to 22.806969ms
2020/01/29 10:07:01 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:07:01 DEBUG : pacer: low level retry 8/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:07:01 DEBUG : pacer: Rate limited, increasing sleep to 45.613938ms
2020/01/29 10:07:01 DEBUG : pacer: Reducing sleep to 34.210453ms
2020/01/29 10:07:01 DEBUG : pacer: Reducing sleep to 25.657839ms
2020/01/29 10:07:01 DEBUG : pacer: Reducing sleep to 19.243379ms
2020/01/29 10:07:01 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:07:02 DEBUG : pacer: Reducing sleep to 14.432534ms
2020/01/29 10:07:02 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:07:02 DEBUG : pacer: low level retry 9/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:07:02 DEBUG : pacer: Rate limited, increasing sleep to 28.865068ms
2020/01/29 10:07:02 DEBUG : pacer: Reducing sleep to 21.648801ms
2020/01/29 10:07:02 DEBUG : pacer: Reducing sleep to 16.2366ms
2020/01/29 10:07:02 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:07:02 DEBUG : pacer: Reducing sleep to 12.17745ms
2020/01/29 10:07:02 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:07:02 DEBUG : pacer: low level retry 10/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:07:02 DEBUG : pacer: Rate limited, increasing sleep to 24.3549ms
2020/01/29 10:07:02 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Error encountered during upload: retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:07:02 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Cancelling multipart upload
2020/01/29 10:07:02 DEBUG : pacer: Reducing sleep to 18.266175ms
2020/01/29 10:07:02 DEBUG : pacer: Reducing sleep to 13.699631ms
2020/01/29 10:07:02 DEBUG : penfold/20200112._FastData.0.gz_al: Received error: retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received. - low level retry 1/10
2020/01/29 10:07:02 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Starting multipart upload
2020/01/29 10:07:02 DEBUG : pacer: Reducing sleep to 10.274723ms
2020/01/29 10:07:02 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Uploading segment 0/5370019872 size 10485760
2020/01/29 10:07:03 DEBUG : pacer: Reducing sleep to 10ms
2020/01/29 10:07:04 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Uploading segment 10485760/5370019872 size 10485760
2020/01/29 10:07:05 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Uploading segment 20971520/5370019872 size 10485760
...

:frowning: Hmm, I double checked the code but I can't see the problem.

Can you do a run with -vv --dump responses? This will be a massive log! I'd like to see the request+responses to the failing 500 error, the GET for the get position and the next failure response if possible.

I'm beginning to think after reading the docs very carefully, that there is something I'm missing so I'm going to go through the other SDKs to see if I can spot something.

It might, of course, be a bug in onedrive - we've found a few of those!

Thanks

OK, trying this out. Hmm... uploaded 25G and the log file is 8M. So... maybe 250Mb complete log... that's not toooooo bad :slight_smile:

OK this is where it starts

2020/01/29 15:44:43 DEBUG : penfold/20200105._FastData.0.gz_ac.bin: Uploading segment 3575644160/5370019872 size 10485760
2020/01/29 15:44:43 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2020/01/29 15:44:43 DEBUG : HTTP REQUEST (req 0xc0000f3d00)
2020/01/29 15:44:43 DEBUG : PUT /rup/665...HLN HTTP/1.1
Host: api.onedrive.com
User-Agent: rclone/v1.50.2-195-gacd1a502-fix-3131-onedrive-416-beta
Content-Length: 10485760
Authorization: XXXX
Content-Range: bytes 3575644160-3586129919/5370019872
Accept-Encoding: gzip

2020/01/29 15:44:43 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2020/01/29 15:44:43 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2020/01/29 15:44:43 DEBUG : HTTP RESPONSE (req 0xc000250300)
2020/01/29 15:44:43 DEBUG : HTTP/2.0 500 Internal Server Error
Content-Type: application/json; charset=utf-8
Date: Wed, 29 Jan 2020 20:44:43 GMT
Ms-Cv: WCUiTvAs1kSrC43L7zaMgA.0
P3p: CP="BUS CUR CONo FIN IVDo ONL OUR PHY SAMo TELo"
Strict-Transport-Security: max-age=31536000; includeSubDomains
Www-Authenticate: Bearer realm="OneDriveAPI", error="invalid_token", error_description="Invalid auth token"
X-Asmversion: UNKNOWN; 19.398.120.2003
X-Msedge-Ref: Ref A: 3A46A9A39DBB4BBB827A23FCF5AE6111 Ref B: EWR30EDGE0206 Ref C: 2020-01-29T20:44:20Z
X-Msnserver: BN2BAPD4F0A3F71
X-Qosstats: {"ApiId":0,"ResultType":0,"SourcePropertyId":42,"TargetPropertyId":274}
X-Throwsite: 15bf.1333

{"error":{"code":"generalException","message":"General Exception While Processing"}}
2020/01/29 15:44:43 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2020/01/29 15:44:43 DEBUG : pacer: low level retry 1/10 (error generalException: General Exception While Processing)
2020/01/29 15:44:43 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2020/01/29 15:44:43 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>

And here's an example of a 416

2020/01/29 15:44:44 DEBUG : penfold/20200105._FastData.0.gz_ac.bin: Uploading segment 3586129920/5370019872 size 10485760
2020/01/29 15:44:44 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2020/01/29 15:44:44 DEBUG : HTTP REQUEST (req 0xc00014b700)
2020/01/29 15:44:44 DEBUG : PUT /rup/665...HLN HTTP/1.1
Host: api.onedrive.com
User-Agent: rclone/v1.50.2-195-gacd1a502-fix-3131-onedrive-416-beta
Content-Length: 10485760
Authorization: XXXX
Content-Range: bytes 3586129920-3596615679/5370019872
Accept-Encoding: gzip

2020/01/29 15:44:44 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2020/01/29 15:44:45 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2020/01/29 15:44:45 DEBUG : HTTP RESPONSE (req 0xc000250800)
2020/01/29 15:44:45 DEBUG : HTTP/2.0 416 Requested Range Not Satisfiable
Content-Type: application/json; charset=utf-8
Date: Wed, 29 Jan 2020 20:44:44 GMT
Ms-Cv: eJf6kFBy0EqJIaJZv0B47A.0
P3p: CP="BUS CUR CONo FIN IVDo ONL OUR PHY SAMo TELo"
Strict-Transport-Security: max-age=31536000; includeSubDomains
Www-Authenticate: Bearer realm="OneDriveAPI", error="invalid_token", error_description="Invalid auth token"
X-Asmversion: UNKNOWN; 19.398.120.2003
X-Msedge-Ref: Ref A: B7DFFE3AE1674DE2B4A302F6BCFCFB50 Ref B: EWR30EDGE0206 Ref C: 2020-01-29T20:44:43Z
X-Msnserver: BN2BAPDC9F871F4
X-Qosstats: {"ApiId":0,"ResultType":2,"SourcePropertyId":0,"TargetPropertyId":42}
X-Throwsite: 06c5.1f40

{"error":{"code":"invalidRange","message":"The uploaded fragment overlaps with data that has already been received.","innererror":{"code":"fragmentOverlap"}}}
2020/01/29 15:44:45 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2020/01/29 15:44:45 DEBUG : penfold/20200105._FastData.0.gz_ae.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.

That is great! Do you thing you could email me the complete log? nick@craig-wood.com - can you put a link to this page for context.

I'll have a go at finding the requests which go with those responses and the following ones.

Thanks

Log might be too big for email even gzipped...

The error started early enough and I aborted it after the 416's stopped. gzip'd the log was 1.8M so hopefully you've received it!

1 Like

Got the log thanks. Will investigate in the morning!

Thanks for the log. A bit of investigation showed that rclone wasn't sending the correct Content-Range header due to a really stupid scoping issue (it is easy to shadow variables in an outer scope in go - I wish it was illegal!)

Here is the fixed version. I really hope this works!

https://beta.rclone.org/branch/v1.50.2-202-g252377e2-fix-3131-onedrive-416-beta/ (uploaded in 15-30 mins)

New test started, but only -vv, no dumping. This should let us see the error and retry and continuation. Afterwards copy the file back down and verify it matches the original.

Sounds perfect - thanks :crossed_fingers:

Hmm, I'm seeing pacer errors, but I'm not seeing any messages about retries or what file the error related to

I'm definitely not seeing any overlap errors, but without knowing what files were impacted it's gonna be hard to tell if the upload recovered cleanly.

Hmm...

There are some interesting new errors, though!

2020/01/31 11:18:15 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2020/01/31 11:18:15 DEBUG : pacer: low level retry 1/10 (error 503 Service Unavailable: )
2020/01/31 11:18:15 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2020/01/31 11:18:15 DEBUG : pacer: Reducing sleep to 15ms

FWIW:

% grep DEBUG typescript  | grep -v pacer | grep -v multipart.upload | grep -v Uploading.segment | grep -v token.*config.file
2020/01/31 10:49:01 DEBUG : rclone: Version "v1.50.2-202-g252377e2-fix-3131-onedrive-416-beta" starting with parameters ["/home/sweh/XX/rclone" "-vv" "-c" "--stats=60s" "--max-size=40000M" "--config" "/home/sweh/.config/rclone/rclone.conf" "--size-only" "sync" "." "OneDriveTST:"]
2020/01/31 10:49:01 DEBUG : Using config file from "/home/sweh/.config/rclone/rclone.conf"
2020/01/31 11:18:15 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2020/01/31 11:49:03 DEBUG : One drive root 'TST/.bin': Token expired but no uploads in progress - doing nothing
2020/01/31 12:53:16 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2020/01/31 13:10:21 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value

The pacer errors:

% grep pacer typescript  | cut -d':' -f4- | sort | uniq -c
    847  pacer: Rate limited, increasing sleep to 20ms
     14  pacer: Rate limited, increasing sleep to 22.5ms
     13  pacer: Rate limited, increasing sleep to 30ms
     14  pacer: Rate limited, increasing sleep to 40ms
      1  pacer: Rate limited, increasing sleep to 80ms
      1  pacer: Reducing sleep to 10.67871ms
    847  pacer: Reducing sleep to 10ms
    820  pacer: Reducing sleep to 11.25ms
     40  pacer: Reducing sleep to 12.65625ms
      1  pacer: Reducing sleep to 14.238281ms
    833  pacer: Reducing sleep to 15ms
     40  pacer: Reducing sleep to 16.875ms
      1  pacer: Reducing sleep to 18.984375ms
     26  pacer: Reducing sleep to 22.5ms
      1  pacer: Reducing sleep to 25.3125ms
     13  pacer: Reducing sleep to 30ms
      1  pacer: Reducing sleep to 33.75ms
      1  pacer: Reducing sleep to 45ms
      1  pacer: Reducing sleep to 60ms
      3  pacer: low level retry 1/10 (error 503 Service Unavailable: )
      5  pacer: low level retry 1/10 (error UnknownError: )
     13  pacer: low level retry 1/10 (error generalException: An error occurred in the data store.)
    851  pacer: low level retry 1/10 (error generalException: General Exception While Processing)
     16  pacer: low level retry 2/10 (error generalException: General Exception While Processing)
      1  pacer: low level retry 3/10 (error generalException: General Exception While Processing)

You should have seen an overlap error still if the problem had manifested so I guess it didn't! I didn't remove any of the debugs.

OK, another complete run later and there's an overlap :slight_smile:

2020/02/01 10:28:00 DEBUG : penfold/20200112._FastData.0.gz_ag.bin: Uploading segment 4456448000/5370019872 size 10485760
2020/02/01 10:28:30 DEBUG : pacer: low level retry 1/10 (error generalException:
 General Exception While Processing)
2020/02/01 10:28:30 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2020/02/01 10:28:30 DEBUG : pacer: Reducing sleep to 15ms
2020/02/01 10:28:30 DEBUG : penfold/20200112._FastData.0.gz_ah.bin: Uploading se
gment 3806330880/5370019872 size 10485760
2020/02/01 10:28:30 DEBUG : penfold/20200112._FastData.0.gz_ag.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/02/01 10:28:31 DEBUG : penfold/20200112._FastData.0.gz_ag.bin: Read position 4464803840, chunk is 4456448000..4466933760, bytes to skip = 8355840
2020/02/01 10:28:31 DEBUG : pacer: low level retry 2/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/02/01 10:28:31 DEBUG : penfold/20200112._FastData.0.gz_ag.bin: Uploading segment 4466933760/5370019872 size 10485760

So if I'm reading that correctly, we get the "general error", which causes a "pacer 1/10 retry" error. That caused the 416 overlap, which causes a "pacer 2/10 retry skipping lots of bytes" error.

It's a little confusing that there "we need to retry" error comes before the pacer message and nothing after the pacer message indicates the retry with the shorter block, but I guess it worked because the next full size block was then sent.

At the end I was able to re-download the file in question and it shows as being identical to the original.

% sudo rclone copy OneDriveTST:penfold/20200112._FastData.0.gz_ag .
% cmp 20200112._FastData.0.gz_ag /BACKUP/penfold/20200112._FastData.0.gz_ag
% md5sum 20200112._FastData.0.gz_ag /BACKUP/penfold/20200112._Fa>
03ad7f4e2f9feb29e7c85f732260be92  20200112._FastData.0.gz_ag
03ad7f4e2f9feb29e7c85f732260be92  /BACKUP/penfold/20200112._FastData.0.gz_ag

So I think this is fixed; just looks a little confusing in the debug logs :slight_smile:

I think it is fixed too :smile::smile::smile:

The logs are a little confusing due to the way the pacer does the retries, but they are as expected.

I'll merge this into the beta now and I'll stick it into a point release at some point.

PS thanks for your heroic testing efforts - couldn't have fixed it without that!