Plans to resolve Google Drive 403?

aj1252 · July 15, 2017, 10:43am

For reference; this is how the API Manager looks after 403 Forbidden.
I do have a 100 req/sec API so it should not have banned me.

Edit: Also, notice the very nice light blue line on the top graph, which is rclone with 100ms, exactly 10/sec perfect.

djsecrist · July 15, 2017, 5:34pm

Well, I think I screwed up and managed to get myself banned… Darn it! I think I ran with the default 1ns interval during some testing by mistake. However, this mistake has shown me that rclone responds differently between the 1.36 release version and this beta version when Google banned.

I ran mkvinfo against a movie file in both versions and will attach the debug logs for both. With the release version, mkvinfo responds appropriately with “(MKVInfo) Error: Couldn’t open input file .gd/Movies/Zootopia (2016)/Zootopia.mkv (open file error).” But with the beta version, mkvinfo says “(MKVInfo) No EBML head found.” It doesn’t return an error. It thinks it could read the file and that it just isn’t a valid MKV. The ramifications of this is that Plex thinks the movie files are available. With the rclone 1.36, once a ban happens, Plex shows “UNAVAILABLE” on the movie details screens and won’t try to play the film. With the beta version, Plex thinks the movie is available and tries to start playing it. After about 30 seconds, it fails with a transcoder error. The user experience is not very good. I’d rather see that a file is unavailable right away instead of letting the user try to start playing it.

I’ll be back to testing once my ban is lifted, but I’d really like to see this reverted back to the original I/O error when Google returns 403 forbidden.

Thanks.

