add: Fails to add file to shared cache on windows drive mount, regression from 1.7.2

[gamis]

Bug Report

add: Fails to add file to shared cache on windows drive mount

Description

We have a shared dvc cache on a ZFS file server shared via Samba. On Windows machines, it is mounted as a drive letter. At one point, we could dvc add a file from a windows machine, and dvc would move the file to the cache and replace the local file with a symlink, as expected.

Somewhere between v1.7.2 and v1.11.10, it stopped working. Specifically, this is what appears to happen:

1. The file hash is calculated as expected.
2. The file bytes are copied to the cache under the correct name, but with the random suffix, denoting that the copy is in progress.
3. It never seems to be able to rename the cache file to it's final file name without the random suffix. No error is emitted, even with -v.
4. No .dvc file is created.
5. It errors out at a point where it's probably trying to replace the local file with a symlink. Output below.

Note that this happens even if I change the cache.type to copy, even if I run from an Admin-elevated cmd.

Note also that the same operation runs just fine using a Ubuntu machine connecting to the same cache.

Reproduce

mkdir D:\dvcregression
mkdir Z:\dvcregression_cache
cd D:\dvcregression
git init
dvc init
dvc config cache.dir Z:\dvcregression_cache
# copy in file TC3-096.oct to D:\dvcregression
dvc add -v TC3-096.oct

And you get the error pasted below.

2021-01-12 15:44:59,435 DEBUG: Check for update is enabled.
2021-01-12 15:44:59,514 DEBUG: Trying to spawn '['daemon', '-q', 'updater']'
2021-01-12 15:45:03,013 DEBUG: Spawned '['daemon', '-q', 'updater']'
2021-01-12 15:45:03,420 DEBUG: Adding 'TC3-096.oct' to '.gitignore'.
2021-01-12 15:45:03,451 DEBUG: Path 'D:\dvcregression\TC3-096.oct' inode '5598938201872874496'
2021-01-12 15:45:03,451 DEBUG: fetched: []
2021-01-12 15:45:04,107 DEBUG: Path 'TC3-096.oct' inode '5598938201872874496'
2021-01-12 15:45:04,107 DEBUG: fetched: []
2021-01-12 15:45:04,107 DEBUG: {'TC3-096.oct': 'modified'}
2021-01-12 15:45:04,107 DEBUG: Path 'D:\dvcregression\TC3-096.oct' inode '5598938201872874496'
2021-01-12 15:45:04,107 DEBUG: fetched: [('1607391879537605376', '364223321', '9baae98c6a197008759288d2dca21ea7', '1610484304107641088')]
2021-01-12 15:45:04,107 DEBUG: Computed stage: 'TC3-096.oct.dvc' md5: 'None'
2021-01-12 15:45:04,123 DEBUG: Saving 'TC3-096.oct' to 'Z:\dvcregression_cache\9b\aae98c6a197008759288d2dca21ea7'.
2021-01-12 15:45:04,123 DEBUG: cache 'Z:\dvcregression_cache\9b\aae98c6a197008759288d2dca21ea7' expected 'HashInfo(name='md5', value='9baae98c6a197008759288d2dca21ea7', dir_info=None, size=364223321, nfiles=None)' actual 'None'
Adding...
2021-01-12 15:45:05,201 DEBUG: fetched: [(0,)]
2021-01-12 15:45:05,217 ERROR: unexpected error - [WinError 5] Access is denied: 'D:\\dvcregression\\TC3-096.oct'
------------------------------------------------------------
Traceback (most recent call last):
  File "shutil.py", line 566, in move
OSError: [WinError 17] The system cannot move the file to a different disk drive: 'D:\\dvcregression\\TC3-096.oct' -> 'Z:\\dvcregression_cache\\9b\\aae98c6a197008759288d2dca21ea7.mFkbHoodLwcYscY9yK6gCZ'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "dvc\main.py", line 90, in main
  File "dvc\command\add.py", line 24, in run
  File "dvc\repo\__init__.py", line 54, in wrapper
  File "dvc\repo\scm_context.py", line 4, in run
  File "dvc\repo\add.py", line 85, in add
  File "dvc\repo\add.py", line 124, in _process_stages
  File "site-packages\funcy\decorators.py", line 39, in wrapper
  File "dvc\stage\decorators.py", line 36, in rwlocked
  File "site-packages\funcy\decorators.py", line 60, in __call__
  File "dvc\stage\__init__.py", line 478, in commit
  File "dvc\output\base.py", line 297, in commit
  File "site-packages\funcy\decorators.py", line 39, in wrapper
  File "dvc\cache\base.py", line 40, in use_state
  File "site-packages\funcy\decorators.py", line 60, in __call__
  File "dvc\cache\base.py", line 317, in save
  File "dvc\cache\base.py", line 326, in _save
  File "dvc\cache\base.py", line 194, in _save_file
  File "dvc\tree\local.py", line 177, in move
  File "dvc\utils\fs.py", line 111, in move
  File "shutil.py", line 581, in move
