Syft does not log warnings when no tty is present

[devfbe]

What happened:
Important WARN logs like

[0000]  WARN file could not be unarchived: unable to create tempdir for archive processing: stat /tmp: no such file or directory

Are not visible / not logged, when no TTY is present. This happens especially in my GitLab pipelines where jobs do not have a tty.

What you expected to happen:
I expect that all logs, especially with Level >= WARN are being logged when /dev/stdout and /dev/stderr are present. A missing (pseudo)tty should not cause missing logs.

Steps to reproduce the issue:
Build a container with a broken environment where no temp dir exists and try to scan a test artifact (in my case containerimage.tar) in this container. 1 Try with a pseudo tty and one time without a tty. You'll see the warnings only, when a pseudo tty has been allocated. I verified, that even without the pseudo tty, /dev/stdout and /dev/stderr are there and work as intended.

Test container:

FROM scratch
COPY syft /
COPY containerimage.tar /
ENTRYPOINT ["/syft"]

Run without tty:

❯ podman run -i syft scan /containerimage.tar
No packages discovered

Run with pseudo tty:

❯ podman run -ti syft scan /containerimage.tar
 ✔ Indexed file system                                                                                                                                                                                                                                                                 /
 ✔ Cataloged contents                                                                                                                                                                                                   ccf875aa8af6073319964e9d36823bf7337a7ca8caf5c386c818452a7307c45f
   ├── ✔ Packages                        [0 packages]
   └── ✔ Executables                     [0 executables]
[0000]  WARN file could not be unarchived: unable to create tempdir for archive processing: stat /tmp: no such file or directory
[0001]  WARN unable to determine GOPATH or user home dir: %!w(string=exec: "getent": executable file not found in $PATH)
[0001]  WARN unable to determine GOPATH or user home dir: %!w(string=exec: "getent": executable file not found in $PATH)
No packages discovered

Anything else we need to know?:
I assume that the logs are missing, because when no TTY is there some special terminal tricks like animations don't work.

Environment:

• Syft 1.9.0
• OCI-Container of all kind

[metametadata]

I have the same problem with Grype.

Adding --verbose helps to see warnings. But stuff like ✔ Indexed file system (and in case of Grype, more interesting lines like by status: 27 fixed, 8 not-fixed, 0 ignored) would still not be printed.

[spiffcs]

Thanks @devfbe for filing the issue! When we have some cycles we can take a look and see where the creation of the logger is failing/dependent on the presence of the tty. We do agree that this should just work sans tty detection.

PRs are also welcome and we can help get those merged if you happen to find where this might be failing in syft.

Thanks!

[popey]

Ok, I reproduced on both Docker on my M3 Mac and in Podman Ubuntu on my X86 ThinkPad.

Lots of testing here. But the tl;dr is that I think it's working as designed. Even if you suppress the WARN messages (which result through having a non-posix or 'very stripped down' container with no $HOME set, and no $TMPDIR set) by setting the environment variables $HOME and $TMPDIR to /, errors can still bubble up.

The error I show at the bottom is because the scratch container has no ca certs and so cannot validate the SSL cert on the update server. We consider that a non-blocking error, and continue with the scan anyway.

M3 Mac - Docker

$ uname
Darwin Alans-MacBook-Pro.local 23.5.0 Darwin Kernel Version 23.5.0: Wed May  1 20:13:18 PDT 2024; root:xnu-10063.121.3~5/RELEASE_ARM64_T6030 arm64

$ docker --version
Docker version 26.0.0, build 2ae903e

$ cat Dockerfile
FROM scratch
COPY syft /
COPY containerimage.tar /
ENTRYPOINT ["/syft"]

$ ls -1
Dockerfile
containerimage.tar
syft

$ docker build -t syft-3081 .
[+] Building 0.0s (6/6) FINISHED	docker:desktop-linux
 => [internal] load build definition from Dockerfile 	0.0s
 => => transferring dockerfile: 109B 					0.0s
 => [internal] load .dockerignore						0.0s
 => => transferring context: 2B							0.0s
 => [internal] load build context						0.0s
 => => transferring context: 68B						0.0s
 => CACHED [1/2] COPY syft /							0.0s
 => CACHED [2/2] COPY containerimage.tar /				0.0s
 => exporting to containerimage							0.0s
 => => exporting layers									0.0s
 => => writing image sha256:6f4dd9f811dc0e2fa7efe1c689e745c968e9780e7f7d7480749758f5c78792c6	0.0s
 => => naming to docker.io/library/syft-3081