v1.36 log snippet:
2017/07/15 10:06:12 INFO : Encrypted Google drive root ‘Apps/Crypt’: Modify window is 1ms
2017/07/15 10:06:12 DEBUG : Encrypted Google drive root ‘Apps/Crypt’: Mounting on “/home/dsecrist/plex/media/.gd/”
2017/07/15 10:06:12 DEBUG : Encrypted Google drive root ‘Apps/Crypt’: Root()
2017/07/15 10:06:52 DEBUG : : Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:06:52 DEBUG : : Dir.ReadDirAll
2017/07/15 10:06:52 DEBUG : : Reading directory
2017/07/15 10:06:52 DEBUG : Google drive root ‘Apps/Crypt’: Reading “”
2017/07/15 10:06:52 DEBUG : Google drive root ‘Apps/Crypt’: Finished reading “”
2017/07/15 10:06:52 DEBUG : : Dir.ReadDirAll OK with 5 entries
2017/07/15 10:06:58 DEBUG : : Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:06:58 DEBUG : Movies: Dir.Lookup
2017/07/15 10:06:58 DEBUG : Movies: Dir.Lookup OK
2017/07/15 10:06:58 DEBUG : Movies: Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:06:58 DEBUG : Movies: Dir.Lookup
2017/07/15 10:06:58 DEBUG : Movies: Dir.Lookup OK
2017/07/15 10:06:58 DEBUG : Movies: Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:06:58 DEBUG : Movies: Dir.ReadDirAll
2017/07/15 10:06:58 DEBUG : Movies: Reading directory
2017/07/15 10:06:59 DEBUG : Google drive root ‘Apps/Crypt’: Reading “v33or58psaime06i4ohqivjgg8/”
2017/07/15 10:07:04 DEBUG : Google drive root ‘Apps/Crypt’: Finished reading “v33or58psaime06i4ohqivjgg8/”
2017/07/15 10:07:04 DEBUG : Movies: Dir.ReadDirAll OK with 1778 entries
2017/07/15 10:07:04 DEBUG : Movies: Dir.Lookup
2017/07/15 10:07:04 DEBUG : Movies: Dir.Lookup OK
2017/07/15 10:07:04 DEBUG : Movies: Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:04 DEBUG : Movies: Dir.Lookup
2017/07/15 10:07:04 DEBUG : Movies: Dir.Lookup OK
2017/07/15 10:07:04 DEBUG : Movies: Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:04 DEBUG : Movies: Dir.ReadDirAll
2017/07/15 10:07:04 DEBUG : Movies: Dir.ReadDirAll OK with 1778 entries
2017/07/15 10:07:04 DEBUG : Movies: Dir.Lookup
2017/07/15 10:07:04 DEBUG : Movies: Dir.Lookup OK
2017/07/15 10:07:04 DEBUG : Movies: Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:04 DEBUG : Movies: Dir.Lookup
2017/07/15 10:07:04 DEBUG : Movies: Dir.Lookup OK
2017/07/15 10:07:04 DEBUG : Movies: Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:04 DEBUG : Movies/Zootopia (2016): Dir.Lookup
2017/07/15 10:07:04 DEBUG : Movies/Zootopia (2016): Dir.Lookup OK
2017/07/15 10:07:04 DEBUG : Movies/Zootopia (2016): Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:04 DEBUG : Movies: Dir.Lookup
2017/07/15 10:07:04 DEBUG : Movies: Dir.Lookup OK
2017/07/15 10:07:04 DEBUG : Movies: Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:04 DEBUG : Movies/Zootopia (2016): Dir.Lookup
2017/07/15 10:07:04 DEBUG : Movies/Zootopia (2016): Dir.Lookup OK
2017/07/15 10:07:04 DEBUG : Movies/Zootopia (2016): Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:05 DEBUG : Movies: Dir.Lookup
2017/07/15 10:07:05 DEBUG : Movies: Dir.Lookup OK
2017/07/15 10:07:05 DEBUG : Movies: Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:05 DEBUG : Movies: Dir.Lookup
2017/07/15 10:07:05 DEBUG : Movies: Dir.Lookup OK
2017/07/15 10:07:05 DEBUG : Movies: Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:05 DEBUG : Movies/Zootopia (2016): Dir.Lookup
2017/07/15 10:07:05 DEBUG : Movies/Zootopia (2016): Dir.Lookup OK
2017/07/15 10:07:05 DEBUG : Movies/Zootopia (2016): Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:05 DEBUG : Movies: Dir.Lookup
2017/07/15 10:07:05 DEBUG : Movies: Dir.Lookup OK
2017/07/15 10:07:05 DEBUG : Movies: Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:05 DEBUG : Movies/Zootopia (2016): Dir.Lookup
2017/07/15 10:07:05 DEBUG : Movies/Zootopia (2016): Dir.Lookup OK
2017/07/15 10:07:05 DEBUG : Movies/Zootopia (2016): Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:05 DEBUG : Movies/Zootopia (2016): Dir.ReadDirAll
2017/07/15 10:07:05 DEBUG : Movies/Zootopia (2016): Reading directory
2017/07/15 10:07:05 DEBUG : Google drive root ‘Apps/Crypt’: Reading “v33or58psaime06i4ohqivjgg8/6j2v58ref4uvtaq237gt40gmto/”
2017/07/15 10:07:06 DEBUG : Google drive root ‘Apps/Crypt’: Finished reading “v33or58psaime06i4ohqivjgg8/6j2v58ref4uvtaq237gt40gmto/”
2017/07/15 10:07:06 DEBUG : Movies/Zootopia (2016): Dir.ReadDirAll OK with 1 entries
2017/07/15 10:07:06 DEBUG : Movies: Dir.Lookup
2017/07/15 10:07:06 DEBUG : Movies: Dir.Lookup OK
2017/07/15 10:07:06 DEBUG : Movies: Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:06 DEBUG : Movies: Dir.Lookup
2017/07/15 10:07:06 DEBUG : Movies: Dir.Lookup OK
2017/07/15 10:07:06 DEBUG : Movies: Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:06 DEBUG : Movies/Zootopia (2016): Dir.Lookup
2017/07/15 10:07:06 DEBUG : Movies/Zootopia (2016): Dir.Lookup OK
2017/07/15 10:07:06 DEBUG : Movies/Zootopia (2016): Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:06 DEBUG : Movies: Dir.Lookup
2017/07/15 10:07:06 DEBUG : Movies: Dir.Lookup OK
2017/07/15 10:07:06 DEBUG : Movies: Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:06 DEBUG : Movies/Zootopia (2016): Dir.Lookup
2017/07/15 10:07:06 DEBUG : Movies/Zootopia (2016): Dir.Lookup OK
2017/07/15 10:07:06 DEBUG : Movies/Zootopia (2016): Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:06 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: Dir.Lookup
2017/07/15 10:07:06 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: Dir.Lookup OK
2017/07/15 10:07:06 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: File.Attr valid=1m0s ino=0 size=14530039018 mode=-rw-rw-r–
2017/07/15 10:07:06 DEBUG : Movies: Dir.Lookup
2017/07/15 10:07:06 DEBUG : Movies: Dir.Lookup OK
2017/07/15 10:07:06 DEBUG : Movies: Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:06 DEBUG : Movies/Zootopia (2016): Dir.Lookup
2017/07/15 10:07:06 DEBUG : Movies/Zootopia (2016): Dir.Lookup OK
2017/07/15 10:07:06 DEBUG : Movies/Zootopia (2016): Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:06 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: Dir.Lookup
2017/07/15 10:07:06 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: Dir.Lookup OK
2017/07/15 10:07:06 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: File.Attr valid=1m0s ino=0 size=14530039018 mode=-rw-rw-r–
2017/07/15 10:07:07 DEBUG : Movies: Dir.Lookup
2017/07/15 10:07:07 DEBUG : Movies: Dir.Lookup OK
2017/07/15 10:07:07 DEBUG : Movies: Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:07 DEBUG : Movies/Zootopia (2016): Dir.Lookup
2017/07/15 10:07:07 DEBUG : Movies/Zootopia (2016): Dir.Lookup OK
2017/07/15 10:07:07 DEBUG : Movies/Zootopia (2016): Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:07 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: Dir.Lookup
2017/07/15 10:07:07 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: Dir.Lookup OK
2017/07/15 10:07:07 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: File.Attr valid=1m0s ino=0 size=14530039018 mode=-rw-rw-r–
2017/07/15 10:07:07 DEBUG : Movies: Dir.Lookup
2017/07/15 10:07:07 DEBUG : Movies: Dir.Lookup OK
2017/07/15 10:07:07 DEBUG : Movies: Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:07 DEBUG : Movies/Zootopia (2016): Dir.Lookup
2017/07/15 10:07:07 DEBUG : Movies/Zootopia (2016): Dir.Lookup OK
2017/07/15 10:07:07 DEBUG : Movies/Zootopia (2016): Dir.Attr valid=1m0s ino=0 size=0 mode=drwxrwxr-x
2017/07/15 10:07:07 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: Dir.Lookup
2017/07/15 10:07:07 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: Dir.Lookup OK
2017/07/15 10:07:07 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: File.Attr valid=1m0s ino=0 size=14530039018 mode=-rw-rw-r–
2017/07/15 10:07:07 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: File.Open OpenReadOnly
2017/07/15 10:07:07 ERROR : Movies/Zootopia (2016)/Zootopia.mkv: File.Open failed: open for read: bad response: 403: 403 Forbidden

