Non-deterministic ordering of buildpack stdout/stderr

[edmorley]

Summary

The pack build ordering of stdout vs stderr output from buildpacks is non-deterministic, which breaks the readability of build logs that contain a mixture of stdout and stderr.

This affects the following common use-cases:

• Buildpacks outputting a deprecation warning to stderr, in-between other stdout content (such as build step messages). With incorrect ordering the messages may not make sense, since they don't appear under the correct build step's heading etc.
• Any of the commands run by buildpacks (eg a package manager) which also output a mixture of stdout vs stderr

We hadn't discovered this until now since out CNB test runner captures stdout and stderr separately (to allow for finer grained test assertions), which masks the fact that when rendered to the user, the combined/interleaved ordering of the two is incorrect.

I'm not sure if this is a Pack CLI bug, or a lifecycle bug (our builder image is using the latest lifecycle, v0.20.5), but filing against Pack CLI for now (feel free to move the issue over if needed). I'm presuming this is related to buffering of some sort.

---

Reproduction

Steps

1. mkdir testcase && cd $_

2. cat > project.toml <<'EOF'
   [_]
   schema-version = "0.2"
   
   [io.buildpacks]
   builder = "heroku/builder:24"
   
   [[io.buildpacks.group]]
   id = "inline"
   
     [io.buildpacks.group.script]
     api = "0.10"
     shell = "/bin/bash"
     inline = '''
   set -euo pipefail
   
   for i in {1..20}; do
       echo "---> Some build step: ${i}"
       echo "Some normal output: ${i}"
       echo "Some stderr: ${i}" >&2
   done
   '''
   EOF
   

3. pack build testcase

Current behavior

The log lines (a) do not appear in the expected order, (b) the order varies from build to build.

$ pack build testcase
24: Pulling from heroku/builder
Digest: sha256:fd633c7b5929eee7dbdfa9f7765f35819266361e9f405fdffbe0b1d36c0edbca
Status: Image is up to date for heroku/builder:24
24: Pulling from heroku/heroku
Digest: sha256:9483dc324ebd0615f936808da8da14c401c790f96b13a331208c4513a57c2051
Status: Image is up to date for heroku/heroku:24
===> ANALYZING
Restoring data for SBOM from previous image
===> DETECTING
inline 0.0.0
===> RESTORING
===> BUILDING
---> Some build step: 1
Some normal output: 1
---> Some build step: 2
Some normal output: 2
---> Some build step: 3
Some normal output: 3
---> Some build step: 4
Some normal output: 4
---> Some build step: 5
Some normal output: 5
---> Some build step: 6
Some normal output: 6
---> Some build step: 7
Some normal output: 7
---> Some build step: 8
Some normal output: 8
---> Some build step: 9
Some normal output: 9
---> Some build step: 10
Some normal output: 10
---> Some build step: 11
Some normal output: 11
---> Some build step: 12
Some normal output: 12
---> Some build step: 13
Some normal output: 13
---> Some build step: 14
Some normal output: 14
Some stderr: 1
Some stderr: 2
Some stderr: 3
Some stderr: 4
Some stderr: 5
Some stderr: 6
Some stderr: 7
Some stderr: 8
Some stderr: 9
Some stderr: 10
Some stderr: 11
Some stderr: 12
Some stderr: 13
---> Some build step: 15
Some normal output: 15
---> Some build step: 16
Some normal output: 16
---> Some build step: 17
Some normal output: 17
---> Some build step: 18
Some normal output: 18
---> Some build step: 19
Some normal output: 19
---> Some build step: 20
Some normal output: 20
Some stderr: 14
Some stderr: 15
Some stderr: 16
Some stderr: 17
Some stderr: 18
Some stderr: 19
Some stderr: 20
===> EXPORTING
Reusing layer 'buildpacksio/lifecycle:launch.sbom'
Added 1/1 app layer(s)
Reusing layer 'buildpacksio/lifecycle:launcher'
Reusing layer 'buildpacksio/lifecycle:config'
Adding label 'io.buildpacks.lifecycle.metadata'
Adding label 'io.buildpacks.build.metadata'
Adding label 'io.buildpacks.project.metadata'
no default process type
Saving testcase...
*** Images (4d3eedd313c0):
      testcase
Successfully built image testcase

