Add flag to exit immediately when --max-duration reached

Log from run 2 (continued)

2.3. Between 1h30m and 1h34m we see lots of "context deadline exceeded" with some partial file deletions as well as API ERROR for listings
2021/03/09 16:00:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 4.176 MBytes/s, ETA 0s
Transferred:        16210 / 26228, 62%
Elapsed time:    1h30m0.0s
Transferring:
 * REDACTED on…20210202_080518643.mp4:  0% /off, 0/s, -
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…210207_143752192~2.mp4:  0% /off, 0/s, -
 * REDACTED on…20210208_170622523.mp4:  0% /off, 0/s, -
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_154841544.mp4:  0% /off, 0/s, -
 * REDACTED on…20210209_155155116.mp4:  0% /off, 0/s, -
 * REDACTED on…20210209_163041688.mp4:  0% /off, 0/s, -
 * REDACTED on…20210209_155509353.mp4:  0% /off, 0/s, -
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:00:03 NOTICE: REDACTED onwards/PXL_20210209_155509353.mp4: Removing partially written file on error: context deadline exceeded
2021/03/09 16:00:03 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	github.com/rclone/rclone/fs/operations/reopen.go:28
runtime.doInit
	runtime/proc.go:5652
runtime.doInit
	runtime/proc.go:5647
runtime.doInit
	runtime/proc.go:5647
runtime.doInit
	runtime/proc.go:5647
runtime.main
	runtime/proc.go:191
runtime.goexit
	runtime/asm_amd64.s:1374
2021/03/09 16:00:20 ERROR : REDACTED_ALBUM_NAME1: error reading source directory: couldn't list files: Post "https://photoslibrary.googleapis.com/v1/mediaItems:search": context deadline exceeded
2021/03/09 16:00:36 ERROR : REDACTED_ALBUM_NAME2: error reading source directory: couldn't list files: Post "https://photoslibrary.googleapis.com/v1/mediaItems:search": context deadline exceeded
2021/03/09 16:00:53 ERROR : REDACTED_ALBUM_NAME3: error reading source directory: couldn't list files: Post "https://photoslibrary.googleapis.com/v1/mediaItems:search": context deadline exceeded
2021/03/09 16:01:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 4.130 MBytes/s, ETA 0s
Errors:                 4 (retrying may help)
Transferred:        16210 / 26227, 62%
Elapsed time:    1h31m0.0s
Transferring:
 * REDACTED on…20210202_080518643.mp4:  0% /off, 0/s, -
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…210207_143752192~2.mp4:  0% /off, 0/s, -
 * REDACTED on…20210208_170622523.mp4:  0% /off, 0/s, -
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_154841544.mp4:  0% /off, 0/s, -
 * REDACTED on…20210209_155155116.mp4:  0% /off, 0/s, -
 * REDACTED on…20210209_163041688.mp4:  0% /off, 0/s, -
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:01:10 NOTICE: REDACTED onwards/PXL_20210208_170622523.mp4: Removing partially written file on error: context deadline exceeded
2021/03/09 16:01:10 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	github.com/rclone/rclone/fs/operations/reopen.go:28
runtime.doInit
	runtime/proc.go:5652
runtime.doInit
	runtime/proc.go:5647
runtime.doInit
	runtime/proc.go:5647
runtime.doInit
	runtime/proc.go:5647
runtime.main
	runtime/proc.go:191
runtime.goexit
	runtime/asm_amd64.s:1374
2021/03/09 16:01:43 NOTICE: REDACTED onwards/PXL_20210209_154841544.mp4: Removing partially written file on error: context deadline exceeded
2021/03/09 16:01:43 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	github.com/rclone/rclone/fs/operations/reopen.go:28
runtime.doInit
	runtime/proc.go:5652
runtime.doInit
	runtime/proc.go:5647
runtime.doInit
	runtime/proc.go:5647
runtime.doInit
	runtime/proc.go:5647
runtime.main
	runtime/proc.go:191
runtime.goexit
	runtime/asm_amd64.s:1374
2021/03/09 16:02:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 4.084 MBytes/s, ETA 0s
Errors:                 6 (retrying may help)
Transferred:        16210 / 26225, 62%
Elapsed time:    1h32m0.0s
Transferring:
 * REDACTED on…20210202_080518643.mp4:  0% /off, 0/s, -
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…210207_143752192~2.mp4:  0% /off, 0/s, -
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_155155116.mp4:  0% /off, 0/s, -
 * REDACTED on…20210209_163041688.mp4:  0% /off, 0/s, -
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:02:16 NOTICE: REDACTED onwards/PXL_20210207_143752192~2.mp4: Removing partially written file on error: context deadline exceeded
2021/03/09 16:02:16 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	github.com/rclone/rclone/fs/operations/reopen.go:28
runtime.doInit
	runtime/proc.go:5652
runtime.doInit
	runtime/proc.go:5647
runtime.doInit
	runtime/proc.go:5647
runtime.doInit
	runtime/proc.go:5647
runtime.main
	runtime/proc.go:191
runtime.goexit
	runtime/asm_amd64.s:1374
2021/03/09 16:02:33 NOTICE: REDACTED onwards/PXL_20210202_080518643.mp4: Removing partially written file on error: context deadline exceeded
2021/03/09 16:02:33 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	github.com/rclone/rclone/fs/operations/reopen.go:28
runtime.doInit
	runtime/proc.go:5652
runtime.doInit
	runtime/proc.go:5647
runtime.doInit
	runtime/proc.go:5647
runtime.doInit
	runtime/proc.go:5647
runtime.main
	runtime/proc.go:191
runtime.goexit
	runtime/asm_amd64.s:1374
2021/03/09 16:02:49 NOTICE: REDACTED onwards/PXL_20210209_155155116.mp4: Removing partially written file on error: context deadline exceeded
2021/03/09 16:02:49 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	github.com/rclone/rclone/fs/operations/reopen.go:28
runtime.doInit
	runtime/proc.go:5652
runtime.doInit
	runtime/proc.go:5647
runtime.doInit
	runtime/proc.go:5647
runtime.doInit
	runtime/proc.go:5647
runtime.main
	runtime/proc.go:191
runtime.goexit
	runtime/asm_amd64.s:1374
2021/03/09 16:03:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 4.040 MBytes/s, ETA 0s
Errors:                 9 (retrying may help)
Transferred:        16210 / 26222, 62%
Elapsed time:    1h33m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163041688.mp4:  0% /off, 0/s, -
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:03:22 NOTICE: REDACTED onwards/PXL_20210209_163041688.mp4: Removing partially written file on error: context deadline exceeded
2021/03/09 16:03:22 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	github.com/rclone/rclone/fs/operations/reopen.go:28
runtime.doInit
	runtime/proc.go:5652
runtime.doInit
	runtime/proc.go:5647
runtime.doInit
	runtime/proc.go:5647
runtime.doInit
	runtime/proc.go:5647
runtime.main
	runtime/proc.go:191
runtime.goexit
	runtime/asm_amd64.s:1374
2021/03/09 16:04:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.997 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h34m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring
2.4. From 1h34m until 2h, three transfers seem to have hung indefinitely until `timeout` kills rclone
2021/03/09 16:04:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.997 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h34m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:05:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.954 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h35m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:06:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.912 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h36m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:07:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.872 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h37m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:08:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.832 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h38m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:09:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.793 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h39m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:10:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.754 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h40m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:11:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.717 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h41m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:12:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.680 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h42m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:13:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.644 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h43m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:14:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.608 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h44m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:15:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.574 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h45m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:16:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.540 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h46m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:17:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.506 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h47m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:18:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.473 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h48m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:19:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.441 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h49m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:20:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.410 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h50m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:21:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.379 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h51m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:22:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.348 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h52m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:23:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.318 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h53m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:24:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.289 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h54m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:25:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.260 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h55m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:26:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.232 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h56m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:27:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.204 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h57m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:28:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.177 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h58m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

2021/03/09 16:29:02 INFO  : 
Transferred:   	   21.769G / 21.769 GBytes, 100%, 3.150 MBytes/s, ETA 0s
Errors:                10 (retrying may help)
Transferred:        16210 / 26221, 62%
Elapsed time:    1h59m0.0s
Transferring:
 * REDACTED on…20210208_082915459.mp4: transferring
 * REDACTED on…20210209_163602964.mp4: transferring
 * REDACTED on…20210209_163931600.mp4: transferring

timeout: sending signal TERM to command ‘rclone’

Observations based on run 1 & 2

  1. The "context deadline exceed" doesn't seem to be the same amount at each run.
  2. In run 1 we see rclone not exiting even though it is not transferring anything. Can't see what it's hung on.
  3. In run 2 we see that rclone never clears 3 files that it hadn't even started to transfer when --max-timeout was reached.

@ncw If these logs and experiments are helpful to finding where the bug or problem might be then I'm happy to keep adding more since I'm probably going to be running this for a few more weeks still (I haven't even started runnng sync on shared-album yet).

But if you already know where the bug is then I'll stop spending time sharing these logs :slight_smile:

Also please let me know if there is anything you'd like me to try in my experiments!

Thanks for your logs.

What would be helpful is if you kill -QUIT rclone when it is hung and collect the backtrace which will show what rclone is doing.

Or alternatively if you want to not be quite so vigorous then add the --rc flag and collect this log curl http://localhost:5572/debug/pprof/goroutine?debug=1 this will show all of rclone's goroutines and what they are doing.

It will be quite long, so one log when it is making no progress on the files after the 1 hour has elapsed would be great and if you can get one a log when it appeared to be transferring no files, but wasn't ending.

Then I can see if there is something specific about the google photos backend which is causing this.

This will be easy since timeout allows specifying the signal to send (by default it sends TERM). I've just set this for next run:
timeout -v -s QUIT --preserve-status -k 1m 175m rclone [...]

I decided to extend timeout from 2 hours to 2 hours 55 minutes (175m) to see if the extra time somehow allows rclone to finish neatly. This is the max I can wait before rclone needs to be killed because I can't do longer than 3 hours due to the way I have the cronjobs scheduled.

I have also changed --log-level INFO to --log-level DEBUG to help see more info. Will be very annoying to shift through the log file but maybe it'll provide the necessary insights.

I've reverted my rclone version to back to stable (v1.54.1) so there is no confusion when I report back (I have been experimenting with my own changes as per https://github.com/rclone/rclone/issues/4504#issuecomment-795526121)

Question

Should I also add --rc as per your suggestion? Does it include anything that's not already covered by the above changes?

Sounds like --rc is for debugging interactively and I can't guarantee that I'll be around the next time the cronjob kicks off.

I've got a new log to share with debug + backtrace.

Command run: timeout -v -s QUIT --preserve-status -k 1m 175m rclone sync --transfers=10 --max-duration=59m --retries 1 --timeout 1m --fast-list --gphotos-include-archived --gphotos-start-year=1900 --log-level DEBUG --log-file=REDACTED.txt gphotos:shared-album shared-album

I've uploaded logs from 59m until the QUIT gets called by timeout:

Pacer retrying non-stop seems to be a big thing that stands out to me.

Hope this helps!

I'll turn off verbose mode now for my next run (happy to leave the backtrace in as it doesn't clutter up the logs).

Here is another run which did finish by itself. In this case I had run out of API quota starting at 5m:

It's still not great that it took over 1 hour for rclone to finally give up and exit even though API errors started at 5m into the run!

That is an alternative way of doing it.

I analysed your backtrace - condensed it looks like this