rclone-v1.36-251-g0b2b4243-tps-limit log snippet:
2017/07/15 01:31:29 DEBUG : rclone: Version “v1.36-251-g0b2b4243-tps-limitβ” finishing with parameters ["/home/dsecrist/downloads/rclone-v1.36-251-g0b2b4243-tps-limitβ-linux-amd64/rclone" “mount” “–config” “/home/dsecrist/downloads/rclone-v1.36-251-g0b2b4243-tps-limitβ-linux-amd64/rclone-test.conf” “–min-transaction-interval” “200ms” “–allow-non-empty” “–allow-other” “–no-traverse” “–buffer-size” “1G” “–max-read-ahead” “1G” “–checkers” “16” “–retries” “3” “–low-level-retries” “12” “–log-file” “/home/dsecrist/scripts/logs/rclone-test-gd-unencrypted.log” “–log-level” “DEBUG” “–stats” “0” “GD-test-crypt:/” “/home/dsecrist/plex/media/.gd-rclone-test.unencrypted/”]
2017/07/15 01:31:31 INFO : Encrypted drive ‘GD-test-crypt:/’: Modify window is 1ms
2017/07/15 10:06:11 INFO : Starting HTTP transaction limiter: minimum interval 200ms
2017/07/15 10:06:11 DEBUG : rclone: Version “v1.36-251-g0b2b4243-tps-limitβ” starting with parameters ["/home/dsecrist/downloads/rclone-v1.36-251-g0b2b4243-tps-limitβ-linux-amd64/rclone" “mount” “–config” “/home/dsecrist/downloads/rclone-v1.36-251-g0b2b4243-tps-limitβ-linux-amd64/rclone-test.conf” “–min-transaction-interval” “200ms” “–allow-non-empty” “–allow-other” “–no-traverse” “–buffer-size” “1G” “–max-read-ahead” “1G” “–checkers” “16” “–retries” “3” “–low-level-retries” “12” “–log-file” “/home/dsecrist/scripts/logs/rclone-test-gd-unencrypted.log” “–log-level” “DEBUG” “–stats” “0” “GD-test-crypt:/” “/home/dsecrist/plex/media/.gd-rclone-test.unencrypted/”]
2017/07/15 10:06:12 INFO : Encrypted drive ‘GD-test-crypt:/’: Modify window is 1ms
2017/07/15 10:06:12 DEBUG : Encrypted drive ‘GD-test-crypt:/’: Mounting on “/home/dsecrist/plex/media/.gd-rclone-test.unencrypted/”
2017/07/15 10:06:12 DEBUG : : Root:
2017/07/15 10:06:12 DEBUG : : >Root: node=/, err=
2017/07/15 10:06:30 DEBUG : /: Attr:
2017/07/15 10:06:30 DEBUG : /: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:32 DEBUG : /: ReadDirAll:
2017/07/15 10:06:32 DEBUG : /: >ReadDirAll: item=5, err=
2017/07/15 10:06:34 DEBUG : /: Attr:
2017/07/15 10:06:34 DEBUG : /: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:34 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:34 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:34 DEBUG : Movies/: Attr:
2017/07/15 10:06:34 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:34 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:34 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:34 DEBUG : Movies/: Attr:
2017/07/15 10:06:34 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:34 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:34 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:34 DEBUG : Movies/: Attr:
2017/07/15 10:06:34 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:34 DEBUG : Movies/: ReadDirAll:
2017/07/15 10:06:38 DEBUG : Movies/: >ReadDirAll: item=1778, err=
2017/07/15 10:06:38 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:38 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:38 DEBUG : Movies/: Attr:
2017/07/15 10:06:38 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:38 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:38 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:38 DEBUG : Movies/: Attr:
2017/07/15 10:06:38 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:38 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:38 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:38 DEBUG : Movies/: Attr:
2017/07/15 10:06:38 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:38 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:38 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:38 DEBUG : Movies/: Attr:
2017/07/15 10:06:38 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:38 DEBUG : Movies/: Lookup: name=“Zootopia (2016)”
2017/07/15 10:06:38 DEBUG : Movies/: >Lookup: node=Movies/Zootopia (2016)/, err=
2017/07/15 10:06:38 DEBUG : Movies/Zootopia (2016)/: Attr:
2017/07/15 10:06:38 DEBUG : Movies/Zootopia (2016)/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:38 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:38 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:38 DEBUG : Movies/: Attr:
2017/07/15 10:06:38 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:38 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:38 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:38 DEBUG : Movies/: Attr:
2017/07/15 10:06:38 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:38 DEBUG : Movies/: Lookup: name=“Zootopia (2016)”
2017/07/15 10:06:38 DEBUG : Movies/: >Lookup: node=Movies/Zootopia (2016)/, err=
2017/07/15 10:06:38 DEBUG : Movies/Zootopia (2016)/: Attr:
2017/07/15 10:06:38 DEBUG : Movies/Zootopia (2016)/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:39 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:39 DEBUG : Movies/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:39 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:39 DEBUG : Movies/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:39 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:39 DEBUG : Movies/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:39 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:39 DEBUG : Movies/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : Movies/: Lookup: name=“Zootopia (2016)”
2017/07/15 10:06:39 DEBUG : Movies/: >Lookup: node=Movies/Zootopia (2016)/, err=
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:39 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:39 DEBUG : Movies/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:39 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:39 DEBUG : Movies/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : Movies/: Lookup: name=“Zootopia (2016)”
2017/07/15 10:06:39 DEBUG : Movies/: >Lookup: node=Movies/Zootopia (2016)/, err=
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/: ReadDirAll:
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/: >ReadDirAll: item=1, err=
2017/07/15 10:06:39 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:39 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:39 DEBUG : Movies/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:39 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:39 DEBUG : Movies/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:39 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:39 DEBUG : Movies/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:39 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:39 DEBUG : Movies/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : Movies/: Lookup: name=“Zootopia (2016)”
2017/07/15 10:06:39 DEBUG : Movies/: >Lookup: node=Movies/Zootopia (2016)/, err=
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:39 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:39 DEBUG : Movies/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:39 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:39 DEBUG : Movies/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : Movies/: Lookup: name=“Zootopia (2016)”
2017/07/15 10:06:39 DEBUG : Movies/: >Lookup: node=Movies/Zootopia (2016)/, err=
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/: Lookup: name=“Zootopia.mkv”
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/: >Lookup: node=Movies/Zootopia (2016)/Zootopia.mkv, err=
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: Attr:
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: >Attr: a=valid=1m0s ino=0 size=14530039018 mode=-rw-rw-r–, err=
2017/07/15 10:06:39 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:39 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:39 DEBUG : Movies/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:39 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:39 DEBUG : Movies/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : Movies/: Lookup: name=“Zootopia (2016)”
2017/07/15 10:06:39 DEBUG : Movies/: >Lookup: node=Movies/Zootopia (2016)/, err=
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/: Attr:
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/: Lookup: name=“Zootopia.mkv”
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/: >Lookup: node=Movies/Zootopia (2016)/Zootopia.mkv, err=
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: Attr:
2017/07/15 10:06:39 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: >Attr: a=valid=1m0s ino=0 size=14530039018 mode=-rw-rw-r–, err=
2017/07/15 10:06:40 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:40 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:40 DEBUG : Movies/: Attr:
2017/07/15 10:06:40 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:40 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:40 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:40 DEBUG : Movies/: Attr:
2017/07/15 10:06:40 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:40 DEBUG : Movies/: Lookup: name=“Zootopia (2016)”
2017/07/15 10:06:40 DEBUG : Movies/: >Lookup: node=Movies/Zootopia (2016)/, err=
2017/07/15 10:06:40 DEBUG : Movies/Zootopia (2016)/: Attr:
2017/07/15 10:06:40 DEBUG : Movies/Zootopia (2016)/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:40 DEBUG : Movies/Zootopia (2016)/: Lookup: name=“Zootopia.mkv”
2017/07/15 10:06:40 DEBUG : Movies/Zootopia (2016)/: >Lookup: node=Movies/Zootopia (2016)/Zootopia.mkv, err=
2017/07/15 10:06:40 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: Attr:
2017/07/15 10:06:40 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: >Attr: a=valid=1m0s ino=0 size=14530039018 mode=-rw-rw-r–, err=
2017/07/15 10:06:40 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:40 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:40 DEBUG : Movies/: Attr:
2017/07/15 10:06:40 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:40 DEBUG : /: Lookup: name=“Movies”
2017/07/15 10:06:40 DEBUG : /: >Lookup: node=Movies/, err=
2017/07/15 10:06:40 DEBUG : Movies/: Attr:
2017/07/15 10:06:41 DEBUG : Movies/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:41 DEBUG : Movies/: Lookup: name=“Zootopia (2016)”
2017/07/15 10:06:41 DEBUG : Movies/: >Lookup: node=Movies/Zootopia (2016)/, err=
2017/07/15 10:06:41 DEBUG : Movies/Zootopia (2016)/: Attr:
2017/07/15 10:06:41 DEBUG : Movies/Zootopia (2016)/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxrwxr-x, err=
2017/07/15 10:06:41 DEBUG : Movies/Zootopia (2016)/: Lookup: name=“Zootopia.mkv”
2017/07/15 10:06:41 DEBUG : Movies/Zootopia (2016)/: >Lookup: node=Movies/Zootopia (2016)/Zootopia.mkv, err=
2017/07/15 10:06:41 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: Attr:
2017/07/15 10:06:41 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: >Attr: a=valid=1m0s ino=0 size=14530039018 mode=-rw-rw-r–, err=
2017/07/15 10:06:41 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: Open: flags=OpenReadOnly
2017/07/15 10:06:41 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv: >Open: fh=Movies/Zootopia (2016)/Zootopia.mkv ®, err=
2017/07/15 10:06:41 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv ®: Read: len=16384, offset=0
2017/07/15 10:06:41 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv ®: >Read: read=-1, err=bad response: 403: 403 Forbidden
2017/07/15 10:06:41 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv ®: Read: len=4096, offset=0
2017/07/15 10:06:41 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv ®: >Read: read=-1, err=bad response: 403: 403 Forbidden
2017/07/15 10:06:41 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv ®: Release:
2017/07/15 10:06:41 DEBUG : Movies/Zootopia (2016)/Zootopia.mkv ®: >Release: err=

