Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ENH: Prefer structured over rendered CommandError info #4157

Merged
merged 4 commits into from Feb 21, 2020

Conversation

mih
Copy link
Member

@mih mih commented Feb 16, 2020

CommandError(msg=) was abused to obfuscate information on
cwd etc. Now these are dedicated properties, and a comprehensive
str representation is rendered at the latest possible stage,
avoiding intermediate overhead.

Turns

% datalad create blowup --bare
[INFO   ] Creating a new annex repo at /tmp/blowup
CommandError: command '['git', '-c', 'annex.largefiles=nothing', 'add', '--dry-run', '-N', '--ignore-missing', '--verbose', '--', '.gitattributes']' failed with exitcode 128
Failed to run ['git', '-c', 'annex.largefiles=nothing', 'add', '--dry-run', '-N', '--ignore-missing', '--verbose', '--', '.gitattributes'] under '/tmp/blowup'. Exit code=128. out= err=fatal: this operation must be run in a work tree

stdout=
stderr=fatal: this operation must be run in a work tree

fatal: this operation must be run in a work tree

into

% datalad create blowup --bare
[INFO   ] Creating a new annex repo at /tmp/blowup
CommandError: 'git -c annex.largefiles=nothing add --dry-run -N --ignore-missing --verbose -- .gitattributes' failed with exitcode 128 under /tmp/blowup
fatal: this operation must be run in a work tree

@mih mih added the UX user experience label Feb 16, 2020
@mih mih changed the title ENH: Prefer structured over rendered info ENH: Prefer structured over rendered CommandError info Feb 16, 2020
@yarikoptic
Copy link
Member

@yarikoptic yarikoptic commented Feb 16, 2020

Looks better. But I am surprised that it is neither in ERROR log message nor in the (error) results renderer.

like in other examples with clone or create (duplication of msg between ERROR log and results renderer aside)
$> datalad clone ///asdlkfj  
[ERROR  ] Failed to clone from any candidate source URL. Encountered errors per each url were:                                                                                                                                     
| - http://datasets.datalad.org/asdlkfj
  CommandError: command '['git', 'clone', '--progress', 'http://datasets.datalad.org/asdlkfj', '/tmp/asdlkfj']' failed with exitcode 128
Failed to run ['git', 'clone', '--progress', 'http://datasets.datalad.org/asdlkfj', '/tmp/asdlkfj'].
stdout=
stderr=Cloning into '/tmp/asdlkfj'...
fatal: repository 'http://datasets.datalad.org/asdlkfj/' not found

- http://datasets.datalad.org/asdlkfj/.git
  CommandError: command '['git', 'clone', '--progress', 'http://datasets.datalad.org/asdlkfj/.git', '/tmp/asdlkfj']' failed with exitcode 128
Failed to run ['git', 'clone', '--progress', 'http://datasets.datalad.org/asdlkfj/.git', '/tmp/asdlkfj'].
stdout=
stderr=Cloning into '/tmp/asdlkfj'...
fatal: repository 'http://datasets.datalad.org/asdlkfj/.git/' not found
 [install(/tmp/asdlkfj)] 
install(error): /tmp/asdlkfj (dataset) [Failed to clone from any candidate source URL. Encountered errors per each url were:
- http://datasets.datalad.org/asdlkfj
  CommandError: command '['git', 'clone', '--progress', 'http://datasets.datalad.org/asdlkfj', '/tmp/asdlkfj']' failed with exitcode 128
Failed to run ['git', 'clone', '--progress', 'http://datasets.datalad.org/asdlkfj', '/tmp/asdlkfj'].
stdout=
stderr=Cloning into '/tmp/asdlkfj'...
fatal: repository 'http://datasets.datalad.org/asdlkfj/' not found

- http://datasets.datalad.org/asdlkfj/.git
  CommandError: command '['git', 'clone', '--progress', 'http://datasets.datalad.org/asdlkfj/.git', '/tmp/asdlkfj']' failed with exitcode 128
Failed to run ['git', 'clone', '--progress', 'http://datasets.datalad.org/asdlkfj/.git', '/tmp/asdlkfj'].
stdout=
stderr=Cloning into '/tmp/asdlkfj'...
fatal: repository 'http://datasets.datalad.org/asdlkfj/.git/' not found
]

$> datalad create /buga        
[INFO   ] Creating a new annex repo at /buga 
[ERROR  ] [Errno 13] Permission denied: '/buga' [os.py:makedirs:221] (PermissionError) 

mih added 2 commits Feb 17, 2020
CommandError(msg=) was abused to obfuscate information and
cwd etc. Not these are dedicated properties, and a comprehensive
str representation is rendered at the latest possible stage,
avoiding intermediate overhead.

Turns

