OneDrive for Business -- oddities when copying

Using Rclone 1.39 to move some files from a VPS to OneDrive for business account.

The source files are 936MB in size…

server82:$ du -h zz
936M zz

And when I start the copy it starts out okay (if a bit slow), then seems to stop and restart the large file a few times…

server82:$ rclone copy zz kittens:node27 -v
2018/02/23 00:24:26 INFO : One drive root ‘node27’: Modify window is 1s
2018/02/23 00:24:32 INFO : 0944b2f5.vol000+001.par2: Copied (new)
2018/02/23 00:24:32 INFO : 0944b2f5.par2: Copied (new)
2018/02/23 00:24:33 INFO : 0944b2f5.vol001+002.par2: Copied (new)
2018/02/23 00:24:33 INFO : One drive root ‘node27’: Waiting for checks to finish
2018/02/23 00:24:33 INFO : One drive root ‘node27’: Waiting for transfers to finish
2018/02/23 00:24:38 INFO : 0944b2f5.vol003+004.par2: Copied (new)
2018/02/23 00:24:38 INFO : 0944b2f5.vol007+008.par2: Copied (new)
2018/02/23 00:24:45 INFO : 0944b2f5.vol031+032.par2: Copied (new)
2018/02/23 00:24:49 INFO : 0944b2f5.vol015+016.par2: Copied (new)
2018/02/23 00:24:55 INFO : 0944b2f5.vol063+064.par2: Copied (new)
2018/02/23 00:25:10 INFO : 0944b2f5.vol255+085.par2: Copied (new)
2018/02/23 00:25:12 INFO : 0944b2f5.vol127+128.par2: Copied (new)
2018/02/23 00:25:26 INFO :
Transferred: 218.438 MBytes (2.619 MBytes/s)
Errors: 0
Checks: 0
Transferred: 10
Elapsed time: 1m23.4s
Transferring:

  •                                 casbu.enc: 10% /798.297M, 2.491M/s, 4m47s
    

2018/02/23 00:26:26 INFO :
Transferred: 347.426 MBytes (2.423 MBytes/s)
Errors: 0
Checks: 0
Transferred: 10
Elapsed time: 2m23.3s
Transferring:

  •                                 casbu.enc: 26% /798.297M, 2.172M/s, 4m30s
    

2018/02/23 00:27:26 INFO :
Transferred: 437.426 MBytes (2.151 MBytes/s)
Errors: 0
Checks: 0
Transferred: 10
Elapsed time: 3m23.3s
Transferring:

  •                                 casbu.enc: 37% /798.297M, 989.004k/s, 8m35s
    

2018/02/23 00:28:26 INFO :
Transferred: 507.426 MBytes (1.927 MBytes/s)
Errors: 0
Checks: 0
Transferred: 10
Elapsed time: 4m23.3s
Transferring:

  •                                 casbu.enc:  8% /798.297M, 2.102M/s, 5m46s
    

=== So it restarted the upload of casbu.enc?

2018/02/23 00:29:26 INFO :
Transferred: 621.352 MBytes (1.922 MBytes/s)
Errors: 0
Checks: 0
Transferred: 10
Elapsed time: 5m23.3s
Transferring:

  •                                 casbu.enc: 23% /798.297M, 2.654M/s, 3m51s
    

2018/02/23 00:30:26 INFO :
Transferred: 769.063 MBytes (2.006 MBytes/s)
Errors: 0
Checks: 0
Transferred: 10
Elapsed time: 6m23.3s
Transferring:

  •                                 casbu.enc: 41% /798.297M, 1.852M/s, 4m11s
    

2018/02/23 00:31:26 INFO :
Transferred: 917.426 MBytes (2.069 MBytes/s)
Errors: 0
Checks: 0
Transferred: 10
Elapsed time: 7m23.3s
Transferring:

  •                                 casbu.enc: 60% /798.297M, 2.584M/s, 2m3s
    

2018/02/23 00:32:26 INFO :
Transferred: 1.003 GBytes (2.041 MBytes/s)
Errors: 0
Checks: 0
Transferred: 10
Elapsed time: 8m23.3s
Transferring:

  •                                 casbu.enc: 73% /798.297M, 2.109M/s, 1m38s
    

2018/02/23 00:33:26 INFO :
Transferred: 1.091 GBytes (1.983 MBytes/s)
Errors: 0
Checks: 0
Transferred: 10
Elapsed time: 9m23.3s
Transferring:

  •                                 casbu.enc:  0% /798.297M, 0/s, -
    

=== And it restarted the upload of casbu.enc AGAIN?

2018/02/23 00:34:26 INFO :
Transferred: 1.179 GBytes (1.937 MBytes/s)
Errors: 0
Checks: 0
Transferred: 10
Elapsed time: 10m23.3s
Transferring:

  •                                 casbu.enc: 11% /798.297M, 998.219k/s, 12m6s
    

2018/02/23 00:35:26 INFO :
Transferred: 1.220 GBytes (1.829 MBytes/s)
Errors: 0
Checks: 0
Transferred: 10
Elapsed time: 11m23.3s
Transferring:

  •                                 casbu.enc: 16% /798.297M, 1.048M/s, 10m35s
    

2018/02/23 00:36:26 INFO :
Transferred: 1.374 GBytes (1.893 MBytes/s)
Errors: 0
Checks: 0
Transferred: 10
Elapsed time: 12m23.3s
Transferring:

  •                                 casbu.enc: 36% /798.297M, 2.719M/s, 3m6s
    

2018/02/23 00:37:26 INFO :
Transferred: 1.540 GBytes (1.964 MBytes/s)
Errors: 0
Checks: 0
Transferred: 10
Elapsed time: 13m23.3s
Transferring:

  •                                 casbu.enc: 57% /798.297M, 2.953M/s, 1m54s
    

2018/02/23 00:38:26 INFO :
Transferred: 1.687 GBytes (2.001 MBytes/s)
Errors: 0
Checks: 0
Transferred: 10
Elapsed time: 14m23.3s
Transferring:

  •                                 casbu.enc: 76% /798.297M, 2.907M/s, 1m4s
    

2018/02/23 00:39:26 INFO :
Transferred: 1.852 GBytes (2.054 MBytes/s)
Errors: 0
Checks: 0
Transferred: 10
Elapsed time: 15m23.3s
Transferring:

  •                                 casbu.enc: 97% /798.297M, 2.492M/s, 7s
    

2018/02/23 00:39:40 INFO : casbu.enc: Copied (new)
2018/02/23 00:39:40 INFO :
Transferred: 1.871 GBytes (2.044 MBytes/s)
Errors: 0
Checks: 0
Transferred: 11
Elapsed time: 15m37.2s

So it appears that rclone copied the 936MB of data up to OneDrive for Business, but it repeated one file twice ending up with a total of 1.87gb transferred.

Any suggestions how to debug this?

The specific section in the rclone.conf file is:

[kittens]
type = onedrive
client_id =
client_secret =
token = {“access_token”:"===stunningly ornate access token herein==="}
resource_url = https://some-site.sharepoint.com/

There will have been an error uploading so it will have started again.

If you change -v to -vv you’ll see details of retries etc.

However the transfer looks like it was successful which is a good sign!

You might want to increase --low-level-retries which is how many times each part is tried.