gforce · July 16, 2017, 1:15am

AJ and Team, just want to say you guys are doing great things! Whoever full gets it fully resolved has an instant $100 donation from me (like fully resolved lol).

aj1252 · July 16, 2017, 4:32am

Both versions are handling the bans the same way for me. And I think it should for you as well; the plex entry only goes to unavailiable after a library scan. Try a scan and see if its makes a difference.

aj1252 · July 16, 2017, 4:43am

Buy Nick some flowers because I belive it is fully solved. Both mine and dj’s bans was our own fault.

I’m currently running the following:
Plex: Plexdrive
Sonarr & Radarr: Mount, 1 req/250ms, 25MB/s limit
Seedbox upload: Move, 1 req/250ms, 25MB/s limit
Scaleway sync between clouds: Sync 1 req/250ms, 25MB/s limit

Also tried the following:
Plex & Sonarr & Radarr: Mount, 1 req/100ms

And not got any bans on these.

djsecrist · July 16, 2017, 5:46am

That’s weird because it is definitely different for me. I get two different responses when running mkvinfo against the same file using the two different versions.

Also, Plex has always told me that a file is unavailable even without doing a scan. I think it does a quick analyze or something whenever opening the movie details screen. If the analyze returns an error, it shows unavailable. The new version is not returning an error when Google returns a 403. If I switch my mount to the old version, it returns to the normal behavior; mkvinfo returns the proper error and Plex almost immediately says that the movie is unavailable without running a scan or trying to play it.