```
% datalad create blowup --bare
[INFO   ] Creating a new annex repo at /tmp/blowup
CommandError: command '['git', '-c', 'annex.largefiles=nothing', 'add', '--dry-run', '-N', '--ignore-missing', '--verbose', '--', '.gitattributes']' failed with exitcode 128
Failed to run ['git', '-c', 'annex.largefiles=nothing', 'add', '--dry-run', '-N', '--ignore-missing', '--verbose', '--', '.gitattributes'] under '/tmp/blowup'. Exit code=128. out= err=fatal: this operation must be run in a work tree

stdout=
stderr=fatal: this operation must be run in a work tree

fatal: this operation must be run in a work tree
```

into

```
% datalad create blowup --bare
[INFO   ] Creating a new annex repo at /tmp/blowup
CommandError: 'git -c annex.largefiles=nothing add --dry-run -N --ignore-missing --verbose -- .gitattributes' failed with exitcode 128 under /tmp/blowup
fatal: this operation must be run in a work tree
```
@mih
Copy link
Member Author

@mih mih commented Feb 17, 2020

But I am surprised that it is neither in ERROR log message nor in the (error) results renderer.

The demo that I picked isn't a regular or anticipated failure. It is a crash, hence there is nothing that sees this until the top-level catch-all.

@yarikoptic
Copy link
Member

@yarikoptic yarikoptic commented Feb 17, 2020

The demo that I picked isn't a regular or anticipated failure. It is a crash, hence there is nothing that sees this until the top-level catch-all.

yeap, and I thought that we are catching all of those, unless in --dbg mode... and we do, but CommandError (and InsufficientArgumentsError, IncompleteResultsError) have their own dedicated "handling" apparently: https://github.com/datalad/datalad/blob/master/datalad/cmdline/main.py#L533 (right at the point where you modifying it). I guess we might want to unify it (I see only InsufficientArgumentsError needing to behave separately since it is the only one due to "user mistake") later on to unify handling e.g. for #3649 .

@mih
Copy link
Member Author

@mih mih commented Feb 17, 2020

No idea how this change can impact the NFS test only...

======================================================================
1179ERROR: datalad.support.tests.test_annexrepo.test_dropkey(True,)
1180----------------------------------------------------------------------
1181Traceback (most recent call last):
1182  File "/home/travis/virtualenv/python3.5.6/lib/python3.5/site-packages/nose/case.py", line 198, in runTest
1183    self.test(*self.arg)
1184  File "/home/travis/virtualenv/python3.5.6/lib/python3.5/site-packages/datalad/tests/utils.py", line 588, in newfunc
1185    rmtemp(d)
1186  File "/home/travis/virtualenv/python3.5.6/lib/python3.5/site-packages/datalad/utils.py", line 521, in rmtemp
1187    rmtree(f, *args, **kwargs)
1188  File "/home/travis/virtualenv/python3.5.6/lib/python3.5/site-packages/datalad/utils.py", line 434, in rmtree
1189    _rmtree(path, *args, **kwargs)
1190  File "/home/travis/virtualenv/python3.5.6/lib/python3.5/site-packages/datalad/utils.py", line 1882, in wrapped
1191    return f(*args, **kwargs)
1192  File "/home/travis/virtualenv/python3.5.6/lib/python3.5/site-packages/datalad/utils.py", line 1922, in _rmtree
1193    return shutil.rmtree(*args, **kwargs)
1194  File "/home/travis/virtualenv/python3.5.6/lib/python3.5/shutil.py", line 480, in rmtree
1195    _rmtree_safe_fd(fd, path, onerror)
1196  File "/home/travis/virtualenv/python3.5.6/lib/python3.5/shutil.py", line 418, in _rmtree_safe_fd
1197    _rmtree_safe_fd(dirfd, fullname, onerror)
1198  File "/home/travis/virtualenv/python3.5.6/lib/python3.5/shutil.py", line 418, in _rmtree_safe_fd
1199    _rmtree_safe_fd(dirfd, fullname, onerror)
1200  File "/home/travis/virtualenv/python3.5.6/lib/python3.5/shutil.py", line 418, in _rmtree_safe_fd
1201    _rmtree_safe_fd(dirfd, fullname, onerror)
1202  File "/home/travis/virtualenv/python3.5.6/lib/python3.5/shutil.py", line 438, in _rmtree_safe_fd
1203    onerror(os.unlink, fullname, sys.exc_info())
1204  File "/home/travis/virtualenv/python3.5.6/lib/python3.5/shutil.py", line 436, in _rmtree_safe_fd
1205    os.unlink(name, dir_fd=topfd)
1206OSError: [Errno 16] Device or resource busy: '.nfs00000000002b02bc0000020b'
1207
1208

Same for the windows failure:

