Stream the output of docker build commands in packaging

[aquarat]

Description

When building docker images we don't see output from the underlying docker build commands.

The relevant output during the docker build process:

$ /build/node_modules/.bin/ts-node docker/scripts/prepare-containers.ts
CLI options: {"_":[],"npmTag":"local","npm-tag":"local","dockerTag":"local","docker-tag":"local","dev":false,"$0":"docker/scripts/prepare-containers.ts"}
Running command: 'docker run -d --rm --name airnode-npm-registry-154a2a4f verdaccio/verdaccio:latest'
Running command: 'docker inspect --format '{{.NetworkSettings.IPAddress}}' airnode-npm-registry-154a2a4f'
Running NPM registry container. Name: airnode-npm-registry-154a2a4f, URL: http://172.17.0.4:4873
Updated .npmrc: //172.17.0.4:4873/:_authToken="Nc9d92BSEnVSg6pOSyyCDSjAW3tJePoz6G43R/N8jL8="
registry=http://172.17.0.4:4873

Updated .yarnrc: registry "http://172.17.0.4:4873"

Running command: 'yarn changeset version --snapshot local' with options {"stdio":"ignore"}
Running command: 'yarn changeset publish --no-git-tag --snapshot --tag local' with options {"stdio":"ignore"}
Running command: 'docker build --no-cache --build-arg npmRegistryUrl=http://172.17.0.4:4873 --build-arg npmTag=local --tag api3/airnode-admin:local --file packages/airnode-admin/docker/Dockerfile packages/airnode-admin/docker'
Running command: 'docker build --no-cache --build-arg npmRegistryUrl=http://172.17.0.4:4873 --build-arg npmTag=local --tag api3/airnode-deployer:local --file packages/airnode-deployer/docker/Dockerfile packages/airnode-deployer/docker'
Running command: 'docker build --no-cache --build-arg npmRegistryUrl=http://172.17.0.4:4873 --build-arg npmTag=local --tag api3/airnode-client:local --file packages/airnode-node/docker/Dockerfile packages/airnode-node/docker'
Running command: 'docker stop airnode-npm-registry-154a2a4f'

[amarthadan]

That's odd, I can see this on my machine

But I see it missing in the CI 🤔

[Siegrift]

You can get more info from here:

(In the settings -> download log archive, or simply click the "view raw logs"). From there I can see this failure:

2022-10-06T07:32:52.1081203Z (node:1073) UnhandledPromiseRejectionWarning: Error: Command failed: docker build --no-cache --build-arg npmRegistryUrl=http://172.17.0.3:4873 --build-arg npmTag=a2e7a03120ce31afe471faf3bbeba247f0b5fd87 --tag api3/airnode-admin-dev:a2e7a03120ce31afe471faf3bbeba247f0b5fd87 --file packages/airnode-admin/docker/Dockerfile packages/airnode-admin/docker
2022-10-06T07:32:52.1083323Z The command '/bin/sh -c npm set registry ${npmRegistryUrl} &&     yarn global add ${packageName}@${npmTag} &&     ln -s /usr/local/share/.config/yarn/global/node_modules/${packageName}/dist ${appDir} &&     adduser -h ${appDir} -s /bin/false -S -D -H ${name}' returned a non-zero code: 1
2022-10-06T07:32:52.1084250Z 
2022-10-06T07:32:52.1084618Z     at checkExecSyncError (child_process.js:790:11)
2022-10-06T07:32:52.1085341Z     at execSync (child_process.js:863:15)
2022-10-06T07:32:52.1085875Z     at runCommand (/build/docker/scripts/utils.ts:7:18)
2022-10-06T07:32:52.1086791Z     at buildContainers (/build/docker/scripts/prepare-containers.ts:57:13)
2022-10-06T07:32:52.1087490Z     at /build/docker/scripts/prepare-containers.ts:71:3
2022-10-06T07:32:52.1088199Z     at Generator.next (<anonymous>)
2022-10-06T07:32:52.1088988Z     at fulfilled (/build/docker/scripts/prepare-containers.ts:11:58)
2022-10-06T07:32:52.1089822Z     at processTicksAndRejections (internal/process/task_queues.js:95:5)
2022-10-06T07:32:52.1090615Z (Use `node --trace-warnings ...` to show where the warning was created)
2022-10-06T07:32:52.1094409Z (node:1073) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 8)
2022-10-06T07:32:52.1096248Z (node:1073) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

[aquarat]

You don't get the Docker build output (like what @amarthadan posted). I see the output on Mac OS, but not on Ubuntu.
The output @Siegrift posted is just the top-level failure; it's indicating a command failed to execute, but there's no indication of that command's output.
It's probably related to stdout vs stderr. It's not a big deal, just makes fault tracing harder.

It's not a biggie, just a nice to have for debugging.

[dcroote]

Same issue for recent renovate bot PRs e.g. #1489 and #1496: see here and here, respectively. One problem is that this CI step, Build Docker containers, "passes" CI and only two steps later, in Push airnode-admin to Docker Hub, is there a CI failure.

[aquarat]

I know what's going on... I could probably fix it myself quickly but I'll leave that to someone else:
In https://github.com/api3dao/airnode/blob/a2e7a03120ce31afe471faf3bbeba247f0b5fd87/packages/airnode-examples/test/utils.ts:

export const runCommand = (command: string) => {
  logger.log(`Running command:\n${command}`);
  const result = spawnSync(command, {
    shell: true,
  });

  if (result.status !== 0 || result.error) {
    throw new Error(`Command failed with non-zero status code. Output:\n${result.stdout.toString()}`);
  }

  const stderr = result.stderr.toString();
  if (stderr) {
    cliPrint.warning(`Stderr output:\n${stderr}`);
  }

  const stdout = result.stdout.toString();
  if (stdout) {
    consoleLog(`Stdout output:\n${stdout}`);
  }
  return stdout;
};

If the command fails, the function throws and the output isn't printed.
Just moving the throw further down would probably be enough.

We also only see the output once the command has finished. A better approach may be to print the outputs as they occur, something like this example:

var spawn = require('child_process').spawn,
    ls    = spawn('ls', ['-lh', '/usr']);

ls.stdout.on('data', function (data) {
  console.log('stdout: ' + data.toString());
});

ls.stderr.on('data', function (data) {
  console.log('stderr: ' + data.toString());
});

ls.on('exit', function (code) {
  console.log('child process exited with code ' + code.toString());
});

[Siegrift]

Moved to done, since this is internal only change and was tested.