Only 1 more hour until my ban is lifted…

aj1252 · July 16, 2017, 5:54am

Mine is already lifted so cannot test.
But this shouldn’t be any problem since with this new version we are never gonna get banned again

djsecrist · July 16, 2017, 8:38am

Well… That sucked… I think my ban was lifted for about 20 minutes before Google dropped the hammer on me again! I can see in the API Manager console that my “queries per 100 seconds” spiked to 253 (15 min average shown in 6hr view) shortly after the ban lifted, but that should still be well below my limit of 1000q/100s. Is there a way to see more detail other than the 1hr or 6hr view in the Google graph? I didn’t check it fast enough to see the 1hr view which shows a 5min average.

I’m not sure what happened… In your earlier or more recent testing, did you determine if each application using the mount was only limited within itself (i.e. parallel)? Was that confirmed? I suppose it is possible that my 200ms setting wasn’t conservative enough with what I had running. I’m going to have to study the log to see what happened. Hopefully I can figure it out. I’m going to up the parameter to 400ms for now in order to be ready for when my freshly minted ban expires… sigh

aj1252 · July 16, 2017, 8:51am

rclone is working as intended, I was just a little confused looking at the log. ncw log commands confirmed this.
If you set 100ms it will never do more that 10req/sec, which looks to me like a sweetspot between performance and not getting bans.

