[gantry] follow the image remover's log and eval_cmd stdout.

In tests, check DONE_REMOVING_IMAGES to ensure all logs are printed.
shizunge · Nov 23, 2024 · 0fef6b3 · 0fef6b3
1 parent 884787e
commit 0fef6b3
Show file tree

Hide file tree

Showing 17 changed files with 170 additions and 56 deletions.
diff --git a/src/lib-common.sh b/src/lib-common.sh
@@ -191,6 +191,13 @@ _log_docker_line() {
   _log_formatter "${LEVEL}" "${TIME}" "${NODE}" "${SCOPE}" "${MESSAGE}";
 }
 
+_log_docker_multiple_lines() {
+  local LINE=
+  while read -r LINE; do
+    _log_docker_line "${LINE}"
+  done
+}
+
 # Usage: echo "${LOGS}" | log_lines INFO
 log_lines() {
   local LEVEL="${1}";
@@ -296,6 +303,10 @@ attach_tag_to_log_scope() {
   echo "${OLD_LOG_SCOPE}${SEP}${TAG}"
 }
 
+_random_string() {
+  head /dev/urandom | LANG=C tr -dc 'a-zA-Z0-9' | head -c 8
+}
+
 eval_cmd() {
   local TAG="${1}"; shift;
   local CMD="${*}"
@@ -304,19 +315,24 @@ eval_cmd() {
   LOG_SCOPE=$(attach_tag_to_log_scope "${TAG}")
   export LOG_SCOPE
   log INFO "Run ${TAG} command: ${CMD}"
-  local EVAL_OUTPUT=
+  # No handle on the output to stderr.
+  local RANDOM_STR=
+  RANDOM_STR=$(_random_string)
+  local PIPE_NAME="/tmp/eval-cmd-pipe-$$-${RANDOM_STR}"
+  mkfifo "${PIPE_NAME}"
+  local PID=
+  log_lines INFO < "${PIPE_NAME}" &
+  PID="${!}"
   local EVAL_RETURN=
-  EVAL_OUTPUT=$(mktemp)
-  eval "${CMD}" > "${EVAL_OUTPUT}"
+  eval "${CMD}" > "${PIPE_NAME}"
   EVAL_RETURN=$?
+  wait "${PID}"
+  rm "${PIPE_NAME}"
   if [ "${EVAL_RETURN}" = "0" ]; then
-    log_lines INFO < "${EVAL_OUTPUT}"
+    log INFO "Finish ${TAG} command."
   else
-    log_lines WARN < "${EVAL_OUTPUT}"
-    log WARN "${TAG} command returned a non-zero value ${EVAL_RETURN}."
+    log WARN "Finish ${TAG} command with a non-zero return value ${EVAL_RETURN}."
   fi
-  rm "${EVAL_OUTPUT}"
-  log INFO "Finish ${TAG} command."
   export LOG_SCOPE="${OLD_LOG_SCOPE}"
   return "${EVAL_RETURN}"
 }
@@ -349,34 +365,51 @@ _get_docker_command_name_arg() {
 }
 
 _get_docker_command_detach() {
-  if echo "${@}" | grep_q "--detach"; then
+  if echo "${@}" | grep_q "--detach=false"; then
+    echo "false"
+  elif echo "${@}" | grep_q "--detach"; then
+    # assume we find --detach or --detach=true.
     echo "true"
-    return 0
+  else
+    echo "false"
   fi
-  echo "false"
+  return 0
 }
 
-docker_service_logs () {
+docker_service_logs() {
   local SERVICE_NAME="${1}"
   local RETURN_VALUE=0
   local LOGS=
   if ! LOGS=$(docker service logs --timestamps --no-task-ids "${SERVICE_NAME}" 2>&1); then
     log ERROR "Failed to obtain logs of service ${SERVICE_NAME}."
     RETURN_VALUE=1
   fi
-  echo "${LOGS}" |
-  while read -r LINE; do
-    _log_docker_line "${LINE}"
-  done
+  echo "${LOGS}" | _log_docker_multiple_lines
   return "${RETURN_VALUE}"
 }
 
-docker_service_logs_follow() {
+_docker_service_exists() {
   local SERVICE_NAME="${1}"
-  docker service logs --timestamps --no-task-ids --follow "${SERVICE_NAME}" 2>&1 |
-  while read -r LINE; do
-    _log_docker_line "${LINE}"
+  docker service inspect --format '{{.ID}}' "${SERVICE_NAME}" >/dev/null 2>&1
+}
+
+# "docker service logs --follow" does not stop when the service stops.
+# This function will check the status of the service and stop the "docker service logs" command.
+_docker_service_logs_follow_and_stop() {
+  local SERVICE_NAME="${1}"
+  ! _docker_service_exists "${SERVICE_NAME}" && return 1;
+  local PID=
+  docker service logs --timestamps --no-task-ids --follow "${SERVICE_NAME}" 2>&1 &
+  PID="${!}"
+  while _docker_service_exists "${SERVICE_NAME}"; do
+    sleep 1s
   done
+  kill "${PID}" 2>&1
+}
+
+docker_service_logs_follow() {
+  local SERVICE_NAME="${1}"
+  _docker_service_logs_follow_and_stop "${SERVICE_NAME}" | _log_docker_multiple_lines
 }
 
 _docker_service_task_states() {
@@ -388,6 +421,7 @@ _docker_service_task_states() {
     return 1
   fi
   local NAME_LIST=
+  local LINE=
   echo "${STATES}" | while read -r LINE; do
     local NAME=
     local NODE_STATE_AND_ERROR=
@@ -460,9 +494,9 @@ wait_service_state() {
     return 1
   fi
   local LINE=
-  while read -r LINE; do
+  echo "${STATES}" | while read -r LINE; do
     log INFO "Service ${SERVICE_NAME}: ${LINE}."
-  done < <(echo "${STATES}")
+  done
   return "${RETURN_VALUE}"
 }
 
@@ -519,19 +553,31 @@ docker_current_container_name() {
 
 docker_service_remove() {
   local SERVICE_NAME="${1}"
-  if ! docker service inspect --format '{{.JobStatus}}' "${SERVICE_NAME}" >/dev/null 2>&1; then
-    return 0
-  fi
+  local POST_COMMAND="${2}"
+  ! _docker_service_exists "${SERVICE_NAME}" && return 0
   log INFO "Removing service ${SERVICE_NAME}."
   local LOG=
   if ! LOG=$(docker service rm "${SERVICE_NAME}" 2>&1); then
     log ERROR "Failed to remove docker service ${SERVICE_NAME}: ${LOG}"
     return 1
   fi
+  if [ -n "${POST_COMMAND}" ]; then
+    eval "${POST_COMMAND}"
+  fi
   log INFO "Removed service ${SERVICE_NAME}."
   return 0
 }
 
+# Works with the service started (e.g. via docker_global_job) with --detach.
+docker_service_follow_logs_wait_complete() {
+  local SERVICE_NAME="${1}"
+  local PID=
+  docker_service_logs_follow "${SERVICE_NAME}" &
+  PID="${!}"
+  wait_service_state "${SERVICE_NAME}" --complete
+  docker_service_remove "${SERVICE_NAME}" "wait ${PID}"
+}
+
 # We do not expect failures when using docker_global_job.
 # Docker will try to restart the failed tasks.
 # We do not check the converge of the service, thus some jobs may failed on some nodes.

diff --git a/src/lib-gantry.sh b/src/lib-gantry.sh
@@ -449,15 +449,14 @@ _remove_images() {
   # SC2086: Double quote to prevent globbing and word splitting.
   # shellcheck disable=SC2086
   docker_global_job --name "${SERVICE_NAME}" \
+    --detach \
     --restart-condition on-failure \
     --restart-max-attempts 1 \
     --mount type=bind,source=/var/run/docker.sock,destination=/var/run/docker.sock \
     --env "GANTRY_IMAGES_TO_REMOVE=${IMAGES_TO_REMOVE_LIST}" \
     ${CLEANUP_IMAGES_OPTIONS} \
     "${IMAGES_REMOVER}";
-  wait_service_state "${SERVICE_NAME}"
-  docker_service_logs "${SERVICE_NAME}"
-  docker_service_remove "${SERVICE_NAME}"
+  docker_service_follow_logs_wait_complete "${SERVICE_NAME}"
 }
 
 _report_list() {

diff --git a/tests/gantry_cleanup_images_spec.sh b/tests/gantry_cleanup_images_spec.sh
@@ -60,6 +60,7 @@ Describe 'cleanup-images'
       The stderr should satisfy spec_expect_message    "${SKIP_REMOVING_IMAGES}"
       The stderr should satisfy spec_expect_no_message "${REMOVED_IMAGE}.*${IMAGE_WITH_TAG}"
       The stderr should satisfy spec_expect_no_message "${FAILED_TO_REMOVE_IMAGE}.*${IMAGE_WITH_TAG}"
+      The stderr should satisfy spec_expect_no_message "${DONE_REMOVING_IMAGES}"
     End
   End
   Describe "test_CLEANUP_IMAGES_OPTIONS_bad" "container_test:true" "coverage:true"
@@ -106,6 +107,7 @@ Describe 'cleanup-images'
       The stderr should satisfy spec_expect_message    "Failed.*--incorrect-option"
       The stderr should satisfy spec_expect_no_message "${REMOVED_IMAGE}.*${IMAGE_WITH_TAG}"
       The stderr should satisfy spec_expect_no_message "${FAILED_TO_REMOVE_IMAGE}.*${IMAGE_WITH_TAG}"
+      The stderr should satisfy spec_expect_no_message "${DONE_REMOVING_IMAGES}"
     End
   End
   Describe "test_CLEANUP_IMAGES_OPTIONS_good" "container_test:true" "coverage:true"
@@ -151,6 +153,7 @@ Describe 'cleanup-images'
       The stderr should satisfy spec_expect_no_message "Failed.*--container-label=test"
       The stderr should satisfy spec_expect_message    "${REMOVED_IMAGE}.*${IMAGE_WITH_TAG}"
       The stderr should satisfy spec_expect_no_message "${FAILED_TO_REMOVE_IMAGE}.*${IMAGE_WITH_TAG}"
+      The stderr should satisfy spec_expect_message    "${DONE_REMOVING_IMAGES}"
     End
   End
   Describe "test_IMAGES_TO_REMOVE_none_empty" "container_test:true" "coverage:true"
@@ -221,6 +224,7 @@ Describe 'cleanup-images'
       The stderr should satisfy spec_expect_message    "${REMOVED_IMAGE}.*${IMAGE_WITH_TAG0}"
       The stderr should satisfy spec_expect_message    "${FAILED_TO_REMOVE_IMAGE}.*${IMAGE_WITH_TAG1}"
       The stderr should satisfy spec_expect_message    "There is no image.*${IMAGE_WITH_TAG2}"
+      The stderr should satisfy spec_expect_message    "${DONE_REMOVING_IMAGES}"
     End
   End
 End # Describe 'Single service'
diff --git a/tests/gantry_common_options_spec.sh b/tests/gantry_common_options_spec.sh
@@ -64,6 +64,7 @@ Describe 'common-options'
       The stderr should satisfy spec_expect_no_message "${SKIP_REMOVING_IMAGES}"
       The stderr should satisfy spec_expect_no_message "${REMOVED_IMAGE}.*${IMAGE_WITH_TAG}"
       The stderr should satisfy spec_expect_no_message "${FAILED_TO_REMOVE_IMAGE}.*${IMAGE_WITH_TAG}"
+      The stderr should satisfy spec_expect_no_message "${DONE_REMOVING_IMAGES}"
       The stderr should satisfy spec_expect_no_message "${SCHEDULE_NEXT_UPDATE_AT}"
       The stderr should satisfy spec_expect_no_message "${SLEEP_SECONDS_BEFORE_NEXT_UPDATE}"
     End
@@ -146,8 +147,10 @@ Describe 'common-options'
       export GANTRY_CLEANUP_IMAGES=
       # Test that pre-run command can change the global configurations.
       export GANTRY_PRE_RUN_CMD="echo \"Pre update\"; GANTRY_UPDATE_OPTIONS=--detach=true; GANTRY_CLEANUP_IMAGES=false;"
+      # This command outputs multiple lines.
+      local POST_CMD="for I in \$(seq 3 5); do echo \"OUTPUT_LINE=\$I\"; done"
       # Test that the command returns a non-zero value.
-      export GANTRY_POST_RUN_CMD="echo \"Post update\"; false;"
+      export GANTRY_POST_RUN_CMD="echo \"Post update\"; ${POST_CMD}; false;"
       run_gantry "${TEST_NAME}"
     }
     BeforeEach "common_setup_new_image ${TEST_NAME} ${IMAGE_WITH_TAG} ${SERVICE_NAME}"
@@ -160,7 +163,7 @@ Describe 'common-options'
       The stderr should satisfy display_output
       The stderr should satisfy spec_expect_no_message "${START_WITHOUT_A_SQUARE_BRACKET}"
       The stderr should satisfy spec_expect_message    "Pre update"
-      The stderr should satisfy spec_expect_no_message "pre-run command returned a non-zero value"
+      The stderr should satisfy spec_expect_message    "Finish pre-run command."
       The stderr should satisfy spec_expect_no_message "${SKIP_UPDATING}.*${SERVICE_NAME}"
       The stderr should satisfy spec_expect_message    "${PERFORM_UPDATING}.*${SERVICE_NAME}.*${PERFORM_REASON_HAS_NEWER_IMAGE}"
       The stderr should satisfy spec_expect_no_message "${NUM_SERVICES_SKIP_JOBS}"
@@ -182,8 +185,12 @@ Describe 'common-options'
       The stderr should satisfy spec_expect_message    "${SKIP_REMOVING_IMAGES}"
       The stderr should satisfy spec_expect_no_message "${REMOVED_IMAGE}.*"
       The stderr should satisfy spec_expect_no_message "${FAILED_TO_REMOVE_IMAGE}.*"
+      The stderr should satisfy spec_expect_no_message "${DONE_REMOVING_IMAGES}"
       The stderr should satisfy spec_expect_message    "Post update"
-      The stderr should satisfy spec_expect_message    "post-run command returned a non-zero value"
+      The stderr should satisfy spec_expect_message    "OUTPUT_LINE=3"
+      The stderr should satisfy spec_expect_message    "OUTPUT_LINE=4"
+      The stderr should satisfy spec_expect_message    "OUTPUT_LINE=5"
+      The stderr should satisfy spec_expect_message    "Finish post-run command with a non-zero return value 1."
       The stderr should satisfy spec_expect_no_message "${SCHEDULE_NEXT_UPDATE_AT}"
       The stderr should satisfy spec_expect_no_message "${SLEEP_SECONDS_BEFORE_NEXT_UPDATE}"
     End
@@ -236,6 +243,7 @@ Describe 'common-options'
       The stderr should satisfy spec_expect_no_message        "${SKIP_REMOVING_IMAGES}"
       The stderr should satisfy spec_expect_no_message        "${REMOVED_IMAGE}.*${IMAGE_WITH_TAG}"
       The stderr should satisfy spec_expect_no_message        "${FAILED_TO_REMOVE_IMAGE}.*${IMAGE_WITH_TAG}"
+      The stderr should satisfy spec_expect_no_message        "${DONE_REMOVING_IMAGES}"
       # Check messages between iterations.
       The stderr should satisfy spec_expect_message           "${SCHEDULE_NEXT_UPDATE_AT}"
       The stderr should satisfy spec_expect_message           "${SLEEP_SECONDS_BEFORE_NEXT_UPDATE}"
@@ -283,6 +291,7 @@ Describe 'common-options'
       The stderr should satisfy spec_expect_no_message "${SKIP_REMOVING_IMAGES}"
       The stderr should satisfy spec_expect_no_message "${REMOVED_IMAGE}.*${IMAGE_WITH_TAG}"
       The stderr should satisfy spec_expect_no_message "${FAILED_TO_REMOVE_IMAGE}.*${IMAGE_WITH_TAG}"
+      The stderr should satisfy spec_expect_no_message "${DONE_REMOVING_IMAGES}"
       The stderr should satisfy spec_expect_no_message "${SCHEDULE_NEXT_UPDATE_AT}"
       The stderr should satisfy spec_expect_no_message "${SLEEP_SECONDS_BEFORE_NEXT_UPDATE}"
     End

diff --git a/tests/gantry_filters_spec.sh b/tests/gantry_filters_spec.sh
@@ -61,6 +61,7 @@ Describe 'filters'
       The stderr should satisfy spec_expect_no_message "${SKIP_REMOVING_IMAGES}"
       The stderr should satisfy spec_expect_no_message "${REMOVED_IMAGE}.*${IMAGE_WITH_TAG}"
       The stderr should satisfy spec_expect_no_message "${FAILED_TO_REMOVE_IMAGE}.*${IMAGE_WITH_TAG}"
+      The stderr should satisfy spec_expect_no_message "${DONE_REMOVING_IMAGES}"
     End
   End
   Describe "test_SERVICES_EXCLUDED_multiple_services" "container_test:true" "coverage:true"
@@ -118,6 +119,7 @@ Describe 'filters'
       The stderr should satisfy spec_expect_no_message "${SKIP_REMOVING_IMAGES}"
       The stderr should satisfy spec_expect_no_message "${REMOVED_IMAGE}.*${IMAGE_WITH_TAG}"
       The stderr should satisfy spec_expect_no_message "${FAILED_TO_REMOVE_IMAGE}.*${IMAGE_WITH_TAG}"
+      The stderr should satisfy spec_expect_no_message "${DONE_REMOVING_IMAGES}"
     End
   End
   Describe "test_SERVICES_EXCLUDED_FILTERS_default" "container_test:true" "coverage:true"
@@ -168,6 +170,7 @@ Describe 'filters'
       The stderr should satisfy spec_expect_no_message "${SKIP_REMOVING_IMAGES}"
       The stderr should satisfy spec_expect_no_message "${REMOVED_IMAGE}.*${IMAGE_WITH_TAG}"
       The stderr should satisfy spec_expect_no_message "${FAILED_TO_REMOVE_IMAGE}.*${IMAGE_WITH_TAG}"
+      The stderr should satisfy spec_expect_no_message "${DONE_REMOVING_IMAGES}"
     End
   End
   Describe "test_SERVICES_EXCLUDED_FILTERS_bad" "container_test:false" "coverage:true"
@@ -212,6 +215,7 @@ Describe 'filters'
       The stderr should satisfy spec_expect_no_message "${SKIP_REMOVING_IMAGES}"
       The stderr should satisfy spec_expect_no_message "${REMOVED_IMAGE}.*${IMAGE_WITH_TAG}"
       The stderr should satisfy spec_expect_no_message "${FAILED_TO_REMOVE_IMAGE}.*${IMAGE_WITH_TAG}"
+      The stderr should satisfy spec_expect_no_message "${DONE_REMOVING_IMAGES}"
     End
   End
 End # Describe 'Filters'