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.