ncw · July 16, 2017, 2:15pm

So when rclone 1.36 opens the file it returns an immediate error, whereas the first error comes from the first read in the beta.

This is a consequence of this change.

That, in general is a good idea as it speeds up fuse operations a lot, especially on windows. I don’t want to revert that change so we need a different work-around!

How important is it to you? My instinct is to leave it as-is because band on drive aren’t that common - what do you think?

ncw · July 16, 2017, 2:18pm

I’ve decided I don’t like the name for the flag --min-transaction-interval as it is far too long!

What would you think about --tpslimit (to echo --bwlimit), then I can add --tpslimit-burst so if you aren’t using your transactions you could accumulate up to that limit to have without waiting.

aj1252 · July 16, 2017, 2:24pm

tpslimit sound fine. Awsome job!

calisro · July 16, 2017, 4:03pm

Isn’t it really a transaction interval and not transactions per second? Not trying to be picky but might be confusing.

ncw · July 16, 2017, 4:09pm

I’ve been back and forth in my mind about that - it brings to mind this quote

There are only two hard things in Computer Science: cache invalidation and naming things.

– Phil Karlton

Anyway I decided that tpslimit does limit the transactions per second so in that case it is accurate. The parameter is perhaps the reciprocal of what you might expect, so what I might do is change it from a duration based limit (10ms) to a floating point number (eg 10 or 0.1) which actually makes more sense in the code anyway.

