Improve logging and notification.

* Notify when there is an error before updating. * Improve docker log when there is an error from daemon. * Improve error messages on registry config files. * Test quote input arguments.
shizunge · May 31, 2024 · 8c40808 · 8c40808
1 parent 209439f
commit 8c40808
Show file tree

Hide file tree

Showing 18 changed files with 244 additions and 200 deletions.
diff --git a/README.md b/README.md
@@ -40,7 +40,7 @@ You can configure the most behaviors of *Gantry* via environment variables.
 
 | Environment Variable  | Default |Description |
 |-----------------------|---------|------------|
-| GANTRY_LOG_LEVEL      | INFO | Control how many logs generated by *Gantry*. Valid values are `NONE`, `ERROR`, `WARN`, `INFO`, `DEBUG` (case sensitive). |
+| GANTRY_LOG_LEVEL      | INFO | Control how many logs generated by *Gantry*. Valid values are `NONE`, `ERROR`, `WARN`, `INFO`, `DEBUG`. |
 | GANTRY_NODE_NAME      |      | Add node name to logs. If not set, *Gantry* will use the host name of the Docker Swarm's manager, which is read from either the Docker daemon socket of current node or `DOCKER_HOST`. |
 | GANTRY_POST_RUN_CMD   |      | Command(s) to `eval` after each updating iteration. |
 | GANTRY_PRE_RUN_CMD    |      | Command(s) to `eval` before each updating iteration. |

diff --git a/src/docker_hub_rate.sh b/src/docker_hub_rate.sh
@@ -46,6 +46,18 @@ _docker_hub_rate_read_rate() {
   wget -qS --spider --header="${HEADER}" -O /dev/null "${URL}" 2>&1
 }
 
