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

RF: Suppress similar repeated messages in the default result renderer #4337

Merged
merged 3 commits into from Mar 25, 2020

Conversation

mih
Copy link
Member

@mih mih commented Mar 24, 2020

Saving a dataset with a 1000 files will now look like this:

% datalad save
add(ok): 1 (file)
  [999 similar messages have been suppressed]
save(ok): . (dataset)
action summary:
  add (ok: 1000)
  save (ok: 1)

Failing to get a 1000 files looks like this (with datalad.log.result-level=debug)

% datalad get .
Total (0 ok, 1000 failed out of 1000):   0%|                     | 0.00/3.89k [00:01<?, ?B/s][WARNING] Running get resulted in stderr output: git-annex: get: 1000 failed

                                                                                             get(error): 1 (file) [Unable to access these remotes: origin; Try making some of these repositories available:;      2cc06516-5731-43a5-88e9-39499f2114e9 -- mih@meiner:/tmp/massive [origin]]
  [999 similar messages have been suppressed]
action summary:
  get (error: 1000)

Without the config switch, the second example would still produce a
thousand additional log messages, because we still report every error
twice. I decided to not address this in the logger, because while I can
relatively safely suppress result rendering based on a handful of result
keys, it is unclear to me what threshold we would use for the logger.
In any case, this can be done later by someone who is still suffering
from those messages ;-)

Fixes gh-2620 in spirit.

Saving a dataset with a 1000 files will now look like this:

```
% datalad save
add(ok): 1 (file)
  [999 similar messages have been suppressed]
save(ok): . (dataset)
action summary:
  add (ok: 1000)
  save (ok: 1)
```

Failing to get a 1000 files looks like this (with `datalad.log.result-level=debug`)

```
% datalad get .
Total (0 ok, 1000 failed out of 1000):   0%|                     | 0.00/3.89k [00:01<?, ?B/s][WARNING] Running get resulted in stderr output: git-annex: get: 1000 failed

                                                                                             get(error): 1 (file) [Unable to access these remotes: origin; Try making some of these repositories available:;      2cc06516-5731-43a5-88e9-39499f2114e9 -- mih@meiner:/tmp/massive [origin]]
  [999 similar messages have been suppressed]
action summary:
  get (error: 1000)
```

Without the config switch, the second example would still produce a
thousand additional log messages, because we still report every error
twice. I decided to not address this in the logger, because while I can
relatively safely suppress result rendering based on a handful of result
keys, it is unclear to me what threshold we would use for the logger.
In any case, this can be done later by someone who is still suffering
from those messages ;-)

Fixes dataladgh-2620 in spirit.
@mih mih added the UX user experience label Mar 24, 2020
We do not render any 'notneeded' results in the default renderer.
@kyleam
Copy link
Collaborator

kyleam commented Mar 24, 2020

I think this looks great for the cases where there are a bunch of results, but it doesn't seem well suited for cases where you have a handful, especially two:

add(ok): one (file)                       
  [1 similar messages have been suppressed]
save(ok): . (dataset)
action summary:
  add (ok: 2)
  save (ok: 1)

What about letting the results through until some threshold (perhaps 15?) and then trimming after that? If the threshold ends up bothering people, we could introduce a config option for it.

@mih
Copy link
Member Author

mih commented Mar 24, 2020

What about letting the results through until some threshold (perhaps 15?) and then trimming after that? If the threshold ends up bothering people, we could introduce a config option for it.

Good idea! Will do!

@kyleam
Copy link
Collaborator

kyleam commented Mar 24, 2020

This PR isn't a proper fix for gh-3868 (behavior when not connected to the internet), but, along the lines of your second example, this change should eliminate the flood of messages mentioned there, assuming datalad.log.result-level=debug.

@codecov
Copy link

codecov bot commented Mar 24, 2020

Codecov Report

Merging #4337 into master will increase coverage by 0.02%.
The diff coverage is 70.58%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master    #4337      +/-   ##
==========================================
+ Coverage   88.83%   88.86%   +0.02%     
==========================================
  Files         285      285              
  Lines       37457    37557     +100     
==========================================
+ Hits        33275    33375     +100     
  Misses       4182     4182              
Impacted Files Coverage Δ
datalad/interface/utils.py 92.09% <70.58%> (-1.58%) ⬇️
datalad/cmdline/main.py 76.13% <0.00%> (-1.28%) ⬇️
datalad/core/local/create.py 93.00% <0.00%> (-1.12%) ⬇️
datalad/support/constraints.py 87.22% <0.00%> (-1.10%) ⬇️
datalad/log.py 89.71% <0.00%> (-0.43%) ⬇️
datalad/core/distributed/tests/test_clone.py 92.19% <0.00%> (-0.14%) ⬇️
datalad/support/gitrepo.py 90.76% <0.00%> (-0.01%) ⬇️
datalad/interface/__init__.py 100.00% <0.00%> (ø)
datalad/support/exceptions.py 83.76% <0.00%> (ø)
datalad/distribution/siblings.py 76.27% <0.00%> (ø)
... and 10 more

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 659f70f...8634a41. Read the comment docs.

This will avoid suppression for smaller operations, as suggested by
@kyleam.