Expected behavior

For the buildpack log lines to appear in this order:

---> Some build step: 1
Some normal output: 1
Some stderr: 1
---> Some build step: 2
Some normal output: 2
Some stderr: 2
---> Some build step: 3
Some normal output: 3
Some stderr: 3
...

---

Environment

pack info

$ pack report
Pack:
  Version:  0.36.4+git-c7f5b1c.build-6274
  OS/Arch:  darwin/arm64

Default Lifecycle Version:  0.20.3

Supported Platform APIs:  0.3, 0.4, 0.5, 0.6, 0.7, 0.8, 0.9, 0.10, 0.11, 0.12, 0.13

Config:
  default-builder-image = "[REDACTED]"

Note: The builder image used above is using lifecycle v0.20.5.

docker info

$ docker info
Client:
 Version:    27.5.1
 Context:    desktop-linux
 Debug Mode: false
 Plugins:
  SNIP

Server:
 Containers: 0
  Running: 0
  Paused: 0
  Stopped: 0
 Images: 69
 Server Version: 27.5.1
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Using metacopy: false
  Native Overlay Diff: true
  userxattr: false
 Logging Driver: json-file
 Cgroup Driver: cgroupfs
 Cgroup Version: 2
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local splunk syslog
 CDI spec directories:
  /etc/cdi
  /var/run/cdi
 Swarm: inactive
 Runtimes: io.containerd.runc.v2 runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: bcc810d6b9066471b0b6fa75f557a15a1cbf31bb
 runc version: v1.1.12-0-g51d5e946
 init version: de40ad0
 Security Options:
  seccomp
   Profile: unconfined
  cgroupns
 Kernel Version: 6.12.5-linuxkit
 Operating System: Docker Desktop
 OSType: linux
 Architecture: aarch64
 CPUs: 10
 Total Memory: 15.6GiB
 Name: docker-desktop
 ID: REDACTED
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 HTTP Proxy: http.docker.internal:3128
 HTTPS Proxy: http.docker.internal:3128
 No Proxy: hubproxy.docker.internal
 Labels:
  com.docker.desktop.address=unix:///Users/emorley/Library/Containers/com.docker.docker/Data/docker-cli.sock
 Experimental: false
 Insecure Registries:
  hubproxy.docker.internal:5555
  127.0.0.0/8
 Live Restore Enabled: false

WARNING: daemon is not using the default seccomp profile

[jjbustamante]

Thanks for creating this issue @edmorley, I believe the indeterministic ordering came from we are using go rutines to collect the messages, maybe? I am not sure, but I think the code related is here we only use a different container handler when running pack with --interactive flag.

I think we are just reading the output from the container executing the lifecycle and putting it into the standard output.

[edmorley]

Due to this bug, we've having to redirect all stderr to stdout (or vice versa), so the user-facing output isn't mangled.

(Sadly I don't have the time to dig into this at the moment)

[dzuelke]

Is the container created using a TTY?

There are a few variables (PTY/TTY, Shell, OS config), but, often, stdout is line buffered, while stderr is unbuffered. That alone can cause issues. When programs then also read both pipes separately, subtle timing differences can lead to non-deterministic output; it's hard to avoid entirely.

For ContainerAttach, the API docs specifically mention having to demultiplex the stream (emphasis mine) if it's not a TTY:

ContainerAttach attaches a connection to a container in the server. It returns a types.HijackedConnection with the hijacked connection and the a reader to get > output. It's up to the called to close the hijacked connection by calling types.HijackedResponse.Close.

The stream format on the response will be in one of two formats:

If the container is using a TTY, there is only a single stream (stdout), and data is copied directly from the container output stream, no extra multiplexing or headers.

If the container is not using a TTY, streams for stdout and stderr are multiplexed. The format of the multiplexed stream is as follows:

[8]byte{STREAM_TYPE, 0, 0, 0, SIZE1, SIZE2, SIZE3, SIZE4}[]byte{OUTPUT}

STREAM_TYPE can be 1 for stdout and 2 for stderr

SIZE1, SIZE2, SIZE3, and SIZE4 are four bytes of uint32 encoded as big endian. This is the size of OUTPUT.

You can use github.com/docker/docker/pkg/stdcopy.StdCopy to demultiplex this stream.