Bug #18316
closedarv-mount tries to save collection on file close even in read-only mode
Description
De-identified customer backtrace:
2021-11-01 15:22:50 arvados.arvados_fuse127303 ERROR: Error during finalize of inode 13
Traceback (most recent call last):
File "/usr/share/python3/dist/python3-arvados-fuse/lib/python3.8/site-packages/arvados_fuse/__init__.py", line 314, in clear
v.finalize()
File "/usr/share/python3/dist/python3-arvados-fuse/lib/python3.8/site-packages/arvados_fuse/fusedir.py", line 581, in finalize
self.collection.save()
File "/usr/share/python3/dist/python3-arvados-fuse/lib/python3.8/site-packages/arvados/arvfile.py", line 469, in must_be_writable_wrapper
return orig_func(self, *args, **kwargs)
File "/usr/share/python3/dist/python3-arvados-fuse/lib/python3.8/site-packages/arvados/arvfile.py", line 270, in synchronized_wrapper
return orig_func(self, *args, **kwargs)
File "/usr/share/python3/dist/python3-arvados-fuse/lib/python3.8/site-packages/arvados/retry.py", line 177, in num_retries_setter
return orig_func(self, *args, **kwargs)
File "/usr/share/python3/dist/python3-arvados-fuse/lib/python3.8/site-packages/arvados/collection.py", line 1626, in save
self._remember_api_response(self._my_api().collections().update(
File "/usr/share/python3/dist/python3-arvados-fuse/lib/python3.8/site-packages/googleapiclient/_helpers.py", line 134, in positional_wrapper
return wrapped(*args, **kwargs)
File "/usr/share/python3/dist/python3-arvados-fuse/lib/python3.8/site-packages/googleapiclient/http.py", line 915, in execute
raise HttpError(resp, content, uri=self.uri)
arvados.errors.ApiError: <HttpError 403 when requesting https://.....com/arvados/v1/collections/....-4zz18-.........?alt=json returned "request failed: http://localhost:8000/arvados/v1/collections/....-4zz18-...........: 403 Forbidden: Uuid ....-4zz18-.......... is not writable by ....-tpzed-......... (req-ixqstv61tuf3vnx21lwf)">
The token doesn't have write access, but it is trying to save the collection anyway. It shouldn't be trying to save the collection when it closes the file.
There seem to be 2 main bugs here:
- Not tracking change operations, tries to saves the collection record on close every time even though nothing changed, which is unnecessary and incorrect
- Arv-mount was started in read-only mode but flush() still tries to save the collection.
Updated by Peter Amstutz about 3 years ago
18316-fuse-read-only @ d3ffe252f9d7cbbad9a7bf61ccf5d26129720f43
This propagates the enable_write flag to the FUSE directory/file python objects to ensure that when in read-only mode, it won't try to save the collection.
Does not fix the related bug that in read-write mode, it still doesn't track if the user has write permission on a collection or not, or if you tried to change the collection or not. So you'll still get error-on-close if you access a file in a collection that was loaded by uuid (via MagicDirectory or ProjectDirectory). This requires a bit more thought on how best to implement properly.
Updated by Peter Amstutz about 3 years ago
- Status changed from New to In Progress
Updated by Lucas Di Pentima about 3 years ago
Although the updates and test look good, I'm wondering why the original report said that this didn't happen on versions previous to 2.3.0
I've tried to do a manual test against a local arvbox instance, and I'm getting I/O Errors when doing a simple cat <file>
. Am I doing something wrong here?
(venv-arvados) lucas@buster:~$ arv-mount --version /home/lucas/venv-arvados/bin/arv-mount 2.4.0.dev20211112222152 (venv-arvados) lucas@buster:~$ arv-mount ./tmp (venv-arvados) lucas@buster:~$ cd ./tmp/by_id/x240b-4zz18-e1s0llgw4y50icd (venv-arvados) lucas@buster:~/tmp/by_id/x240b-4zz18-e1s0llgw4y50icd$ cat test.js cat: test.js: Input/output error
Updated by Lucas Di Pentima about 3 years ago
Same thing with --debug
:
(venv-arvados) lucas@buster:~$ arv-mount --debug ./tmp 2021-11-15 13:27:53 arvados.arv-mount[24252] DEBUG: arv-mount debugging enabled 2021-11-15 13:27:53 arvados.arv-mount[24252] INFO: /home/lucas/venv-arvados/bin/arv-mount 2.4.0.dev20211112222152 started 2021-11-15 13:27:53 arvados.arv-mount[24252] INFO: enable write is False 2021-11-15 13:27:54 arvados.arvados_fuse[24252] DEBUG: InodeCache touched inode 5 (size 0) (uuid x240b-tpzed-k11iuqilds4s827) total now 0 (1 entries) FUSE library version: 2.9.9 (venv-arvados) lucas@buster:~$ cd ./tmp/by_id/x240b-4zz18-e1s0llgw4y50icd (venv-arvados) lucas@buster:~/tmp/by_id/x240b-4zz18-e1s0llgw4y50icd$ cat test.js cat: test.js: Input/output error
Updated by Lucas Di Pentima about 3 years ago
Let me re-do my manual test with arvbox in dev
mode instead of publicdev
because part of the log says:
2021-11-15 13:40:10 arvados.keep[14412] DEBUG: Request fail: GET http://localhost:25107/136b64e537cfd8920f03646ab852fb61+46+A1975c2037e57581f288f8820b26e005b86e5ac92@61a5022b => <class 'arvados.errors.HttpError'>: (0, "(7, 'Failed to connect to localhost port 25107: Connection refused')") 2021-11-15 13:40:10 arvados.arvados_fuse[14412] ERROR: Unhandled exception during FUSE operation Traceback (most recent call last): File "/home/lucas/venv-arvados/lib/python3.7/site-packages/arvados_fuse-2.4.0.dev20211112222152-py3.7.egg/arvados_fuse/__init__.py", line 327, in catch_exceptions_wrapper return orig_func(self, *args, **kwargs) File "/home/lucas/venv-arvados/lib/python3.7/site-packages/arvados_fuse-2.4.0.dev20211112222152-py3.7.egg/arvados_fuse/__init__.py", line 655, in read r = handle.obj.readfrom(off, size, self.num_retries) File "/home/lucas/venv-arvados/lib/python3.7/site-packages/arvados_fuse-2.4.0.dev20211112222152-py3.7.egg/arvados_fuse/fusefile.py", line 66, in readfrom return self.arvfile.readfrom(off, size, num_retries, exact=True) File "/home/lucas/venv-arvados/lib/python3.7/site-packages/arvados/arvfile.py", line 1106, in readfrom block = self.parent._my_block_manager().get_block_contents(lr.locator, num_retries=num_retries, cache_only=(bool(data) and not exact)) File "/home/lucas/venv-arvados/lib/python3.7/site-packages/arvados/arvfile.py", line 784, in get_block_contents return self._keep.get(locator, num_retries=num_retries) File "/home/lucas/venv-arvados/lib/python3.7/site-packages/arvados/retry.py", line 177, in num_retries_setter return orig_func(self, *args, **kwargs) File "/home/lucas/venv-arvados/lib/python3.7/site-packages/arvados/keep.py", line 1056, in get return self._get_or_head(loc_s, method="GET", **kwargs) File "/home/lucas/venv-arvados/lib/python3.7/site-packages/arvados/keep.py", line 1182, in _get_or_head "[{}] failed to read {} after {}".format(request_id, loc_s, loop.attempts_str()), service_errors, label="service") arvados.errors.KeepReadError: [req-qgowoe2t8nm779xdla27] failed to read 136b64e537cfd8920f03646ab852fb61+46+A1975c2037e57581f288f8820b26e005b86e5ac92@61a5022b after 5 attempts: service http://localhost:25108/ responded with 0 (7, 'Failed to connect to localhost port 25108: Connection refused'); service http://localhost:25107/ responded with 0 (7, 'Failed to connect to localhost port 25107: Connection refused')
Maybe I'm having a keepproxy issue.
Updated by Peter Amstutz about 3 years ago
- Status changed from In Progress to Resolved