Read failures while using api for sync but command line has no issues

Help and Support
1

What is the problem you are having with rclone?

Sync from AWS S3 to OCI object storage fails with read failures when using rclone API but sync completes successfully when using rclone at command line.   Error: "Reopening on read failure after 2425418571 bytes: retry 1/10: context canceled"   number of bytes read varies.

What is your rclone version (output from rclone version)

1.54.0

Which OS you are using and how many bits (eg Windows 7, 64 bit)

docker image in Kubernetes cluster in AWS (EKS)

Which cloud storage system are you using? (eg Google Drive)

AWS S3 and OCI (Oracle Cloud Infrastructure) object storage (S3 compatible)

The command you were trying to run (eg rclone copy /tmp remote:tmp)

'rcd', '--rc-web-gui', '--s3-chunk-size=10M', '--log-level=DEBUG', '--low-level-retries=10', '--rc-job-expire-duration=0', '--rc-web-gui-force-update', '--auto-confirm', '--rc-enable-metrics', '--rc-addr=:5572', '--rc-user=XXXXX', '--rc-pass=XXXXX', '--checksum', '--transfers=2']

API:  curl -H "Content-Type: application/json" -X POST -d '{"srcFs":"aws:XXXXX/XXXXX/", "dstFs":"oci:XXXXX/XXXXX/"}' 'http://xxxxx:xxxxx@rclone.xxxxx.xxxx/sync/sync'

CLI:  rclone sync 'aws:XXXXX/XXXXX' 'oci:XXXXX/XXXXX'

The rclone config contents with secrets removed.

    [aws]
    type = s3
    provider = AWS
    env_auth = true
    region = us-east-1

    [oci]
    type = s3
    provider = Other
    upload_cutoff = 5g
    shared_credentials_file = $HOME/.oci/config
    access_key_id = XXXXX
    secret_access_key = XXXXX
    region = us-ashburn-1
    endpoint =

A log from the command with the -vv flag