PermissionError: [WinError 5] Access is denied: 'D:\\dvcregression\\TC3-096.oct'
------------------------------------------------------------
2021-01-12 15:45:05,795 DEBUG: Version info for developers:
DVC version: 1.11.10 (exe)
---------------------------------
Platform: Python 3.7.9 on Windows-10-10.0.18362-SP0
Supports: All remotes
Cache types: symlink
Cache directory: NTFS on Z:\
Caches: local
Remotes: None
Workspace directory: NTFS on D:\
Repo: dvc, git

Expected

Expect that dvc would continue to support a shared cache like this.

Environment information

Output of dvc version:

DVC version: 1.11.10 (exe)
---------------------------------
Platform: Python 3.7.9 on Windows-10-10.0.18362-SP0
Supports: All remotes
Cache types: symlink
Cache directory: NTFS on Z:\
Caches: local
Remotes: None
Workspace directory: NTFS on D:\
Repo: dvc, git

Additional Information (if any):

From the error output, it seems that dvc expects that a "local" cache is always going to be on the same drive, which is not the case here. Is there a way to tell it not to have that expectation?

I tried reverting to 1.7.2 and confirmed it still works there. I can try searching for the breaking version, but I'd appreciate some guidance.

[efiop]

Hi @gamis !

Looks like shutil.move properly fallen back to copy&delete logic but then failed to delete the source file https://github.com/python/cpython/blob/117830de332c8dfbd9a437c0968e16e11aa7e6a1/Lib/shutil.py#L581 What are the permissions on dvcregression\TC3-096.oct, is it read-only?

[gamis]

Hi @efiop , note that the cache file never gets renamed from it's temporary form, with the random suffix. I confirmed that the cache file is complete; it has the same sha-256 as the original file.

Also, TC3-096.oct was originally not read-only but it appears dvc changes it to read only at some point.

[efiop]

@gamis Indeed, we make it read-only before the move, to make it atomic.

dvc/dvc/utils/fs.py

Line 111 in 77bc277

shutil.move(src, tmp)

Strange that we didn't catch it in our windows tests, need to take a closer look...

[gamis]

I have now tried with a more recent python version (3.8.6, i had been using 3.7.2), and same problem.
I even tried just making the cache on a different local drive, not even a network mount, and it fails.
So definitely something wrong with dvc knowing when it needs to copy rather than just rename.

[efiop]

@gamis Makes sense. The regression is likely in #4832 . Looking into it.

[efiop]

@gamis Ok, so the issue is that after #4832 we started testing access with that chmod, which also leaves the file with incorrect permissions in case of a failure. Need to handle it gracefully.

[gamis]

Does that explain why the cache file isn't being renamed from its temp form to the final form?

[efiop]

@gamis Yeah, it fails to unlink the temporary file, because on windows if file is read-only - you can't delete it.

[efiop]

@gamis We've adjusted this in the upstream (future 2.0) and reverted the PR that has caused this bug in 1.11.x. 1.11.12 will be out on pypi in a few minutes. Please give it a try and let us know if that works for you. Thanks! 🙏

[gamis]

Sorry to say, that didn't fix it!

On a separate thread of discussion, I've mentioned that we recently abandoned trying to use this shared cache over the network, instead using it as a "local" remote. But this same Windows issue persists.

If I call dvc push -v -r z, I get the output below.

2021-01-25 08:55:31,080 DEBUG: Check for update is disabled.
2021-01-25 08:55:31,096 DEBUG: fetched: [(3,)]
2021-01-25 08:57:50,768 DEBUG: Assuming 'H:\researchdata\.dvc\cache\2b\95ceac01304e1ce8511f59b07c5db2.dir' is unchanged since it is read-only
2021-01-25 08:57:50,768 DEBUG: Assuming 'H:\researchdata\.dvc\cache\2b\95ceac01304e1ce8511f59b07c5db2.dir' is unchanged since it is read-only
2021-01-25 08:57:50,768 DEBUG: Assuming 'H:\researchdata\.dvc\cache\15\393c7590870fe4b29f4b6836a38c98.dir' is unchanged since it is read-only
2021-01-25 08:57:50,768 DEBUG: Assuming 'H:\researchdata\.dvc\cache\15\393c7590870fe4b29f4b6836a38c98.dir' is unchanged since it is read-only
2021-01-25 08:57:50,784 DEBUG: Preparing to upload data to 'Z:\researchdata'
2021-01-25 08:57:50,784 DEBUG: Preparing to collect status from Z:\researchdata
2021-01-25 08:57:50,847 DEBUG: Collecting information from local cache...
2021-01-25 08:53:19,893 DEBUG: cache 'H:\researchdata\.dvc\cache\81\466ad7a5e5d242552ae7e170b65bf6' expected 'HashInfo(name='md5', value='81466ad7a5e5d242552ae7e170b65bf6', dir_info=None, size=None, nfiles=None)' actual 'None'
# the above is repeated many times, because I haven't pulled the full dvc repo down to this local cache.