======================================================================
ERROR: datalad.support.tests.test_annexrepo.test_find_batch_equivalence
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\hostedtoolcache\windows\Python\3.7.6\x64\lib\site-packages\nose\case.py", line 198, in runTest
    self.test(*self.arg)
  File "C:\hostedtoolcache\windows\Python\3.7.6\x64\lib\site-packages\datalad\tests\utils.py", line 588, in newfunc
    rmtemp(d)
  File "C:\hostedtoolcache\windows\Python\3.7.6\x64\lib\site-packages\datalad\utils.py", line 521, in rmtemp
    rmtree(f, *args, **kwargs)
  File "C:\hostedtoolcache\windows\Python\3.7.6\x64\lib\site-packages\datalad\utils.py", line 434, in rmtree
    _rmtree(path, *args, **kwargs)
  File "C:\hostedtoolcache\windows\Python\3.7.6\x64\lib\site-packages\datalad\utils.py", line 1882, in wrapped
    return f(*args, **kwargs)
  File "C:\hostedtoolcache\windows\Python\3.7.6\x64\lib\site-packages\datalad\utils.py", line 1922, in _rmtree
    return shutil.rmtree(*args, **kwargs)
  File "C:\hostedtoolcache\windows\Python\3.7.6\x64\lib\shutil.py", line 516, in rmtree
    return _rmtree_unsafe(path, onerror)
  File "C:\hostedtoolcache\windows\Python\3.7.6\x64\lib\shutil.py", line 404, in _rmtree_unsafe
    onerror(os.rmdir, path, sys.exc_info())
  File "C:\hostedtoolcache\windows\Python\3.7.6\x64\lib\shutil.py", line 402, in _rmtree_unsafe
    os.rmdir(path)
PermissionError: [WinError 32] The process cannot access the file because it is being used by another process: 'C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\datalad_temp_tree__pqsunvu'

@yarikoptic
Copy link
Member

@yarikoptic yarikoptic commented Feb 17, 2020

indeed, eyeballed the diff and didn't spot anything obvious which could have left a process holding that path. There is a helper mode DATALAD_ASSERT_NO_OPEN_FILES but not sure it would be of help here to pin it down :-/

@yarikoptic
Copy link
Member

@yarikoptic yarikoptic commented Feb 18, 2020

FWIW, NFS issue replicates locally:
$> python -m nose -s -v datalad/support/tests/test_annexrepo.py:test_dropkey
datalad.support.tests.test_annexrepo.test_dropkey(False,) ... ok
datalad.support.tests.test_annexrepo.test_dropkey(True,) ... ERROR
Versions: appdirs=1.4.3 boto=2.49.0 cmd:7z=16.02 cmd:annex=7.20200204+git1-gb2c529b88-1~ndall+1 cmd:bundled-git=2.24.0 cmd:git=2.24.0 cmd:system-git=2.24.0 cmd:system-ssh=8.1p1 exifread=2.1.2 git=3.0.5 gitdb=2.0.6 humanize=0.5.1 iso8601=0.1.11 keyring=18.0.1 keyrings.alt=3.1.1 msgpack=0.5.6 mutagen=1.40.0 requests=2.21.0 wrapt=1.11.2
Obscure filename: str=b' "\';a&b&c\xce\x94\xd0\x99\xd7\xa7\xd9\x85\xe0\xb9\x97\xe3\x81\x82 `| ' repr=' "\';a&b&cΔЙקم๗あ `| '
Encodings: default='utf-8' filesystem='utf-8' locale.prefered='UTF-8'
Environment: LANG='en_US.UTF-8' GIT_PAGER='less --no-init --quit-if-one-screen' PATH='/home/yoh/gocode/bin:/home/yoh/proj/datalad/datalad-master/venvs/dev3/bin:/home/yoh/gocode/bin:/home/yoh/gocode/bin:/home/yoh/bin:/home/yoh/.local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games:/sbin:/usr/sbin:/usr/local/sbin:/home/yoh/.mutt/soft' GIT_PYTHON_GIT_EXECUTABLE='/usr/lib/git-annex.linux/git'