API::
2021/03/23 16:04:12 DEBUG : rclone: Version "v1.54.0" starting with parameters ["/usr/local/bin/rclone" "rcd" "--rc-web-gui" "--s3-chunk-size=10M" "--log-level=DEBUG" "--low-level-retries=10" "--rc-job-expire-duration=0" "--rc-web-gui-force-update" "--auto-confirm" "--rc-enable-metrics" "--rc-addr=:5572" "--rc-user=XXXXX" "--rc-pass=XXXXX" "--checksum" "--transfers=2"]
2021/03/23 16:04:13 ERROR : Error reading tag file at /root/.cache/rclone/webgui/tag 
2021/03/23 16:04:13 DEBUG : Current tag: , Release tag: v2.0.4
2021/03/23 16:04:13 INFO  : A release (v2.0.4) for gui is present at https://github.com/rclone/rclone-webui-react/releases/download/v2.0.4/currentbuild.zip. Use --rc-web-gui-update to update. Your current version is ()
2021/03/23 16:04:13 NOTICE: A new release for gui (v2.0.4) is present at https://github.com/rclone/rclone-webui-react/releases/download/v2.0.4/currentbuild.zip
2021/03/23 16:04:13 NOTICE: Downloading webgui binary. Please wait. [Size: 4740206, Path :  /root/.cache/rclone/webgui/v2.0.4.zip]
2021/03/23 16:04:13 NOTICE: Unzipping webgui binary
2021/03/23 16:04:13 NOTICE: Serving Web GUI
2021/03/23 16:04:13 INFO  : Using --user XXXXX --pass XXXXX as authenticated user
2021/03/23 16:04:13 NOTICE: Serving remote control on http://[::]:5572/
2021/03/23 16:04:13 DEBUG : login_token "XXXXX"
2021/03/23 16:04:13 ERROR : Failed to open Web GUI in browser: exec: "xdg-open": executable file not found in $PATH. Manually access it at: http://XXXXX:XXXXX@[::]:5572/?login_token=XXXXX
2021/03/23 16:04:14 DEBUG : rc: "core/stats": with parameters map[]
2021/03/23 16:04:14 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletedDirs:0 deletes:0 elapsedTime:1.29488784 errors:0 fatalError:false renames:0 retryError:false speed:0 transferTime:0 transfers:0]: <nil>
2021/03/23 16:04:15 DEBUG : rc: "core/stats": with parameters map[]
2021/03/23 16:04:15 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletedDirs:0 deletes:0 elapsedTime:2.289996524 errors:0 fatalError:false renames:0 retryError:false speed:0 transferTime:0 transfers:0]: <nil>
2021/03/23 16:04:19 DEBUG : rc: "core/stats": with parameters map[]
2021/03/23 16:04:19 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletedDirs:0 deletes:0 elapsedTime:6.30880169 errors:0 fatalError:false renames:0 retryError:false speed:0 transferTime:0 transfers:0]: <nil>
2021/03/23 16:04:20 DEBUG : rc: "core/stats": with parameters map[]
2021/03/23 16:04:20 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletedDirs:0 deletes:0 elapsedTime:7.311641409 errors:0 fatalError:false renames:0 retryError:false speed:0 transferTime:0 transfers:0]: <nil>
2021/03/23 16:04:24 DEBUG : rc: "core/stats": with parameters map[]
2021/03/23 16:04:24 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletedDirs:0 deletes:0 elapsedTime:11.325401454 errors:0 fatalError:false renames:0 retryError:false speed:0 transferTime:0 transfers:0]: <nil>
2021/03/23 16:04:25 DEBUG : rc: "operations/size": with parameters map[fs:aws:XXXXX/XXXXX/]
2021/03/23 16:04:25 DEBUG : Creating backend with remote "aws:ss-XXXXX/XXXXX/"
2021/03/23 16:04:25 DEBUG : Using config file from "/config/rclone/rclone.conf"
2021/03/23 16:04:25 DEBUG : rc: "core/stats": with parameters map[]
2021/03/23 16:04:25 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletedDirs:0 deletes:0 elapsedTime:12.329557552 errors:0 fatalError:false renames:0 retryError:false speed:0 transferTime:0 transfers:0]: <nil>
2021/03/23 16:04:25 DEBUG : fs cache: renaming cache item "aws:XXXXX/XXXXX/" to be canonical "aws:XXXXX/XXXXX"
2021/03/23 16:04:25 DEBUG : rc: "operations/size": reply map[bytes:31982386202 count:12]: <nil>
2021/03/23 16:04:25 DEBUG : rc: "sync/sync": with parameters map[dstFs:oci:XXXXX/XXXXX/ srcFs:aws:XXXXX/XXXXX/]
2021/03/23 16:04:25 DEBUG : fs cache: switching user supplied name "aws:XXXXX/XXXXX/" for canonical name "aws:XXXXX/XXXXX"
2021/03/23 16:04:25 DEBUG : Creating backend with remote "oci:XXXXX/XXXXX/"
2021/03/23 16:04:25 DEBUG : fs cache: renaming cache item "oci:XXXXX/XXXXX/" to be canonical "oci:XXXXX/XXXXX"
2021/03/23 16:04:25 DEBUG : 433166.ism: MD5 = 53df04dc507606d364fe65354f4e7ad5 OK
2021/03/23 16:04:25 DEBUG : 433166.ism: Size and MD5 of src and dst objects identical
2021/03/23 16:04:25 DEBUG : 433166.ism: Unchanged skipping
2021/03/23 16:04:25 DEBUG : 433166.mp4: MD5 = 3316795dbd31127b872c0ba9d5b30930 OK
2021/03/23 16:04:25 DEBUG : 433166UHD.mp4: MD5 = c1b06f08b0ef6ccea6886ecda6b1b8e4 OK
2021/03/23 16:04:25 DEBUG : 433166.mp4: Size and MD5 of src and dst objects identical
2021/03/23 16:04:25 DEBUG : 433166UHD.mp4: Size and MD5 of src and dst objects identical
2021/03/23 16:04:25 DEBUG : 433166.mp4: Unchanged skipping
2021/03/23 16:04:25 DEBUG : 433166UHD.mp4: Unchanged skipping
2021/03/23 16:04:25 DEBUG : 433166HD.mp4: MD5 = ba0029b9e0807d9850a7ff2a45f47bcb OK
2021/03/23 16:04:25 DEBUG : 433166HD.mp4: Size and MD5 of src and dst objects identical
2021/03/23 16:04:25 DEBUG : 433166HD.mp4: Unchanged skipping
2021/03/23 16:04:25 DEBUG : S3 bucket bucket path 433166: Waiting for checks to finish
2021/03/23 16:04:25 DEBUG : 433166.ismc: MD5 = af423485f2b1e967562b9dc251eda9ec OK
2021/03/23 16:04:25 DEBUG : 433166.ismc: Size and MD5 of src and dst objects identical
2021/03/23 16:04:25 DEBUG : 433166.ismc: Unchanged skipping
2021/03/23 16:04:25 DEBUG : 433166_1241.ismv: Size of src and dst objects identical
2021/03/23 16:04:25 DEBUG : 433166_1241.ismv: Unchanged skipping
2021/03/23 16:04:25 DEBUG : 433166_200.ismv: Size of src and dst objects identical
2021/03/23 16:04:25 DEBUG : 433166_200.ismv: Unchanged skipping
2021/03/23 16:04:25 DEBUG : S3 bucket bucket path 433166: Waiting for transfers to finish
2021/03/23 16:04:25 DEBUG : 433166_16000.ismv: multipart upload starting chunk 1 size 10M offset 0/18.255G
2021/03/23 16:04:26 DEBUG : 433166_16000.ismv: multipart upload starting chunk 2 size 10M offset 10M/18.255G
2021/03/23 16:04:26 DEBUG : 433166_16000.ismv: multipart upload starting chunk 3 size 10M offset 20M/18.255G
2021/03/23 16:04:26 DEBUG : 433166_16000.ismv: multipart upload starting chunk 4 size 10M offset 30M/18.255G
...
2021/03/23 16:05:24 DEBUG : rc: "core/stats": with parameters map[]
2021/03/23 16:05:24 DEBUG : rc: "core/stats": reply map[bytes:4644134912 checks:7 deletedDirs:0 deletes:0 elapsedTime:71.379772814 errors:0 fatalError:false renames:0 retryError:false speed:7.912108928985105e+07 transferTime:58.696563806 transferring:[map[bytes:2262822912 eta:438 group:job/8 name:433166_16000.ismv percentage:11 size:19601164083 speed:3.864807038141444e+07 speedAvg:3.954396937306828e+07] map[bytes:2381312000 eta:5 group:job/8 name:433166_2048.ismv percentage:91 size:2601679644 speed:4.0805016721664906e+07 speedAvg:4.203323373796079e+07]] transfers:0]: <nil>
2021/03/23 16:05:24 DEBUG : 433166_16000.ismv: multipart upload starting chunk 216 size 10M offset 2.100G/18.255G
2021/03/23 16:05:24 DEBUG : 433166_16000.ismv: multipart upload starting chunk 217 size 10M offset 2.109G/18.255G
2021/03/23 16:05:24 DEBUG : 433166_16000.ismv: multipart upload starting chunk 218 size 10M offset 2.119G/18.255G
2021/03/23 16:05:25 DEBUG : 433166_16000.ismv: multipart upload starting chunk 219 size 10M offset 2.129G/18.255G
2021/03/23 16:05:25 DEBUG : rc: "core/stats": with parameters map[]
2021/03/23 16:05:25 DEBUG : rc: "core/stats": reply map[bytes:4720680960 checks:7 deletedDirs:0 deletes:0 elapsedTime:72.383956318 errors:0 fatalError:false renames:0 retryError:false speed:7.907241403644264e+07 transferTime:59.700747246 transferring:[map[bytes:2297425920 eta:440 group:job/8 name:433166_16000.ismv percentage:11 size:19601164083 speed:3.857743144378006e+07 speedAvg:3.930045149720097e+07] map[bytes:2423255040 eta:4 group:job/8 name:433166_2048.ismv percentage:93 size:2601679644 speed:4.082131054427544e+07 speedAvg:4.224260631336402e+07]] transfers:0]: <nil>
2021/03/23 16:05:25 DEBUG : 433166_2048.ismv: Reopening on read failure after 2425418571 bytes: retry 1/10: context canceled
2021/03/23 16:05:25 DEBUG : 433166_16000.ismv: Reopening on read failure after 2305106569 bytes: retry 1/10: context canceled
2021/03/23 16:05:25 DEBUG : 433166_2048.ismv: Reopen failed after 2425418571 bytes read: RequestCanceled: request context canceled
caused by: context canceled
2021/03/23 16:05:25 ERROR : 433166_2048.ismv: Failed to copy: Put "https://XXXXX.compat.objectstorage.us-ashburn-1.oraclecloud.com/XXXXX/XXXXX/XXXXX.xxx?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=XXXXX%2F20210323%2Fus-ashburn-1%2Fs3%2Faws4_request&X-Amz-Date=20210323T160425Z&X-Amz-Expires=900&X-Amz-SignedHeaders=content-type%3Bhost%3Bx-amz-acl%3Bx-amz-meta-mtime&X-Amz-Signature=81dc75fff762904676b30f545dd454ac98c65f56d629477f4158897aaa3c401e": context canceled
2021/03/23 16:05:25 DEBUG : 433166_16000.ismv: Reopen failed after 2305106569 bytes read: RequestCanceled: request context canceled
caused by: context canceled
2021/03/23 16:05:25 DEBUG : pacer: low level retry 1/10 (error RequestCanceled: request context canceled
caused by: context canceled)
2021/03/23 16:05:25 DEBUG : pacer: Rate limited, increasing sleep to 10ms
2021/03/23 16:05:25 DEBUG : 433166_16000.ismv: Cancelling multipart upload
2021/03/23 16:05:25 DEBUG : pacer: Reducing sleep to 0s
2021/03/23 16:05:25 ERROR : 433166_16000.ismv: Failed to copy: multipart upload failed to read source: context canceled
2021/03/23 16:05:25 ERROR : S3 bucket bucket path 433166: not deleting files as there were IO errors
2021/03/23 16:05:25 ERROR : S3 bucket bucket path 433166: not deleting directories as there were IO errors
2021/03/23 16:05:25 ERROR : rc: "sync/sync": error: context canceled
2021/03/23 16:05:25 DEBUG : pacer: low level retry 2/10 (error RequestCanceled: request context canceled
caused by: context canceled)
2021/03/23 16:05:25 DEBUG : pacer: Rate limited, increasing sleep to 10ms
2021/03/23 16:05:25 DEBUG : pacer: low level retry 3/10 (error RequestCanceled: request context canceled
caused by: context canceled)
2021/03/23 16:05:25 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2021/03/23 16:05:25 DEBUG : pacer: low level retry 4/10 (error RequestCanceled: request context canceled
caused by: context canceled)
2021/03/23 16:05:25 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2021/03/23 16:05:25 DEBUG : pacer: low level retry 5/10 (error RequestCanceled: request context canceled
caused by: context canceled)
2021/03/23 16:05:25 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2021/03/23 16:05:25 DEBUG : pacer: low level retry 6/10 (error RequestCanceled: request context canceled
caused by: context canceled)
2021/03/23 16:05:25 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2021/03/23 16:05:25 DEBUG : pacer: low level retry 7/10 (error RequestCanceled: request context canceled
caused by: context canceled)
2021/03/23 16:05:25 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2021/03/23 16:05:25 DEBUG : pacer: low level retry 8/10 (error RequestCanceled: request context canceled
caused by: context canceled)
2021/03/23 16:05:25 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2021/03/23 16:05:26 DEBUG : pacer: low level retry 9/10 (error RequestCanceled: request context canceled
caused by: context canceled)
2021/03/23 16:05:26 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2021/03/23 16:05:26 DEBUG : pacer: low level retry 10/10 (error RequestCanceled: request context canceled
caused by: context canceled)
2021/03/23 16:05:26 DEBUG : pacer: Rate limited, increasing sleep to 2s
2021/03/23 16:05:29 DEBUG : rc: "core/stats": with parameters map[]
2021/03/23 16:05:29 DEBUG : rc: "core/stats": reply map[bytes:4728820361 checks:7 deletedDirs:0 deletes:0 elapsedTime:76.373698336 errors:2 fatalError:false lastError:multipart upload failed to read source: context canceled renames:0 retryError:true speed:7.88577152180291e+07 transferTime:59.966489619 transfers:0]: <nil>
2021/03/23 16:05:30 DEBUG : rc: "core/stats": with parameters map[]
2021/03/23 16:05:30 DEBUG : rc: "core/stats": reply map[bytes:4728820361 checks:7 deletedDirs:0 deletes:0 elapsedTime:77.381751232 errors:2 fatalError:false lastError:multipart upload failed to read source: context canceled renames:0 retryError:true speed:7.88577152180291e+07 transferTime:59.966489619 transfers:0]: <nil>
2

