devcontainer build/test -d/test -f false-positive "Exit Code 1" or "Exit Code 2" log messages lead to user confusion

[mjnowen]

Using: Dev Containers 0.369.0 in VS Code 1.90.1 (611f9bfce64f25108829dd295f54a6894e87339d)
macOS v14.5 on M1 Pro, running linux/amd64 Ubuntu 24.04 LTS devcontainer/remote-ssh via Docker Desktop/Engine v26.1.4

In a typical devcontainer build, my log has 11 x "Exit Code 1" log messages and 1 x "Exit Code 127" log message. I can summarise the log messages as all effectively being "false-positives" and honestly, confusing for any user and why I'm spending time to write this discussion topic. IMO, these log messages unless critical/causing a break, should be silenced.

The vast majority of the "Exit Code 1" log messages are from various test -d or test -f checks and presumably, if not present (Exit Code 1), then the devcontainer build creates the dir/file. End users don't need to see this, unless it fails.

Similarly, if gpg is not installed/present in the devcontainer, you will get a Exit Code 2 log message. Again, should only be surfaced if it needs fixing/breaks some functionality.

Ideally? I propose all "Exit Code" log messages are removed and only surfaced if there is actually an error that the end-user needs to know about. Additionally, I note that I applied the "dev.containers.logLevel": "info" at both VSC user-settings level on the macOS host as well as in my devcontainer.json and that had no effect compared to setting it to: "dev.containers.logLevel": "debug", so I question the lack of granular log verbosity in the devcontainer build logs here as well...

Examples:

[2024-06-19T12:25:43.724Z] Stop (23 ms): Run in container: (cat /etc/os-release || cat /usr/lib/os-release) 2>/dev/null
[2024-06-19T12:25:43.724Z] Start: Run in container:  (command -v getent >/dev/null 2>&1 && getent passwd 'ubuntu' || grep -E '^ubuntu|^[^:]*:[^:]*:ubuntu:' /etc/passwd || true)
[2024-06-19T12:25:43.751Z] Stop (27 ms): Run in container:  (command -v getent >/dev/null 2>&1 && getent passwd 'ubuntu' || grep -E '^ubuntu|^[^:]*:[^:]*:ubuntu:' /etc/passwd || true)
[2024-06-19T12:25:43.752Z] Start: Run in container: test -f '/var/devcontainer/.patchEtcEnvironmentMarker'
[2024-06-19T12:25:43.754Z] 
[2024-06-19T12:25:43.754Z] 
[2024-06-19T12:25:43.754Z] Exit code 1
[2024-06-19T12:25:43.754Z] Stop (2 ms): Run in container: test -f '/var/devcontainer/.patchEtcEnvironmentMarker'
[2024-06-19T12:25:43.754Z] Start: Run in container: /bin/sh
[2024-06-19T12:25:43.755Z] Start: Run in container: test ! -f '/var/devcontainer/.patchEtcEnvironmentMarker' && set -o noclobber && mkdir -p '/var/devcontainer' && { > '/var/devcontainer/.patchEtcEnvironmentMarker' ; } 2> /dev/null
[2024-06-19T12:25:43.839Z] 
[2024-06-19T12:25:43.839Z] 
[2024-06-19T12:25:43.839Z] Stop (84 ms): Run in container: test ! -f '/var/devcontainer/.patchEtcEnvironmentMarker' && set -o noclobber && mkdir -p '/var/devcontainer' && { > '/var/devcontainer/.patchEtcEnvironmentMarker' ; } 2> /dev/null
[2024-06-19T12:25:43.839Z] Start: Run in container: cat >> /etc/environment <<'etcEnvrionmentEOF'
[2024-06-19T12:25:43.861Z] 
[2024-06-19T12:25:43.861Z] 
[2024-06-19T12:25:43.861Z] Stop (22 ms): Run in container: cat >> /etc/environment <<'etcEnvrionmentEOF'
[2024-06-19T12:25:43.861Z] Start: Run in container: test -f '/var/devcontainer/.patchEtcProfileMarker'
[2024-06-19T12:25:43.863Z] 
[2024-06-19T12:25:43.863Z] 
[2024-06-19T12:25:43.863Z] Exit code 1
[2024-06-19T12:25:43.863Z] Stop (2 ms): Run in container: test -f '/var/devcontainer/.patchEtcProfileMarker'
[2024-06-19T12:25:43.863Z] Start: Run in container: test ! -f '/var/devcontainer/.patchEtcProfileMarker' && set -o noclobber && mkdir -p '/var/devcontainer' && { > '/var/devcontainer/.patchEtcProfileMarker' ; } 2> /dev/null
[2024-06-19T12:25:43.887Z] 
[2024-06-19T12:25:43.887Z] 
[2024-06-19T12:25:43.887Z] Stop (24 ms): Run in container: test ! -f '/var/devcontainer/.patchEtcProfileMarker' && set -o noclobber && mkdir -p '/var/devcontainer' && { > '/var/devcontainer/.patchEtcProfileMarker' ; } 2> /dev/null