$ docker run -i syft-3081:latest scan /containerimage.tar
No packages discovered

$ docker run -it syft-3081:latest scan /containerimage.tar
 ✔ Indexed file system	/
 ✔ Cataloged contents	70176cd12232c83ad087f8a29d475b49e285f6a50c15c8cd727e12775cf23447
   ├── ✔ Packages                        [0 packages]
   └── ✔ Executables                     [0 executables]
[0000]  WARN file could not be unarchived: unable to create tempdir for archive processing: stat /tmp: no such file or directory
No packages discovered

$ docker run -it -e TMPDIR=/ syft-3081:latest scan /containerimage.tar
 ✔ Parsed image sha256:425f8e4e2ae1e409e5de8333096a034049a68e2743129e2e811f73cac1b23ad8
 ✔ Cataloged contents c7edf18fda38e1470cd4056bb49104743d60761d154cce75b45d5f6e26a4b05a
   ├── ✔ Packages                        [88 packages]
   ├── ✔ File digests                    [4,731 files]
   ├── ✔ File metadata                   [4,731 locations]
   └── ✔ Executables                     [693 executables]
NAME                    VERSION                TYPE
adduser                 3.134                  deb
apt                     2.6.1                  deb
base-files              12.4+deb12u6           deb
base-passwd             3.6.1                  deb
bash                    5.2.15-2+b7            deb
-- 8< -- 

$ docker run -i -e TMPDIR=/ syft-3081:latest scan /containerimage.tar
NAME                    VERSION                TYPE
adduser                 3.134                  deb
apt                     2.6.1                  deb
base-files              12.4+deb12u6           deb
base-passwd             3.6.1                  deb
bash                    5.2.15-2+b7            deb
-- 8< -- 

Linux

Let's also repeat on my Ubuntu laptop using Podman, to make sure it's not a docker<->podman thing.

$ uname
Linux PrecisePad 6.8.0-35-generic #35-Ubuntu SMP PREEMPT_DYNAMIC Mon May 20 15:51:52 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux

$ podman --version
podman version 4.9.3

$ cat Dockerfile
FROM scratch
COPY syft /
COPY containerimage.tar /
ENTRYPOINT ["/syft"]

$ ls -1
containerimage.tar
Dockerfile
syft
$ podman run -i syft-3081:latest scan /containerimage.tar
No packages discovered

$ podman run -it syft-3081:latest scan /containerimage.tar
 ✔ Indexed file system /
 ✔ Cataloged contents 74b7dc87c36ab80f108a31311cee6b878d070e2ca54dc6885e1c6fb5f8042eba
   ├── ✔ Packages                        [0 packages]
   └── ✔ Executables                     [0 executables]
[0000]  WARN file could not be unarchived: unable to create tempdir for archive processing: stat /tmp: no such file or directory
[0000]  WARN unable to determine GOPATH or user home dir: %!w(string=exec: "getent": executable file not found in $PATH)
[0000]  WARN unable to determine GOPATH or user home dir: %!w(string=exec: "getent": executable file not found in $PATH)
No packages discovered

$ podman run -it -e TMPDIR=/ syft-3081:latest scan /containerimage.tar
 ✔ Parsed image sha256:2e5b8d3ef33ebde2b2a943fadb241a63de1535a007a7bd185e7037abfff99f63
 ✔ Cataloged contents 61c9fbada2048bc7a229a0d38ee6e6a9a07f729d3136c0bc36b10c3ccba9fee6
   ├── ✔ Packages                        [88 packages]
   ├── ✔ File digests                    [4,732 files]
   ├── ✔ File metadata                   [4,732 locations]
   └── ✔ Executables                     [694 executables]
[0000]  WARN unable to determine GOPATH or user home dir: %!w(string=exec: "getent": executable file not found in $PATH)
[0000]  WARN unable to determine GOPATH or user home dir: %!w(string=exec: "getent": executable file not found in $PATH)
NAME                    VERSION                TYPE
adduser                 3.134                  deb
apt                     2.6.1                  deb
base-files              12.4+deb12u6           deb
base-passwd             3.6.1                  deb
bash                    5.2.15-2+b7            deb
-- 8< -- 