Can you try this again with the latest beta once?

3

I think @darthShadow is correct - this is a fixed bug when starting remotes over the rc.

However it got fixed in this commit

Which currently is only in the latest beta

4

Thanks for the quick response.

I downloaded the docker image with the tag beta.

When I tried to sync, it came back with access denied. When I switched back to the docker image I've been using (1.54), it can access the data fine but sync fails .

Logs from beta:
2021/03/24 16:03:59 DEBUG : Using config file from "/config/rclone/rclone.conf"
2021/03/24 16:03:59 DEBUG : rclone: Version "v1.55.0-beta.5334.d6870473a" starting with parameters ["/usr/local/bin/rclone" "rcd" "--rc-web-gui" "--s3-chunk-size=10M" "--log-level=DEBUG" "--low-level-retries=10" "--rc-job-expire-duration=0" "--rc-web-gui-force-update" "--auto-confirm" "--rc-enable-metrics" "--rc-addr=:5572" "--rc-user=XXXXX" "--rc-pass=XXXXX" "--checksum" "--transfers=2"]
2021/03/24 16:04:00 ERROR : Error reading tag file at /root/.cache/rclone/webgui/tag
2021/03/24 16:04:00 DEBUG : Current tag: , Release tag: v2.0.4
2021/03/24 16:04:00 INFO : A release (v2.0.4) for gui is present at xhttps://github.com/rclone/rclone-webui-react/releases/download/v2.0.4/currentbuild.zip. Use --rc-web-gui-update to update. Your current version is ()
2021/03/24 16:04:00 NOTICE: A new release for gui (v2.0.4) is present at xhttps://github.com/rclone/rclone-webui-react/releases/download/v2.0.4/currentbuild.zip
2021/03/24 16:04:00 NOTICE: Downloading webgui binary. Please wait. [Size: 4740206, Path : /root/.cache/rclone/webgui/v2.0.4.zip]
2021/03/24 16:04:00 NOTICE: Unzipping webgui binary
2021/03/24 16:04:00 NOTICE: Serving Web GUI
2021/03/24 16:04:00 INFO : Using --user XXXX --pass XXXX as authenticated user
2021/03/24 16:04:00 NOTICE: Serving remote control on http://[::]:5572/
2021/03/24 16:04:00 DEBUG : login_token "cmNsb25lOmNEdTg4MzZtdlNYbUU0"
2021/03/24 16:04:00 ERROR : Failed to open Web GUI in browser: exec: "xdg-open": executable file not found in $PATH. Manually access it at: xhttp://XXXXX:XXXXX@[::]:5572/?login_token=cmNsb25lOmNEdTg4MzZtdlNYbUU0
21/03/24 16:04:10 DEBUG : rc: "core/stats": with parameters map[]
2021/03/24 16:04:10 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletedDirs:0 deletes:0 elapsedTime:10.093325744 errors:0 eta: fatalError:false renames:0 retryError:false speed:0 totalBytes:0 totalChecks:0 totalTransfers:0 transferTime:0 transfers:0]:
2021/03/24 16:04:12 DEBUG : rc: "sync/sync": with parameters map[dstFs:oci:XXXXX/431616/ srcFs:aws:XXXXX/431616/]
2021/03/24 16:04:12 DEBUG : Creating backend with remote "aws:XXXXX/431616/"
2021/03/24 16:04:12 DEBUG : aws: detected overridden config - adding "{W/f9T}" suffix to name
2021/03/24 16:04:12 DEBUG : fs cache: renaming cache item "aws:XXXXX/431616/" to be canonical "aws{W/f9T}:XXXXX/431616"
2021/03/24 16:04:12 DEBUG : Creating backend with remote "oci:XXXXX/431616/"
2021/03/24 16:04:12 DEBUG : oci: detected overridden config - adding "{W/f9T}" suffix to name
2021/03/24 16:04:12 DEBUG : fs cache: renaming cache item "oci:XXXXX/431616/" to be canonical "oci{W/f9T}:XXXXX/431616"
2021/03/24 16:04:12 ERROR : : error reading source directory: AccessDenied: Access Denied
status code: 403, request id: Y6MJJ2P5YF222QYD, host id: vtOmlmXIP8qQF6OfsdZh9D4KkPHej4xg6afXmcgx9LdeyW6mHK/e2Wb9q28tJsBxpUb61/vvnAI=
2021/03/24 16:04:12 DEBUG : S3 bucket XXXXX path 431616: Waiting for checks to finish
2021/03/24 16:04:12 DEBUG : S3 bucket XXXXX path 431616: Waiting for transfers to finish
2021/03/24 16:04:12 ERROR : S3 bucket XXXXX path 431616: not deleting files as there were IO errors
2021/03/24 16:04:12 ERROR : S3 bucket XXXXX path 431616: not deleting directories as there were IO errors
2021/03/24 16:04:12 ERROR : rc: "sync/sync": error: AccessDenied: Access Denied
status code: 403, request id: Y6MJJ2P5YF222QYD, host id: vtOmlmXIP8qQF6OfsdZh9D4KkPHej4xg6afXmcgx9LdeyW6mHK/e2Wb9q28tJsBxpUb61/vvnAI=
2021/03/24 16:04:14 DEBUG : rc: "core/stats": with parameters map[]
2021/03/24 16:04:14 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletedDirs:0 deletes:0 elapsedTime:14.098253368 errors:1 eta: fatalError:false lastError:AccessDenied: Access Denied
status code: 403, request id: Y6MJJ2P5YF222QYD, host id: vtOmlmXIP8qQF6OfsdZh9D4KkPHej4xg6afXmcgx9LdeyW6mHK/e2Wb9q28tJsBxpUb61/vvnAI= renames:0 retryError:true speed:0 totalBytes:0 totalChecks:0 totalTransfers:0 transferTime:0 transfers:0]:

Logs from rclone 1.54:
2021/03/24 16:12:55 DEBUG : rclone: Version "v1.54.0" starting with parameters ["/usr/local/bin/rclone" "rcd" "--rc-web-gui" "--s3-chunk-size=10M" "--log-level=DEBUG" "--low-level-retries=10" "--rc-job-expire-duration=0" "--rc-web-gui-force-update" "--auto-confirm" "--rc-enable-metrics" "--rc-addr=:5572" "--rc-user=XXXXX" "--rc-pass=XXXXX" "--checksum" "--transfers=2"]
2021/03/24 16:12:55 ERROR : Error reading tag file at /root/.cache/rclone/webgui/tag
2021/03/24 16:12:55 DEBUG : Current tag: , Release tag: v2.0.4
2021/03/24 16:12:55 INFO : A release (v2.0.4) for gui is present at https://github.com/rclone/rclone-webui-react/releases/download/v2.0.4/currentbuild.zip. Use --rc-web-gui-update to update. Your current version is ()
2021/03/24 16:12:55 NOTICE: A new release for gui (v2.0.4) is present at https://github.com/rclone/rclone-webui-react/releases/download/v2.0.4/currentbuild.zip
2021/03/24 16:12:55 NOTICE: Downloading webgui binary. Please wait. [Size: 4740206, Path : /root/.cache/rclone/webgui/v2.0.4.zip]
2021/03/24 16:12:55 NOTICE: Unzipping webgui binary
2021/03/24 16:12:56 NOTICE: Serving Web GUI
2021/03/24 16:12:56 INFO : Using --user XXXXX --pass XXXX as authenticated user
2021/03/24 16:12:56 NOTICE: Serving remote control on http://[::]:5572/
2021/03/24 16:12:56 DEBUG : login_token "cmNsb25lOmNEdTg4MzZtdlNYbUU0"
2021/03/24 16:12:56 ERROR : Failed to open Web GUI in browser: exec: "xdg-open": executable file not found in $PATH. Manually access it at: xhttp://XXXXX:XXXXX@[::]:5572/?login_token=cmNsb25lOmNEdTg4MzZtdlNYbUU0
2021/03/24 16:12:56 DEBUG : rc: "core/stats": with parameters map[]
2021/03/24 16:12:56 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletedDirs:0 deletes:0 elapsedTime:1.250778643 errors:0 fatalError:false renames:0 retryError:false speed:0 transferTime:0 transfers:0]:
2021/03/24 16:12:57 DEBUG : rc: "sync/sync": with parameters map[dstFs:oci:XXXXX/431616/ srcFs:aws:XXXXX/431616/]
2021/03/24 16:12:57 DEBUG : Creating backend with remote "aws:XXXXX/431616/"
2021/03/24 16:12:57 DEBUG : Using config file from "/config/rclone/rclone.conf"
2021/03/24 16:12:57 DEBUG : fs cache: renaming cache item "aws:XXXXX/431616/" to be canonical "aws:XXXXX/431616"
2021/03/24 16:12:57 DEBUG : Creating backend with remote "oci:XXXXX/431616/"
2021/03/24 16:12:58 DEBUG : fs cache: renaming cache item "oci:XXXXX/431616/" to be canonical "oci:XXXXX/431616"
2021/03/24 16:12:58 DEBUG : 431616.ismc: MD5 = 75761a773120d4877526e57144b6dda9 OK
2021/03/24 16:12:58 DEBUG : 431616.ism: MD5 = b27f2791f731b8133e7414fa366cc7d9 OK
2021/03/24 16:12:58 DEBUG : 431616.mp4: MD5 = b753102f16c544d9130af3deb0282fb7 OK
2021/03/24 16:12:58 DEBUG : 431616.ism: Size and MD5 of src and dst objects identical
2021/03/24 16:12:58 DEBUG : 431616.ism: Unchanged skipping
2021/03/24 16:12:58 DEBUG : 431616.mp4: Size and MD5 of src and dst objects identical
2021/03/24 16:12:58 DEBUG : 431616HD.mp4: MD5 = 71873e3e8229a815d16b0155af0a4998 OK
2021/03/24 16:12:58 DEBUG : 431616.mp4: Unchanged skipping
2021/03/24 16:12:58 DEBUG : 431616HD.mp4: Size and MD5 of src and dst objects identical
2021/03/24 16:12:58 DEBUG : 431616HD.mp4: Unchanged skipping
2021/03/24 16:12:58 DEBUG : 431616.ismc: Size and MD5 of src and dst objects identical
2021/03/24 16:12:58 DEBUG : 431616.ismc: Unchanged skipping
2021/03/24 16:12:58 DEBUG : S3 bucket XXXXX path 431616: Waiting for checks to finish
2021/03/24 16:12:58 DEBUG : 431616_1241.ismv: Size of src and dst objects identical
2021/03/24 16:12:58 DEBUG : 431616_1241.ismv: Unchanged skipping
2021/03/24 16:12:58 DEBUG : 431616_200.ismv: Size of src and dst objects identical
2021/03/24 16:12:58 DEBUG : 431616_200.ismv: Unchanged skipping
2021/03/24 16:12:58 DEBUG : 431616_403.ismv: Size of src and dst objects identical
2021/03/24 16:12:58 DEBUG : 431616_403.ismv: Unchanged skipping
2021/03/24 16:12:58 DEBUG : 431616_708.ismv: Size of src and dst objects identical
2021/03/24 16:12:58 DEBUG : 431616_708.ismv: Unchanged skipping
2021/03/24 16:12:58 DEBUG : 431616_2048.ismv: Size of src and dst objects identical
2021/03/24 16:12:58 DEBUG : 431616_2048.ismv: Unchanged skipping
2021/03/24 16:12:58 DEBUG : S3 bucket XXXXX path 431616: Waiting for transfers to finish
2021/03/24 16:13:57 DEBUG : 431616_5000.ismv: Reopening on read failure after 2373965571 bytes: retry 1/10: context canceled
2021/03/24 16:13:57 DEBUG : 431616_5000.ismv: Reopen failed after 2373965571 bytes read: RequestCanceled: request context canceled
caused by: context canceled
2021/03/24 16:13:57 ERROR : 431616_5000.ismv: Failed to copy: Put "xhttpsx://XXXXX.compat.objectstorage.us-ashburn-1.oraclecloud.com/XXXXX/431616/431616_5000.ismv?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=XXXXX%2Fus-ashburn-1%2Fs3%2Faws4_request&X-Amz-Date=20210324T161258Z&X-Amz-Expires=900&X-Amz-SignedHeaders=content-type%3Bhost%3Bx-amz-acl%3Bx-amz-meta-mtime&X-Amz-Signature=XXXXX": context canceled
2021/03/24 16:13:57 ERROR : S3 bucket XXXXX path 431616: not deleting files as there were IO errors
2021/03/24 16:13:57 ERROR : S3 bucket XXXXX path 431616: not deleting directories as there were IO errors
2021/03/24 16:13:57 ERROR : rc: "sync/sync": error: context canceled

