Does `--multi-thread-streams` work for Dropbox Business?

What is the problem you are having with rclone?

Does --multi-thread-streams work with Dropbox business? I do not see any logs in DEBUG that indicates that it is working. Does the encrypted drive effect this?

Basically i am trying to do a large amount of seeks on a single file and it is taking a very long time. 64 to be exact. Yes, im trying to get chia to work via rclone. I saw posts that it was done via gdrive.

It looks like by checking out the forms, i should be seeing DEBUG logs indicating the --multi-thread-streams is working, however, i do not. Please let me know if there is any other optimization i can try to make reads faster. Do you think my encrypted drive is hurting performance by a large margin?

What is your rclone version (output from rclone version)

root@VEG64:/home/trevorksmith# rclone version
rclone v1.56.0
- os/version: debian 11.0 (64 bit)
- os/kernel: 5.10.0-8-amd64 (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.16.5
- go/linking: static
- go/tags: none

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

Dropbox Business Unlimited with App ID Keys

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

Likely alot of stuff that doesnt need to be here since its default, but i was trying to play and test things.

/usr/bin/rclone mount \
        --config=/root/.config/rclone/rclone.conf \
        --vfs-cache-mode full \
        --vfs-cache-max-age 168h \
        --vfs-cache-max-size off \
        --vfs-cache-poll-interval 30m \
        --vfs-write-back 5s \
        --vfs-read-chunk-size 64k \
        --vfs-read-chunk-size-limit off \
        --attr-timeout 1s \
        --dir-cache-time 1h \
        --poll-interval 30m \
        --buffer-size 0 \
        --allow-other \
        --cache-dir /srv/cache_2/rclone \
        --no-checksum \
        --no-modtime \
        --read-only \
        --vfs-read-wait 0 \
        --vfs-write-wait 0 \
        --max-read-ahead 0 \
        --fast-list \
        --use-mmap \
        --checkers 0 \
        --multi-thread-cutoff 0 \
        --multi-thread-streams 4 \
        --log-file=/root/.rclone/logs/rclone.txt \
        --log-level DEBUG \
        --use-cookies \
        --no-check-certificate \
        Encrypted_Client_Backups: /srv/plots_2

The rclone config contents with secrets removed.


[Client_Backups]
type = dropbox
client_id = REMOVED
client_secret = REMOVED
chunk_size = 128Ki
token = REMOVED

[Encrypted_Client_Backups]
type = crypt
remote = Client_Backups:/Client Backups/Backups
password = REMOVED
password2 = REMOVED

A log from the command with the -vv flag

Log from DEBUG flag

hi,
i could be wrong but
--multi-thread-streams is used when downloading files, not for seeking withing a file.

how much is the total amount of data in dropbox?

The entire mount is around 5TB, but in regards to the seeks, its a total of 61 seeks on single 100GB file at a time.

I would have thought downloading would be relevant here cause i need to download chuncks of the file on the fly to read it.

Ideally i would want it to send all 64 seeks at once, which i tried with --multi-thread-streams 64, but it seems to not make any difference.

seeking and downloading are not the same.

--fast-list does nothing on a mount...

Wouldn't the VFS layer make it relevant? I was imagining it would mulithread download what I wanted to "seek" and then truly seek it over cache. But my understanding must be incorrect.

And understood, I'll strip it out.

the goal of the vfs cache is not to download the entire file, just to seek parts within it as needed.

Which is exactly what I'm trying to set up

this file you are trying to multi-seek, is that the plot file or what?
what is the size of data per seek?
once a chunk has been read, how many more times will does chia read that chunk?

Yes, it is a reading a single plot. The Chia reads are between 8 and 16KB. It will seek 8 - 16KB a total of 64 times on the plot. It will never read the same chunk of data twice during this.

Is this an issue that my thread keeping timing out? Any explanation so i know whats going on here?

2021/08/05 20:39:21 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:21 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:21 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:27 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:27 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:27 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:27 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:27 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:27 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:27 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:27 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:28 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:28 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:28 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:28 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:28 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:30 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:30 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:31 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:33 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:35 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:35 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:35 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:41 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:41 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:41 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:41 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:41 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:41 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:41 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:41 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:41 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:41 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:41 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:41 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:41 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:44 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:44 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:44 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:45 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:52 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:54 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:57 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:39:59 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:40:01 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:40:03 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:40:11 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:40:13 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:40:15 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:40:18 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:40:20 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:40:20 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:40:20 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:40:20 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:40:20 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:40:23 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out
2021/08/05 20:40:24 DEBUG : plot-k32-2021-08-04-09-39-a66ae2ba9e509bfd2f304befe1918c94a1d22d998e0ee65b9e5ae895a30bb4d9.plot: vfs cache: stopping download thread as it timed out


See:

I did see that while doing my searching. Maybe im confused, but why is it timing out if there is more data to be downloaded from the thread on that particular file?

I would be expecting it to keep using that same thread that's already open to do multiple seeks, but yet it looks like multiple threads are instead timing out within very short window frames.

I guess just trying to understand whats going on. I did warm heartily try to read as much as i could before posting here. Just still confused on whats going on.

I can only see a snippet of a log and there are the only errors that are there which means a thread timed out as it got nothing back over and over.

I can only go by the logfile snippet you got as there's nothing else there.

Link to log file.

The snippet i provided was me grepping that for "timed out"

maybe i should try troubleshooting this without the encrypted drive first.

That seems to be part of the file so I'm not sure what command you ran as it's only a partial file.

I had echo'd it clear so there was no junk in there. I echo'd it clear before starting the mount this time so you can see how it started. Sorry about that. Should be entire log file this time. I cleared the logs, started the mount, performed the test, then closed mount.

Here is the related chia logs, if needed. Timestamps may be useful.

A single challenge should perform 7 seeks, followed by another 64 seeks. Seeks should be between 8 and 16KB in size, however, i don't quite know how to interpret the logs correct to follow whats going on in rclone. In this test, 5 challenges were performed. The times for each challenge took a total of 30-45 seconds. This needs to be under 30, the more, the better.

2021-08-10T11:21:47.124  chia.plotting.check_plots        : INFO     Starting to test each plot with 5 challenges each

2021-08-10T11:21:47.124  chia.plotting.check_plots        : INFO     Testing plot /srv/plots_2/plot-k32-2021-08-04-09-39-a66ae2ba9.plot k=32
2021-08-10T11:21:47.124  chia.plotting.check_plots        : INFO        Pool public key: None
2021-08-10T11:21:47.133  chia.plotting.check_plots        : INFO        Farmer public key: 8d3bf651ad680e05dece642533a10a67ad8e2794d
2021-08-10T11:21:47.133  chia.plotting.check_plots        : INFO        Local sk: <PrivateKey 3e2e531ab8f075c915855fc3f233e824598
2021-08-10T11:21:47.221  chia.plotting.check_plots        : INFO        Looking up qualities took: 87 ms.
2021-08-10T11:22:06.979  chia.plotting.check_plots        : WARNING     Finding proof took: 19758 ms. This should be below 15 sec
2021-08-10T11:22:06.980  chia.plotting.check_plots        : INFO        Looking up qualities took: 0 ms.
2021-08-10T11:22:26.506  chia.plotting.check_plots        : WARNING     Finding proof took: 19526 ms. This should be below 15 sec
2021-08-10T11:22:37.912  chia.plotting.check_plots        : WARNING     Looking up qualities took: 11406 ms. This should be below
 2021-08-10T11:22:57.871  chia.plotting.check_plots        : WARNING    Finding proof took: 19958 ms. This should be below 15 sec
2021-08-10T11:23:08.439  chia.plotting.check_plots        : WARNING     Looking up qualities took: 10567 ms. This should be below
2021-08-10T11:23:29.998  chia.plotting.check_plots        : WARNING     Finding proof took: 21560 ms. This should be below 15 sec
2021-08-10T11:23:55.713  chia.plotting.check_plots        : WARNING     Looking up qualities took: 25714 ms. This should be below
2021-08-10T11:24:16.572  chia.plotting.check_plots        : WARNING     Finding proof took: 20858 ms. This should be below 15 sec
2021-08-10T11:24:16.572  chia.plotting.check_plots        : INFO        Looking up qualities took: 0 ms.
2021-08-10T11:24:37.947  chia.plotting.check_plots        : WARNING     Finding proof took: 21375 ms. This should be below 15 sec
2021-08-10T11:24:37.948  chia.plotting.check_plots        : INFO        Looking up qualities took: 0 ms.
2021-08-10T11:24:57.306  chia.plotting.check_plots        : WARNING     Finding proof took: 19358 ms. This should be below 15 sec

I'm trying to find a way to optimize this for faster times. I dont believe i am hitting any API limits yet, so i think i should be able to configure to be more aggressive (although i don't know how). The testing im doing itself is more agressive that what the mount will be doing after setup, so if im not hitting api limits not, i surely wont be hitting them once its passively running, and not doing active tests. I think i may have read that dropbox only support seeks in sequence on a single file? not sure if its true, but if so, maybe that's the bottleneck.