2021-01-25 08:53:20,080 ERROR: unexpected error - [WinError 6] The handle is invalid: 'Z:\\researchdata\\29\\b21cb5993462d6e33980e361652a6b'
------------------------------------------------------------
Traceback (most recent call last):
  File "g:\temp\venvs\dvc_regression\lib\site-packages\dvc\main.py", line 90, in main
    ret = cmd.run()
  File "g:\temp\venvs\dvc_regression\lib\site-packages\dvc\command\data_sync.py", line 50, in run
    processed_files_count = self.repo.push(
  File "g:\temp\venvs\dvc_regression\lib\site-packages\dvc\repo\__init__.py", line 54, in wrapper
    return f(repo, *args, **kwargs)
  File "g:\temp\venvs\dvc_regression\lib\site-packages\dvc\repo\push.py", line 35, in push
    return len(used_run_cache) + self.cloud.push(used, jobs, remote=remote)
  File "g:\temp\venvs\dvc_regression\lib\site-packages\dvc\data_cloud.py", line 65, in push
    return remote.push(
  File "g:\temp\venvs\dvc_regression\lib\site-packages\dvc\remote\base.py", line 56, in wrapper
    return f(obj, *args, **kwargs)
  File "g:\temp\venvs\dvc_regression\lib\site-packages\dvc\remote\base.py", line 432, in push
    return self._process(
  File "g:\temp\venvs\dvc_regression\lib\site-packages\dvc\remote\base.py", line 327, in _process
    dir_status, file_status, dir_contents = self._status(
  File "g:\temp\venvs\dvc_regression\lib\site-packages\dvc\remote\base.py", line 175, in _status
    self.hashes_exist(
  File "g:\temp\venvs\dvc_regression\lib\site-packages\dvc\remote\base.py", line 132, in hashes_exist
    return indexed_hashes + self.cache.hashes_exist(list(hashes), **kwargs)
  File "g:\temp\venvs\dvc_regression\lib\site-packages\dvc\cache\local.py", line 47, in hashes_exist
    return [
  File "g:\temp\venvs\dvc_regression\lib\site-packages\dvc\cache\local.py", line 55, in <listcomp>
    if not self.changed_cache_file(
  File "g:\temp\venvs\dvc_regression\lib\site-packages\dvc\cache\base.py", line 368, in changed_cache_file
    self.tree.protect(cache_info)
  File "g:\temp\venvs\dvc_regression\lib\site-packages\dvc\tree\local.py", line 301, in protect
    self.chmod(path_info, self.CACHE_MODE)
  File "g:\temp\venvs\dvc_regression\lib\site-packages\dvc\tree\local.py", line 249, in chmod
    os.chmod(path, mode)
OSError: [WinError 6] The handle is invalid: 'Z:\\researchdata\\29\\b21cb5993462d6e33980e361652a6b'
------------------------------------------------------------
2021-01-25 08:53:20,142 DEBUG: Version info for developers:
DVC version: 1.11.12 (pip)
---------------------------------
Platform: Python 3.8.6 on Windows-10-10.0.18362-SP0
Supports: http, https
Cache types: hardlink, symlink
Caches: local
Remotes: local, ssh, ssh, local
Repo: dvc, git

[efiop]

@gamis The move was successful, but protect()-ing wasn't, so this is a new issue. We were thinking of just ignoring protect() errors, as they are not fatal, we just try to make the file read-only for some additional safety. Still, pretty odd that chmod is failing like that, might be a filesystem limitation. Could you try pip install psutil and then run dvc doctor again and show us the output for it, please?

[gamis]

This is strange because a) it worked in 1.7.2, and b) If I check that cache file on Z, it is indeed read-only for user, group, and other.

[gamis]

DVC version: 1.11.12 (pip)
---------------------------------
Platform: Python 3.8.6 on Windows-10-10.0.18362-SP0
Supports: http, https
Cache types: hardlink, symlink
Cache directory: NTFS on H:\
Caches: local
Remotes: local, ssh, ssh, local
Workspace directory: NTFS on H:\
Repo: dvc, git

[gamis]

This happens on dvc pull as well. Not sure why dvc should be trying to modify anything on the remote cache on a pull.

[efiop]

@gamis It checks if the cache file is intact and tries to set it read-only, so that it doesn't need to check it next time. We could also consider supporting verify config option for that, to make dvc skip the verification for those cache files for trusted local remotes (it skips it for most of other remote types by default).

[gamis]

That seems like a good option. If other remote types skip it, and people would generally expect a pull to not change remote in anyway, then skipping seems appropriate to me.

[efiop]

@gamis Besides the question of chmoding on remote, I'm still surprised that the chmod error is so odd. It might affect people that have their cache on samba. Leaning towards ignoring such errors for protect(), as they are really not fatal.

[efiop]

Keeping open for confirmation.

Backporting to 1.11.x...

[efiop]

@gamis 1.11.13 is out, please give it a try and let us know how it goes.

[gamis]

It appears that fixed the problem! Thanks as always for all the hard work and determination.

[efiop]

@gamis Thanks for the feedback! 🙏