5

One thing I noticed is that the serviceaccount role associated with rclone is not getting hit with the beta, which is probably why it's getting AccessDenied. Same exact commands using the rclone v1.54.0 will hit that role and therefore have access.

Has the way that rclone access s3 changed?

6

I don't think v1.54.0 is getting far enough to say whether it got AccessDenied or not - the bug causes a context canceled immediately.

Hopefully not, but we might have broken something, s3 auth is complicated!

Can you try it on the command line?

7

No issues with the sync at the command line using beta image:

2021/03/25 16:47:28 INFO :
Transferred: 2.180G / 3.671 GBytes, 59%, 37.220 MBytes/s, ETA 41s
Checks: 9 / 9, 100%
Transferred: 0 / 1, 0%
Elapsed time: 1m0.4s
Transferring:

  •                          431616_5000.ismv: 59% /3.671G, 37.386M/s, 40s

2021/03/25 16:48:09 INFO : 431616_5000.ismv: Copied (new)
2021/03/25 16:48:09 INFO : 431616_5000.ismv/431616_5000.ismv: Deleted
2021/03/25 16:48:09 INFO :
Transferred: 3.671G / 3.671 GBytes, 100%, 37.167 MBytes/s, ETA 0s
Checks: 10 / 10, 100%
Deleted: 1 (files), 0 (dirs)
Transferred: 1 / 1, 100%
Elapsed time: 1m41.6s