Im not expecting you to do any major legwork for me, i feel bad enough asking for help, i feel like i should be able to figure this out but i struggle to understand the log outputs.

If your skilled enough, can you just let me know if you see any major gaps for optimizations?

Here is my mount for readability.

[Unit]
Description=Client Backups Cyber Forces
AssertPathIsDirectory=/srv/plots_2
After=network-online.target

[Service]
Type=simple
ExecStart=/usr/bin/rclone mount \
        --config=/root/.config/rclone/rclone.conf \
        --vfs-cache-mode full \
        --vfs-cache-max-age 168h \
        --vfs-cache-max-size off \
        --vfs-cache-poll-interval 30m \
        --vfs-write-back 5s \
        --vfs-read-chunk-size 64k \
        --vfs-read-chunk-size-limit off \
        --attr-timeout 1s \
        --dir-cache-time 1h \
        --poll-interval 30m \
        --buffer-size 0 \
        --allow-other \
        --cache-dir /srv/cache_2/rclone \
        --no-checksum \
        --no-modtime \
        --read-only \
        --vfs-read-wait 0 \
        --vfs-write-wait 0 \
        --max-read-ahead 0 \
        --use-mmap \
        --checkers 0 \
        --multi-thread-cutoff 0 \
        --multi-thread-streams 64 \
        --log-file=/root/.rclone/logs/rclone.txt \
        --log-level DEBUG \
        --use-cookies \
        --no-check-certificate \
        --drive-pacer-min-sleep 1ms \
        --disable-http2 \
        Client_Backups:Test /srv/plots_2