$ podman run -it -e HOME=/ -e TMPDIR=/ syft-3081:latest scan /containerimage.tar
 ✔ Parsed image sha256:2e5b8d3ef33ebde2b2a943fadb241a63de1535a007a7bd185e7037abfff99f63
 ✔ Cataloged contents 61c9fbada2048bc7a229a0d38ee6e6a9a07f729d3136c0bc36b10c3ccba9fee6
   ├── ✔ Packages                        [88 packages]
   ├── ✔ File digests                    [4,732 files]
   ├── ✔ File metadata                   [4,732 locations]
   └── ✔ Executables                     [694 executables]
NAME                    VERSION                TYPE
adduser                 3.134                  deb
apt                     2.6.1                  deb
base-files              12.4+deb12u6           deb
base-passwd             3.6.1                  deb
bash                    5.2.15-2+b7            deb
-- 8< -- 

Conclusion

With the WARN messages have successfully been suppressed, but with -v I am able to surface an INFO (and an ERROR) which will indeed be displayed whether using a pseudo tty or not.

Docker (with tty)

docker run -it -e HOME=/ -e TMPDIR=/ syft-3081:latest -v scan /containerimage.tar
[0000]  INFO syft version: 1.10.0
[0000] ERROR failed to fetch latest version: Get "https://toolbox-data.anchore.io/syft/releases/latest/VERSION": tls: failed to verify certificate: x509: certificate signed by unknown authority
NAME                    VERSION                TYPE
adduser                 3.134                  deb
apt                     2.6.1                  deb
base-files              12.4+deb12u6           deb
base-passwd             3.6.1                  deb
bash                    5.2.15-2+b7            deb
-- 8< -- 

Podman (with tty)

podman run -ti -e HOME=/ -e TMPDIR=/ syft-3081:latest -v scan /containerimage.tar
[0000]  INFO syft version: 1.10.0
[0000] ERROR failed to fetch latest version: Get "https://toolbox-data.anchore.io/syft/releases/latest/VERSION": tls: failed to verify certificate: x509: certificate signed by unknown authority
NAME                    VERSION                TYPE
adduser                 3.134                  deb
apt                     2.6.1                  deb
base-files              12.4+deb12u6           deb
base-passwd             3.6.1                  deb
bash                    5.2.15-2+b7            deb
-- 8< -- 

Docker (no tty)

docker run -i -e HOME=/ -e TMPDIR=/ syft-3081:latest -v scan /containerimage.tar
[0000]  INFO syft version: 1.10.0
[0000] ERROR failed to fetch latest version: Get "https://toolbox-data.anchore.io/syft/releases/latest/VERSION": tls: failed to verify certificate: x509: certificate signed by unknown authority
NAME                    VERSION                TYPE
adduser                 3.134                  deb
apt                     2.6.1                  deb
base-files              12.4+deb12u6           deb
base-passwd             3.6.1                  deb
bash                    5.2.15-2+b7            deb
-- 8< -- 

Podman (no tty)

podman run -i -e HOME=/ -e TMPDIR=/ syft-3081:latest -v scan /containerimage.tar
[0000]  INFO syft version: 1.10.0
[0000] ERROR failed to fetch latest version: Get "https://toolbox-data.anchore.io/syft/releases/latest/VERSION": tls: failed to verify certificate: x509: certificate signed by unknown authority
NAME                    VERSION                TYPE
adduser                 3.134                  deb
apt                     2.6.1                  deb
base-files              12.4+deb12u6           deb
base-passwd             3.6.1                  deb
bash                    5.2.15-2+b7            deb
-- 8< -- 

The assumption that animations are preventing things appearing is unfounded in my opinion.
So I think it's working as designed, and I'm unconvinced this is a bug.

[willmurphyscode]

I did a little more work understanding what's happening over on the related Grype issue: anchore/grype#2180 (comment)

I think it might be a clio fix, but I think, in general, when we have a noUI setup in clio, we should still make a stderr logger set at WARN.

[willmurphyscode]

I did some experiments and proved a couple for things:

1. We discard log.Warn incorrectly when there's no TTY present, because the lack of TTY makes us not initiate the terminal UI, and the lack of --verbose makes us not initiate the stderr logger.
2. The same issue affects grype (see link above)
3. The bug is in clio (see below)

https://github.com/anchore/clio/blob/f538a9016e10cb9563c9fb40f0d3345ba12e6c70/logging.go#L44 is incorrect, because it assumes that there's nothing to log if there's verbosity=0, but verbosity=0 is log.Warn, so we should still initiate stderr logging here, even if there's no TTY.