and some more:

[2024-06-19T12:25:44.395Z] Stop (3 ms): Setup shutdown monitor
[2024-06-19T12:25:44.395Z] Start: Run in container: test -d '/home/ubuntu/.vscode-server'
[2024-06-19T12:25:44.398Z] 
[2024-06-19T12:25:44.398Z] 
[2024-06-19T12:25:44.398Z] Exit code 1
[2024-06-19T12:25:44.398Z] Stop (3 ms): Run in container: test -d '/home/ubuntu/.vscode-server'
[2024-06-19T12:25:44.398Z] Start: Run in container: test -d '/home/ubuntu/.vscode-remote'
[2024-06-19T12:25:44.400Z] 
[2024-06-19T12:25:44.400Z] 
[2024-06-19T12:25:44.400Z] Exit code 1
[2024-06-19T12:25:44.400Z] Stop (2 ms): Run in container: test -d '/home/ubuntu/.vscode-remote'
[2024-06-19T12:25:44.400Z] Start: Run in container: test ! -f '/home/ubuntu/.vscode-server/data/Machine/.writeMachineSettingsMarker' && set -o noclobber && mkdir -p '/home/ubuntu/.vscode-server/data/Machine' && { > '/home/ubuntu/.vscode-server/data/Machine/.writeMachineSettingsMarker' ; } 2> /dev/null
[2024-06-19T12:25:44.424Z] 
[2024-06-19T12:25:44.424Z] 
[2024-06-19T12:25:44.424Z] Stop (24 ms): Run in container: test ! -f '/home/ubuntu/.vscode-server/data/Machine/.writeMachineSettingsMarker' && set -o noclobber && mkdir -p '/home/ubuntu/.vscode-server/data/Machine' && { > '/home/ubuntu/.vscode-server/data/Machine/.writeMachineSettingsMarker' ; } 2> /dev/null
[2024-06-19T12:25:44.424Z] Start: Run in container: mkdir -p '/home/ubuntu/.vscode-server/data/Machine' && cat >'/home/ubuntu/.vscode-server/data/Machine/settings.json' <<'settingsJSON'
[2024-06-19T12:25:44.467Z] 
[2024-06-19T12:25:44.467Z] 
[2024-06-19T12:25:44.467Z] Stop (43 ms): Run in container: mkdir -p '/home/ubuntu/.vscode-server/data/Machine' && cat >'/home/ubuntu/.vscode-server/data/Machine/settings.json' <<'settingsJSON'
[2024-06-19T12:25:44.467Z] Start: Run in container: test -d '/home/ubuntu/.vscode-server/bin/611f9bfce64f25108829dd295f54a6894e87339d'
[2024-06-19T12:25:44.469Z] 
[2024-06-19T12:25:44.469Z] 
[2024-06-19T12:25:44.469Z] Exit code 1
[2024-06-19T12:25:44.469Z] Stop (2 ms): Run in container: test -d '/home/ubuntu/.vscode-server/bin/611f9bfce64f25108829dd295f54a6894e87339d'
[2024-06-19T12:25:44.469Z] Start: Run in container: test -d '/vscode/vscode-server/bin/linux-x64/611f9bfce64f25108829dd295f54a6894e87339d'

and Exit Code 2 example:

[2024-06-19T12:25:45.055Z] Stop (539 ms): Run in container: '/home/ubuntu/.vscode-server/bin/611f9bfce64f25108829dd295f54a6894e87339d/bin/helpers/check-requirements.sh'
[2024-06-19T12:25:45.055Z] Start: Launching Dev Containers helper.
[2024-06-19T12:25:45.055Z] ssh-agent: SSH_AUTH_SOCK not set on local host.
[2024-06-19T12:25:45.055Z] X11 forwarding: DISPLAY not set on local host.
[2024-06-19T12:25:45.055Z] Start: Run in container: gpgconf --list-dir agent-socket
[2024-06-19T12:25:45.059Z] 
[2024-06-19T12:25:45.059Z] /bin/sh: 202: gpgconf: not found
[2024-06-19T12:25:45.059Z] Exit code 127
[2024-06-19T12:25:45.059Z] Stop (4 ms): Run in container: gpgconf --list-dir agent-socket
[2024-06-19T12:25:45.059Z] gpg-agent: No agent-socket found in container.
[2024-06-19T12:25:45.059Z] Start: Run in container: command -v docker >/dev/null 2>&1
[2024-06-19T12:25:45.062Z] 
[2024-06-19T12:25:45.062Z] 
[2024-06-19T12:25:45.062Z] Stop (3 ms): Run in container: command -v docker >/dev/null 2>&1
[2024-06-19T12:25:45.062Z] Start: Run in container: /bin/sh
[2024-06-19T12:25:45.062Z] Stop (7 ms): Launching Dev Containers helper.
[2024-06-19T12:25:45.064Z] userEnvProbe: loginInteractiveShell (default)
[2024-06-19T12:25:45.064Z] Start: Run in container: test -f '/tmp/devcontainers-f62ba3ce-8e08-4b38-a8d6-4f6a060f7f7b1718799416121/env-loginInteractiveShell.json'
[2024-06-19T12:25:45.064Z] Start: Run in container: echo ~
[2024-06-19T12:25:45.066Z] 
[2024-06-19T12:25:45.066Z] 
[2024-06-19T12:25:45.066Z] Exit code 1
[2024-06-19T12:25:45.066Z] Stop (2 ms): Run in container: test -f '/tmp/devcontainers-f62ba3ce-8e08-4b38-a8d6-4f6a060f7f7b1718799416121/env-loginInteractiveShell.json'
[2024-06-19T12:25:45.066Z] Start: Run in container: # Test for /home/ubuntu/.ssh/known_hosts and ssh
[2024-06-19T12:25:45.066Z] userEnvProbe: not found in cache
[2024-06-19T12:25:45.066Z] userEnvProbe shell: /bin/bash
[2024-06-19T12:25:45.068Z] /home/ubuntu/.ssh/known_hosts exists
[2024-06-19T12:25:45.069Z] 
[2024-06-19T12:25:45.069Z] Exit code 1
[2024-06-19T12:25:45.069Z] Stop (3 ms): Run in container: # Test for /home/ubuntu/.ssh/known_hosts and ssh
[2024-06-19T12:25:45.069Z] Start: Run in container: command -v git >/dev/null 2>&1 && git config --system --replace-all credential.helper '!f() { /home/ubuntu/.vscode-server/bin/611f9bfce64f25108829dd295f54a6894e87339d/node /tmp/vscode-remote-containers-0c87f4c7-4582-49f2-9a79-3930ff4f9f81.js git-credential-helper $*; }; f' || true

and a few more, marker errors:

[2024-06-19T12:25:49.166Z] 
[2024-06-19T12:25:49.166Z] Stop (23 ms): Run in container: cat '/tmp/devcontainers-f62ba3ce-8e08-4b38-a8d6-4f6a060f7f7b1718799416121/env-loginInteractiveShell.json'
[2024-06-19T12:25:49.166Z] Start: Run in container: mkdir -p '/home/ubuntu/.devcontainer' && CONTENT="$(cat '/home/ubuntu/.devcontainer/.updateContentCommandMarker' 2>/dev/null || echo ENOENT)" && [ "${CONTENT:-2024-06-19T12:25:43.378237881Z}" != '2024-06-19T12:25:43.378237881Z' ] && echo '2024-06-19T12:25:43.378237881Z' > '/home/ubuntu/.devcontainer/.updateContentCommandMarker'
[2024-06-19T12:25:49.214Z] 
[2024-06-19T12:25:49.214Z] 
[2024-06-19T12:25:49.214Z] Exit code 1
[2024-06-19T12:25:49.214Z] Stop (48 ms): Run in container: mkdir -p '/home/ubuntu/.devcontainer' && CONTENT="$(cat '/home/ubuntu/.devcontainer/.updateContentCommandMarker' 2>/dev/null || echo ENOENT)" && [ "${CONTENT:-2024-06-19T12:25:43.378237881Z}" != '2024-06-19T12:25:43.378237881Z' ] && echo '2024-06-19T12:25:43.378237881Z' > '/home/ubuntu/.devcontainer/.updateContentCommandMarker'
[2024-06-19T12:25:49.214Z] Start: Run in container: mkdir -p '/home/ubuntu/.devcontainer' && CONTENT="$(cat '/home/ubuntu/.devcontainer/.postCreateCommandMarker' 2>/dev/null || echo ENOENT)" && [ "${CONTENT:-2024-06-19T12:25:43.378237881Z}" != '2024-06-19T12:25:43.378237881Z' ] && echo '2024-06-19T12:25:43.378237881Z' > '/home/ubuntu/.devcontainer/.postCreateCommandMarker'
[2024-06-19T12:25:49.264Z] 
[2024-06-19T12:25:49.264Z] 
[2024-06-19T12:25:49.264Z] Exit code 1
[2024-06-19T12:25:49.264Z] Stop (50 ms): Run in container: mkdir -p '/home/ubuntu/.devcontainer' && CONTENT="$(cat '/home/ubuntu/.devcontainer/.postCreateCommandMarker' 2>/dev/null || echo ENOENT)" && [ "${CONTENT:-2024-06-19T12:25:43.378237881Z}" != '2024-06-19T12:25:43.378237881Z' ] && echo '2024-06-19T12:25:43.378237881Z' > '/home/ubuntu/.devcontainer/.postCreateCommandMarker'
[2024-06-19T12:25:49.264Z] Start: Run in container: mkdir -p '/home/ubuntu/.devcontainer' && CONTENT="$(cat '/home/ubuntu/.devcontainer/.postStartCommandMarker' 2>/dev/null || echo ENOENT)" && [ "${CONTENT:-2024-06-19T12:25:43.52737209Z}" != '2024-06-19T12:25:43.52737209Z' ] && echo '2024-06-19T12:25:43.52737209Z' > '/home/ubuntu/.devcontainer/.postStartCommandMarker'
[2024-06-19T12:25:49.315Z] 
[2024-06-19T12:25:49.315Z] 
[2024-06-19T12:25:49.315Z] Stop (51 ms): Run in container: mkdir -p '/home/ubuntu/.devcontainer' && CONTENT="$(cat '/home/ubuntu/.devcontainer/.postStartCommandMarker' 2>/dev/null || echo ENOENT)" && [ "${CONTENT:-2024-06-19T12:25:43.52737209Z}" != '2024-06-19T12:25:43.52737209Z' ] && echo '2024-06-19T12:25:43.52737209Z' > '/home/ubuntu/.devcontainer/.postStartCommandMarker'
[2024-06-19T12:25:49.315Z] Running the postStartCommand from devcontainer.json...

[bamurtaugh]

Thanks for opening. I'm curious to get @chrmarti's thoughts on this one.

[chrmarti]

We write to the log all the information that might help us investigate any issues the user might come across. When users file an issue for us, we usually ask for this log. Non-zero exit codes are part of the information we need, they do not necessarily indicate a problem by themselves.

[mjnowen]

As a developer, I appreciate the need for detailed (enough) log(s) from support or end user(s) to effectively root-cause the issue.

However, from the perspective of engineers having to provide first-line support or just due diligent end-users/developers, when they see a "Exit Code 1" they know it means failure and raise a support ticket causing unnecessary churn.

As a compromise, why not surface these errors only when "dev.containers.logLevel" is set to debug or higher? (Currently, its surfaced for all verbosity log levels, including info which feels excessive).

Better still, I think this discussion raises another issue which is the need for a "Create Support Bundle" function, if MSFT needs a bunch of logs/stats/config to effectively investigate any "VS Code" issue. With such a function, you could expose it as a button/API call somewhere and your messaging to customers/end-users would be far simpler when you need logs. The API call, could even 'send' this support bundle to your server for analysis. For customers that do not wish to send such info/the API function could simply be disabled.