dvc pull does not seem to work for files whose md5 starts with 00

[jnd77]

Bug Report

Please provide information about your setup

Output of dvc version:
1.1.1

Additional Information (if any):

When I run dvc pull on a repo with around 500+ items, all but 4 are retrieved successfully .
I have noticed these 4 files all have a md5 starting with 00 and therefore are in a folder called 00 in their S3 bucket.
(these 4 files are also the only ones in that folder)

Finally, it works fine if I revert back to 0.90.2 version.

[2020-07-01T03:20:41.823Z] WARNING: Some of the cache files do not exist neither locally nor on remote. Missing cache files:
[2020-07-01T03:20:41.823Z] name: file_1, md5: 0095a0fe51ee2bd82af8c340cb67d498
[2020-07-01T03:20:41.823Z] name: file_2, md5: 00d434948357f9d1acfc946b6eaf7545
[2020-07-01T03:20:41.823Z] name: file_3, md5: 007ae42fd5c0a6dcbd5e9e21f7d87839
[2020-07-01T03:20:41.823Z] name: file_4, md5: 00b0505560fdac60652fd50deaf7b95b
[2020-07-01T03:21:52.089Z] WARNING: Cache '0095a0fe51ee2bd82af8c340cb67d498' not found. File 'file_1' won't be created.
[2020-07-01T03:21:52.089Z] WARNING: Cache '007ae42fd5c0a6dcbd5e9e21f7d87839' not found. File 'file_2' won't be created.
[2020-07-01T03:21:52.089Z] WARNING: Cache '00d434948357f9d1acfc946b6eaf7545' not found. File 'file_3' won't be created.
[2020-07-01T03:21:52.089Z] WARNING: Cache '00b0505560fdac60652fd50deaf7b95b' not found. File 'file_4' won't be created.

...

ERROR: failed to pull data from the cloud - Checkout failed for following targets:

[2020-07-01T03:21:52.094Z] file_1
[2020-07-01T03:21:52.094Z] file_2
[2020-07-01T03:21:52.094Z] file_3
[2020-07-01T03:21:52.094Z] file_4
[2020-07-01T03:21:52.094Z] Did you forget to fetch?

[pmrowla]

@jnd77 thanks for the bug report. Could you post the rest of your verbose output (linking a gist or something would be fine)?

Bug is most likely something causing us to drop the hashes fetched during remote size estimation after:

dvc/dvc/remote/base.py

Line 816 in 00c135f