Also, I am seeing that the ServiceAccount Role was accessed, unlike with the API.

8

You've set env_auth = true and are using a docker image. Are you passing the environment variables necessary in to the docker image? Or have you mounted your aws config into the docker image?

9

I'm actually running rclone in kubernetes. The pod running rclone has been assigned a serviceaccount role that has access to the S3 bucket. However, I am not seeing the role getting hit (when using the beta image). When I use either the 1.54.0 image or running it at the command line (via a kubernetes job), it does hit the role and can access the S3 bucket.

10

I created a test IAM account for rclone to use and updated the config with the access_key_id and secret_access_key.

I am no longer getting the authentication error when running with the beta image, but I'm still getting the read failure for the larger files:

2021/03/29 13:32:46 DEBUG : rclone: Version "v1.55.0-beta.5334.d6870473a" starting with parameters ["/usr/local/bin/rclone" "rcd" "--rc-web-gui" "--s3-chunk-size=10M" "-vv" "--rc-job-expire-duration=0" "--rc-web-gui-force-update" "--auto-confirm" "--rc-enable-metrics" "--rc-addr=:5572" "--rc-user=xxxxx" "--rc-pass=xxxxx" "--checksum" "--transfers=2"]
2021/03/29 13:32:46 ERROR : Error reading tag file at /root/.cache/rclone/webgui/tag
2021/03/29 13:32:46 DEBUG : Current tag: , Release tag: v2.0.4
2021/03/29 13:32:46 NOTICE: Serving Web GUI
2021/03/29 13:32:46 INFO : Using --user rclone --pass XXXX as authenticated user
2021/03/29 13:32:46 NOTICE: Serving remote control on http://[::]:5572/