I went for 10 (not 15), because with longer messages multiple lines in a
terminal are needed per results and the screen could still be flooded in
relatively normal error situations, like getting files without network
connection).
@mih
Copy link
Member Author

mih commented Mar 25, 2020

GitHub actions seem broken right now (several attempts). Will wait for appveyor and travis and then merge. The incremental change is only of cosmetic nature:

% datalad get .
Total (0 ok, 1000 failed out of 1000):   0%|                     | 0.00/3.89k [00:01<?, ?B/s][WARNING] Running get resulted in stderr output: git-annex: get: 1000 failed                                                                                             get(error): 1 (file) [Unable to access these remotes: origin; Try making some of these repositories available:;      2cc06516-5731-43a5-88e9-39499f2114e9 -- mih@meiner:/tmp/massive [origin]]
get(error): 100 (file) [Unable to access these remotes: origin; Try making some of these repositories available:;    2cc06516-5731-43a5-88e9-39499f2114e9 -- mih@meiner:/tmp/massive [origin]]
get(error): 10 (file) [Unable to access these remotes: origin; Try making some of these repositories available:;     2cc06516-5731-43a5-88e9-39499f2114e9 -- mih@meiner:/tmp/massive [origin]]
get(error): 107 (file) [Unable to access these remotes: origin; Try making some of these repositories available:;    2cc06516-5731-43a5-88e9-39499f2114e9 -- mih@meiner:/tmp/massive [origin]]
get(error): 1000 (file) [Unable to access these remotes: origin; Try making some of these repositories available:;   2cc06516-5731-43a5-88e9-39499f2114e9 -- mih@meiner:/tmp/massive [origin]]
get(error): 11 (file) [Unable to access these remotes: origin; Try making some of these repositories available:;     2cc06516-5731-43a5-88e9-39499f2114e9 -- mih@meiner:/tmp/massive [origin]]
get(error): 110 (file) [Unable to access these remotes: origin; Try making some of these repositories available:;    2cc06516-5731-43a5-88e9-39499f2114e9 -- mih@meiner:/tmp/massive [origin]]
get(error): 113 (file) [Unable to access these remotes: origin; Try making some of these repositories available:;    2cc06516-5731-43a5-88e9-39499f2114e9 -- mih@meiner:/tmp/massive [origin]]
get(error): 112 (file) [Unable to access these remotes: origin; Try making some of these repositories available:;    2cc06516-5731-43a5-88e9-39499f2114e9 -- mih@meiner:/tmp/massive [origin]]
get(error): 108 (file) [Unable to access these remotes: origin; Try making some of these repositories available:;    2cc06516-5731-43a5-88e9-39499f2114e9 -- mih@meiner:/tmp/massive [origin]]
get(error): 104 (file) [Unable to access these remotes: origin; Try making some of these repositories available:;    2cc06516-5731-43a5-88e9-39499f2114e9 -- mih@meiner:/tmp/massive [origin]]
  [989 similar messages have been suppressed]
action summary:
  get (error: 1000)

@mih mih merged commit 8d4f2d0 into datalad:master Mar 25, 2020
3 of 4 checks passed
@mih mih deleted the bf-2620 branch Mar 25, 2020
@yarikoptic
Copy link
Member

yarikoptic commented Mar 26, 2020

woohoo! Me & My terminal Love it

$> datalad save ...
add(ok): 022-cmrr_mbep2d_bold-s1p2-3contrasts/000001.dcm (file)                                                                                                                                                                    
add(ok): 022-cmrr_mbep2d_bold-s1p2-3contrasts/000002.dcm (file)
add(ok): 022-cmrr_mbep2d_bold-s1p2-3contrasts/000003.dcm (file)
add(ok): 022-cmrr_mbep2d_bold-s1p2-3contrasts/000004.dcm (file)
add(ok): 022-cmrr_mbep2d_bold-s1p2-3contrasts/000005.dcm (file)
add(ok): 022-cmrr_mbep2d_bold-s1p2-3contrasts/000006.dcm (file)
add(ok): 022-cmrr_mbep2d_bold-s1p2-3contrasts/000007.dcm (file)
add(ok): 022-cmrr_mbep2d_bold-s1p2-3contrasts/000008.dcm (file)
add(ok): 022-cmrr_mbep2d_bold-s1p2-3contrasts/000009.dcm (file)
add(ok): 022-cmrr_mbep2d_bold-s1p2-3contrasts/000010.dcm (file)
add(ok): 022-cmrr_mbep2d_bold-s1p2-3contrasts/000011.dcm (file)
  [2389 similar messages have been suppressed]
save(ok): . (dataset)
action summary:
  add (ok: 2400)
  save (ok: 1)

kyleam added a commit to kyleam/datalad that referenced this pull request Mar 27, 2020
As shown by the example in dataladgh-4352, there are a couple of issues with
the message about suppressed results introduced in 8d4f2d0
(dataladgh-4337, 2020-03-25):

  * With a number of similar results at or below render_n_repetitions
    (which is 10), a message about a _negative_ number of suppressed
    results is shown.

  * Right above the limit, a message about zero suppressed results is
    shown.

Change the "display suppression message?" condition to check whether
there was a number of similar messages beyond the threshold rather
than simply checking that there was a chain of similar messages.

Fixes datalad#4352.
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.

Make our logger suppress repetitive messages
3 participants