+_docker_hub_echo_error() {
+  local TITLE="${1}"
+  local RESPONSE="${2}"
+  local OLD_LOG_SCOPE="${LOG_SCOPE}"
+  LOG_SCOPE=$(attach_tag_to_log_scope "docker-hub")
+  export LOG_SCOPE
+  log DEBUG "${TITLE}: RESPONSE="
+  echo "${RESPONSE}" | log_lines DEBUG
+  echo "[${TITLE}]"
+  export LOG_SCOPE="${OLD_LOG_SCOPE}"
+}
+
 docker_hub_rate() {
   local IMAGE="${1:-ratelimitpreview/test}"
   local USER_AND_PASS="${2}"
@@ -58,35 +70,27 @@ docker_hub_rate() {
   fi
   local RESPONSE=
   if ! RESPONSE=$(_docker_hub_rate_token "${IMAGE}" "${USER_AND_PASS}" 2>&1); then
-    log DEBUG "Read docker hub token error: RESPONSE="
-    echo "${RESPONSE}" | log_lines DEBUG
-    echo "[GET TOKEN RESPONSE ERROR]"
+    _docker_hub_echo_error "GET TOKEN RESPONSE ERROR" "${RESPONSE}"
     return 1
   fi
   local TOKEN=
   TOKEN=$(echo "${RESPONSE}" | sed 's/.*"token":"\([^"]*\).*/\1/')
   if [ -z "${TOKEN}" ]; then
-    log DEBUG "Parse docker hub token error: RESPONSE="
-    echo "${RESPONSE}" | log_lines DEBUG
-    echo "[PARSE TOKEN ERROR]"
+    _docker_hub_echo_error "PARSE TOKEN ERROR" "${RESPONSE}"
     return 1
   fi
   if ! RESPONSE=$(_docker_hub_rate_read_rate "${IMAGE}" "${TOKEN}" 2>&1); then
     if echo "${RESPONSE}" | grep -q "Too Many Requests" ; then
       echo "0"
       return 0
     fi
-    log DEBUG "Read docker hub rate error: RESPONSE="
-    echo "${RESPONSE}" | log_lines DEBUG
-    echo "[GET RATE RESPONSE ERROR]"
+    _docker_hub_echo_error "GET RATE RESPONSE ERROR" "${RESPONSE}"
     return 1
   fi
   local RATE=
   RATE=$(echo "${RESPONSE}" | sed -n 's/.*ratelimit-remaining: \([0-9]*\).*/\1/p' )
   if [ -z "${RATE}" ]; then
-    log DEBUG "Parse docker hub rate error: RESPONSE="
-    echo "${RESPONSE}" | log_lines DEBUG
-    echo "[PARSE RATE ERROR]"
+    _docker_hub_echo_error "PARSE RATE ERROR" "${RESPONSE}"
     return 1
   fi
   echo "${RATE}"

diff --git a/src/entrypoint.sh b/src/entrypoint.sh
@@ -126,7 +126,7 @@ gantry() {
   DOCKER_HUB_RATE_USED=$(difference_between "${DOCKER_HUB_RATE_BEFORE}" "${DOCKER_HUB_RATE_AFTER}")
   log INFO "After updating, Docker Hub rate remains ${DOCKER_HUB_RATE_AFTER}. Used rate ${DOCKER_HUB_RATE_USED}."
 
-  gantry_finalize "${STACK}";
+  gantry_finalize "${STACK}" "${ACCUMULATED_ERRORS}";
   ACCUMULATED_ERRORS=$((ACCUMULATED_ERRORS + $?))
 
   eval_cmd "post-run" "${POST_RUN_CMD}"
@@ -142,7 +142,7 @@ gantry() {
     log INFO "${MESSAGE}"
     RETURN_VALUE=0
   fi
-  return ${RETURN_VALUE}
+  return "${RETURN_VALUE}"
 }
 
 main() {
@@ -172,7 +172,7 @@ main() {
       sleep "${SLEEP_SECONDS}"
     fi
   done
-  return ${RETURN_VALUE}
+  return "${RETURN_VALUE}"
 }
 
 load_libraries

diff --git a/src/lib-common.sh b/src/lib-common.sh
@@ -21,11 +21,11 @@
 _log_level() {
   local LEVEL="${1}";
   [ -z "${LEVEL}" ] && _log_level "INFO" && return 1;
-  [ "${LEVEL}" = "DEBUG" ] && echo 0 && return 0;
-  [ "${LEVEL}" = "INFO"  ] && echo 1 && return 0;
-  [ "${LEVEL}" = "WARN"  ] && echo 2 && return 0;
-  [ "${LEVEL}" = "ERROR" ] && echo 3 && return 0;
-  [ "${LEVEL}" = "NONE"  ] && echo 4 && return 0;
+  echo "${LEVEL}" | grep -q -i "^DEBUG$" && echo 0 && return 0;
+  echo "${LEVEL}" | grep -q -i "^INFO$"  && echo 1 && return 0;
+  echo "${LEVEL}" | grep -q -i "^WARN$"  && echo 2 && return 0;
+  echo "${LEVEL}" | grep -q -i "^ERROR$" && echo 3 && return 0;
+  echo "${LEVEL}" | grep -q -i "^NONE$"  && echo 4 && return 0;
   _log_level "NONE";
   return 1;
 }
@@ -56,6 +56,7 @@ _log_formatter() {
   local LOG_LEVEL="${LOG_LEVEL}"
   local LEVEL="${1}"; shift;
   [ "$(_log_level "${LEVEL}")" -lt "$(_log_level "${LOG_LEVEL}")" ] && return 0;
+  LEVEL=$(echo "${LEVEL}" | tr '[:lower:]' '[:upper:]')
   local TIME="${1}"; shift;
   local LOCATION="${1}"; shift;
   local SCOPE="${1}"; shift;
@@ -94,32 +95,55 @@ _log_docker_time() {
   local TIME_INPUT="${1}"
   local EPOCH=
   if ! EPOCH="$(busybox date -d "${TIME_INPUT}" -D "%Y-%m-%dT%H:%M:%S" -u +%s 2>/dev/null)"; then
-    local TIME=
-    TIME=$(echo "${TIME_INPUT}" | cut -d '.' -f 1)
-    echo "${TIME}+00:00"
-    return 0
+    date -Iseconds
+    return 1
   fi
   busybox date -d "@${EPOCH}" -Iseconds 2>&1
 }
 
+_log_docker_scope() {
+  local LOG_SCOPE="${LOG_SCOPE}"
+  local TASK_NODE="${1}"
+  local SCOPE=
+  SCOPE=$(echo "${TASK_NODE}" | sed -n "s/\(.*\)@.*/\1/p");
+  if [ -z "${SCOPE}" ]; then
+    echo "${LOG_SCOPE}"
+    return 1
+  fi
+  echo "${SCOPE}"
+}
+
+_log_docker_node() {
+  local NODE_NAME="${NODE_NAME}"
+  local TASK_NODE="${1}"
+  local NODE=
+  NODE=$(echo "${TASK_NODE}" | sed -n "s/.*@\(.*\)/\1/p");
+  if [ -z "${NODE}" ]; then
+    echo "${NODE_NAME}"
+    return 1
+  fi
+  echo "${NODE}"
+}
+
 # Convert logs from `docker service logs` to `log` format.
 # docker service logs --timestamps --no-task-ids <service>
 # 2023-06-22T01:20:54.535860111Z <task>@<node>    | <msg>
 _log_docker_line() {
   local LEVEL="INFO";
-  local TIME_DOCKER TIME SCOPE NODE MESSAGE SPACE FIRST_WORD
-  TIME_DOCKER=$(echo "${@}" | cut -d ' ' -f 1);
+  local TIME_DOCKER TIME TASK_NODE SCOPE NODE MESSAGE SPACE FIRST_WORD
+  TIME_DOCKER=$(echo "${*} " | cut -d ' ' -f 1);
   TIME=$(_log_docker_time "${TIME_DOCKER}")
-  SCOPE=$(echo "${@}" | cut -d ' ' -f 2 | cut -d '@' -f 1);
-  NODE=$(echo "${@}" | cut -d ' ' -f 2 | cut -d '@' -f 2);
-  MESSAGE=$(echo "${@}" | cut -d '|' -f 2-);
+  TASK_NODE=$(echo "${*} " | cut -d ' ' -f 2)
+  SCOPE=$(_log_docker_scope "${TASK_NODE}");
+  NODE=$(_log_docker_node "${TASK_NODE}");
+  MESSAGE=$(echo "${*}" | cut -d '|' -f 2-);
   # Remove the leading space.
-  SPACE=$(echo "${MESSAGE}" | cut -d ' ' -f 1)
-  [ -z "${SPACE}" ] && MESSAGE=$(echo "${MESSAGE}" | cut -d ' ' -f 2-)
-  FIRST_WORD=$(echo "${MESSAGE}" | cut -d ' ' -f 1);
+  SPACE=$(echo "${MESSAGE} " | cut -d ' ' -f 1)
+  [ -z "${SPACE}" ] && MESSAGE=$(echo "${MESSAGE} " | cut -d ' ' -f 2-)
+  FIRST_WORD=$(echo "${MESSAGE} " | cut -d ' ' -f 1);
   if _log_level "${FIRST_WORD}" >/dev/null; then
     LEVEL=${FIRST_WORD};
-    MESSAGE=$(echo "${MESSAGE}" | cut -d ' ' -f 2-);
+    MESSAGE=$(echo "${MESSAGE} " | cut -d ' ' -f 2-);
   fi
   _log_formatter "${LEVEL}" "${TIME}" "${NODE}" "${SCOPE}" "${MESSAGE}";
 }
@@ -139,7 +163,7 @@ is_number() {
 
 is_true() {
   local CONFIG="${1}"
-  CONFIG=$(echo "${CONFIG}" | cut -d ' ' -f 1)
+  CONFIG=$(echo "${CONFIG} " | cut -d ' ' -f 1)
   echo "${CONFIG}" | grep -q -i "true"
 }
 
@@ -228,18 +252,18 @@ eval_cmd() {
   LOG_SCOPE=$(attach_tag_to_log_scope "${TAG}")
   export LOG_SCOPE
   local LOG=
-  local RT=0
+  local RETURN_VALUE=0
   log INFO "Run ${TAG} command: ${CMD}"
   if LOG=$(eval "${CMD}"); then
     echo "${LOG}" | log_lines INFO
   else
-    RT=$?
+    RETURN_VALUE=$?
     echo "${LOG}" | log_lines WARN
-    log WARN "${TAG} command returned a non-zero value ${RT}."
+    log WARN "${TAG} command returned a non-zero value ${RETURN_VALUE}."
   fi
   log INFO "Finish ${TAG} command."
   export LOG_SCOPE="${OLD_LOG_SCOPE}"
-  return "${RT}"
+  return "${RETURN_VALUE}"
 }
 
 swarm_network_arguments() {
@@ -279,15 +303,17 @@ _get_docker_command_detach() {
 
 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}. ${LOGS}"
-    return 1
+    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
+  return "${RETURN_VALUE}"
 }
 
 docker_service_logs_follow() {
@@ -329,45 +355,58 @@ wait_service_state() {
   local WAIT_RUNNING WAIT_COMPLETE;
   WAIT_RUNNING=$(echo "${@}" | grep -q -- "--running" && echo "true" || echo "false")
   WAIT_COMPLETE=$(echo "${@}" | grep -q -- "--complete" && echo "true" || echo "false")
+  local RETURN_VALUE=0
+  local DOCKER_CMD_ERROR=1
   local SLEEP_SECONDS=1
   local STATES=
   while STATES=$(_docker_service_task_states "${SERVICE_NAME}" 2>&1); do
+    if ! ("${WAIT_RUNNING}" || "${WAIT_COMPLETE}"); then
+      RETURN_VALUE=0
+      DOCKER_CMD_ERROR=0
+      break
+    fi
     local NUM_LINES=0
     local NUM_RUNS=0
     local NUM_DONES=0
     local NUM_FAILS=0
     while read -r LINE; do
       [ -z "${LINE}" ] && continue;
-      log INFO "Service ${SERVICE_NAME}: ${LINE}."
       NUM_LINES=$((NUM_LINES+1));
       echo "${LINE}" | grep -q "Running" && NUM_RUNS=$((NUM_RUNS+1));
       echo "${LINE}" | grep -q "Complete" && NUM_DONES=$((NUM_DONES+1));
       echo "${LINE}" | grep -q "Failed" && NUM_FAILS=$((NUM_FAILS+1));
     done < <(echo "${STATES}")
     if [ "${NUM_LINES}" -gt 0 ]; then
       if "${WAIT_RUNNING}" && [ "${NUM_RUNS}" -eq "${NUM_LINES}" ]; then
-        return 0;
+        RETURN_VALUE=0
+        DOCKER_CMD_ERROR=0
+        break
       fi
       if "${WAIT_COMPLETE}" && [ "${NUM_DONES}" -eq "${NUM_LINES}" ]; then
-        return 0;
+        RETURN_VALUE=0
+        DOCKER_CMD_ERROR=0
+        break
       fi
       if "${WAIT_COMPLETE}" && [ "${NUM_FAILS}" -gt 0 ]; then
         # Get return value of the task from the string "task: non-zero exit (1)".
         local TASK_RETURN_VALUE=
         TASK_RETURN_VALUE=$(echo "${STATES}" | grep "Failed" | sed -n 's/.*task: non-zero exit (\([0-9]\+\)).*/\1/p')
         # Get the first error code.
-        local RETURN_VALUE=0
-        RETURN_VALUE=$(echo "${TASK_RETURN_VALUE:-1}" | cut -d ' ' -f 1)
-        return "${RETURN_VALUE}"
+        RETURN_VALUE=$(echo "${TASK_RETURN_VALUE:-1} " | cut -d ' ' -f 1)
+        DOCKER_CMD_ERROR=0
+        break
       fi
     fi
-    if ! ("${WAIT_RUNNING}" || "${WAIT_COMPLETE}"); then
-      return 0;
-    fi
     sleep "${SLEEP_SECONDS}"
   done
-  log ERROR "Failed to obtain task states of service ${SERVICE_NAME}: ${STATES}"
-  return 1
+  if [ "${DOCKER_CMD_ERROR}" != "0" ]; then
+    log ERROR "Failed to obtain task states of service ${SERVICE_NAME}: ${STATES}"
+    return 1
+  fi
+  while read -r LINE; do
+    log INFO "Service ${SERVICE_NAME}: ${LINE}."
+  done < <(echo "${STATES}")
+  return "${RETURN_VALUE}"
 }
 
 docker_service_remove() {