ncw · July 16, 2017, 5:08pm

I’ve merged this to master now so you can find the latest here

https://beta.rclone.org/v1.36-254-g6f71260a/

And you’ll find it in the latest beta from now on.

Here are the docs for the new flags. So I’ve changed the name and the meaning of the flag, but it still does the same thing! So instead of using --min-transaction-interval 100ms use --tpslimit 10.

Thank you to @aj1252 for suggesting the feature and for diligent testing and to everyone in this thread for their help.

–tpslimit float

Limit HTTP transactions per second to this. Default is 0 which is used to mean unlimited transactions per second.

For example to limit rclone to 10 HTTP transactions per second use --tpslimit 10, or to 1 transaction every 2 seconds use --tpslimit 0.5.

Use this when the number of transactions per second from rclone is causing a problem with the cloud storage provider (eg getting you banned or rate limited).

This can be very useful for rclone mount to control the behaviour of applications using it.

–tpslimit-burst int

Max burst of transactions for --tpslimit. (default 1)

Normally --tpslimit will do exactly the number of transaction per second specified. However if you supply --tps-burst then rclone can save up some transactions from when it was idle giving a burst of up to the parameter supplied.

For example if you provide --tpslimit-burst 10 then if rclone has been idle for more than 10*--tpslimit then it can do 10 transactions very quickly before they are limited again.

This may be used to increase performance of --tpslimit without changing the long term average number of transactions per second.

aj1252 · July 16, 2017, 5:50pm

Great work. Personally just have some fuse panics left, then it should be perfect. Sent you some flowers and beer btc, well deserved.

ncw · July 16, 2017, 6:30pm

Thank you very much @aj1252 much appreciated

Did you file issues about the panics?

aj1252 · July 16, 2017, 6:54pm

yes its on git #1533 #1534

calisro · July 16, 2017, 8:20pm

Good stuff. Can’t wait to give it a whirl.

djsecrist · July 16, 2017, 10:25pm

So when rclone 1.36 opens the file it returns an immediate error, whereas the first error comes from the first read in the beta.

This is a consequence of this change1.

That, in general is a good idea as it speeds up fuse operations a lot, especially on windows. I don’t want to revert that change so we need a different work-around!

In giving this a little thought, I think some form of caching is the best solution here, too. I would even go for a “poor man’s cache” where it uses the “old” behavior the first time it opens a file or if a file hasn’t been opened for x minutes.

This could be the start of a true caching solution, if you haven’t already made plans for that. There could be various levels added as you built it up.
Level 0: “poor man’s cache” that only changes the behavior of RO file open commands
Level 1: minimal caching of just the file attributes
Level 2: moderate caching of file attributes and data
etc…

Of course, you would need to address both of Phil Karlton’s difficulties! The level 0 would be fairly easy though since you could just have a time-based invalidation and wouldn’t need to worry about the file being modified outside of the rclone mount, I think… It greatly improves the user experience when the applications know that a file is unavailable rather than thinking that they have a good file handle, only to have it return no data when they try to read from it.

Thanks again!