Noisy `INFO task completed elapsed=...` verbose logs

[metametadata]

v0.82.0

There are many seemingly useless logs on --verbose which make the reports harder to read and can hide more important messages produced on --verbose (such as suggesting setting add-cpes-if-none).

Maybe they could be hidden behind some other CLI flag instead of --verbose?

[0003]  INFO task completed elapsed=50.792µs task=environment-cataloger
[0003]  INFO task completed elapsed=59.708µs task=alpm-db-cataloger
[0003]  INFO task completed elapsed=25.625µs task=apk-db-cataloger
[0003]  INFO task completed elapsed=204.915708ms task=dpkg-db-cataloger
[0003]  INFO task completed elapsed=79.875µs task=portage-cataloger
[0003]  INFO task completed elapsed=25.083µs task=rpm-db-cataloger
[0003]  INFO task completed elapsed=21.458µs task=rpm-archive-cataloger
[0003]  INFO task completed elapsed=18.208µs task=conan-cataloger
[0003]  INFO task completed elapsed=17.042µs task=dart-pubspec-lock-cataloger
[0003]  INFO task completed elapsed=16.625µs task=dotnet-deps-cataloger
[0003]  INFO task completed elapsed=15.083µs task=elixir-mix-lock-cataloger
[0003]  INFO task completed elapsed=26.25µs task=erlang-rebar-lock-cataloger
[0003]  INFO task completed elapsed=24.5µs task=erlang-otp-application-cataloger
[0003]  INFO task completed elapsed=28.208µs task=haskell-cataloger
[0003]  INFO task completed elapsed=27.583µs task=go-module-file-cataloger
[0003]  INFO task completed elapsed=5.019792ms task=java-gradle-lockfile-cataloger
[0003]  INFO task completed elapsed=1.713291ms task=java-pom-cataloger
[0003]  INFO task completed elapsed=213.875µs task=javascript-lock-cataloger
[0003]  INFO task completed elapsed=45.666µs task=php-composer-lock-cataloger
[0003]  INFO task completed elapsed=26.958µs task=php-pecl-serialized-cataloger
[0003]  INFO task completed elapsed=6.45125ms task=python-package-cataloger
[0003]  INFO task completed elapsed=40.75µs task=ruby-gemfile-cataloger
[0003]  INFO task completed elapsed=42.583µs task=ruby-gemspec-cataloger
[0003]  INFO task completed elapsed=35.541µs task=rust-cargo-lock-cataloger
[0003]  INFO task completed elapsed=28.375µs task=cocoapods-cataloger
[0003]  INFO task completed elapsed=34.292µs task=swift-package-manager-cataloger
[0003]  INFO task completed elapsed=53.917µs task=swipl-pack-cataloger
[0003]  INFO task completed elapsed=5.472583ms task=opam-cataloger
[0003]  INFO task completed elapsed=27.557417ms task=dotnet-portable-executable-cataloger
[0008]  INFO task completed elapsed=4.720901544s task=python-installed-package-cataloger
[0014]  INFO task completed elapsed=6.761570169s task=go-module-binary-cataloger
[0031]  INFO task completed elapsed=16.39040755s task=java-archive-cataloger
[0031]  INFO task completed elapsed=163.184625ms task=graalvm-native-image-cataloger
[0031]  INFO task completed elapsed=30.75575ms task=nix-store-cataloger
[0031]  INFO task completed elapsed=78.375µs task=lua-rock-cataloger
[0033]  INFO task completed elapsed=1.788227334s task=binary-classifier-cataloger
[0033]  WARN unable to parse cpe attributes for elf binary package error=unable to parse Attributes string: failed to parse Attributes="": wfn: unsupported format ""
[0033]  INFO task completed elapsed=35.8165ms task=elf-binary-package-cataloger
[0033]  INFO task completed elapsed=5.235708ms task=github-actions-usage-cataloger
[0033]  INFO task completed elapsed=4.340833ms task=github-action-workflow-usage-cataloger
[0033]  INFO task completed elapsed=4.474333ms task=java-jvm-cataloger
[0033]  INFO task completed elapsed=14.448916ms task=linux-kernel-cataloger
[0033]  INFO task completed elapsed=34.761875ms task=wordpress-plugins-cataloger
[0034]  INFO task completed elapsed=1.322602626s task=file-digest-cataloger
[0034]  INFO task completed elapsed=67.577375ms task=file-metadata-cataloger
[0035]  INFO task completed elapsed=470.578584ms task=file-executable-cataloger
[0035]  INFO task completed elapsed=348.151959ms task=relationships-cataloger
[0035]  INFO task completed elapsed=94.359333ms task=unknowns-labeler

