Max-duration not working as intended with B2

Hi, I'm not sure if the new max-duration is working fully as intended (at least with B2; or maybe this is just the way it is?). It doesn't seem to allow existing transfers to complete once the duration is reached and instead just gets put in retry mode. And never exits, just continues (forever) with 0/s transfer rate. I tested the same command to an sftp remote and rclone did exit after the allotted time with an error. My intention is to use max-duration on cron jobs (to B2), so I do need rclone to exit. For now I'll use max-transfer, but I don't prefer its impolite exit (I prefer to allow existing transfers to complete). I understand why max-transfer is that way though.

Tested rclone 1.51 on mac and an ARM box (tested on both, same results). I posted some output below; can send more details later if necessary (but it should be easily reproducible). This was just a test short run, but I had one that ran for 5 hours and same extended results (script was supposed to end at 3h).
Thanks.


2020/02/24 20:04:25 DEBUG : rclone: Version "v1.51.0" starting with parameters ["rclone" "-vv" "--log-file=maxdurb2" "--max-duration=20s" "copy" "uptestdir" "B2REMOTE:/tmp/uptestdir"]
2020/02/24 20:04:25 DEBUG : Using config file from "rclone.conf"
2020/02/24 20:04:28 INFO : B2 bucket BUCKET path tmp/uptestdir: Transfer session deadline: 2020/02/24 20:04:48
2020/02/24 20:04:28 INFO : B2 bucket BUCKET path tmp/uptestdir: Waiting for checks to finish
2020/02/24 20:04:28 INFO : B2 bucket BUCKET path tmp/uptestdir: Waiting for transfers to finish
2020/02/24 20:04:29 DEBUG : mediumfile1-220M: Starting upload of large file in 3 chunks (id "")
2020/02/24 20:04:29 DEBUG : mediumfile1-220M: Sending chunk 1 length 100663296
2020/02/24 20:04:29 DEBUG : mediumfile2-220M: Starting upload of large file in 3 chunks (id "")
2020/02/24 20:04:29 DEBUG : mediumfile1-220M: Sending chunk 2 length 100663296
2020/02/24 20:04:29 DEBUG : mediumfile2-220M: Sending chunk 1 length 100663296
2020/02/24 20:04:29 DEBUG : mediumfile1-220M: Sending chunk 3 length 28393644
2020/02/24 20:04:42 DEBUG : file2-20M: SHA-1 = 746a1ca24c6f49e971222a35cb3fb7bb3d1e25f0 OK
2020/02/24 20:04:42 INFO : file2-20M: Copied (new)
2020/02/24 20:04:42 DEBUG : file1-20M: SHA-1 = e097386b63ff70335830b74e88d76368ccd483d5 OK
2020/02/24 20:04:42 INFO : file1-20M: Copied (new)
2020/02/24 20:04:43 DEBUG : mediumfile3-220M: Starting upload of large file in 3 chunks (id "")
2020/02/24 20:04:47 DEBUG : mediumfile1-220M: Done sending chunk 3
2020/02/24 20:04:47 DEBUG : mediumfile2-220M: Sending chunk 2 length 100663296
2020/02/24 20:04:48 DEBUG : upsplitac: Clearing upload URL because of error: Post https://pod-000-1041-07.backblaze.com/b2api/v1/b2_upload_file/: context deadline exceeded
2020/02/24 20:04:48 DEBUG : mediumfile1-220M: Error sending chunk 2 (retry=true): Post https://pod-000-1120-11.backblaze.com/b2api/v1/b2_upload_part/: context deadline exceeded: &url.Error{Op:"Post", URL:"https://pod-000-1120-11.backblaze.com/b2api/v1/b2_upload_part/", Err:context.deadlineExceededError{}}
2020/02/24 20:04:48 DEBUG : mediumfile1-220M: Clearing part upload URL because of error: Post https://pod-000-1120-11.backblaze.com/b2api/v1/b2_upload_part/: context deadline exceeded
2020/02/24 20:04:48 DEBUG : pacer: low level retry 1/10 (error Post https://pod-000-1120-11.backblaze.com/b2api/v1/b2_upload_part/: context deadline exceeded)
<snip, lots of same errors>
2020/02/24 20:04:50 DEBUG : upsplitac: Clearing upload URL because of error: Post https://pod-000-1128-17.backblaze.com/b2api/v1/b2_upload_file/: context deadline exceeded
2020/02/24 20:04:50 DEBUG : pacer: low level retry 1/1 (error Post https://pod-000-1128-17.backblaze.com/b2api/v1/b2_upload_file/: context deadline exceeded)
2020/02/24 20:04:50 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2020/02/24 20:04:50 DEBUG : upsplitac: Received error: Post https://pod-000-1128-17.backblaze.com/b2api/v1/b2_upload_file/: context deadline exceeded - low level retry 2/10
2020/02/24 20:04:51 DEBUG : pacer: low level retry 1/10 (error Post https://api001.backblazeb2.com/b2api/v1/b2_get_upload_part_url: context deadline exceeded)
2020/02/24 20:04:51 DEBUG : pacer: Rate limited, increasing sleep to 2.56s
2020/02/24 20:04:52 DEBUG : pacer: low level retry 1/10 (error Post https://api001.backblazeb2.com/b2api/v1/b2_get_upload_part_url: context deadline exceeded)
<snip, lots of same erorrs>
2020/02/24 20:10:17 DEBUG : pacer: low level retry 3/10 (error Post https://api001.backblazeb2.com/b2api/v1/b2_get_upload_url: context deadline exceeded)
2020/02/24 20:10:28 INFO :
Transferred: 168.199M / 888.122 MBytes, 19%, 478.774 kBytes/s, ETA 25m39s
Transferred: 2 / 14, 14%
Elapsed time: 5m59.7s
Transferring:

  •                                 upsplitac:  0% /20M, 0/s, -
    
  •                          mediumfile1-220M: 43% /219.078M, 0/s, 2069405h28m37.161793536s
    
  •                          mediumfile2-220M:  9% /219.078M, 0/s, 0s
    
  •                          mediumfile3-220M:  0% /219.078M, 0/s, -
    

2020/02/24 20:11:28 INFO :
Transferred: 168.199M / 888.122 MBytes, 19%, 410.336 kBytes/s, ETA 29m56s
Transferred: 2 / 14, 14%
Elapsed time: 6m59.7s
Transferring:

  •                                 upsplitac:  0% /20M, 0/s, -
    
  •                          mediumfile1-220M: 43% /219.078M, 0/s, 0s
    
  •                          mediumfile2-220M:  9% /219.078M, 0/s, 0s
    
  •                          mediumfile3-220M:  0% /219.078M, 0/s, -
    

(manually terminated rclone)

Yes, this looks like a bug... Well two bugs actually!

  1. the --max-duration flag doesn't work like it is documented to
  2. b2 shouldn't be retrying deadline exceeded errors.

It looks like I've got the context's muddled up in the sync routine or at least I need to be a lot more careful which context is used where!

Can you please make a new issue on github about this and I'll have a go at fixing - thanks.

You want 2 issues created or one combined?

One issue is fine, I'll spin out another one if the b2 fix is more complicated than I think.