1: semacquire [87 minutes]
    sync         sema.go:56            runtime_Semacquire(#17)
    sync         waitgroup.go:130      (*WaitGroup).Wait(#16)
    sync         sync.go:430           (*syncCopyMove).stopTransfers(#15)
    sync         sync.go:865           (*syncCopyMove).run(#15, #21, #11)
    sync         sync.go:1078          runSyncCopyMove(#7, #21, #11, #28, #9, #38, 0x3, #29, 0x4428ae)
    sync         sync.go:1084          Sync(#7, #21, #11, #28, #9, #38, #2, #3, #45)
    sync         sync.go:55            glob..func1.1(#45, #21)
    cmd          cmd.go:250            Run(#18, #13, #55)
    sync         sync.go:53            glob..func1(#13, #20, 0x2, 0xe)
    cobra        command.go:854        (*Command).execute(#13, #19, 0xe, 0xe, #13, #19)
    cobra        command.go:958        (*Command).ExecuteC(#12, 0, 0x406325, #24)
    cobra        command.go:895        (*Command).Execute(...)
    cmd          cmd.go:543            Main()
    main         rclone.go:14          main()
10: chan receive [0~3 minutes] [Created by sync.(*syncCopyMove).startTransfers @ sync.go:422]
    pacer        pacer.go:159          (*Pacer).beginCall(#30)
    pacer        pacer.go:196          (*Pacer).call(#30, *, 0xa, 0x40, #4)
    pacer        pacer.go:216          (*Pacer).Call(#30, *, *, *)
    googlephotos googlephotos.go:939   (*Object).Open(*, #8, #31, *, 0x1, 0x1, 0, 0, *, 0x80)
    operations   reopen.go:96          (*ReOpen).open(*, *, *)
    operations   reopen.go:47          NewReOpen(#8, #31, #10, *, 0xa, *, 0x1, 0x1, 0, 0, ...)
    operations   operations.go:440     Copy(#8, #31, #11, #28, 0, 0, *, *, #10, *, ...)
    sync         sync.go:395           (*syncCopyMove).pairCopyOrMove(#15, #8, #31, #27, #11, #28, *, #16)
1: sleep [Created by pacer.(*Pacer).beginCall @ pacer.go:166]
    time         time.go:188           Sleep(#14)
    pacer        pacer.go:167          (*Pacer).beginCall.func1(#30, #14)
1: select [Created by cmd.StartStats @ cmd.go:355]
    cmd          cmd.go:359            StartStats.func2(#39, #25)
1: select [Created by view.init.0 @ worker.go:34]
    view         worker.go:276         (*worker).start(#26)

You can see the 10 transfer go routines and they are all running Copy which is in turn calling NewReOpen to reopen a failed transfer.

The transfers are all failing with context deadline exceeded because the max duration has been exceeded, however they are being retried because that is a retriable error. These retries are taking a very long time though since the time between retries has gone up to 16 seconds. I think also that these might be retried 10 times also so each failing thing is being retried 100 times at 16 seconds is 26 minutes.

So I think what is happening is

  • the context deadline exceeded errors are being retried when they shouldn't be
  • NewOpen is doing --low-level-retries and also so is Copy so it is doing the number of retries squared...
  • the time between retries is 16 seconds (that is according to google's spec)

I've attempted to fix the first of these which should fix all the problems - can you give this a go

v1.55.0-beta.5251.85cc93c20.fix-context-deadline on branch fix-context-deadline (uploaded in 15-30 mins)

If that works I'll put that change into all the backends...

Built & deployed for my next scheduled run (in ~1.5 hours). Will report back with success or backtraces if timeout ends up calling QUIT on it.

Success!

Relevant log bits below as FYI. I ran this at log level DEBUG but for the below bits I'm only showing egrep -v DEBUG as the DEBUG messages don't seem relevant. If you want to see them please let me know and I can upload them to Google Drive again.

Starting info:
2021/03/11 18:30:01 DEBUG : rclone: Version "v1.55.0-beta.5251.85cc93c20.fix-context-deadline" starting with parameters ["rclone" "sync" "--transfers=10" "--max-duration=59m" "--retries" "1" "--timeout" "1m" "--fast-list" "--gphotos-include-archived" "--gphotos-start-year=1900" "--log-level" "DEBUG" "--log-file=REDACTED.txt" "gphotos:shared-album" "shared-album"]

Also: 2021/03/11 18:30:01 INFO : Local file system at /REDACTED/shared-album: Transfer session deadline: 2021/03/11 19:29:01

Logs from 59m until end:

2021/03/11 19:29:01 INFO  : 
Transferred:   	   24.687G / 24.687 GBytes, 100%, 7.239 MBytes/s, ETA 0s
Transferred:        18506 / 28524, 65%
Elapsed time:      59m0.0s
Transferring:
 *  REDACTED_Trip/IMG_20181119_123240.jpg: transferring
 *  REDACTED_Trip/IMG_20181119_134444.jpg: transferring
 *  REDACTED_Trip/IMG_20181119_134450.jpg: transferring
 *  REDACTED_Trip/IMG_20181119_134500.jpg: transferring
 *  REDACTED_Trip/IMG_20181119_134507.jpg: transferring
 *  REDACTED_Trip/IMG_20181119_134816.jpg: transferring
 *  REDACTED_Trip/IMG_20181119_134822.jpg: transferring
 *  REDACTED_Trip/IMG_20181119_134828.jpg: transferring
 *  REDACTED_Trip/IMG_20181119_123713.jpg:  0% /off, 0/s, -
 *  REDACTED_Trip/IMG_20181119_134836.jpg: transferring

2021/03/11 19:29:01 ERROR : REDACTED_ALBUM_NAME_1: error reading source directory: couldn't list files: Post "https://photoslibrary.googleapis.com/v1/mediaItems:search": context deadline exceeded
2021/03/11 19:29:01 ERROR : REDACTED_ALBUM_NAME_2: error reading source directory: couldn't list files: Post "https://photoslibrary.googleapis.com/v1/mediaItems:search": context deadline exceeded
2021/03/11 19:29:01 ERROR : REDACTED_ALBUM_NAME_3: error reading source directory: couldn't list files: Post "https://photoslibrary.googleapis.com/v1/mediaItems:search": context deadline exceeded
2021/03/11 19:29:01 ERROR : REDACTED_ALBUM_NAME_4: error reading source directory: couldn't list files: Post "https://photoslibrary.googleapis.com/v1/mediaItems:search": context deadline exceeded
2021/03/11 19:29:01 NOTICE: REDACTED_Trip/IMG_20181119_123713.jpg: Removing partially written file on error: context deadline exceeded
2021/03/11 19:29:01 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	/home/ro0t/Downloads/rclone/fs/operations/reopen.go:28
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5652
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.main
	/snap/go/7013/src/runtime/proc.go:191
runtime.goexit
	/snap/go/7013/src/runtime/asm_amd64.s:1374
2021/03/11 19:29:02 ERROR : REDACTED_Trip/IMG_20181119_134507.jpg: Failed to copy: failed to open source object: Get "https://lh3.googleusercontent.com/lr/AFBm1_Z_WzuDb6LDHP8KHrl3Fmk1zVPxxSLdouc3Gy9OQjPegrKgMqpX7-zAi5vMxFzPCcC0g17a7PlPyQs805qGj1PdHj-uDh4AwnM0o4T65g4dsh3pIOMhGrMFuzT93Qm_VYeBSHuF-ZXbH1592uiij_bZyKD_irnIAAQZ9u9EJcXmcMdz_SLbDTT0auslj-bxrgHeOuvFYvEOt20h_i1hL1tgMz3SOr18PWLWNUAxPA8emFg88WJaEuf1PdbYTHZPyYZfSiAZOZxwb4-jMsuoYRXc72s_zev-yyXm8LzbWnDskS8yw4UzqHn3EscnB7dadF9yvTHh-LyxUf5lsEKZ4ZsXu8cgJfP7EF_dGcljPLZHi0KAESy3isbzhd4IgDE8LTfGFYaMniWcJ6B1-vwLMtAb7oIPYsE7Cd6rx0WgQGQQ1FKSoIyQmwkiHaMwaUwYVRM8F2q645ZPB0h8J7hqiDtAVdXUubuvTXCO4TLJQjNLGeP6yKWDfkMd8eyYv8foyu20nfoKWhyJmXuO0_bGTYKDy0zISN6NPkddH1FCCqd9sR5IsQMfqdFYWHlGN4rqsK7dITn8uDP4H1qYY2UD96RQapK_c7VL7pSeKf9IdDKW3INVys-28qCS6nKsV2gcebUBp7Vm34zTL1vQpL4tdG6Zw0diJhnC8f5ik_T6se-dit5vm_GkJejM2e3mk8mB44ov6XrEIc0DbTfrzt-YXFZ9Z4TN809u_u5TRaM8Ohw_6c__qyocd4QPPEGGWjdDZHePMHg0KrXdLYcjO8w4JNtRyMYYSxJUaUxc6rLD0uMT9WfbI-Ov04fvUYUHLEDTdepR5dFdo1R0w3lk_w=d": context deadline exceeded
2021/03/11 19:29:02 ERROR : REDACTED_Trip/IMG_20181119_134500.jpg: Failed to copy: failed to open source object: Get "https://lh3.googleusercontent.com/lr/AFBm1_bWYpbbBjxaEVCUySybgQmRbOUQc0bm0C7dGQMwuemmjfhHYLp0LXB3Wm98KvUayxD9GWbW_w8bwu7xccaBpBWcMRbqP0BoAzAiWQIXNYN6QsyTGnin2WSsseAcgf_0YbbgUtRBWgVXRhHCxegdHM7IIte9p47RSFclTHoy9Jq9ihg9Rv-Iz6SfkqogcbwH785SHFhpYMYxz8bMtPm7Jxk8G8uUdwVrIXY4q153AmkA9Mj5lai1BkhW3lRQUHj5jivB1q0yWWIOyorsLX1tlbpP0W4porwlGvJ-Gg9cPLHnLzvKddEH4rMCVk8UtsTfioFfNCCFgHK5H1LE6M6dwZsvXWjOkkQU3gVyjT_QVcO3HPpkJ_dYAn0Jtf-knj7C8c-RuREqHEaOspdNSKsKHEQtvXPHi7PyYleAXXXErFfrCjPm3W8PlWkfI3XuMZRxJc-tyFHbCwVSaWCNrkSokmATCjCJ8D5XHgjndty_AuZa6v3LUxeEx5jn2vxfY_kuBOjzBpSE3tMDDk3BjDoR625lKQWFikMJeAcwJQaTx12uv-l1MHDjbxLzL2D5cqWn2fZihT26yWA1xFDSePduAbKZXWQF0p3skCAM8vJeR9v7V4PCtA_NvdYmWXdGKn2Q96T76uDWhOHP-8mORieL6ww_YTr0Bl-Y22j8vDWaC2qvxOLaACjz3HbOgqBMtPovP6SHi65WCE1Tq3L4AcQnUUziaueH0pgXUQUc8z14sHs_W7bQWR3UOnG5ZcnDEQ52NSrlpT1BLRFHWeYR6FY1nMkV7gfCI9mMFXn8YFSxaFeFi3kFuXtIByr3FZW6od35gEKOWDcdaynOOAX2rA=d": context deadline exceeded
2021/03/11 19:29:02 ERROR : REDACTED_Trip/IMG_20181119_134450.jpg: Failed to copy: failed to open source object: Get "https://lh3.googleusercontent.com/lr/AFBm1_bwjnhIgOjoKH7L9TzbYazjCPEDcbw8W9FyW7K68Xa61scPJ9pTmd0dfaloJsKHCoL-KSDarMB-0GIbnjUjaoU1A6S-PVUNdKf7sXiOOAUNhBpw_wKoQbjY98C3FktsVEiPDL46R2AAvcIUNtPJ30QdhkdaRRj6_uz0z_CsVoptC5uj9LAEN2W4wMAcPiFuGFO1-Lgtqtg6wCFRotrR28ww3zNosPMI78sFF1DTHMCsTeu9xVwGXtryxdyx9UAwxI2AzhKu-wzoiv5N_yJrkdJsbDnX3jk4U9YqWmaHkZZg-iP5nXGFhu0QgjTONmA9X8yoZwCoS-2eiqUQoMwzED7_FPaGCv6345rlZSPj1pearjZfW50B_gXOErEtCmH30aHvC4H5_lujkHdGRhlEwqu3YqPjS5kSN5VczSN4lnCFIAW62u7-iAkDAieKOvNHI5uUSnL4xbUevXi8S7bZABYGs587jhHiWvIEKnjLT3hHxOFiFkPMcg7xIrJn1f7q9wzXszxAr6RWF1QhAe4ZTI8y9PHr--Mlu4HDJwAD0cVBXksGSVzrgCQYmoA2PePGmQv-CmpiM6VmR89vSywfjUzhu-lUUv2AcR1UPGAMxWU4RdOhno2mIH7EheCN7x5TISqatmvSFS0Ddx2SQSwpHlc1a8G9CdqkzP4dVLWlGfKrsPghE-I4Qh4KeTnXQ3WoQYgQlJ0sBUZ6SpqOi7jT04HbZWzx3bXnGZ5uJufK0Mjx5rfboV0nam-0a797nYzhmNHymr728NnHShOKWYF7n4bkaJt2Fyv6uEEyzmd3w7Vh6_nJ4n8YptUoND8ZaUrQ6tfiKN5AvHfW6x9BLQ=d": context deadline exceeded
2021/03/11 19:29:02 ERROR : REDACTED_Trip/IMG_20181119_134444.jpg: Failed to copy: failed to open source object: Get "https://lh3.googleusercontent.com/lr/AFBm1_Z1GUUEQDBkl5bcPWs_rCF2Mda2CdrAPs9tgIyyXxv4Zc_GPtrJO42eqX9YQgUB_vAxayIAAV6yozDYbPxpZomHqqdhoAsL5gS6PItHD1PBJhqPFJMpJXcLaw-BVX6eLaGwnPyj9G5tMMOOgy1E88h9ggmjJqDXIzIgZnreVWs-e2YmR3r4muHGmV7jmdsFDnVi4HY1_FctA9wBw4KkmmqdzTtZGpo4POJ4VLeUV5tgXq_3vUBTdj69XUgX70qgrjdUEBZlxNF2SnVIi7ZE4ODGah3VtGENVTYopEJlLiAL0kCGE9LNNItUv1ECkSc787kdAaxTi3UEHmaIFh05rGuXN6HLYBCkcgZ43FFTlw77HPzvSLO2CLGlZGMIOqT9XsD841GuGWjm6RH5WMHrGG5afvM0RsjrjceZ60o6R8ak8ue5EJy40PVjXq77osfwJC-nzvgQOGj9B8wwXQUM93JhruUpIxx355EzwpMQeA5at_hY2K04GdgXpQgcrUhArWU_eI1jw4MkpotyBqusk-N0gQ210I5pY9BHbKiVEFOjjYadCVYaogzJH2gjte7ppNC_dkd8V3teoV6fGcrdWnUhQDmpKUQXlWxH9y-31J4BYwMhAVD3Z4d4RiK-Fo3q82ojhDOrRmN5Ch2vIRnwM578Y4jxWvFt8P_A_FFG5pdL7DBRMA7fJA39O2kEKH9u--bSYVpA1gBHVZWV0OxjrjHl9bcuwuOe2hM8xYDSLzO-uVdykzAyMwpHJkOHUuL2wt7CBuYeCMczQZ40RlwbKHPQyeP9dbjale4QR6qjlUHqBkbShetK34NLnc9Cw4x4IgtLOeLqC_DKqiatTw=d": context deadline exceeded
2021/03/11 19:29:02 ERROR : REDACTED_Trip/IMG_20181119_134836.jpg: Failed to copy: failed to open source object: Get "https://lh3.googleusercontent.com/lr/AFBm1_Z8MJ40IVLlYYFkafFqjGAXI9szs2zN3LBqAy25blshRhvAXFW0tJcZcsBu0RlYjCjEAF_AYrd2wNQW_Ahrvl4CCMTUMJrgmEW0TzCz5aSlthcu5lKpnBf7BSPZnm9tqw6iOZH3ETwv7nsxjPRbUr4XznZuydeLzRlIUxSZqm2BDIGGnlYD-Mj41V6kW75GbDFcfF_ZEezbvSlidJQNKAQ-CThL1qqvfmynIwM1HnH8ENdHyrSuawAbtkeE7spCiKjTcqELyKVSwjvZQU9Gt86um1TRwlvNM1wDSUBRhPdWvNJA_gz_axkprEM5nEgQd6xa37aMVcZVwhNqTbFEnCBOwvBsP7WGDNIEXcv8Fe0JgBN4yIfd2v2Glol0Se7E7XK9XIwjdsA-saAe-g1smzsPf3YYJBVzVVQCutSF1600jTM-y9Hx7TICRkDzIWpAMG2WR-PVYziH4GSfwKrUBINlWIfz571BAAbRjYZX0Gjmgv2jruBFlvarlHSJX1ruwB2_szz0NLKvVez4w64htkJ47AcZmOhCxfsLgSV0Gmr6W68yGCGHht0Pr1E5shno4KrKeW5796o-mw1gyinq5FJEVz7isnZF_L2xvwOgPAMtZrnedKkp_64ckbplGyVpGf05JBbkoZHu0P0d59wE5kEmhX52iHTN0m9cI_JkznZ-cTMgHOPpjTJ6p4MH1mF7GAYkocdEF3xltrKgPK_0Qo5WjZ5kypW41DQDHpjhAPyVRHy4XCak_HfE_5Qcxp0dXWfraJmDVwnBjeLJkgE5oHlLzr5lDu8wPtQ4GhFFzB_jncT0rB_1uhvV-R5zgYwmmftin4w_ZuWRO4DeVg=d": context deadline exceeded
2021/03/11 19:29:02 ERROR : REDACTED_Trip/IMG_20181119_134828.jpg: Failed to copy: failed to open source object: Get "https://lh3.googleusercontent.com/lr/AFBm1_aGWQiUPgzszroXQ7_iGMKYxgp9eq4ki0I-qlSbwIWUH6kAfJQMAfBJdktbT5QoUX4dMntJsWPIr4hpQJIZIo_Nrvt-i3M-MjV65XkMkRyOIF9EBkwD9db62DvEGfVZu56bEQq7rWcbVxHc_gBZoYFZeq3EWB-4P5Wq6db9ACEmGtRTrWj9tsXleEvvXWl8NG7O9Dbcdg6gyGnw6f0Beyng7W1B7t7aG4eS90-BVXljmKtkbjL8L2qXYhxQJftZYLmqW_S438jatI7u0Izfycqx9uRYUUUs_aPS9foX5wcl9jA9idCA8PAOd3l8i-CyC3CDOk3715VJXIEtFsKCEwBd8c-IqFzDMEcYcHwzN_CJsf9bTDA3uYcISBIUfqek3KoTqVgWCl4aOcney74ozvAsPuisefTu9SEXFEKbU-3TqEoJB9ufl74H831_wY3n8XE60TdzwjmOvtUo8NcvO-i10Hee1_qRWEiUchzDqHElZkxdrstBw7AJPAJGkwoq6B5fOAUN0E26dGjzirFgtGgSIOEHjD31mFk41Rfp9Cz_Pen1UTfWGsga5LWuGA3GhM0I6jQe5wuJBEwHC7sQ6wcjplbawDzFGJ3z7fTtP9EXUwQIni9LbZdlFBp6okhuUbdyM1P-0F7T_ax1PUNECwItOXv0nM4bJcvHLG3NYYs0Or6CXsIILAwHaQlMcxu6-ERxUE-WWyWGdCNddDVJd1Hkd56oV5C_yCzP1GpZFLVknb5gloxfywnFsz8wsyAu6SYwYP8jgUjTwHU42XkH7fPe592waTgGsDoNaXkpb0JaOvNUyPxJZ_oeSr2915lwtIFgulIwHmC6Bw9hhg=d": context deadline exceeded
2021/03/11 19:29:02 ERROR : REDACTED_Trip/IMG_20181119_134816.jpg: Failed to copy: failed to open source object: Get "https://lh3.googleusercontent.com/lr/AFBm1_ZtW8qpHnFW_nDQWt9tI56kFubJU-zSFWWoqEE3H_KBevuz160EHW09bZCC-wsB42Bptqx2LNvt1wMu2bJAzWLxYVjtiApSCF3TusCS-EWNuyibh8A1GPtG0TF0JLtYfKG2vGX1gbPijLGLNBwPJuLOpoxElv7myFPFqKjgEoC2k-1zTV8t3ZcRYtrKDmilknlwNEnhwTCfL9A264pwJK7qVxtQZJ9yW5AmY0y0juBXT4J7FI6orF3jXKk60ImKxH7W8rYNWf2Gn_2_C6h21xBlH2-WS8Zo5WcW0G66THLMIXsfa9wac2HPiYFt2rb1Kl-5tnDyeYr1H55dGkmv3YsJ-YYu8i4Cwdgu4jnl0p33kNP3zdVZeWAH-Q7LMPtbWzHhONULf6hnxOWq8VuBtBMDm3eSc5RiEhN3BxnrQ-4-hBoJfqcAwyVi-I7p4pSHcCEF3cJWL8GDb3fERas0_hWdgAXILUhFUXmNeeppwHsWaXB4_nv9WreDv4iWGZsDioTnApCEWQLX_RX0DLT8V8qid7FlVCgb_ipIxR4PEfshiErcY94Odb-70Zsq2QsXbQHlh8zzAgO_8h9IAcjlXHlbPrJWSnrmh7xKIrWgyS77c_IAh5NQv5WY4fq61z5-Jmwwx1mdK090aJ38fX6OFj37ZD2qx8P9nPYZF_YmBgabVNFRdv85H3oJN6Bi_d-qjGl-Z0VapUypO1P97a9VzF6XdVBMITRkHJuQXAo6DoWZOOKHRgzBU5-fD3mKexmRBosmeBRzaMoQEMOJ0LNjaTiI3k5o6LJ_6ny7utTQhUNutTyJTjQYnh7fCMMvXsd35EE0DM_L6X8DWXB5RQ=d": context deadline exceeded
2021/03/11 19:29:02 ERROR : REDACTED_Trip/IMG_20181119_134822.jpg: Failed to copy: failed to open source object: Get "https://lh3.googleusercontent.com/lr/AFBm1_Z7IaLckeaelYDDRKrJW7CgUXEWx02RVHgv13AmHCsfECdyqYU9xhnf2IFsOqn78vrUspcTgNzVNuqgFvB5chIVO3tKbwOWwKBkD27qR9lUOclCQ3AscLLmEGgh5akFvzXeWZfjpXd5rIRM7-cwVwJI461N1JhsKDQiaAmVsLPJ-9IzWrOPna-QNyEGqvkZBZ-P1QP4Et2xhndHd9KqQOBVF3aFFCRbEx6cGiKLJ81a5szk7kLbntqTdAKX0itT-CQDBYuOOvgSQYYcviHqgtsKr43wnakHbO_Kf4mpNIzz6A5YnVwuARUrgu4-vbtJwxVywieeG_8WG7q37IeFfpauwJs1eNuX9j07kscdzRwx4OVzXXBWHa8ChpK9NK9xsNNEUSyWot49HohzwvlZTzH81Yi6MbikXK5-CemOaYJ0SnJXDssxkFb6vIrl6HbVtnQNFkCVD8hTB9dHDlWnh0r3PQV-lVEJMDhv-2-wUbxJBb0iixntgXOUceBItnaBSBV4H5XEW4fEQxTBcuDaWCGYg01O6SHCxWwI5mnSnRNWjTpWhS10cvYGe2JXiRNKVbM4RRlJcIWOGRWKkv3pCgjenmNCyinMFznKxnyjr26AzwvQcvqQRpgDHcWov4AoMwuLGvfcaFgrGr4jToeKoPllUIf1lBB7Oq39taxAge0wnz9XXCVvnOJH9LmBcdfZzfyZuOzbN0atsNm3IqN8EW02JL18QhhYt66jzHDgGLYInFANJlY0wui04M-Sl77n2y_w-ig1fPCYqzUvCVBUUhal01Cddg6zW8rSTndS1Oq5EPKuOfKvrXK_CCkqdqWE9ZHhVwF5GwoT_gbHOg=d": context deadline exceeded
2021/03/11 19:29:02 ERROR : REDACTED_Trip/IMG_20181119_123240.jpg: Failed to copy: failed to open source object: Get "https://lh3.googleusercontent.com/lr/AFBm1_bAFYDxfDxj76tYX4VrxmVhboQlWHN9JOJ5zWCpxblDBeosD0WDJgnKeWhoP67LsyChdIVrHwMmBhQGkyctpDr-gi3x-n7e0EFNkffNoYHktX4CgkbuNHMDe5C2yS-MbXSoyCcdndq86Nip0WrWg27KXheAkyOBxHIpWcK_60sylvBlkhX6aQPorO-Ses3G1EHB3CGQJqHok-tD9gwQZPB3IDQw_nwXLe1LWhxPTyMrl3TdpzCyO903s6Ex5yCCLd68DRzoOlv2zdAEvIFllpHFJuiX8Si_2DUSLmDZm-Ck3LGc1qf9h5kxJapfX-AKLCqog5g5zbN_EySSPdMmpIHKIK-3q5E0mphlrhNXTzGP5Yx8LgsRSyvmgSlQTy9s8b2bpy_8YMqsp4TB7LGj2vTseW5Iy1qeSlK8udEk3yvoUHu-egnsVgTaAAYXtEJOxL7tLJOhJ58_YTukm5d9ATizZJ1UsNhf4h-IqAPz5qSMGjCXwTXXijBM2tTBms90bf7kuFtx0f0uMz8AnRne5ZQ0UiXDutr2rkFv1whdYJvxc0Rn_yQWxJ_koO4fEW04EPQMIoQHQjvSLd4gy7reR-hZpirltpx9tbLzsYdI7nKgpa6DLAuxYjsAn1Yf6ozqdyQgbDNo5657GhZz_Cx2auHToMVjy7hzANu_Eod4u13BA4D7qr5Qd4MfA1whLvr4DyuCjE3XoBU9Bs8j227YFdTha-tCsbOBh1h7_uSdpOrX6LIZh2MtA1jAjn4DlgAALH3wyMUcCh0Y1U4BUzyTrFOa7h0fwBXnQ7YCXoTDKii0b-xldmwQ5QuYtOTnZBW1ChQwByQAz9XVCpaoyg=d": context deadline exceeded
2021/03/11 19:29:02 ERROR : REDACTED_Trip/IMG_20181119_123713.jpg: Failed to copy: failed to open source object: Get "https://lh3.googleusercontent.com/lr/AFBm1_ZL-Uy5RwVExjT7Iwy04R-cLLXXGX_sK1k59DhpmP9oDlmtCINsxRgf4sk5LJ2glCm26VFyEvkZJ91pM5oWlogvuYs0Ef4oev76FYADPlRznTpZq47xIMWzLjVb3uMsnJ1Xxi1BUcoZdod3Qsd_ltdT_4w4UyEC5QCArRrdc3-et_z5mSx6uzfgactWKkrrpnPWiaNLQ_kRlaDV1Ijdg8KwaTQNgAnW_LKVEqjbIZJrRfNV5N8sBgGhYwbotLsYD6izreadCGg3hFqQF21wyJYcx2nMQZmaJ-eoC6GMgDU0aYsSY3zcKXdjRQw96O-H92ircAr9D00Rbkc0uhrubHEQJ61suh53QwcMIzGeBaUrgzw62dxbSIo1mHW-h6pCElpztFQSIeQgFBsHT9j3FeQXRsslZFDMffsC_dS6d_KPS01mOwZW-DKVc-seGBbjQwQuAmYBwYdXXRANeHNO6HiSgRYDctGnoGaChljkyByjM9gpo302O6vbn7XEXNCJI0bjb1g4DMJegsvpxLCd3SuXP74g7DPSwNl53e9O6A8pPi_AoWS_7c_FdFhwSQy43VFW4uYEmX231JB3-j8iO_VYViV8Aqg5p8E-lJ528PV_W8_RsW7dhzIs-EaX2oLca-uPMCQQTzAbH_kkFoecHa_dBU-EBryORkzaU-LyuLbfrvVe-f8M-jL5OdcVpJfnGjFdXy-VukO2Wkz-3KSFM17HGv4vd8UfHtyWf8AMKVq4rapmWUggw-NOgdLHvVTseiMuZEIqk5r_50MMVR31EFYA9FGu-zcAeiCKzrIdgljqaldLr7R2CWCOaleiHRHUyuyxOCieh3w4GHVxhw=d": context deadline exceeded
2021/03/11 19:29:02 ERROR : Local file system at /REDACTED/shared-album: not deleting files as there were IO errors
2021/03/11 19:29:02 ERROR : Local file system at /REDACTED/shared-album: not deleting directories as there were IO errors
2021/03/11 19:29:02 ERROR : Attempt 1/1 failed with 15 errors and: failed to open source object: Get "https://lh3.googleusercontent.com/lr/AFBm1_ZL-Uy5RwVExjT7Iwy04R-cLLXXGX_sK1k59DhpmP9oDlmtCINsxRgf4sk5LJ2glCm26VFyEvkZJ91pM5oWlogvuYs0Ef4oev76FYADPlRznTpZq47xIMWzLjVb3uMsnJ1Xxi1BUcoZdod3Qsd_ltdT_4w4UyEC5QCArRrdc3-et_z5mSx6uzfgactWKkrrpnPWiaNLQ_kRlaDV1Ijdg8KwaTQNgAnW_LKVEqjbIZJrRfNV5N8sBgGhYwbotLsYD6izreadCGg3hFqQF21wyJYcx2nMQZmaJ-eoC6GMgDU0aYsSY3zcKXdjRQw96O-H92ircAr9D00Rbkc0uhrubHEQJ61suh53QwcMIzGeBaUrgzw62dxbSIo1mHW-h6pCElpztFQSIeQgFBsHT9j3FeQXRsslZFDMffsC_dS6d_KPS01mOwZW-DKVc-seGBbjQwQuAmYBwYdXXRANeHNO6HiSgRYDctGnoGaChljkyByjM9gpo302O6vbn7XEXNCJI0bjb1g4DMJegsvpxLCd3SuXP74g7DPSwNl53e9O6A8pPi_AoWS_7c_FdFhwSQy43VFW4uYEmX231JB3-j8iO_VYViV8Aqg5p8E-lJ528PV_W8_RsW7dhzIs-EaX2oLca-uPMCQQTzAbH_kkFoecHa_dBU-EBryORkzaU-LyuLbfrvVe-f8M-jL5OdcVpJfnGjFdXy-VukO2Wkz-3KSFM17HGv4vd8UfHtyWf8AMKVq4rapmWUggw-NOgdLHvVTseiMuZEIqk5r_50MMVR31EFYA9FGu-zcAeiCKzrIdgljqaldLr7R2CWCOaleiHRHUyuyxOCieh3w4GHVxhw=d": context deadline exceeded
2021/03/11 19:29:02 INFO  : 
Transferred:   	   24.687G / 24.687 GBytes, 100%, 7.236 MBytes/s, ETA 0s
Errors:                15 (retrying may help)
Transferred:        18506 / 28514, 65%
Elapsed time:      59m1.5s

2021/03/11 19:29:02 Failed to sync with 15 errors: last error was: failed to open source object: Get "https://lh3.googleusercontent.com/lr/AFBm1_ZL-Uy5RwVExjT7Iwy04R-cLLXXGX_sK1k59DhpmP9oDlmtCINsxRgf4sk5LJ2glCm26VFyEvkZJ91pM5oWlogvuYs0Ef4oev76FYADPlRznTpZq47xIMWzLjVb3uMsnJ1Xxi1BUcoZdod3Qsd_ltdT_4w4UyEC5QCArRrdc3-et_z5mSx6uzfgactWKkrrpnPWiaNLQ_kRlaDV1Ijdg8KwaTQNgAnW_LKVEqjbIZJrRfNV5N8sBgGhYwbotLsYD6izreadCGg3hFqQF21wyJYcx2nMQZmaJ-eoC6GMgDU0aYsSY3zcKXdjRQw96O-H92ircAr9D00Rbkc0uhrubHEQJ61suh53QwcMIzGeBaUrgzw62dxbSIo1mHW-h6pCElpztFQSIeQgFBsHT9j3FeQXRsslZFDMffsC_dS6d_KPS01mOwZW-DKVc-seGBbjQwQuAmYBwYdXXRANeHNO6HiSgRYDctGnoGaChljkyByjM9gpo302O6vbn7XEXNCJI0bjb1g4DMJegsvpxLCd3SuXP74g7DPSwNl53e9O6A8pPi_AoWS_7c_FdFhwSQy43VFW4uYEmX231JB3-j8iO_VYViV8Aqg5p8E-lJ528PV_W8_RsW7dhzIs-EaX2oLca-uPMCQQTzAbH_kkFoecHa_dBU-EBryORkzaU-LyuLbfrvVe-f8M-jL5OdcVpJfnGjFdXy-VukO2Wkz-3KSFM17HGv4vd8UfHtyWf8AMKVq4rapmWUggw-NOgdLHvVTseiMuZEIqk5r_50MMVR31EFYA9FGu-zcAeiCKzrIdgljqaldLr7R2CWCOaleiHRHUyuyxOCieh3w4GHVxhw=d": context deadline exceeded

Thanks for testing that.

OK I've done that patch properly now which involved patching every backend!

Would you mind giving it another go?

v1.55.0-beta.5261.004fa1c5f.fix-context-deadline on branch fix-context-deadline (uploaded in 15-30 mins)

Thanks very much for the quick fix :slight_smile:

Re-deployed. Will report back after next run (starting in ~5 minutes).

All good still:

2021/03/12 21:02:06 INFO  : 
Transferred:   	   14.175G / 14.175 GBytes, 100%, 5.659 MBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:            301116 / 301116, 100%
Transferred:         1286 / 11297, 11%
Elapsed time:      58m0.0s
Transferring:
 * REDACTED…ID_20190512_132333.mp4:  0% /off, 654.671k/s, -
 * REDACTED…ID_20190515_065814.mp4:  0% /off, 650.390k/s, -
 * REDACTED…ID_20190521_175146.mp4:  0% /off, 644.214k/s, -
 * REDACTED…ID_20190522_202954.mp4:  0% /off, 635.360k/s, -
 * REDACTED…ID_20190523_084436.mp4:  0% /off, 609.859k/s, -
 * REDACTED…ID_20190523_144729.mp4:  0% /off, 633.930k/s, -
 * REDACTED…ID_20190525_092153.mp4:  0% /off, 664.352k/s, -
 * REDACTED…ID_20190526_082912.mp4:  0% /off, 611.605k/s, -
 * REDACTED…ID_20190526_103317.mp4:  0% /off, 584.582k/s, -
 * REDACTED…ID_20190526_114626.mp4:  0% /off, 0/s, -

2021/03/12 21:02:15 INFO  : REDACTED year/VID_20190526_103317.mp4: Copied (Rcat, new)
2021/03/12 21:02:20 INFO  : REDACTED year/VID_20190526_114626.mp4: Copied (Rcat, new)
2021/03/12 21:02:27 INFO  : REDACTED year/VID_20190526_082912.mp4: Copied (Rcat, new)
2021/03/12 21:02:41 INFO  : REDACTED year/VID_20190521_175146.mp4: Copied (Rcat, new)
2021/03/12 21:02:45 INFO  : REDACTED year/VID_20190529_160434.mp4: Copied (Rcat, new)
2021/03/12 21:03:06 INFO  : 
Transferred:   	   14.519G / 14.519 GBytes, 100%, 5.664 MBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:            301116 / 301116, 100%
Transferred:         1296 / 11307, 11%
Elapsed time:      59m0.0s
Transferring:
 * REDACTED…ID_20190512_132333.mp4:  0% /off, 638.434k/s, -
 * REDACTED…ID_20190515_065814.mp4:  0% /off, 634.998k/s, -
 * REDACTED…ID_20190522_202954.mp4:  0% /off, 610.715k/s, -
 * REDACTED…ID_20190523_084436.mp4:  0% /off, 652.677k/s, -
 * REDACTED…ID_20190523_144729.mp4:  0% /off, 621.430k/s, -
 * REDACTED…ID_20190525_092153.mp4:  0% /off, 648.054k/s, -
 * REDACTED…ID_20190526_140131.mp4:  0% /off, 646.598k/s, -
 * REDACTED…ID_20190530_072101.mp4:  0% /off, 590.840k/s, -
 * REDACTED…ID_20190530_101729.mp4:  0% /off, 603.809k/s, -
 * REDACTED…ID_20190530_171458.mp4:  0% /off, 584.856k/s, -

2021/03/12 21:03:06 NOTICE: REDACTED year/VID_20190526_140131.mp4: Removing partially written file on error: context deadline exceeded
2021/03/12 21:03:06 NOTICE: REDACTED year/VID_20190525_092153.mp4: Removing partially written file on error: context deadline exceeded
2021/03/12 21:03:06 NOTICE: REDACTED year/VID_20190530_171458.mp4: Removing partially written file on error: context deadline exceeded
2021/03/12 21:03:06 NOTICE: REDACTED year/VID_20190523_084436.mp4: Removing partially written file on error: context deadline exceeded
2021/03/12 21:03:06 NOTICE: REDACTED year/VID_20190530_101729.mp4: Removing partially written file on error: context deadline exceeded
2021/03/12 21:03:06 NOTICE: REDACTED year/VID_20190523_144729.mp4: Removing partially written file on error: context deadline exceeded
2021/03/12 21:03:06 NOTICE: REDACTED year/VID_20190530_072101.mp4: Removing partially written file on error: context deadline exceeded
2021/03/12 21:03:06 NOTICE: REDACTED year/VID_20190522_202954.mp4: Removing partially written file on error: context deadline exceeded
2021/03/12 21:03:06 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	/home/ro0t/Downloads/rclone/fs/operations/reopen.go:28
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5652
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.main
	/snap/go/7013/src/runtime/proc.go:191
runtime.goexit
	/snap/go/7013/src/runtime/asm_amd64.s:1374
2021/03/12 21:03:06 ERROR : REDACTED year/VID_20190526_140131.mp4: Failed to copy: context deadline exceeded
2021/03/12 21:03:06 NOTICE: REDACTED year/VID_20190515_065814.mp4: Removing partially written file on error: context deadline exceeded
2021/03/12 21:03:06 NOTICE: REDACTED year/VID_20190512_132333.mp4: Removing partially written file on error: context deadline exceeded
2021/03/12 21:03:06 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	/home/ro0t/Downloads/rclone/fs/operations/reopen.go:28
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5652
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.main
	/snap/go/7013/src/runtime/proc.go:191
runtime.goexit
	/snap/go/7013/src/runtime/asm_amd64.s:1374
2021/03/12 21:03:06 ERROR : REDACTED year/VID_20190530_171458.mp4: Failed to copy: context deadline exceeded
2021/03/12 21:03:06 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	/home/ro0t/Downloads/rclone/fs/operations/reopen.go:28
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5652
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.main
	/snap/go/7013/src/runtime/proc.go:191
runtime.goexit
	/snap/go/7013/src/runtime/asm_amd64.s:1374
2021/03/12 21:03:06 ERROR : REDACTED year/VID_20190525_092153.mp4: Failed to copy: context deadline exceeded
2021/03/12 21:03:06 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	/home/ro0t/Downloads/rclone/fs/operations/reopen.go:28
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5652
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.main
	/snap/go/7013/src/runtime/proc.go:191
runtime.goexit
	/snap/go/7013/src/runtime/asm_amd64.s:1374
2021/03/12 21:03:06 ERROR : REDACTED year/VID_20190530_101729.mp4: Failed to copy: context deadline exceeded
2021/03/12 21:03:06 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	/home/ro0t/Downloads/rclone/fs/operations/reopen.go:28
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5652
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.main
	/snap/go/7013/src/runtime/proc.go:191
runtime.goexit
	/snap/go/7013/src/runtime/asm_amd64.s:1374
2021/03/12 21:03:06 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	/home/ro0t/Downloads/rclone/fs/operations/reopen.go:28
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5652
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.main
	/snap/go/7013/src/runtime/proc.go:191
runtime.goexit
	/snap/go/7013/src/runtime/asm_amd64.s:1374
2021/03/12 21:03:06 ERROR : REDACTED year/VID_20190530_072101.mp4: Failed to copy: context deadline exceeded
2021/03/12 21:03:06 ERROR : REDACTED year/VID_20190523_084436.mp4: Failed to copy: context deadline exceeded
2021/03/12 21:03:06 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	/home/ro0t/Downloads/rclone/fs/operations/reopen.go:28
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5652
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.main
	/snap/go/7013/src/runtime/proc.go:191
runtime.goexit
	/snap/go/7013/src/runtime/asm_amd64.s:1374
2021/03/12 21:03:06 ERROR : REDACTED year/VID_20190523_144729.mp4: Failed to copy: context deadline exceeded
2021/03/12 21:03:06 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	/home/ro0t/Downloads/rclone/fs/operations/reopen.go:28
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5652
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.main
	/snap/go/7013/src/runtime/proc.go:191
runtime.goexit
	/snap/go/7013/src/runtime/asm_amd64.s:1374
2021/03/12 21:03:06 ERROR : REDACTED year/VID_20190522_202954.mp4: Failed to copy: context deadline exceeded
2021/03/12 21:03:06 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	/home/ro0t/Downloads/rclone/fs/operations/reopen.go:28
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5652
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.main
	/snap/go/7013/src/runtime/proc.go:191
runtime.goexit
	/snap/go/7013/src/runtime/asm_amd64.s:1374
2021/03/12 21:03:06 ERROR : REDACTED year/VID_20190515_065814.mp4: Failed to copy: context deadline exceeded
2021/03/12 21:03:06 INFO  : can't close account: file already closed
github.com/rclone/rclone/fs/operations.init
	/home/ro0t/Downloads/rclone/fs/operations/reopen.go:28
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5652
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.doInit
	/snap/go/7013/src/runtime/proc.go:5647
runtime.main
	/snap/go/7013/src/runtime/proc.go:191
runtime.goexit
	/snap/go/7013/src/runtime/asm_amd64.s:1374
2021/03/12 21:03:06 ERROR : REDACTED year/VID_20190512_132333.mp4: Failed to copy: context deadline exceeded
2021/03/12 21:03:06 ERROR : Local file system at /REDACTED/album: not deleting files as there were IO errors
2021/03/12 21:03:06 ERROR : Local file system at /REDACTED/album: not deleting directories as there were IO errors
2021/03/12 21:03:06 ERROR : Attempt 1/1 failed with 21 errors and: context deadline exceeded
2021/03/12 21:03:06 INFO  : 
Transferred:   	   14.520G / 14.520 GBytes, 100%, 5.664 MBytes/s, ETA 0s
Errors:                21 (retrying may help)
Checks:            301116 / 301116, 100%
Transferred:         1296 / 11297, 11%
Elapsed time:      59m0.2s

2021/03/12 21:03:06 Failed to sync with 21 errors: last error was: context deadline exceeded

Thanks for testing :slight_smile:

I've merged this to master now which means it will be in the latest beta in 15-30 mins and released in v1.55

Thanks! Any idea when v1.55 will be cut? I've been running to custom build since your last post and it would be good to move away from that and back to the stable builds :slight_smile:

1.55 should be out at the end of the month (March)

The issue has re-emerged. rclone is no longer exiting even when --max-duration session deadline is reached. I think this is a seperate bug from the one fixed earlier.

Two changes since my post ~19 days ago:

  • I just upgraded to v1.55.0 (I had been running v1.55.0-beta.5261.004fa1c5f.fix-context-deadline until now)
  • I added --gphotos-read-size to my rclone runs to start catching corruptions from previous runs.

The fact that the issue has re-emerged means either of the above two changes are at fault. Personally, I don't think upgrading to v1.55.0 is the cause. I think adding --gphotos-read-size is reaching parts of the code that wasn't reached before.

Here's the command that was run:
timeout -v -s QUIT --preserve-status -k 1m 121m rclone sync --gphotos-read-size --transfers=10 --max-duration=59m --retries 1 --timeout 1m --fast-list --gphotos-include-archived --gphotos-start-year=1900 --log-level INFO --log-file=REDACTED.txt gphotos:media/by-month media/by-month

Instead of exiting after 59m, rclone was killed by timeout after 121m so I got a backtrace:

2021/04/01 03:02:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:     2h0m0.0s

timeout: sending signal QUIT to command ‘rclone’
SIGQUIT: quit
PC=0x474221 m=0 sigcode=0

goroutine 0 [idle]:
runtime.futex(0x2d2bd50, 0x80, 0x0, 0x0, 0x7ffc00000000, 0x7ffccfb2b918, 0x7ffccfaf5428, 0x2d2b380, 0x7ffccfaf5438, 0x40c3ff, ...)
	runtime/sys_linux_amd64.s:579 +0x21
runtime.futexsleep(0x2d2bd50, 0x0, 0xffffffffffffffff)
	runtime/os_linux.go:44 +0x46
runtime.notesleep(0x2d2bd50)
	runtime/lock_futex.go:159 +0x9f
runtime.mPark()
	runtime/proc.go:1340 +0x39
runtime.stopm()
	runtime/proc.go:2257 +0x92
runtime.findrunnable(0xc000053000, 0x0)
	runtime/proc.go:2916 +0x72e
runtime.schedule()
	runtime/proc.go:3125 +0x2d7
runtime.park_m(0xc000001080)
	runtime/proc.go:3274 +0x9d
runtime.mcall(0x0)
	runtime/asm_amd64.s:327 +0x5b

goroutine 1 [semacquire, 120 minutes]:
sync.runtime_Semacquire(0xc0004d4d28)
	runtime/sema.go:56 +0x45
sync.(*WaitGroup).Wait(0xc0004d4d20)
	sync/waitgroup.go:130 +0x65
github.com/rclone/rclone/fs/march.(*March).Run(0xc0002ab5f0, 0x213dd20, 0xc0003e7380, 0xc0004b2fa0, 0xc0004b2f00)
	github.com/rclone/rclone/fs/march/march.go:210 +0x397
github.com/rclone/rclone/fs/sync.(*syncCopyMove).run(0xc000507600, 0xc000128000, 0x21536e8)
	github.com/rclone/rclone/fs/sync/sync.go:843 +0x225
github.com/rclone/rclone/fs/sync.runSyncCopyMove(0x213dce8, 0xc000128000, 0x21536e8, 0xc0002ab4d0, 0x2153218, 0xc0004b2fa0, 0xc000000003, 0xc000635ad8, 0x2d2bc00)
	github.com/rclone/rclone/fs/sync/sync.go:1078 +0x299
github.com/rclone/rclone/fs/sync.Sync(0x213dce8, 0xc000128000, 0x21536e8, 0xc0002ab4d0, 0x2153218, 0xc0004b2fa0, 0x1733200, 0x1bb7d20, 0xc00059a828)
	github.com/rclone/rclone/fs/sync/sync.go:1084 +0x9c
github.com/rclone/rclone/cmd/sync.glob..func1.1(0xc00059a828, 0xc000128000)
	github.com/rclone/rclone/cmd/sync/sync.go:60 +0x79
github.com/rclone/rclone/cmd.Run(0xc0001f0101, 0x2d18980, 0xc000923d30)
	github.com/rclone/rclone/cmd/cmd.go:256 +0xed
github.com/rclone/rclone/cmd/sync.glob..func1(0x2d18980, 0xc0001fe690, 0x2, 0xf)
	github.com/rclone/rclone/cmd/sync/sync.go:58 +0x12a
github.com/spf13/cobra.(*Command).execute(0x2d18980, 0xc0001fe5a0, 0xf, 0xf, 0x2d18980, 0xc0001fe5a0)
	github.com/spf13/cobra@v1.1.1/command.go:854 +0x2c2
github.com/spf13/cobra.(*Command).ExecuteC(0x2d0cf20, 0x0, 0x0, 0xc00005c778)
	github.com/spf13/cobra@v1.1.1/command.go:958 +0x375
github.com/spf13/cobra.(*Command).Execute(...)
	github.com/spf13/cobra@v1.1.1/command.go:895
github.com/rclone/rclone/cmd.Main()
	github.com/rclone/rclone/cmd/cmd.go:555 +0xad
main.main()
	github.com/rclone/rclone/rclone.go:14 +0x25

goroutine 20 [select, 2 minutes]:
go.opencensus.io/stats/view.(*worker).start(0xc000185380)
	go.opencensus.io@v0.22.6/stats/view/worker.go:276 +0xcd
created by go.opencensus.io/stats/view.init.0
	go.opencensus.io@v0.22.6/stats/view/worker.go:34 +0x68

goroutine 8 [select, 2 minutes]:
github.com/rclone/rclone/cmd.StartStats.func2(0xc0004d4cb0, 0xc000114f60)
	github.com/rclone/rclone/cmd/cmd.go:365 +0x10d
created by github.com/rclone/rclone/cmd.StartStats
	github.com/rclone/rclone/cmd/cmd.go:361 +0xb1

goroutine 59 [semacquire, 68 minutes]:
sync.runtime_Semacquire(0xc0093ed984)
	runtime/sema.go:56 +0x45
sync.(*WaitGroup).Wait(0xc0093ed984)
	sync/waitgroup.go:130 +0x65
github.com/rclone/rclone/fs/march.(*March).processJob(0xc0002ab5f0, 0xc0007a82f0, 0xc, 0xc0005a77d0, 0xc, 0x7ffffffc, 0x7ffffffc, 0x0, 0x0, 0x0, ...)
	github.com/rclone/rclone/fs/march/march.go:405 +0x129
github.com/rclone/rclone/fs/march.(*March).Run.func1(0xc0004d4d10, 0xc0002ab5f0, 0xc0003e73e0, 0xc0004d4d00, 0xc000299890, 0xc0004d4d08, 0xc0004d4d20)
	github.com/rclone/rclone/fs/march/march.go:163 +0x1d6
created by github.com/rclone/rclone/fs/march.(*March).Run
	github.com/rclone/rclone/fs/march/march.go:153 +0x265

goroutine 60 [semacquire, 115 minutes]:
sync.runtime_Semacquire(0xc0007a92f8)
	runtime/sema.go:56 +0x45
sync.(*WaitGroup).Wait(0xc0007a92f0)
	sync/waitgroup.go:130 +0x65
github.com/rclone/rclone/fs/march.(*March).processJob(0xc0002ab5f0, 0xc000645440, 0xc, 0xc000b6e520, 0xc, 0x7ffffffc, 0x7ffffffc, 0x0, 0x0, 0x0, ...)
	github.com/rclone/rclone/fs/march/march.go:405 +0x129
github.com/rclone/rclone/fs/march.(*March).Run.func1(0xc0004d4d10, 0xc0002ab5f0, 0xc0003e73e0, 0xc0004d4d00, 0xc000299890, 0xc0004d4d08, 0xc0004d4d20)
	github.com/rclone/rclone/fs/march/march.go:163 +0x1d6
created by github.com/rclone/rclone/fs/march.(*March).Run
	github.com/rclone/rclone/fs/march/march.go:153 +0x265

goroutine 61 [semacquire, 116 minutes]:
sync.runtime_Semacquire(0xc00049aec8)
	runtime/sema.go:56 +0x45
sync.(*WaitGroup).Wait(0xc00049aec0)
	sync/waitgroup.go:130 +0x65
github.com/rclone/rclone/fs/march.(*March).processJob(0xc0002ab5f0, 0xc000a1d820, 0xc, 0xc000a1d730, 0xc, 0x7ffffffc, 0x7ffffffc, 0x0, 0x0, 0x0, ...)
	github.com/rclone/rclone/fs/march/march.go:405 +0x129
github.com/rclone/rclone/fs/march.(*March).Run.func1(0xc0004d4d10, 0xc0002ab5f0, 0xc0003e73e0, 0xc0004d4d00, 0xc000299890, 0xc0004d4d08, 0xc0004d4d20)
	github.com/rclone/rclone/fs/march/march.go:163 +0x1d6
created by github.com/rclone/rclone/fs/march.(*March).Run
	github.com/rclone/rclone/fs/march/march.go:153 +0x265

goroutine 62 [semacquire, 96 minutes]:
sync.runtime_Semacquire(0xc00902f9c8)
	runtime/sema.go:56 +0x45
sync.(*WaitGroup).Wait(0xc00902f9c0)
	sync/waitgroup.go:130 +0x65
github.com/rclone/rclone/fs/march.(*March).processJob(0xc0002ab5f0, 0xc0032dccd0, 0xc, 0xc00246d3c0, 0xc, 0x7ffffffc, 0x7ffffffc, 0x0, 0x0, 0x0, ...)
	github.com/rclone/rclone/fs/march/march.go:405 +0x129
github.com/rclone/rclone/fs/march.(*March).Run.func1(0xc0004d4d10, 0xc0002ab5f0, 0xc0003e73e0, 0xc0004d4d00, 0xc000299890, 0xc0004d4d08, 0xc0004d4d20)
	github.com/rclone/rclone/fs/march/march.go:163 +0x1d6
created by github.com/rclone/rclone/fs/march.(*March).Run
	github.com/rclone/rclone/fs/march/march.go:153 +0x265

goroutine 63 [semacquire, 84 minutes]:
sync.runtime_Semacquire(0xc009767368)
	runtime/sema.go:56 +0x45
sync.(*WaitGroup).Wait(0xc009767360)
	sync/waitgroup.go:130 +0x65
github.com/rclone/rclone/fs/march.(*March).processJob(0xc0002ab5f0, 0xc000a1d850, 0xc, 0xc000a1d640, 0xc, 0x7ffffffc, 0x7ffffffc, 0x0, 0x0, 0x0, ...)
	github.com/rclone/rclone/fs/march/march.go:405 +0x129
github.com/rclone/rclone/fs/march.(*March).Run.func1(0xc0004d4d10, 0xc0002ab5f0, 0xc0003e73e0, 0xc0004d4d00, 0xc000299890, 0xc0004d4d08, 0xc0004d4d20)
	github.com/rclone/rclone/fs/march/march.go:163 +0x1d6
created by github.com/rclone/rclone/fs/march.(*March).Run
	github.com/rclone/rclone/fs/march/march.go:153 +0x265

goroutine 65 [semacquire, 116 minutes]:
sync.runtime_Semacquire(0xc000645a88)
	runtime/sema.go:56 +0x45
sync.(*WaitGroup).Wait(0xc000645a80)
	sync/waitgroup.go:130 +0x65
github.com/rclone/rclone/fs/march.(*March).processJob(0xc0002ab5f0, 0xc000b6f8b0, 0xc, 0xc00084d7e0, 0xc, 0x7ffffffc, 0x7ffffffc, 0x0, 0x0, 0x0, ...)
	github.com/rclone/rclone/fs/march/march.go:405 +0x129
github.com/rclone/rclone/fs/march.(*March).Run.func1(0xc0004d4d10, 0xc0002ab5f0, 0xc0003e73e0, 0xc0004d4d00, 0xc000299890, 0xc0004d4d08, 0xc0004d4d20)
	github.com/rclone/rclone/fs/march/march.go:163 +0x1d6
created by github.com/rclone/rclone/fs/march.(*March).Run
	github.com/rclone/rclone/fs/march/march.go:153 +0x265

goroutine 67 [chan receive, 61 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc0002ab5f0, 0xc0003e73e0, 0xc0004d4d20)
	github.com/rclone/rclone/fs/march/march.go:206 +0xb6
created by github.com/rclone/rclone/fs/march.(*March).Run
	github.com/rclone/rclone/fs/march/march.go:203 +0x386

goroutine 5594 [chan receive, 2 minutes]:
github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall(0xc0003e7140)
	github.com/rclone/rclone/lib/pacer/pacer.go:159 +0x3c
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc0003e7140, 0xc000596980, 0xa, 0x38, 0x1c96520)
	github.com/rclone/rclone/lib/pacer/pacer.go:196 +0x65
github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc0003e7140, 0xc000596980, 0x6, 0x1dcb900)
	github.com/rclone/rclone/lib/pacer/pacer.go:216 +0x6a
github.com/rclone/rclone/backend/googlephotos.(*Object).Size(0xc0046aa9a0, 0x0)
	github.com/rclone/rclone/backend/googlephotos/googlephotos.go:814 +0x456
github.com/rclone/rclone/fs/filter.(*Filter).IncludeObject(0xc000102600, 0x213dcb0, 0xc00041dac0, 0x2153288, 0xc0046aa9a0, 0x2153288)
	github.com/rclone/rclone/fs/filter/filter.go:485 +0x134
github.com/rclone/rclone/fs/list.filterAndSortDir(0x213dcb0, 0xc00041dac0, 0xc0060a0000, 0x4a4f, 0x4c00, 0xc0002fcb00, 0xc000a1d820, 0xc, 0xc000d1be98, 0xc0002fcba0, ...)
	github.com/rclone/rclone/fs/list/list.go:54 +0x685
github.com/rclone/rclone/fs/list.DirSorted(0x213dcb0, 0xc00041dac0, 0x2153218, 0xc0004b2fa0, 0x748400, 0xc000a1d820, 0xc, 0x1af4cc0, 0x1ae2800, 0x7f61508c0dd0, ...)
	github.com/rclone/rclone/fs/list/list.go:36 +0x1dc
github.com/rclone/rclone/fs/march.(*March).makeListDir.func1(0xc000a1d820, 0xc, 0x1af4cc0, 0x1ae2800, 0xc00098f600, 0x7f61508c0dd0, 0xc000cad7d0)
	github.com/rclone/rclone/fs/march/march.go:85 +0x68
github.com/rclone/rclone/fs/march.(*March).processJob.func1(0xc00049aec0, 0xc0002ab5f0, 0xc000a1d820, 0xc, 0xc000a1d730, 0xc, 0x7ffffffc, 0x7ffffffc, 0x0, 0xc000b57a40, ...)
	github.com/rclone/rclone/fs/march/march.go:393 +0x6a
created by github.com/rclone/rclone/fs/march.(*March).processJob
	github.com/rclone/rclone/fs/march/march.go:391 +0x1265

goroutine 83483 [IO wait, 2 minutes]:
internal/poll.runtime_pollWait(0x7f6150d370f0, 0x72, 0xffffffffffffffff)
	runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc000184918, 0x72, 0xf00, 0xfd7, 0xffffffffffffffff)
	internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
	internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000184900, 0xc0005e4000, 0xfd7, 0xfd7, 0x0, 0x0, 0x0)
	internal/poll/fd_unix.go:166 +0x1d5
net.(*netFD).Read(0xc000184900, 0xc0005e4000, 0xfd7, 0xfd7, 0xc0005e4005, 0xc00085e518, 0xc0006a67c0)
	net/fd_posix.go:55 +0x4f
net.(*conn).Read(0xc0006ce2a8, 0xc0005e4000, 0xfd7, 0xfd7, 0x0, 0x0, 0x0)
	net/net.go:183 +0x91
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc0006ac138, 0xc0005e4000, 0xfd7, 0xfd7, 0x40db9b, 0xc00042c210, 0x18)
	github.com/rclone/rclone/fs/fshttp/dialer.go:98 +0x58
crypto/tls.(*atLeastReader).Read(0xc00042c210, 0xc0005e4000, 0xfd7, 0xfd7, 0xc0006a6801, 0xc000100000, 0x0)
	crypto/tls/conn.go:776 +0x63
bytes.(*Buffer).ReadFrom(0xc0000e5078, 0x210a940, 0xc00042c210, 0x40b925, 0x1af4d40, 0x1c6f9a0)
	bytes/buffer.go:204 +0xbe
crypto/tls.(*Conn).readFromUntil(0xc0000e4e00, 0x7f61508a6128, 0xc0006ac138, 0x5, 0xc0006ac138, 0x2d2ab00)
	crypto/tls/conn.go:798 +0xf3
crypto/tls.(*Conn).readRecordOrCCS(0xc0000e4e00, 0x0, 0x0, 0x0)
	crypto/tls/conn.go:605 +0x115
crypto/tls.(*Conn).readRecord(...)
	crypto/tls/conn.go:573
crypto/tls.(*Conn).Read(0xc0000e4e00, 0xc00075c000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	crypto/tls/conn.go:1276 +0x165
bufio.(*Reader).Read(0xc0062346c0, 0xc00977c1f8, 0x9, 0x9, 0x11, 0x0, 0x0)
	bufio/bufio.go:227 +0x222
io.ReadAtLeast(0x210a6c0, 0xc0062346c0, 0xc00977c1f8, 0x9, 0x9, 0x9, 0xc0006a6d08, 0x59939b, 0xc0006acca8)
	io/io.go:328 +0x87
io.ReadFull(...)
	io/io.go:347
net/http.http2readFrameHeader(0xc00977c1f8, 0x9, 0x9, 0x210a6c0, 0xc0062346c0, 0x0, 0x0, 0xc000758468, 0x0)
	net/http/h2_bundle.go:1477 +0x89
net/http.(*http2Framer).ReadFrame(0xc00977c1c0, 0xc00927a048, 0x0, 0x0, 0x0)
	net/http/h2_bundle.go:1735 +0xa5
net/http.(*http2clientConnReadLoop).run(0xc0006a6fa8, 0x0, 0x0)
	net/http/h2_bundle.go:8322 +0xd8
net/http.(*http2ClientConn).readLoop(0xc000758300)
	net/http/h2_bundle.go:8244 +0x6f
created by net/http.(*http2Transport).newClientConn
	net/http/h2_bundle.go:7208 +0x6c5

goroutine 83471 [sleep]:
time.Sleep(0x3db41fbda)
	runtime/time.go:193 +0xd2
github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall.func1(0xc0003e7140, 0x3db41fbda)
	github.com/rclone/rclone/lib/pacer/pacer.go:167 +0x2b
created by github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall
	github.com/rclone/rclone/lib/pacer/pacer.go:166 +0x90

goroutine 5392 [chan receive, 2 minutes]:
github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall(0xc0003e7140)
	github.com/rclone/rclone/lib/pacer/pacer.go:159 +0x3c
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc0003e7140, 0xc000140300, 0xa, 0x38, 0x1c96520)
	github.com/rclone/rclone/lib/pacer/pacer.go:196 +0x65
github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc0003e7140, 0xc000140300, 0x6, 0x1dcb900)
	github.com/rclone/rclone/lib/pacer/pacer.go:216 +0x6a
github.com/rclone/rclone/backend/googlephotos.(*Object).Size(0xc005d6b5e0, 0x0)
	github.com/rclone/rclone/backend/googlephotos/googlephotos.go:814 +0x456
github.com/rclone/rclone/fs/filter.(*Filter).IncludeObject(0xc000102600, 0x213dcb0, 0xc00041dac0, 0x2153288, 0xc005d6b5e0, 0x2153288)
	github.com/rclone/rclone/fs/filter/filter.go:485 +0x134
github.com/rclone/rclone/fs/list.filterAndSortDir(0x213dcb0, 0xc00041dac0, 0xc002980000, 0x22e3, 0x2600, 0xc00569e600, 0xc000b6f8b0, 0xc, 0xc001303e98, 0xc00569e660, ...)
	github.com/rclone/rclone/fs/list/list.go:54 +0x685
github.com/rclone/rclone/fs/list.DirSorted(0x213dcb0, 0xc00041dac0, 0x2153218, 0xc0004b2fa0, 0x466a00, 0xc000b6f8b0, 0xc, 0x1af4cc0, 0x1ae2800, 0x7f61508c0dd0, ...)
	github.com/rclone/rclone/fs/list/list.go:36 +0x1dc
github.com/rclone/rclone/fs/march.(*March).makeListDir.func1(0xc000b6f8b0, 0xc, 0x1af4cc0, 0x1ae2800, 0x0, 0x7f61508c0dd0, 0xc000741fd0)
	github.com/rclone/rclone/fs/march/march.go:85 +0x68
github.com/rclone/rclone/fs/march.(*March).processJob.func1(0xc000645a80, 0xc0002ab5f0, 0xc000b6f8b0, 0xc, 0xc00084d7e0, 0xc, 0x7ffffffc, 0x7ffffffc, 0x0, 0xc000b56bb8, ...)
	github.com/rclone/rclone/fs/march/march.go:393 +0x6a
created by github.com/rclone/rclone/fs/march.(*March).processJob
	github.com/rclone/rclone/fs/march/march.go:391 +0x1265

goroutine 5859 [chan receive, 2 minutes]:
github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall(0xc0003e7140)
	github.com/rclone/rclone/lib/pacer/pacer.go:159 +0x3c
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc0003e7140, 0xc0006f2180, 0xa, 0x38, 0x1c96520)
	github.com/rclone/rclone/lib/pacer/pacer.go:196 +0x65
github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc0003e7140, 0xc0006f2180, 0x6, 0x1dcb900)
	github.com/rclone/rclone/lib/pacer/pacer.go:216 +0x6a
github.com/rclone/rclone/backend/googlephotos.(*Object).Size(0xc00416ef50, 0x0)
	github.com/rclone/rclone/backend/googlephotos/googlephotos.go:814 +0x456
github.com/rclone/rclone/fs/filter.(*Filter).IncludeObject(0xc000102600, 0x213dcb0, 0xc00041dac0, 0x2153288, 0xc00416ef50, 0x2153288)
	github.com/rclone/rclone/fs/filter/filter.go:485 +0x134
github.com/rclone/rclone/fs/list.filterAndSortDir(0x213dcb0, 0xc00041dac0, 0xc0071fe000, 0x529b, 0x6000, 0xc008306300, 0xc000645440, 0xc, 0xc00091de98, 0xc008306300, ...)
	github.com/rclone/rclone/fs/list/list.go:54 +0x685
github.com/rclone/rclone/fs/list.DirSorted(0x213dcb0, 0xc00041dac0, 0x2153218, 0xc0004b2fa0, 0x748400, 0xc000645440, 0xc, 0x1af4cc0, 0x1ae2800, 0x7f61508c0dd0, ...)
	github.com/rclone/rclone/fs/list/list.go:36 +0x1dc
github.com/rclone/rclone/fs/march.(*March).makeListDir.func1(0xc000645440, 0xc, 0x1af4cc0, 0x1ae2800, 0xc000b80a00, 0x7f61508c0dd0, 0xc00069e7d0)
	github.com/rclone/rclone/fs/march/march.go:85 +0x68
github.com/rclone/rclone/fs/march.(*March).processJob.func1(0xc0007a92f0, 0xc0002ab5f0, 0xc000645440, 0xc, 0xc000b6e520, 0xc, 0x7ffffffc, 0x7ffffffc, 0x0, 0xc0006d2270, ...)
	github.com/rclone/rclone/fs/march/march.go:393 +0x6a
created by github.com/rclone/rclone/fs/march.(*March).processJob
	github.com/rclone/rclone/fs/march/march.go:391 +0x1265

goroutine 23451 [chan receive, 2 minutes]:
github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall(0xc0003e7140)
	github.com/rclone/rclone/lib/pacer/pacer.go:159 +0x3c
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc0003e7140, 0xc0006f2340, 0xa, 0x38, 0x1c96520)
	github.com/rclone/rclone/lib/pacer/pacer.go:196 +0x65
github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc0003e7140, 0xc0006f2340, 0x6, 0x1dcb900)
	github.com/rclone/rclone/lib/pacer/pacer.go:216 +0x6a
github.com/rclone/rclone/backend/googlephotos.(*Object).Size(0xc003845b20, 0x0)
	github.com/rclone/rclone/backend/googlephotos/googlephotos.go:814 +0x456
github.com/rclone/rclone/fs/filter.(*Filter).IncludeObject(0xc000102600, 0x213dcb0, 0xc00041dac0, 0x2153288, 0xc003845b20, 0x2153288)
	github.com/rclone/rclone/fs/filter/filter.go:485 +0x134
github.com/rclone/rclone/fs/list.filterAndSortDir(0x213dcb0, 0xc00041dac0, 0xc008a88000, 0x1803, 0x1e00, 0xc0089da000, 0xc0032dccd0, 0xc, 0xc000613e98, 0xc0089da060, ...)
	github.com/rclone/rclone/fs/list/list.go:54 +0x685
github.com/rclone/rclone/fs/list.DirSorted(0x213dcb0, 0xc00041dac0, 0x2153218, 0xc0004b2fa0, 0x748400, 0xc0032dccd0, 0xc, 0xc000114ef8, 0xc000114eb0, 0xc0070f6fc0, ...)
	github.com/rclone/rclone/fs/list/list.go:36 +0x1dc
github.com/rclone/rclone/fs/march.(*March).makeListDir.func1(0xc0032dccd0, 0xc, 0x40e2f8, 0x48, 0x43b205, 0x1eae608, 0x0)
	github.com/rclone/rclone/fs/march/march.go:85 +0x68
github.com/rclone/rclone/fs/march.(*March).processJob.func1(0xc00902f9c0, 0xc0002ab5f0, 0xc0032dccd0, 0xc, 0xc00246d3c0, 0xc, 0x7ffffffc, 0x7ffffffc, 0x0, 0xc00063c408, ...)
	github.com/rclone/rclone/fs/march/march.go:393 +0x6a
created by github.com/rclone/rclone/fs/march.(*March).processJob
	github.com/rclone/rclone/fs/march/march.go:391 +0x1265

goroutine 82568 [IO wait]:
internal/poll.runtime_pollWait(0x7f6150d37578, 0x72, 0xffffffffffffffff)
	runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc0006ba798, 0x72, 0x1800, 0x18db, 0xffffffffffffffff)
	internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
	internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc0006ba780, 0xc000a62000, 0x18db, 0x18db, 0x0, 0x0, 0x0)
	internal/poll/fd_unix.go:166 +0x1d5
net.(*netFD).Read(0xc0006ba780, 0xc000a62000, 0x18db, 0x18db, 0x7f6150d50c00, 0x0, 0x418dd3)
	net/fd_posix.go:55 +0x4f
net.(*conn).Read(0xc0006ce218, 0xc000a62000, 0x18db, 0x18db, 0x0, 0x0, 0x0)
	net/net.go:183 +0x91
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc00059a300, 0xc000a62000, 0x18db, 0x18db, 0x40db9b, 0xc00042c018, 0x18)
	github.com/rclone/rclone/fs/fshttp/dialer.go:98 +0x58
crypto/tls.(*atLeastReader).Read(0xc00042c018, 0xc000a62000, 0x18db, 0x18db, 0xc0006a4801, 0xc0006c0000, 0x0)
	crypto/tls/conn.go:776 +0x63
bytes.(*Buffer).ReadFrom(0xc0008b8278, 0x210a940, 0xc00042c018, 0x40b925, 0x1af4d40, 0x1c6f9a0)
	bytes/buffer.go:204 +0xbe
crypto/tls.(*Conn).readFromUntil(0xc0008b8000, 0x7f61508a6128, 0xc00059a300, 0x5, 0xc00059a300, 0x2d2ab00)
	crypto/tls/conn.go:798 +0xf3
crypto/tls.(*Conn).readRecordOrCCS(0xc0008b8000, 0x0, 0x0, 0x0)
	crypto/tls/conn.go:605 +0x115
crypto/tls.(*Conn).readRecord(...)
	crypto/tls/conn.go:573
crypto/tls.(*Conn).Read(0xc0008b8000, 0xc000639000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	crypto/tls/conn.go:1276 +0x165
bufio.(*Reader).Read(0xc006234240, 0xc00977c2d8, 0x9, 0x9, 0x11, 0x0, 0x0)
	bufio/bufio.go:227 +0x222
io.ReadAtLeast(0x210a6c0, 0xc006234240, 0xc00977c2d8, 0x9, 0x9, 0x9, 0xc0006a4d08, 0x59939b, 0xc008802d20)
	io/io.go:328 +0x87
io.ReadFull(...)
	io/io.go:347
net/http.http2readFrameHeader(0xc00977c2d8, 0x9, 0x9, 0x210a6c0, 0xc006234240, 0x0, 0x0, 0xc000758168, 0x0)
	net/http/h2_bundle.go:1477 +0x89
net/http.(*http2Framer).ReadFrame(0xc00977c2a0, 0xc00927a078, 0x0, 0x0, 0x0)
	net/http/h2_bundle.go:1735 +0xa5
net/http.(*http2clientConnReadLoop).run(0xc0006a4fa8, 0x0, 0x0)
	net/http/h2_bundle.go:8322 +0xd8
net/http.(*http2ClientConn).readLoop(0xc000758000)
	net/http/h2_bundle.go:8244 +0x6f
created by net/http.(*http2Transport).newClientConn
	net/http/h2_bundle.go:7208 +0x6c5

goroutine 35183 [chan receive, 2 minutes]:
github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall(0xc0003e7140)
	github.com/rclone/rclone/lib/pacer/pacer.go:159 +0x3c
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc0003e7140, 0xc000596740, 0xa, 0x38, 0x1c96520)
	github.com/rclone/rclone/lib/pacer/pacer.go:196 +0x65
github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc0003e7140, 0xc000596740, 0x6, 0x1dcb900)
	github.com/rclone/rclone/lib/pacer/pacer.go:216 +0x6a
github.com/rclone/rclone/backend/googlephotos.(*Object).Size(0xc003eaa770, 0x0)
	github.com/rclone/rclone/backend/googlephotos/googlephotos.go:814 +0x456
github.com/rclone/rclone/fs/filter.(*Filter).IncludeObject(0xc000102600, 0x213dcb0, 0xc00041dac0, 0x2153288, 0xc003eaa770, 0x2153288)
	github.com/rclone/rclone/fs/filter/filter.go:485 +0x134
github.com/rclone/rclone/fs/list.filterAndSortDir(0x213dcb0, 0xc00041dac0, 0xc009e5e000, 0x1178, 0x1200, 0xc003982800, 0xc000a1d850, 0xc, 0xc00070fe98, 0xc003982870, ...)
	github.com/rclone/rclone/fs/list/list.go:54 +0x685
github.com/rclone/rclone/fs/list.DirSorted(0x213dcb0, 0xc00041dac0, 0x2153218, 0xc0004b2fa0, 0xc0006c2400, 0xc000a1d850, 0xc, 0xc000114ef8, 0xc000114eb0, 0xc000b7b7c0, ...)
	github.com/rclone/rclone/fs/list/list.go:36 +0x1dc
github.com/rclone/rclone/fs/march.(*March).makeListDir.func1(0xc000a1d850, 0xc, 0x40e2f8, 0x48, 0x43b205, 0x1eae608, 0x0)
	github.com/rclone/rclone/fs/march/march.go:85 +0x68
github.com/rclone/rclone/fs/march.(*March).processJob.func1(0xc009767360, 0xc0002ab5f0, 0xc000a1d850, 0xc, 0xc000a1d640, 0xc, 0x7ffffffc, 0x7ffffffc, 0x0, 0xc0005d13b0, ...)
	github.com/rclone/rclone/fs/march/march.go:393 +0x6a
created by github.com/rclone/rclone/fs/march.(*March).processJob
	github.com/rclone/rclone/fs/march/march.go:391 +0x1265

goroutine 79731 [chan receive]:
github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall(0xc0003e7140)
	github.com/rclone/rclone/lib/pacer/pacer.go:159 +0x3c
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc0003e7140, 0xc0006f2240, 0xa, 0x38, 0x1c96520)
	github.com/rclone/rclone/lib/pacer/pacer.go:196 +0x65
github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc0003e7140, 0xc0006f2240, 0x6, 0x1dcb900)
	github.com/rclone/rclone/lib/pacer/pacer.go:216 +0x6a
github.com/rclone/rclone/backend/googlephotos.(*Object).Size(0xc003071420, 0x0)
	github.com/rclone/rclone/backend/googlephotos/googlephotos.go:814 +0x456
github.com/rclone/rclone/fs/filter.(*Filter).IncludeObject(0xc000102600, 0x213dcb0, 0xc00041dac0, 0x2153288, 0xc003071420, 0x2153288)
	github.com/rclone/rclone/fs/filter/filter.go:485 +0x134
github.com/rclone/rclone/fs/list.filterAndSortDir(0x213dcb0, 0xc00041dac0, 0xc00968e000, 0x2ea, 0x400, 0xc00a1d4100, 0xc0007a82f0, 0xc, 0xc000847e98, 0xc00a1d41e0, ...)
	github.com/rclone/rclone/fs/list/list.go:54 +0x685
github.com/rclone/rclone/fs/list.DirSorted(0x213dcb0, 0xc00041dac0, 0x2153218, 0xc0004b2fa0, 0xc00084ec00, 0xc0007a82f0, 0xc, 0xc000114ef8, 0xc000114eb0, 0xc0009017c0, ...)
	github.com/rclone/rclone/fs/list/list.go:36 +0x1dc
github.com/rclone/rclone/fs/march.(*March).makeListDir.func1(0xc0007a82f0, 0xc, 0x40e2f8, 0x48, 0x43b205, 0x1eae608, 0x0)
	github.com/rclone/rclone/fs/march/march.go:85 +0x68
github.com/rclone/rclone/fs/march.(*March).processJob.func1(0xc0093ed984, 0xc0002ab5f0, 0xc0007a82f0, 0xc, 0xc0005a77d0, 0xc, 0x7ffffffc, 0x7ffffffc, 0x0, 0xc007da1d70, ...)
	github.com/rclone/rclone/fs/march/march.go:393 +0x6a
created by github.com/rclone/rclone/fs/march.(*March).processJob
	github.com/rclone/rclone/fs/march/march.go:391 +0x1265

rax    0xca
rbx    0x2d2bc00
rcx    0x474223
rdx    0x0
rdi    0x2d2bd50
rsi    0x80
rbp    0x7ffccfaf5400
rsp    0x7ffccfaf53b8
r8     0x0
r9     0x0
r10    0x0
r11    0x286
r12    0x0
r13    0x189
r14    0x2c76500
r15    0x2030000
rip    0x474221
rflags 0x286
cs     0x33
fs     0x0
gs     0x0

Here's the rest of log file (excluding backtrace already pasted above) - not much happens after the 58m mark:

2021/04/01 01:02:02 INFO  : Local file system at /REDACTED/media/by-month: Transfer session deadline: 2021/04/01 02:01:02
2021/04/01 01:03:02 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Elapsed time:       1m0.0s

2021/04/01 01:04:02 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Elapsed time:       2m0.0s

2021/04/01 01:05:02 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Elapsed time:       3m0.0s

2021/04/01 01:06:02 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Elapsed time:       4m0.0s

2021/04/01 01:06:44 INFO  : 2008/2008-01/chand room1 001_Resized.jpg: Copied (replaced existing)
2021/04/01 01:06:45 INFO  : 2008/2008-01/chand room1 003_Resize.jpg: Copied (replaced existing)
2021/04/01 01:06:45 INFO  : 2008/2008-01/chand room1 011_Resize.jpg: Copied (replaced existing)
2021/04/01 01:07:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.140 MBytes/s, ETA 0s
Checks:                54 / 54, 100%
Transferred:            3 / 3, 100%
Elapsed time:       5m0.0s

2021/04/01 01:08:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.122 MBytes/s, ETA 0s
Checks:               330 / 330, 100%
Transferred:            3 / 3, 100%
Elapsed time:       6m0.0s

2021/04/01 01:09:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.122 MBytes/s, ETA 0s
Checks:               330 / 330, 100%
Transferred:            3 / 3, 100%
Elapsed time:       7m0.0s

2021/04/01 01:10:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.103 MBytes/s, ETA 0s
Checks:               679 / 679, 100%
Transferred:            3 / 3, 100%
Elapsed time:       8m0.0s

2021/04/01 01:11:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.076 MBytes/s, ETA 0s
Checks:              1061 / 1061, 100%
Transferred:            3 / 3, 100%
Elapsed time:       9m0.0s

2021/04/01 01:12:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.047 MBytes/s, ETA 0s
Checks:              1585 / 1585, 100%
Transferred:            3 / 3, 100%
Elapsed time:      10m0.0s

2021/04/01 01:13:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.047 MBytes/s, ETA 0s
Checks:              1585 / 1585, 100%
Transferred:            3 / 3, 100%
Elapsed time:      11m0.0s

2021/04/01 01:14:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.047 MBytes/s, ETA 0s
Checks:              1585 / 1585, 100%
Transferred:            3 / 3, 100%
Elapsed time:      12m0.0s

2021/04/01 01:15:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.047 MBytes/s, ETA 0s
Checks:              1585 / 1585, 100%
Transferred:            3 / 3, 100%
Elapsed time:      13m0.0s

2021/04/01 01:16:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.047 MBytes/s, ETA 0s
Checks:              1585 / 1585, 100%
Transferred:            3 / 3, 100%
Elapsed time:      14m0.0s

2021/04/01 01:17:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.047 MBytes/s, ETA 0s
Checks:              1585 / 1585, 100%
Transferred:            3 / 3, 100%
Elapsed time:      15m0.0s

2021/04/01 01:18:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.047 MBytes/s, ETA 0s
Checks:              1585 / 1585, 100%
Transferred:            3 / 3, 100%
Elapsed time:      16m0.0s

2021/04/01 01:19:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.047 MBytes/s, ETA 0s
Checks:              1585 / 1585, 100%
Transferred:            3 / 3, 100%
Elapsed time:      17m0.0s

2021/04/01 01:20:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.016 MBytes/s, ETA 0s
Checks:              2500 / 2500, 100%
Transferred:            3 / 3, 100%
Elapsed time:      18m0.0s

2021/04/01 01:21:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.009 MBytes/s, ETA 0s
Checks:              2602 / 2602, 100%
Transferred:            3 / 3, 100%
Elapsed time:      19m0.0s

2021/04/01 01:22:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.009 MBytes/s, ETA 0s
Checks:              2602 / 2602, 100%
Transferred:            3 / 3, 100%
Elapsed time:      20m0.0s

2021/04/01 01:23:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.995 MBytes/s, ETA 0s
Checks:              2802 / 2802, 100%
Transferred:            3 / 3, 100%
Elapsed time:      21m0.0s

2021/04/01 01:24:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.995 MBytes/s, ETA 0s
Checks:              2802 / 2802, 100%
Transferred:            3 / 3, 100%
Elapsed time:      22m0.0s

2021/04/01 01:25:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.995 MBytes/s, ETA 0s
Checks:              2802 / 2802, 100%
Transferred:            3 / 3, 100%
Elapsed time:      23m0.0s

2021/04/01 01:26:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.995 MBytes/s, ETA 0s
Checks:              2802 / 2802, 100%
Transferred:            3 / 3, 100%
Elapsed time:      24m0.0s

2021/04/01 01:27:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.973 MBytes/s, ETA 0s
Checks:              3190 / 3190, 100%
Transferred:            3 / 3, 100%
Elapsed time:      25m0.0s

2021/04/01 01:28:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.940 MBytes/s, ETA 0s
Checks:              5016 / 5016, 100%
Transferred:            3 / 3, 100%
Elapsed time:      26m0.0s

2021/04/01 01:29:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.926 MBytes/s, ETA 0s
Checks:              5251 / 5251, 100%
Transferred:            3 / 3, 100%
Elapsed time:      27m0.0s

2021/04/01 01:30:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.926 MBytes/s, ETA 0s
Checks:              5251 / 5251, 100%
Transferred:            3 / 3, 100%
Elapsed time:      28m0.0s

2021/04/01 01:31:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.926 MBytes/s, ETA 0s
Checks:              5251 / 5251, 100%
Transferred:            3 / 3, 100%
Elapsed time:      29m0.0s

2021/04/01 01:32:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.926 MBytes/s, ETA 0s
Checks:              5251 / 5251, 100%
Transferred:            3 / 3, 100%
Elapsed time:      30m0.0s

2021/04/01 01:33:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.926 MBytes/s, ETA 0s
Checks:              5251 / 5251, 100%
Transferred:            3 / 3, 100%
Elapsed time:      31m0.0s

2021/04/01 01:34:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.894 MBytes/s, ETA 0s
Checks:              5865 / 5865, 100%
Transferred:            3 / 3, 100%
Elapsed time:      32m0.0s

2021/04/01 01:35:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.884 MBytes/s, ETA 0s
Checks:              5952 / 5952, 100%
Transferred:            3 / 3, 100%
Elapsed time:      33m0.0s

2021/04/01 01:36:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.884 MBytes/s, ETA 0s
Checks:              5952 / 5952, 100%
Transferred:            3 / 3, 100%
Elapsed time:      34m0.0s

2021/04/01 01:37:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.884 MBytes/s, ETA 0s
Checks:              5952 / 5952, 100%
Transferred:            3 / 3, 100%
Elapsed time:      35m0.0s

2021/04/01 01:38:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.884 MBytes/s, ETA 0s
Checks:              5952 / 5952, 100%
Transferred:            3 / 3, 100%
Elapsed time:      36m0.0s

2021/04/01 01:39:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.884 MBytes/s, ETA 0s
Checks:              5952 / 5952, 100%
Transferred:            3 / 3, 100%
Elapsed time:      37m0.0s

2021/04/01 01:40:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.849 MBytes/s, ETA 0s
Checks:              6673 / 6673, 100%
Transferred:            3 / 3, 100%
Elapsed time:      38m0.0s

2021/04/01 01:41:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.849 MBytes/s, ETA 0s
Checks:              6673 / 6673, 100%
Transferred:            3 / 3, 100%
Elapsed time:      39m0.0s

2021/04/01 01:42:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.849 MBytes/s, ETA 0s
Checks:              6673 / 6673, 100%
Transferred:            3 / 3, 100%
Elapsed time:      40m0.0s

2021/04/01 01:43:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.849 MBytes/s, ETA 0s
Checks:              6673 / 6673, 100%
Transferred:            3 / 3, 100%
Elapsed time:      41m0.0s

2021/04/01 01:44:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.849 MBytes/s, ETA 0s
Checks:              6673 / 6673, 100%
Transferred:            3 / 3, 100%
Elapsed time:      42m0.0s

2021/04/01 01:45:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.849 MBytes/s, ETA 0s
Checks:              6673 / 6673, 100%
Transferred:            3 / 3, 100%
Elapsed time:      43m0.0s

2021/04/01 01:46:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.849 MBytes/s, ETA 0s
Checks:              6673 / 6673, 100%
Transferred:            3 / 3, 100%
Elapsed time:      44m0.0s

2021/04/01 01:47:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.849 MBytes/s, ETA 0s
Checks:              6673 / 6673, 100%
Transferred:            3 / 3, 100%
Elapsed time:      45m0.0s

2021/04/01 01:48:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.849 MBytes/s, ETA 0s
Checks:              6673 / 6673, 100%
Transferred:            3 / 3, 100%
Elapsed time:      46m0.0s

2021/04/01 01:49:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.849 MBytes/s, ETA 0s
Checks:              6673 / 6673, 100%
Transferred:            3 / 3, 100%
Elapsed time:      47m0.0s

2021/04/01 01:50:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 33.553 kBytes/s, ETA 0s
Checks:              7120 / 7123, 100%
Transferred:            3 / 3, 100%
Elapsed time:      48m0.0s

2021/04/01 01:51:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 12.463 kBytes/s, ETA 0s
Checks:             11031 / 11345, 97%
Transferred:            3 / 3, 100%
Elapsed time:      49m0.0s
Checking:
 * 2009/2009-02/fb_DSC_03…J4uhgNcq0VNbtjpVA}.JPG: checking
 * 2009/2009-02/fb_DSC_03…3XbO57Kje3oZO74fQ}.JPG: checking

2021/04/01 01:52:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 6.847 kBytes/s, ETA 0s
Checks:             12439 / 12443, 100%
Transferred:            3 / 3, 100%
Elapsed time:      50m0.0s
Checking:
 *                  2009/2009-02/sr_DSC_0615.JPG: checking
 *                  2009/2009-02/sr_DSC_0616.JPG: checking

2021/04/01 01:53:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 5.141 kBytes/s, ETA 0s
Checks:             13175 / 13177, 100%
Transferred:            3 / 3, 100%
Elapsed time:      51m0.0s

2021/04/01 01:54:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.983 kBytes/s, ETA 0s
Checks:             14167 / 14171, 100%
Transferred:            3 / 3, 100%
Elapsed time:      52m0.0s
Checking:
 *                     2010/2010-02/DSC_4208.JPG: checking

2021/04/01 01:55:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 3.277 kBytes/s, ETA 0s
Checks:             15139 / 15143, 100%
Transferred:            3 / 3, 100%
Elapsed time:      53m0.0s
Checking:
 *                     2010/2010-02/DSC_5085.JPG: checking
 *                     2010/2010-02/DSC_5086.JPG: checking

2021/04/01 01:56:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.899 kBytes/s, ETA 0s
Checks:             19209 / 19211, 100%
Transferred:            3 / 3, 100%
Elapsed time:      54m0.0s

2021/04/01 01:57:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.739 kBytes/s, ETA 0s
Checks:             19389 / 19392, 100%
Transferred:            3 / 3, 100%
Elapsed time:      55m0.0s
Checking:
 *                     2011/2011-02/DSC_0225.JPG: checking

2021/04/01 01:58:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.451 kBytes/s, ETA 0s
Checks:             19391 / 19398, 100%
Transferred:            3 / 3, 100%
Elapsed time:      56m0.0s

2021/04/01 01:59:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 2.213 kBytes/s, ETA 0s
Checks:             19392 / 19399, 100%
Transferred:            3 / 3, 100%
Elapsed time:      57m0.0s
Checking:
 *                     2011/2011-02/DSC_0228.JPG: checking
 *                     2011/2011-02/DSC_0229.JPG: checking

2021/04/01 02:00:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.881 kBytes/s, ETA 0s
Checks:             19395 / 19399, 100%
Transferred:            3 / 3, 100%
Elapsed time:      58m0.0s
Checking:
 *                     2011/2011-02/DSC_0230.JPG: checking

2021/04/01 02:01:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.636 kBytes/s, ETA 0s
Checks:             19398 / 19401, 100%
Transferred:            3 / 3, 100%
Elapsed time:      59m0.0s
Checking:
 *                     2011/2011-02/DSC_0234.JPG: checking

2021/04/01 02:01:03 ERROR : 2013/2013-02: error reading source directory: couldn't list files: Post "https://photoslibrary.googleapis.com/v1/mediaItems:search": context deadline exceeded
2021/04/01 02:02:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.545 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19400 / 19401, 100%
Transferred:            3 / 3, 100%
Elapsed time:     1h0m0.0s

2021/04/01 02:03:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.387 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19400 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:     1h1m0.0s
Checking:
 *                     2011/2011-02/DSC_0236.JPG: checking

2021/04/01 02:04:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:     1h2m0.0s

2021/04/01 02:05:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:     1h3m0.0s

2021/04/01 02:06:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:     1h4m0.0s

2021/04/01 02:07:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:     1h5m0.0s

2021/04/01 02:08:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:     1h6m0.0s

2021/04/01 02:09:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:     1h7m0.0s

2021/04/01 02:10:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:     1h8m0.0s

2021/04/01 02:11:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:     1h9m0.0s

2021/04/01 02:12:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h10m0.0s

2021/04/01 02:13:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h11m0.0s

2021/04/01 02:14:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h12m0.0s

2021/04/01 02:15:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h13m0.0s

2021/04/01 02:16:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h14m0.0s

2021/04/01 02:17:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h15m0.0s

2021/04/01 02:18:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h16m0.0s

2021/04/01 02:19:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h17m0.0s

2021/04/01 02:20:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h18m0.0s

2021/04/01 02:21:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h19m0.0s

2021/04/01 02:22:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h20m0.0s

2021/04/01 02:23:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h21m0.0s

2021/04/01 02:24:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h22m0.0s

2021/04/01 02:25:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h23m0.0s

2021/04/01 02:26:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h24m0.0s

2021/04/01 02:27:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h25m0.0s

2021/04/01 02:28:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h26m0.0s

2021/04/01 02:29:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h27m0.0s

2021/04/01 02:30:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h28m0.0s

2021/04/01 02:31:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h29m0.0s

2021/04/01 02:32:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h30m0.0s

2021/04/01 02:33:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h31m0.0s

2021/04/01 02:34:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h32m0.0s

2021/04/01 02:35:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h33m0.0s

2021/04/01 02:36:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h34m0.0s

2021/04/01 02:37:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h35m0.0s

2021/04/01 02:38:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h36m0.0s

2021/04/01 02:39:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h37m0.0s

2021/04/01 02:40:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h38m0.0s

2021/04/01 02:41:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h39m0.0s

2021/04/01 02:42:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h40m0.0s

2021/04/01 02:43:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h41m0.0s

2021/04/01 02:44:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h42m0.0s

2021/04/01 02:45:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h43m0.0s

2021/04/01 02:46:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h44m0.0s

2021/04/01 02:47:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h45m0.0s

2021/04/01 02:48:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h46m0.0s

2021/04/01 02:49:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h47m0.0s

2021/04/01 02:50:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h48m0.0s

2021/04/01 02:51:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h49m0.0s

2021/04/01 02:52:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h50m0.0s

2021/04/01 02:53:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h51m0.0s

2021/04/01 02:54:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h52m0.0s

2021/04/01 02:55:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h53m0.0s

2021/04/01 02:56:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h54m0.0s

2021/04/01 02:57:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h55m0.0s

2021/04/01 02:58:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h56m0.0s

2021/04/01 02:59:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h57m0.0s

2021/04/01 03:00:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h58m0.0s

2021/04/01 03:01:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:    1h59m0.0s

2021/04/01 03:02:02 INFO  : 
Transferred:   	  535.923k / 535.923 kBytes, 100%, 1.229 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             19401 / 19402, 100%
Transferred:            3 / 3, 100%
Elapsed time:     2h0m0.0s

timeout: sending signal QUIT to command ‘rclone’
SIGQUIT: quit
PC=0x474221 m=0 sigcode=0

Yes, you are quite right that is exactly what is happening.

func (o *Object) Size() int64 {
	defer log.Trace(o, "")("")
	if !o.fs.opt.ReadSize || o.bytes >= 0 {
		return o.bytes
	}
	ctx := context.TODO()
	err := o.readMetaData(ctx)
	if err != nil {
		fs.Debugf(o, "Size: Failed to read metadata: %v", err)
		return -1
	}
	var resp *http.Response
	opts := rest.Opts{
		Method:  "HEAD",
		RootURL: o.downloadURL(),
	}
	err = o.fs.pacer.Call(func() (bool, error) {
		resp, err = o.fs.srv.Call(ctx, &opts)
		return shouldRetry(ctx, resp, err)
	})

Note the context.TODO that is because context isn't being passed into the Size call so we are just using a background context which won't be cancelled on --max-duration.

The proper way to fix this would be to change the interface to Size to pass the context in. This unfortunately is not a small change as it would involve changing all the backends and a lot of the sync code. It isn't a difficult change though.

That said, I'd encourage you not to use the --gphotos-read-size flag as it is really expensive in API hits - it is equivalent to 1 download every time it is called!

Thanks for a quick response as usual :slight_smile:

I see. As this doesn't cause any corruption I'm not bothered by it - timeout is making sure that rclone doesn't run forever. So for me personally this is very low impact & low priority issue.

Understood! As I've finally finished a full sync of my gphotos, I am using --gphotos-read-size as an easy way to be identify corrupt files. Since I have the workflow automated this seemed like the first easy option to go for - waiting days/weeks is not a problem for me since this all happens in the background anyway :slight_smile:

Once I have some time to spare (hopefully this easter weekend) I'll go through the rclone lsf options we discussed in Detecting incomplete file download from Google Photos - #4 by timevortex and then I can stop using --gphotos-read-size.

As usual, really appreciate your help and quick responses.

Glad I can help!

I agree with you that googlephotos Size method vs --max-duration is probably a minor problem and I'll ignore it for the moment.