remote_size, remote_hashes = self.tree.estimate_remote_size(

[pmrowla]

more discord context https://discordapp.com/channels/485586884165107732/485596304961962003/727419109167595531

[jnd77]

Thanks @pmrowla to have suck a quick look.

I reran with --verbose.
Here is the output:

[2020-07-01T05:14:57.317Z] 2020-07-01 05:14:57,192 DEBUG: Trying to spawn '['/usr/local/bin/python', '/home/builder/.local/bin/dvc', 'daemon', '-q', 'updater']'
[2020-07-01T05:14:57.317Z] 2020-07-01 05:14:57,193 DEBUG: Spawned '['/usr/local/bin/python', '/home/builder/.local/bin/dvc', 'daemon', '-q', 'updater']'
[2020-07-01T05:14:58.598Z] 2020-07-01 05:14:58,107 DEBUG: Preparing to download data from 's3://XXX/dvc-resources-cache'
[2020-07-01T05:14:58.598Z] 2020-07-01 05:14:58,107 DEBUG: Preparing to collect status from s3://XXX/dvc-resources-cache
[2020-07-01T05:14:58.598Z] 2020-07-01 05:14:58,108 DEBUG: Collecting information from local cache...

Following is identical for all files:

[2020-07-01T05:14:58.598Z] 2020-07-01 05:14:58,109 DEBUG: cache 'xxx/.dvc/cache/f4/71d8a795e0d11d3c78b0c2a4db5f2a' expected 'f471d8a795e0d11d3c78b0c2a4db5f2a' actual 'None'
[2020-07-01T05:14:58.598Z] 2020-07-01 05:14:58,109 DEBUG: cache 'xxx/.dvc/cache/af/51d6315d981d259363b2f52abc7626' expected 'af51d6315d981d259363b2f52abc7626' actual 'None'
...

[2020-07-01T05:14:58.607Z] 2020-07-01 05:14:58,164 DEBUG: Collecting information from remote cache...
[2020-07-01T05:14:58.607Z] 2020-07-01 05:14:58,165 DEBUG: Matched '0' indexed hashes
[2020-07-01T05:15:00.476Z] 2020-07-01 05:15:00,452 DEBUG: Estimated remote size: 4096 files
[2020-07-01T05:15:00.476Z] 2020-07-01 05:15:00,452 DEBUG: Querying '511' hashes via traverse
[2020-07-01T05:15:08.073Z] 2020-07-01 05:15:06,965 WARNING: Some of the cache files do not exist neither locally nor on remote. Missing cache files:

[2020-07-01T05:15:08.073Z] name: file_1, md5: 0095a0fe51ee2bd82af8c340cb67d498
[2020-07-01T05:15:08.073Z] name: file_2, md5: 00d434948357f9d1acfc946b6eaf7545
[2020-07-01T05:15:08.073Z] name: file_3, md5: 007ae42fd5c0a6dcbd5e9e21f7d87839
[2020-07-01T05:15:08.073Z] name: file_4, md5: 00b0505560fdac60652fd50deaf7b95b

Then for all files except the 4 ones:

[2020-07-01T05:15:08.073Z] 2020-07-01 05:15:07,256 DEBUG: Downloading 's3://XXX/dvc-resources-cache/22/3d90d352451f23a530020f0ec5a170' to '.dvc/cache/22/3d90d352451f23a530020f0ec5a170'
...

Again same for all files except the 4 problematic ones:

[2020-07-01T05:16:19.840Z] 2020-07-01 05:16:14,105 DEBUG: Path '.dvc/cache/22/3d90d352451f23a530020f0ec5a170' inode '102763765'
[2020-07-01T05:16:19.840Z] 2020-07-01 05:16:14,106 DEBUG: fetched: []

...

For successful files, I get something like:

[2020-07-01T05:16:19.850Z] 2020-07-01 05:16:14,267 DEBUG: checking if 'good_file'('{'md5': 'c312e2e4d31bd1a1e830d6c94f79c827'}') has changed.
[2020-07-01T05:16:19.850Z] 2020-07-01 05:16:14,267 DEBUG: 'good_file' doesn't exist.
[2020-07-01T05:16:19.850Z] 2020-07-01 05:16:14,268 DEBUG: Path 'xxx/.dvc/cache/c3/12e2e4d31bd1a1e830d6c94f79c827' inode '102892085'
[2020-07-01T05:16:19.850Z] 2020-07-01 05:16:14,268 DEBUG: fetched: [('1593580516374882304', '780984', 'c312e2e4d31bd1a1e830d6c94f79c827', '1593580574142706432')]
[2020-07-01T05:16:19.850Z] 2020-07-01 05:16:14,268 DEBUG: cache 'xxx/.dvc/cache/c3/12e2e4d31bd1a1e830d6c94f79c827' expected 'c312e2e4d31bd1a1e830d6c94f79c827' actual 'c312e2e4d31bd1a1e830d6c94f79c827'
[2020-07-01T05:16:19.850Z] 2020-07-01 05:16:14,268 DEBUG: Checking out 'good_file' with cache 'c312e2e4d31bd1a1e830d6c94f79c827'.
[2020-07-01T05:16:19.850Z] 2020-07-01 05:16:14,268 DEBUG: Cache type 'reflink' is not supported: reflink is not supported
[2020-07-01T05:16:19.850Z] 2020-07-01 05:16:14,269 DEBUG: Created 'copy': .dvc/cache/c3/12e2e4d31bd1a1e830d6c94f79c827 -> good_file
[2020-07-01T05:16:19.850Z] 2020-07-01 05:16:14,269 DEBUG: Path 'good_file' inode '102242719'
[2020-07-01T05:16:19.850Z] 2020-07-01 05:16:14,269 DEBUG: Path 'good_file' inode '102242719'
[2020-07-01T05:16:19.850Z] 2020-07-01 05:16:14,269 DEBUG: fetched: []


For the 4 files, I get something like:

[2020-07-01T05:16:19.854Z] 2020-07-01 05:16:14,320 DEBUG: checking if 'file_2'('{'md5': '00d434948357f9d1acfc946b6eaf7545'}') has changed.
[2020-07-01T05:16:19.854Z] 2020-07-01 05:16:14,320 DEBUG: 'file_2' doesn't exist.
[2020-07-01T05:16:19.854Z] 2020-07-01 05:16:14,320 DEBUG: cache 'xxx/.dvc/cache/00/d434948357f9d1acfc946b6eaf7545' expected '00d434948357f9d1acfc946b6eaf7545' actual 'None'
[2020-07-01T05:16:19.854Z] 2020-07-01 05:16:14,320 WARNING: Cache '00d434948357f9d1acfc946b6eaf7545' not found. File 'file_2' won't be created.

...

[2020-07-01T05:16:19.937Z] 2020-07-01 05:16:16,213 DEBUG: fetched: [(0,)]
[2020-07-01T05:16:19.937Z] A	good_file
...

[2020-07-01T05:16:19.942Z] 553 files added and 4 files failed
[2020-07-01T05:16:19.942Z] 2020-07-01 05:16:16,246 ERROR: failed to pull data from the cloud - Checkout failed for following targets:
[2020-07-01T05:16:19.942Z] file_1
[2020-07-01T05:16:19.942Z] file_2
[2020-07-01T05:16:19.942Z] file_3
[2020-07-01T05:16:19.942Z] file_4
[2020-07-01T05:16:19.942Z] Did you forget to fetch?
[2020-07-01T05:16:19.942Z] ------------------------------------------------------------
[2020-07-01T05:16:19.942Z] Traceback (most recent call last):
[2020-07-01T05:16:19.942Z]   File "xxx/.local/lib/python3.8/site-packages/dvc/command/data_sync.py", line 26, in run
[2020-07-01T05:16:19.942Z]     stats = self.repo.pull(
[2020-07-01T05:16:19.943Z]   File "xxx/.local/lib/python3.8/site-packages/dvc/repo/__init__.py", line 36, in wrapper
[2020-07-01T05:16:19.943Z]     ret = f(repo, *args, **kwargs)
[2020-07-01T05:16:19.943Z]   File "xxx/.local/lib/python3.8/site-packages/dvc/repo/pull.py", line 36, in pull
[2020-07-01T05:16:19.943Z]     stats = self._checkout(  # pylint: disable=protected-access
[2020-07-01T05:16:19.943Z]   File "xxx/.local/lib/python3.8/site-packages/dvc/repo/checkout.py", line 101, in _checkout
[2020-07-01T05:16:19.943Z]     raise CheckoutError(stats["failed"], stats)
[2020-07-01T05:16:19.943Z] dvc.exceptions.CheckoutError: Checkout failed for following targets:
[2020-07-01T05:16:19.943Z] file_1
[2020-07-01T05:16:19.943Z] file_2
[2020-07-01T05:16:19.943Z] file_3
[2020-07-01T05:16:19.943Z] file_4
[2020-07-01T05:16:19.943Z] Did you forget to fetch?

[jnd77]

I have run this within a simple Docker container:

FROM python:alpine
RUN addgroup -S -g 1000 builder && adduser -S -u 1000 -G builder builder
RUN apk add --update build-base python3 python3-dev zlib-dev jpeg-dev linux-headers git bash openssh
USER builder
RUN pip3 install --no-cache-dir --upgrade pip
RUN pip3 install --no-cache-dir dvc[s3]==1.1.2
ENV PATH $PATH:/home/builder/.local/bin/

[pmrowla]

Issue is that for S3 walk_files we force appending a trailing slash to paths

dvc/dvc/remote/s3.py

Lines 189 to 190 in 07da9f1

	def walk_files(self, path_info, **kwargs):
	for fname in self._list_paths(path_info / "", **kwargs):

This breaks behavior when we try to walk 3-character prefixes like 00/0, 00/1, ..., 00/f since we end up trying to walk 00/0/ instead.

Being able to walk arbitrary-length prefixes is useful (for remotes that support it). So I think we should probably explicitly append trailing slashes before calling remote_tree.walk_files whenever that is the intended behavior, rather than appending the slash in the remote-specific walk_files implementations.

This was not an issue before the 1.x remote tree refactor because we had the separate (but essentially duplicated) list_cache_paths and walk_files methods

[jnd77]

Thanks guys. :)