2021/03/29 13:36:58 DEBUG : rc: "sync/sync": reply map[]:
2021/03/29 13:36:58 DEBUG : rc: "operations/size": with parameters map[fs:aws:xxxxx/430594/]
2021/03/29 13:36:58 DEBUG : Creating backend with remote "aws:xxxxx/430594/"
2021/03/29 13:36:58 DEBUG : aws: detected overridden config - adding "{W/f9T}" suffix to name
2021/03/29 13:36:58 DEBUG : fs cache: renaming cache item "aws:xxxxx/430594/" to be canonical "aws{W/f9T}:xxxxx/430594"
2021/03/29 13:36:58 DEBUG : rc: "operations/size": reply map[bytes:13238537904 count:10]:
2021/03/29 13:36:58 DEBUG : rc: "sync/sync": with parameters map[dstFs:oci:xxxxx/430594/ srcFs:aws:xxxxx/430594/]
2021/03/29 13:36:58 DEBUG : fs cache: switching user supplied name "aws:xxxxx/430594/" for canonical name "aws{W/f9T}:xxxxx/430594"
2021/03/29 13:36:58 DEBUG : Creating backend with remote "oci:xxxxx/430594/"
2021/03/29 13:36:58 DEBUG : oci: detected overridden config - adding "{W/f9T}" suffix to name
2021/03/29 13:36:59 DEBUG : fs cache: renaming cache item "oci:xxxxx/430594/" to be canonical "oci{W/f9T}:xxxxx/430594"
2021/03/29 13:36:59 DEBUG : 430594_5000.ismv: multipart upload starting chunk 1 size 10M offset 0/6.155G
2021/03/29 13:36:59 DEBUG : 430594_5000.ismv: multipart upload starting chunk 2 size 10M offset 10M/6.155G
...
2021/03/29 13:37:58 DEBUG : 430594_5000.ismv: multipart upload starting chunk 289 size 10M offset 2.812G/6.155G
2021/03/29 13:37:58 DEBUG : 430594_5000.ismv: multipart upload starting chunk 290 size 10M offset 2.822G/6.155G
2021/03/29 13:37:58 DEBUG : pacer: low level retry 1/10 (error RequestCanceled: request context canceled
caused by: context canceled)
2021/03/29 13:37:58 DEBUG : 430594_5000.ismv: Reopening on read failure after 3045050537 bytes: retry 1/10: context canceled
2021/03/29 13:37:58 DEBUG : pacer: low level retry 1/10 (error RequestCanceled: request context canceled
caused by: context canceled)
2021/03/29 13:37:58 DEBUG : pacer: Rate limited, increasing sleep to 10ms
2021/03/29 13:37:58 DEBUG : 430594_5000.ismv: Reopen failed after 3045050537 bytes read: RequestCanceled: request context canceled
caused by: context canceled

