From 96287d8e95066ee768f453ec422a690530a6ab02 Mon Sep 17 00:00:00 2001 From: Opal Symes Date: Wed, 29 Jun 2022 13:10:33 +1200 Subject: [PATCH 1/4] Upload logs when services fail to start Fixes Container logs are not uploaded when dependencies fail to start #327 --- commands/run.sh | 54 ++++++++++++++++++----------------------- lib/run.bash | 39 +++++++++++++++++++++++++++++ tests/output.bats | 62 +++++++++++++++++++++++++++++++++++++++++------ 3 files changed, 117 insertions(+), 38 deletions(-) diff --git a/commands/run.sh b/commands/run.sh index 1fc39aeb..9af11c64 100755 --- a/commands/run.sh +++ b/commands/run.sh @@ -241,15 +241,35 @@ fi # Start up service dependencies in a different header to keep the main run with less noise if [[ "$(plugin_read_config DEPENDENCIES "true")" == "true" ]] ; then + exitcode=0 + echo "~~~ :docker: Starting dependencies" if [[ ${#up_params[@]} -gt 0 ]] ; then - run_docker_compose "${up_params[@]}" up -d --scale "${run_service}=0" "${run_service}" + if ! run_docker_compose "${up_params[@]}" up -d --scale "${run_service}=0" "${run_service}"; then + exitcode=1 + fi else - run_docker_compose up -d --scale "${run_service}=0" "${run_service}" + if ! run_docker_compose up -d --scale "${run_service}=0" "${run_service}"; then + exitcode=1 + fi fi # Sometimes docker-compose leaves unfinished ansi codes echo + + if [[ $exitcode -ne 0 ]] ; then + # Dependent services failed to start. + echo "^^^ +++" + echo "+++ 🚨 Failed to start dependencies" + + if [[ -n "${BUILDKITE_AGENT_ACCESS_TOKEN:-}" ]] ; then + print_failed_container_information + + upload_container_logs "$run_service" + fi + + return $exitcode + fi fi shell=() @@ -354,35 +374,9 @@ fi if [[ -n "${BUILDKITE_AGENT_ACCESS_TOKEN:-}" ]] ; then if [[ "$(plugin_read_config CHECK_LINKED_CONTAINERS "true")" != "false" ]] ; then + print_failed_container_information - # Get list of failed containers - containers=() - while read -r container ; do - [[ -n "$container" ]] && containers+=("$container") - done <<< "$(docker_ps_by_project -q)" - - failed_containers=() - if [[ 0 != "${#containers[@]}" ]] ; then - while read -r container ; do - [[ -n "$container" ]] && failed_containers+=("$container") - done <<< "$(docker inspect -f '{{if ne 0 .State.ExitCode}}{{.Name}}.{{.State.ExitCode}}{{ end }}' \ - "${containers[@]}")" - fi - - if [[ 0 != "${#failed_containers[@]}" ]] ; then - echo "+++ :warning: Some containers had non-zero exit codes" - docker_ps_by_project \ - --format 'table {{.Label "com.docker.compose.service"}}\t{{ .ID }}\t{{ .Status }}' - fi - - check_linked_containers_and_save_logs \ - "$run_service" "docker-compose-logs" \ - "$(plugin_read_config UPLOAD_CONTAINER_LOGS "on-error")" - - if [[ -d "docker-compose-logs" ]] && test -n "$(find docker-compose-logs/ -maxdepth 1 -name '*.log' -print)"; then - echo "~~~ Uploading linked container logs" - buildkite-agent artifact upload "docker-compose-logs/*.log" - fi + upload_container_logs "$run_service" fi fi diff --git a/lib/run.bash b/lib/run.bash index bd057ab7..3c88be92 100644 --- a/lib/run.bash +++ b/lib/run.bash @@ -88,3 +88,42 @@ expand_relative_volume_path() { echo "${path/.\//$pwd/}" } + +# Prints information about the failed containers. +function print_failed_container_information() { + # Get list of failed containers + containers=() + while read -r container ; do + [[ -n "$container" ]] && containers+=("$container") + done <<< "$(docker_ps_by_project -q)" + + failed_containers=() + if [[ 0 != "${#containers[@]}" ]] ; then + while read -r container ; do + [[ -n "$container" ]] && failed_containers+=("$container") + done <<< "$(docker inspect -f '{{if ne 0 .State.ExitCode}}{{.Name}}.{{.State.ExitCode}}{{ end }}' \ + "${containers[@]}")" + fi + + if [[ 0 != "${#failed_containers[@]}" ]] ; then + echo "+++ :warning: Some containers had non-zero exit codes" + docker_ps_by_project \ + --format 'table {{.Label "com.docker.compose.service"}}\t{{ .ID }}\t{{ .Status }}' + fi +} + +# Uploads the container's logs, respecting the `UPLOAD_CONTAINER_LOGS` option +function upload_container_logs() { + run_service="$1" + + if [[ -n "${BUILDKITE_AGENT_ACCESS_TOKEN:-}" ]] ; then + check_linked_containers_and_save_logs \ + "$run_service" "docker-compose-logs" \ + "$(plugin_read_config UPLOAD_CONTAINER_LOGS "on-error")" + + if [[ -d "docker-compose-logs" ]] && test -n "$(find docker-compose-logs/ -maxdepth 1 -name '*.log' -print)"; then + echo "~~~ Uploading linked container logs" + buildkite-agent artifact upload "docker-compose-logs/*.log" + fi + fi +} diff --git a/tests/output.bats b/tests/output.bats index 3139f7ca..c4a6f07a 100644 --- a/tests/output.bats +++ b/tests/output.bats @@ -29,8 +29,8 @@ load '../lib/run' stub docker-compose \ "-f docker-compose.yml -p buildkite1111 build --pull myservice : echo built myservice" \ - "-f docker-compose.yml -p buildkite1111 up -d --scale myservice=0 : echo ran myservice dependencies" \ - "-f docker-compose.yml -p buildkite1111 run --name buildkite1111_myservice_build_1 --rm myservice echo 'hello world' : echo ran myservice" + "-f docker-compose.yml -p buildkite1111 up -d --scale myservice=0 myservice : echo ran myservice dependencies" \ + "-f docker-compose.yml -p buildkite1111 run --name buildkite1111_myservice_build_1 --rm myservice echo 'hello world' : echo ran myservice command" stub docker \ "ps -a --filter label=com.docker.compose.project=buildkite1111 -q : cat tests/fixtures/id-multiple-services.txt" \ @@ -46,7 +46,51 @@ load '../lib/run' assert_success assert_output --partial "built myservice" - assert_output --partial "ran myservice" + assert_output --partial "ran myservice dependencies" + assert_output --partial "ran myservice command" + assert_output --partial "Some containers had non-zero exit codes" + unstub buildkite-agent + unstub docker-compose + unstub docker +} + +@test "Logs: Detect dependent services KO" { + # Test for Issue #327, Container logs are not uploaded when services fail to start. + export BUILDKITE_AGENT_ACCESS_TOKEN="123123" + export BUILDKITE_JOB_ID=1111 + export BUILDKITE_PLUGIN_DOCKER_COMPOSE_RUN=myservice + export BUILDKITE_PIPELINE_SLUG=test + export BUILDKITE_BUILD_NUMBER=1 + export BUILDKITE_COMMAND="" + export BUILDKITE_PLUGIN_DOCKER_COMPOSE_COMMAND_0=echo + export BUILDKITE_PLUGIN_DOCKER_COMPOSE_COMMAND_1="hello world" + export BUILDKITE_PLUGIN_DOCKER_COMPOSE_CHECK_LINKED_CONTAINERS=true + export BUILDKITE_PLUGIN_DOCKER_COMPOSE_CLEANUP=false + + + stub buildkite-agent \ + "meta-data exists docker-compose-plugin-built-image-tag-myservice : exit 1" \ + "artifact upload : exit 0" + + stub docker-compose \ + "-f docker-compose.yml -p buildkite1111 build --pull myservice : echo built myservice" \ + "-f docker-compose.yml -p buildkite1111 up -d --scale myservice=0 myservice : exit 1" \ + + stub docker \ + "ps -a --filter label=com.docker.compose.project=buildkite1111 -q : cat tests/fixtures/id-multiple-services.txt" \ + "inspect -f {{if\ ne\ 0\ .State.ExitCode}}{{.Name}}.{{.State.ExitCode}}{{\ end\ }} 456456 789789 : echo 456456.1" \ + "ps -a --filter label=com.docker.compose.project=buildkite1111 --format \* : cat tests/fixtures/service-id-exit-multiple-services-failed.txt" \ + "ps -a --filter label=com.docker.compose.project=buildkite1111 --format \* : cat tests/fixtures/id-service-multiple-services.txt" \ + "inspect --format={{.State.ExitCode}} 456456 : echo 1" \ + "logs --timestamps --tail 5 456456 : exit 0" \ + "logs -t 456456 : exit 0" \ + "inspect --format={{.State.ExitCode}} 789789 : echo 0" + + run $PWD/hooks/command + + assert_failure + assert_output --partial "built myservice" + assert_output --partial "Failed to start dependencies" assert_output --partial "Some containers had non-zero exit codes" unstub buildkite-agent unstub docker-compose @@ -72,7 +116,7 @@ load '../lib/run' stub docker-compose \ "-f docker-compose.yml -p buildkite1111 build --pull myservice : echo built myservice" \ "-f docker-compose.yml -p buildkite1111 up -d --scale myservice=0 myservice : echo ran myservice dependencies" \ - "-f docker-compose.yml -p buildkite1111 run --name buildkite1111_myservice_build_1 --rm myservice echo 'hello world' : echo ran myservice" + "-f docker-compose.yml -p buildkite1111 run --name buildkite1111_myservice_build_1 --rm myservice echo 'hello world' : echo ran myservice command" stub docker \ "ps -a --filter label=com.docker.compose.project=buildkite1111 -q : cat tests/fixtures/id-multiple-services.txt" \ @@ -85,7 +129,8 @@ load '../lib/run' assert_success assert_output --partial "built myservice" - assert_output --partial "ran myservice" + assert_output --partial "ran myservice dependencies" + assert_output --partial "ran myservice command" refute_output --partial "Some containers had non-zero exit codes" unstub docker unstub docker-compose @@ -113,8 +158,8 @@ load '../lib/run' stub docker-compose \ "-f docker-compose.yml -p buildkite1111 build --pull myservice : echo built myservice" \ - "-f docker-compose.yml -p buildkite1111 up -d --scale myservice=0 : echo ran myservice dependencies" \ - "-f docker-compose.yml -p buildkite1111 run --name buildkite1111_myservice_build_1 --rm myservice echo 'hello world' : echo ran myservice" + "-f docker-compose.yml -p buildkite1111 up -d --scale myservice=0 myservice : echo ran myservice dependencies" \ + "-f docker-compose.yml -p buildkite1111 run --name buildkite1111_myservice_build_1 --rm myservice echo 'hello world' : echo ran myservice command" stub docker \ "ps -a --filter label=com.docker.compose.project=buildkite1111 -q : echo" \ @@ -124,7 +169,8 @@ load '../lib/run' assert_success assert_output --partial "built myservice" - assert_output --partial "ran myservice" + assert_output --partial "ran myservice dependencies" + assert_output --partial "ran myservice command" refute_output --partial "Uploading linked container logs" unstub docker unstub docker-compose From 81d574974e41708ce735cdad7352737e87e4f702 Mon Sep 17 00:00:00 2001 From: Opal Symes Date: Thu, 22 Sep 2022 17:49:37 +1200 Subject: [PATCH 2/4] Updates & fixes from code review --- commands/run.sh | 32 ++++++++++++++------------------ tests/output.bats | 6 +++--- 2 files changed, 17 insertions(+), 21 deletions(-) diff --git a/commands/run.sh b/commands/run.sh index 9af11c64..f1e4c653 100755 --- a/commands/run.sh +++ b/commands/run.sh @@ -239,37 +239,33 @@ elif [[ ! -f "$override_file" ]]; then echo fi -# Start up service dependencies in a different header to keep the main run with less noise +dependency_exitcode=0 if [[ "$(plugin_read_config DEPENDENCIES "true")" == "true" ]] ; then - exitcode=0 + # Start up service dependencies in a different header to keep the main run with less noise echo "~~~ :docker: Starting dependencies" if [[ ${#up_params[@]} -gt 0 ]] ; then - if ! run_docker_compose "${up_params[@]}" up -d --scale "${run_service}=0" "${run_service}"; then - exitcode=1 - fi + run_docker_compose "${up_params[@]}" up -d --scale "${run_service}=0" "${run_service}" || dependency_exitcode=$? else - if ! run_docker_compose up -d --scale "${run_service}=0" "${run_service}"; then - exitcode=1 - fi + run_docker_compose up -d --scale "${run_service}=0" "${run_service}" || dependency_exitcode=$? fi # Sometimes docker-compose leaves unfinished ansi codes echo +fi - if [[ $exitcode -ne 0 ]] ; then - # Dependent services failed to start. - echo "^^^ +++" - echo "+++ 🚨 Failed to start dependencies" - - if [[ -n "${BUILDKITE_AGENT_ACCESS_TOKEN:-}" ]] ; then - print_failed_container_information +if [[ $dependency_exitcode -ne 0 ]] ; then + # Dependent services failed to start. + echo "^^^ +++" + echo "+++ 🚨 Failed to start dependencies" - upload_container_logs "$run_service" - fi + if [[ -n "${BUILDKITE_AGENT_ACCESS_TOKEN:-}" ]] ; then + print_failed_container_information - return $exitcode + upload_container_logs "$run_service" fi + + return $exitcode fi shell=() diff --git a/tests/output.bats b/tests/output.bats index c4a6f07a..a7952cb7 100644 --- a/tests/output.bats +++ b/tests/output.bats @@ -25,7 +25,7 @@ load '../lib/run' stub buildkite-agent \ "meta-data exists docker-compose-plugin-built-image-tag-myservice : exit 1" \ - "artifact upload : exit 0" + "artifact upload docker-compose-logs/\*.log : exit 0" stub docker-compose \ "-f docker-compose.yml -p buildkite1111 build --pull myservice : echo built myservice" \ @@ -70,7 +70,7 @@ load '../lib/run' stub buildkite-agent \ "meta-data exists docker-compose-plugin-built-image-tag-myservice : exit 1" \ - "artifact upload : exit 0" + "artifact upload docker-compose-logs/\*.log : exit 0" stub docker-compose \ "-f docker-compose.yml -p buildkite1111 build --pull myservice : echo built myservice" \ @@ -163,7 +163,7 @@ load '../lib/run' stub docker \ "ps -a --filter label=com.docker.compose.project=buildkite1111 -q : echo" \ - "ps -a --filter : cat tests/fixtures/id-service-no-services.txt" + "ps -a --filter label=com.docker.compose.project=buildkite1111 --format '{{.ID}}\\t{{.Label \"com.docker.compose.service\"}}' : cat tests/fixtures/id-service-no-services.txt" run $PWD/hooks/command From 6a0db48e44e97642e04d7ddb84b98eb763c697f4 Mon Sep 17 00:00:00 2001 From: Opal Symes Date: Fri, 23 Sep 2022 10:31:31 +1200 Subject: [PATCH 3/4] Fix variable name --- commands/run.sh | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/commands/run.sh b/commands/run.sh index bcdaa892..9f15be28 100755 --- a/commands/run.sh +++ b/commands/run.sh @@ -265,7 +265,7 @@ if [[ $dependency_exitcode -ne 0 ]] ; then upload_container_logs "$run_service" fi - return $exitcode + return $dependency_exitcode fi shell=() From 59bb87d7250a72596c9f74009449d8de8ca6b0a5 Mon Sep 17 00:00:00 2001 From: Opal Symes Date: Fri, 23 Sep 2022 12:11:32 +1200 Subject: [PATCH 4/4] Update versions to v3.11.1 --- README.md | 42 +++++++++++++++++++++--------------------- 1 file changed, 21 insertions(+), 21 deletions(-) diff --git a/README.md b/README.md index 092519ae..d53066f5 100644 --- a/README.md +++ b/README.md @@ -15,7 +15,7 @@ The following pipeline will run `test.sh` inside a `app` service container using steps: - command: test.sh plugins: - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: run: app ``` @@ -26,7 +26,7 @@ through if you need: steps: - command: test.sh plugins: - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: run: app config: docker-compose.tests.yml env: @@ -39,7 +39,7 @@ or multiple config files: steps: - command: test.sh plugins: - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: run: app config: - docker-compose.yml @@ -54,7 +54,7 @@ env: steps: - command: test.sh plugins: - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: run: app ``` @@ -65,7 +65,7 @@ steps: - plugins: - docker-login#v2.0.1: username: xyz - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: build: app image-repository: index.docker.io/myorg/myrepo - wait @@ -73,7 +73,7 @@ steps: plugins: - docker-login#v2.0.1: username: xyz - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: run: app ``` @@ -82,7 +82,7 @@ If you want to control how your command is passed to docker-compose, you can use ```yml steps: - plugins: - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: run: app command: ["custom", "command", "values"] ``` @@ -98,7 +98,7 @@ steps: - command: generate-dist.sh artifact_paths: "dist/*" plugins: - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: run: app ``` @@ -116,7 +116,7 @@ steps: - command: generate-dist.sh artifact_paths: "dist/*" plugins: - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: run: app volumes: - "./dist:/app/dist" @@ -137,7 +137,7 @@ this plugin offers a `environment` block of its own: steps: - command: generate-dist.sh plugins: - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: run: app env: - BUILDKITE_BUILD_NUMBER @@ -157,7 +157,7 @@ Alternatively, if you want to set build arguments when pre-building an image, th steps: - command: generate-dist.sh plugins: - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: build: app image-repository: index.docker.io/myorg/myrepo args: @@ -174,7 +174,7 @@ To speed up run steps that use the same service/image (such as steps that run in steps: - label: ":docker: Build" plugins: - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: build: app image-repository: index.docker.io/myorg/myrepo @@ -184,7 +184,7 @@ steps: command: test.sh parallelism: 25 plugins: - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: run: app ``` @@ -200,7 +200,7 @@ steps: agents: queue: docker-builder plugins: - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: build: - app - tests @@ -212,7 +212,7 @@ steps: command: test.sh parallelism: 25 plugins: - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: run: tests ``` @@ -224,7 +224,7 @@ If you want to push your Docker images ready for deployment, you can use the `pu steps: - label: ":docker: Push" plugins: - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: push: app ``` @@ -236,7 +236,7 @@ steps: plugins: - docker-login#v2.0.1: username: xyz - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: push: app ``` @@ -248,7 +248,7 @@ steps: plugins: - docker-login#v2.0.1: username: xyz - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: push: - first-service - second-service @@ -262,7 +262,7 @@ steps: plugins: - docker-login#v2.0.1: username: xyz - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: push: - app:index.docker.io/myorg/myrepo/myapp - app:index.docker.io/myorg/myrepo/myapp:latest @@ -276,14 +276,14 @@ A newly spawned agent won't contain any of the docker caches for the first run w steps: - label: ":docker: Build an image" plugins: - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: build: app image-repository: index.docker.io/myorg/myrepo cache-from: app:index.docker.io/myorg/myrepo/myapp:latest - wait - label: ":docker: Push to final repository" plugins: - - docker-compose#v3.10.0: + - docker-compose#v3.11.1: push: - app:index.docker.io/myorg/myrepo/myapp - app:index.docker.io/myorg/myrepo/myapp:latest