[willmurphyscode]

Thanks for the report!

These logs are being generated in Syft, here: https://github.com/anchore/syft/blob/8095f7b8c14d2b2abf08c9516c7617c08e9fc319/internal/task/executor.go#L103

I can see how these seem noisy. I'll see if there's some better experience we can implement.

[willmurphyscode]

Hi @metametadata!

I went looking for our suggestion to add CPEs if we try to match on a CPE and non are available, and it is at https://github.com/anchore/grype/blob/c87f4a0f53225269097b478b9a5ef33521e13eef/grype/search/criteria.go#L31 as a log.Warn, and warning show up without --verbose.

In general, if a message is something a user could do to make the scan better, we try to log.Warn it, which will show up without --verbose. Is the message that got hidden in all the log.Infos visible if you don't pass --verbose?

[metametadata]

Without --verbose the message Consider re-running with --add-cpes-if-none is not printed when grype process is executed by my Clojure app (instead of directly in an interactive terminal).

I've written about it in the similar Syft issue: https://github.com/anchore/syft/issues/3081#issuecomment-2259026478.

Maybe the similar issue should be added in the Grype repo?

[willmurphyscode]

Hi @metametadata thanks for the response and for connecting this with the Syft issue! I think warnings being lost when not TTY is available is not a great experience and we should treat it as a bug.

Also, thanks for mentioning it happens when Grype is invoked via a Kotlin script - this clue really helped.

For investigating, I made a simple python script that wraps Grype and repros the issue:

import subprocess
import sys

args = ["grype"]
args.extend(sys.argv[1:])

process = subprocess.Popen(
    args,
    stdout=subprocess.PIPE,
    stderr=subprocess.PIPE,
    text=True,
    bufsize=1,
)

try:
    for stdout_line in iter(process.stdout.readline, ""):
        sys.stdout.write(f"out: {stdout_line}")
        sys.stdout.flush()

    for stderr_line in iter(process.stderr.readline, ""):
        sys.stderr.write(f"err: {stderr_line}")
        sys.stderr.flush()
finally:
    process.stdout.close()
    process.stderr.close()
    process.wait()

I'm guessing this is similar to the situation for Grype in your Kotlin script: stderr and stdout are captured within the parent process and printed indirectly, so grype can write bytes to either stderr or stdout, but no tty is present.

Reproing the error:

Grype will log.Warn if you scan a dir because it wants to be told the name of the artifact rather than assuming the dir name, which gives us a quick way to repro: scan an empty directory.

❯ grype dir:.
... snip ...
[0000]  WARN no explicit name and version provided for directory source, deriving artifact ID from the given path (which is not ideal)
No vulnerabilities found

❯ python pygrype.py dir:.
out: No vulnerabilities found

❯ python pygrype.py dir:. --verbose
python pygrype.py dir:. --verbose
out: No vulnerabilities found
err: [0000]  INFO grype version: 0.82.0
err: [0000]  WARN no explicit name and version provided for directory source, deriving artifact ID from the given path (which is not ideal)
err: [0000]  INFO task completed elapsed=54.167µs task=environment-cataloger
... snip ... 
... dozens of lines of log spam hiding the warning ...

So in the second version, we can see that the warning is dropped. I can get it back with --verbose, but then, as @metametadata points out, the warning is drowned in a bunch of log.Info calls.

I think a reasonable requirement we should take here is: Grype (and Syft) should display log.Warn messages, even if no tty is present, unless --quiet is passed.

I think what's happening is this:

1. When run with --verbose, Grype (and Syft) allocate a logger tied to stderr
2. When run without a tty, Grype (and Syft) don't allocate a terminal UI, because there's no TTY to do fun interactive terminal UI tricks with.
3. When run without --verbose, log.Warns go to the TUI.

These three statements make sense separately, but combine to make it so that log.Warns don't have anywhere to go if there's no TUI and no --verbose.

I'll try to add some code links in a minute.

[willmurphyscode]

The UI setup command is here: https://github.com/anchore/grype/blob/5c2b26249fbd4885a7d10a2046ef9d600acd346f/cmd/grype/cli/cli.go#L39

I suspect the bug may be over in https://github.com/anchore/clio, which is a Terminal UI library shared by Syft and Grype.

[metametadata]

I think a reasonable requirement we should take here is: Grype (and Syft) should display log.Warn messages, even if no tty is present, unless --quiet is passed.

Agree. I then will be able to delete --verbose arg from my grype calls to see WARN logs without INFO ones.