11

This is exactly 60 seconds after the job started did the process doing the rc API call timeout then?

Maybe you need to run your jobs with _async=true or increase the timeout of the API caller.

12

Good catch! I've updated rc to start with --contimeout=30m flag. However, I'm still seeing timeouts after 1min. Am I using the wrong flag? I tried with both beta and 1.54. Below are the logs. I originally tried _async=true, but due to the large number of folders(prefixes), it would crash the pod. I searched but couldn't find anything that can limit the number of jobs running concurrently. Is there such a flag?

Thanks!

--beta logs
2021/03/30 15:19:51 DEBUG : Using config file from "/config/rclone/rclone.conf"
2021/03/30 15:19:51 DEBUG : rclone: Version "v1.55.0-beta.5334.d6870473a" starting with parameters ["/usr/local/bin/rclone" "rcd" "--rc-web-gui" "--contimeout=30m" "--s3-chunk-size=10M" "-vv" "--rc-job-expire-duration=0" "--rc-web-gui-force-update" "--auto-confirm" "--rc-addr=:5572" "--rc-user=xxxxx" "--rc-pass=xxxxx" "--checksum" "--transfers=2"]
2021/03/30 15:19:52 ERROR : Error reading tag file at /root/.cache/rclone/webgui/tag
2021/03/30 15:19:52 DEBUG : Current tag: , Release tag: v2.0.4
2021/03/30 15:21:39 DEBUG : 430824_16000.ismv: multipart upload starting chunk 1 size 10M offset 0/20.724G

2021/03/30 15:22:39 DEBUG : 430824_16000.ismv: multipart upload starting chunk 298 size 10M offset 2.900G/20.724G
2021/03/30 15:22:39 DEBUG : 430824_16000.ismv: multipart upload starting chunk 299 size 10M offset 2.910G/20.724G
2021/03/30 15:22:39 DEBUG : 430824_16000.ismv: Reopening on read failure after 3141558569 bytes: retry 1/10: context canceled
2021/03/30 15:22:39 DEBUG : 430824_2048.ismv: Reopening on read failure after 2854422931 bytes: retry 1/10: context canceled
2021/03/30 15:22:39 DEBUG : 430824_16000.ismv: Reopen failed after 3141558569 bytes read: RequestCanceled: request context canceled
caused by: context canceled
2021/03/30 15:22:39 DEBUG : pacer: low level retry 1/10 (error RequestCanceled: request context canceled
caused by: context canceled)

--1.54.0 logs
2021/03/30 15:31:40 DEBUG : rclone: Version "v1.54.0" starting with parameters ["/usr/local/bin/rclone" "rcd" "--rc-web-gui" "--contimeout=30m" "--s3-chunk-size=10M" "-vv" "--rc-job-expire-duration=0" "--rc-web-gui-force-update" "--auto-confirm" "--rc-addr=:5572" "--rc-user=rclone" "--rc-pass=cDu8836mvSXmE4" "--checksum" "--transfers=2"]

2021/03/30 15:32:43 DEBUG : 430824_16000.ismv: multipart upload starting chunk 1 size 10M offset 0/20.724G
2021/03/30 15:32:43 DEBUG : 430824_16000.ismv: multipart upload starting chunk 2 size 10M offset 10M/20.724G

2021/03/30 15:33:42 DEBUG : 430824_16000.ismv: multipart upload starting chunk 308 size 10M offset 2.998G/20.724G
2021/03/30 15:33:42 DEBUG : 430824_16000.ismv: multipart upload starting chunk 309 size 10M offset 3.008G/20.724G
2021/03/30 15:33:42 DEBUG : pacer: low level retry 1/10 (error RequestCanceled: request context canceled
caused by: context canceled)
2021/03/30 15:33:42 DEBUG : 430824_16000.ismv: Reopening on read failure after 3250415305 bytes: retry 1/10: context canceled
2021/03/30 15:33:42 DEBUG : 430824_2048.ismv: Reopening on read failure after 2683935971 bytes: retry 1/10: context canceled
2021/03/30 15:33:42 DEBUG : 430824_16000.ismv: Reopen failed after 3250415305 bytes read: RequestCanceled: request context canceled
caused by: context canceled
2021/03/30 15:33:42 DEBUG : 430824_2048.ismv: Reopen failed after 2683935971 bytes read: RequestCanceled: request context canceled
caused by: context canceled

13

It is the client that controls the timeout. So the client that is submitting the rc jobs is timing out after 1 minute and closing the HTTP connection. Rclone cancels the job at that point.

Which client are you using to submit jobs to rclone?

There isn't at present but there could be easily enough.

14

That would be great if you can have a flag that can set a limit on concurrent jobs.

For now I've been able to add a conditional to keep it from looping with the _async=true flag on and it's been completing.

Thank you!

15

What do you think it should do when you reach the limit? Fail to submit the next job would be the obvious thing.

If you are thinking it should wait until there is a job slot free then you'll have the timeout problem all over again :frowning:

If you want you can propose a new issue on github about this. Maybe you'd like to help implement it?

16

This topic was automatically closed 3 days after the last reply. New replies are no longer allowed.