ExecStop=/bin/fusermount -u /srv/plots_2
Restart=always
RestartSec=10

[Install]
WantedBy=default.target

Offtopic, but if you or the rclone team every needs a business dropbox account to test for rclone development, I would be more than happy to provide one anytime for free. Just let me know.

Is anyone able to interpret the DEBUG messages to understand whats going on?

Example, does anyone know what this means in the logs?

2021/08/10 11:21:57 DEBUG : vfs cache: looking for range={Pos:25389215744 Size:4096} in [{Pos:0 Size:65536} {Pos:2465468416 Size:32768} {Pos:8954368000 Size:65536} {Pos:11809198080 Size:65536} {Pos:12242497536 Size:32768} {Pos:12884443136 Size:32768} {Pos:16047853568 Size:32768} {Pos:16080052224 Size:32768} {Pos:17228468224 Size:32768} {Pos:19930664960 Size:65536} {Pos:20944281600 Size:32768} {Pos:21340979200 Size:32768} {Pos:22404362240 Size:32768} {Pos:23093297152 Size:32768} {Pos:23694495744 Size:65536} {Pos:24958713856 Size:32768} {Pos:25380401152 Size:65536} {Pos:26130001920 Size:32768} {Pos:27208454144 Size:32768} {Pos:27513323520 Size:32768} {Pos:27639390208 Size:32768} {Pos:29232971776 Size:65536} {Pos:31867813888 Size:65536} {Pos:33731051520 Size:65536} {Pos:34313691136 Size:65536} {Pos:36828667904 Size:65536} {Pos:36842061824 Size:32768} {Pos:38007894016 Size:65536} {Pos:39846555648 Size:65536} {Pos:40628129792 Size:32768} {Pos:45091876864 Size:65536} {Pos:47548080128 Size:65536} {Pos:49014792192 Size:65536} {Pos:51703218176 Size:65536} {Pos:52994203648 Size:65536} {Pos:58613534720 Size:65536} {Pos:62928531456 Size:65536} {Pos:64712396800 Size:65536} {Pos:76605689856 Size:65536} {Pos:88327909376 Size:65536} {Pos:96895426560 Size:65536} {Pos:107520962560 Size:65536} {Pos:107521998848 Size:65536} {Pos:108037201920 Size:65536}] - present false

It checked for part of the file in the the cache, didn't find it and I'd assume the next line is it downloading it.