======================================================================
ERROR: datalad.support.tests.test_annexrepo.test_dropkey(True,)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/nose/case.py", line 197, in runTest
    self.test(*self.arg)
  File "/home/yoh/proj/datalad/datalad-master/datalad/tests/utils.py", line 588, in newfunc
    rmtemp(d)
  File "/home/yoh/proj/datalad/datalad-master/datalad/utils.py", line 521, in rmtemp
    rmtree(f, *args, **kwargs)
  File "/home/yoh/proj/datalad/datalad-master/datalad/utils.py", line 434, in rmtree
    _rmtree(path, *args, **kwargs)
  File "/home/yoh/proj/datalad/datalad-master/datalad/utils.py", line 1882, in wrapped
    return f(*args, **kwargs)
  File "/home/yoh/proj/datalad/datalad-master/datalad/utils.py", line 1922, in _rmtree
    return shutil.rmtree(*args, **kwargs)
  File "/home/yoh/proj/datalad/datalad-master/venvs/dev3/lib/python3.7/shutil.py", line 494, in rmtree
    _rmtree_safe_fd(fd, path, onerror)
  File "/home/yoh/proj/datalad/datalad-master/venvs/dev3/lib/python3.7/shutil.py", line 432, in _rmtree_safe_fd
    _rmtree_safe_fd(dirfd, fullname, onerror)
  File "/home/yoh/proj/datalad/datalad-master/venvs/dev3/lib/python3.7/shutil.py", line 432, in _rmtree_safe_fd
    _rmtree_safe_fd(dirfd, fullname, onerror)
  File "/home/yoh/proj/datalad/datalad-master/venvs/dev3/lib/python3.7/shutil.py", line 432, in _rmtree_safe_fd
    _rmtree_safe_fd(dirfd, fullname, onerror)
  File "/home/yoh/proj/datalad/datalad-master/venvs/dev3/lib/python3.7/shutil.py", line 452, in _rmtree_safe_fd
    onerror(os.unlink, fullname, sys.exc_info())
  File "/home/yoh/proj/datalad/datalad-master/venvs/dev3/lib/python3.7/shutil.py", line 450, in _rmtree_safe_fd
    os.unlink(entry.name, dir_fd=topfd)
OSError: [Errno 16] Device or resource busy: '.nfs0000000000fa337f00000013'

@yarikoptic
Copy link
Member

@yarikoptic yarikoptic commented Feb 18, 2020

hm, but not again! right after initial attempt, started to redo and failed to replicate... heh heh

@yarikoptic
Copy link
Member

@yarikoptic yarikoptic commented Feb 18, 2020

oh, and there is already in the stack:

datalad/utils.py", line 1882, in wrapped
1191    return f(*args, **kwargs)

which comes from try_multiple_dec, so we are already trying multiple (3) times on linux and 50 on windows with interval of 0.1 sec. So the only thing which comes to mind is to double those numbers and see how it goes (pushed, feel welcome to revert if doesn't help)

@codecov
Copy link

@codecov codecov bot commented Feb 18, 2020

Codecov Report

Merging #4157 into master will not change coverage.
The diff coverage is n/a.

Impacted file tree graph

@@           Coverage Diff           @@
##           master    #4157   +/-   ##
=======================================
  Coverage   87.56%   87.56%           
=======================================
  Files         279      279           
  Lines       39131    39131           
=======================================
  Hits        34267    34267           
  Misses       4864     4864

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update adb7d92...3c94e70. Read the comment docs.

@yarikoptic
Copy link
Member

@yarikoptic yarikoptic commented Feb 18, 2020

adb7d92 didn't help Windows, so I guess someone needs to figure it out properly :-/

@yarikoptic yarikoptic added this to the 0.13.0 milestone Feb 20, 2020
@mih
Copy link
Member Author

@mih mih commented Feb 21, 2020

Windows tests are generally in a bad place right now. Will dig on a more global scale ...

@mih mih merged commit 473e9bc into datalad:master Feb 21, 2020
12 of 15 checks passed
@mih mih deleted the enh-errorux branch Feb 21, 2020
@yarikoptic yarikoptic mentioned this pull request Feb 21, 2020
kyleam added a commit to kyleam/datalad that referenced this issue Sep 25, 2020
09d3fd8 (ENH: Prefer structured over rendered info, 2020-02-16,
dataladgh-4157) switched datalad.cmdline.main over to using to_str() for
rendering a caught CommandError.  None of the CommandError subclasses
have a to_str() method, though, so the value returned by
CommandError.to_str() is displayed rather than the value returned by
the child's __str__() method.

For example, now an OutOfSpaceError is shown as "OutOfSpaceError:  "
rather than "OutOfSpaceError:  needs N more".  Likewise, calling
`datalad get --source=DO-NOT-EXIST` no longer shows the remote name,
just

    RemoteNotAvailableError: 'annex get'

Convert the __str__() methods of all subclasses to to_str().  The
message above becomes

    Remote 'DO-NOT-EXIST' is not available. Command failed:
    RemoteNotAvailableError: 'annex get'

This commit just intends to restore the displayed information that was
lost with 09d3fd8.  However, the rendering of these CommandError
subclasses could arguably be improved (e.g., the "Command failed:
RemoteNotAvailableError: 'annex get'" stacking is confusing and could
probably be dropped altogether).
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
UX user experience
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants