[lib-common] increase docker log speed.

shizunge · Nov 24, 2024 · 0ff356c · 0ff356c
1 parent 1f030ec
commit 0ff356c
Show file tree

Hide file tree

Showing 3 changed files with 129 additions and 81 deletions.
diff --git a/src/lib-common.sh b/src/lib-common.sh
@@ -29,6 +29,14 @@ _pipe_name() {
   echo "${PIPE_NAME}"
 }
 
+_get_first_word() {
+  echo "${*}" | sed -n "s/^\([^ ]\+\).*/\1/p";
+}
+
+_to_upper() {
+  echo "${*}" | tr '[:lower:]' '[:upper:]'
+}
+
 # Run "grep -q" and avoid broken pipe errors.
 grep_q() {
   # "grep -q" will exit immediately when the first line of data matches, and leading to broken pipe errors.
@@ -78,12 +86,41 @@ extract_string() {
 _log_level() {
   local LEVEL="${1}";
   [ -z "${LEVEL}" ] && _log_level "INFO" && return 1;
-  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";
+  LEVEL=$(_to_upper "${LEVEL}")
+  case "${LEVEL}" in
+    "DEBUG") echo 0 && return 0; ;;
+    "INFO")  echo 1 && return 0; ;;
+    "WARN")  echo 2 && return 0; ;;
+    "ERROR") echo 3 && return 0; ;;
+    "NONE")  echo 4 && return 0; ;;
+    *) _log_level "NONE"; return 1; ;;
+  esac
+}
+
+# Return 0 if the first work is a supported level.
+# Return 1 else.
+# We can also use _log_level() to check whether the level is supported, but this function is faster.
+_first_word_is_level() {
+  local MSG="${1}"
+  local LEN="${#MSG}"
+  local LEVEL=
+  [ "${LEN}" -lt 4 ] && return 1
+  if [ "${LEN}" = 4 ] || [ "${MSG:4:1}" = " " ]; then
+    LEVEL="${MSG:0:4}"
+  elif [ "${LEN}" = 5 ] || [ "${MSG:5:1}" = " " ]; then
+    LEVEL="${MSG:0:5}"
+  else
+    return 1
+  fi
+  LEVEL=$(_to_upper "${LEVEL}")
+  case "${LEVEL}" in
+    "DEBUG") return 0; ;;
+    "INFO")  return 0; ;;
+    "WARN")  return 0; ;;
+    "ERROR") return 0; ;;
+    "NONE")  return 0; ;;
+    *) return 1; ;;
+  esac
   return 1;
 }
 
@@ -94,114 +131,127 @@ _level_color() {
   local ORANGE='\033[0;33m'
   local GREEN='\033[0;32m'
   local BLUE='\033[0;34m'
-  echo "${LEVEL}" | grep_q_i "^DEBUG$" && echo "${BLUE}" && return 0;
-  echo "${LEVEL}" | grep_q_i "^INFO$"  && echo "${GREEN}" && return 0;
-  echo "${LEVEL}" | grep_q_i "^WARN$"  && echo "${ORANGE}" && return 0;
-  echo "${LEVEL}" | grep_q_i "^ERROR$" && echo "${RED}" && return 0;
-  echo "${NO_COLOR}"
+  LEVEL=$(_to_upper "${LEVEL}")
+  case "${LEVEL}" in
+    "DEBUG") echo "${BLUE}"; ;;
+    "INFO")  echo "${GREEN}"; ;;
+    "WARN")  echo "${ORANGE}"; ;;
+    "ERROR") echo "${RED}"; ;;
+    *)       echo "${NO_COLOR}"; ;;
+  esac
+  return 0;
 }
 
 _color_iso_time() {
-  # Highlight time within the day in ISO-8601
+  local EPOCH="${1}"
+  # Highlight time within the day in ISO-8601 (2024-11-23T21:50:13-08:00)
   # \\033[1;30m : Dark Gray
   # \\033[0;37m : Ligth Gray
   # \\033[0m    : No color
-  echo "${*}" | sed -E 's/(.*[0-9]+-[0-9]+-[0-9]+)T([0-9]+:[0-9]+:[0-9]+)(.*)/\\033[1;30m\1T\\033[0;37m\2\\033[1;30m\3\\033[0m/'
+  # date -d "@${EPOCH}" -Iseconds | sed -E 's/(.*[0-9]+-[0-9]+-[0-9]+)T([0-9]+:[0-9]+:[0-9]+)(.*)/\\033[1;30m\1T\\033[0;37m\2\\033[1;30m\3\\033[0m/'
+  local DAY TIME ZONE
+  DAY=$(busybox date -d "@${EPOCH}" +%Y-%m-%d)
+  TIME=$(busybox date -d "@${EPOCH}" +%H:%M:%S)
+  ZONE=$(busybox date -d "@${EPOCH}" +%z)
+  # +0000 -> +00:00
+  ZONE="${ZONE:0:-2}:${ZONE:0-2}"
+  local NO_COLOR='\033[0m'
+  local DGRAY="\033[1;30m"
+  local LGRAY="\033[0;37m"
+  echo "${DGRAY}${DAY}T${LGRAY}${TIME}${DGRAY}${ZONE}${NO_COLOR}"
 }
 
 _log_formatter() {
-  local LOG_LEVEL="${LOG_LEVEL}"
+  local TARGET_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;
+  [ "$(_log_level "${LEVEL}")" -lt "$(_log_level "${TARGET_LEVEL}")" ] && return 0;
+  LEVEL=$(_to_upper "${LEVEL}")
+  local EPOCH="${1}"; shift;
   local LOCATION="${1}"; shift;
   local SCOPE="${1}"; shift;
   local NO_COLOR='\033[0m'
   local DGRAY='\033[1;30m'
-  local MSG=
-  MSG="${DGRAY}[$(_color_iso_time "${TIME}")${DGRAY}]${NO_COLOR}"
+  local TIME_STR LOC_STR LEVEL_STR SCOPE_STR
+  TIME_STR="${DGRAY}[$(_color_iso_time "${EPOCH}")${DGRAY}]${NO_COLOR}"
   if [ -n "${LOCATION}" ]; then
-    MSG="${MSG}${DGRAY}[${LOCATION}]${NO_COLOR}"
+    LOC_STR="${DGRAY}[${LOCATION}]${NO_COLOR}"
   fi
-  MSG="${MSG}$(_level_color "${LEVEL}")[${LEVEL}]${NO_COLOR} "
+  LEVEL_STR="$(_level_color "${LEVEL}")[${LEVEL}]${NO_COLOR} "
   if [ -n "${SCOPE}" ]; then
-    MSG="${MSG}${DGRAY}${SCOPE}:${NO_COLOR} "
+    SCOPE_STR="${DGRAY}${SCOPE}:${NO_COLOR} "
   fi
-  MSG="${MSG}$(echo "${*}" | tr '\n' ' ')"
-  echo -e "${MSG}" >&2
+  local MSG_STR=
+  MSG_STR=$(echo "${*}" | tr '\n' ' ')
+  echo -e "${TIME_STR}${LOC_STR}${LEVEL_STR}${SCOPE_STR}${MSG_STR}" >&2
 }
 
 # We want to print an empty line for log without an argument. Thus we do not run the following check.
 # [ -z "${1}" ] && return 0
 log() {
-  local NODE_NAME="${NODE_NAME}"
-  local LOG_SCOPE="${LOG_SCOPE}"
+  local LOCAL_NODE="${NODE_NAME:-}"
+  local LOCAL_SCOPE="${LOG_SCOPE:-}"
   local LEVEL="INFO";
-  if _log_level "${1}" >/dev/null; then
+  if _first_word_is_level "${1}"; then
     LEVEL="${1}";
     shift;
   fi
-  _log_formatter "${LEVEL}" "$(date -Iseconds)" "${NODE_NAME}" "${LOG_SCOPE}" "${@}";
+  local EPOCH=
+  EPOCH="$(date +%s)"
+  _log_formatter "${LEVEL}" "${EPOCH}" "${LOCAL_NODE}" "${LOCAL_SCOPE}" "${@}";
 }
 
-_log_docker_time() {
-  # Convert timestamps from `docker service logs` to ISO-8601. The timestamps is in UTC.
+_log_docker_time_epoch() {
+  # Convert timestamps from `docker service logs` to EPOCH.
+  # The timestamps is in UTC.
   # docker service logs --timestamps --no-task-ids <service>
   # 2023-06-22T01:20:54.535860111Z <task>@<node>    | <msg>
   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
-    date -Iseconds
+    date +%s
     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}"
+  echo "${EPOCH}"
 }
 
 # 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 LOCAL_NODE="${NODE_NAME:-}"
+  local LOCAL_SCOPE="${LOG_SCOPE:-}"
   local LEVEL="INFO";
-  local TIME_DOCKER TIME TASK_NODE SCOPE NODE MESSAGE FIRST_WORD
-  TIME_DOCKER=$(extract_string "${*}" ' ' 1)
-  TIME=$(_log_docker_time "${TIME_DOCKER}")
-  TASK_NODE=$(extract_string "${*}" ' ' 2)
-  SCOPE=$(_log_docker_scope "${TASK_NODE}");
-  NODE=$(_log_docker_node "${TASK_NODE}");
-  MESSAGE=$(extract_string "${*}" '|' 2-);
-  # Remove a single leading space.
-  [ "${MESSAGE:0:1}" = " " ] && MESSAGE="${MESSAGE:1}"
-  FIRST_WORD=$(extract_string "${MESSAGE}" ' ' 1);
-  if _log_level "${FIRST_WORD}" >/dev/null; then
-    LEVEL=${FIRST_WORD};
-    MESSAGE=$(extract_string "${MESSAGE}" ' ' 2-);
+  local EPOCH NODE SCOPE MESSAGE
+  # Using the same regexp for all 4 parts is about 8% slower.
+  # TIME_DOCKER=$(echo "${*}" | sed -n "s/^\([^ ]\+\) \+\([^ ]\+\)@\([^ ]\+\) \+| \(.*\)/\1/p");
+  # TASK_DOCKER=$(echo "${*}" | sed -n "s/^\([^ ]\+\) \+\([^ ]\+\)@\([^ ]\+\) \+| \(.*\)/\2/p");
+  # NODE_DOCKER=$(echo "${*}" | sed -n "s/^\([^ ]\+\) \+\([^ ]\+\)@\([^ ]\+\) \+| \(.*\)/\3/p");
+  # MESSAGE=$(echo "${*}"     | sed -n "s/^\([^ ]\+\) \+\([^ ]\+\)@\([^ ]\+\) \+| \(.*\)/\4/p");
+  local TIME_DOCKER TASK_DOCKER NODE_DOCKER
+  TIME_DOCKER=$(_get_first_word "${*}");
+  if EPOCH=$(_log_docker_time_epoch "${TIME_DOCKER}"); then
+    TASK_DOCKER=$(echo "${*}" | sed -n "s/^[^ ]\+ \+\([^ ]\+\)@.*/\1/p");
+    NODE_DOCKER=$(echo "${*}" | sed -n "s/^.*@\([^ ]\+\) \+.*/\1/p");
+    MESSAGE=$(echo "${*}"     | sed -n "s/^.*| \(.*\)/\1/p");
+  fi
+  # All three are empty, either the time is in unexpected format, or all sed failed, indicates errors.
+  if [ -z "${MESSAGE}" ] && [ -z "${TASK_DOCKER}" ] && [ -z "${NODE_DOCKER}" ]; then
+    # format error, imply that we receive an error message from the "docker service logs" command.
+    LEVEL="ERROR"
+    NODE="${LOCAL_NODE}"
+    SCOPE="${LOCAL_SCOPE}"
+    MESSAGE="${*}"
+  else
+    NODE="${NODE_DOCKER}"
+    [ -z "${NODE}" ] && NODE="${LOCAL_NODE}"
+    SCOPE="${TASK_DOCKER}"
+    [ -z "${SCOPE}" ] && SCOPE="${LOCAL_SCOPE}"
+    if _first_word_is_level "${MESSAGE}"; then
+      LEVEL=$(_get_first_word "${MESSAGE}");
+      MESSAGE=$(extract_string "${MESSAGE}" ' ' 2-);
+    fi
   fi
-  _log_formatter "${LEVEL}" "${TIME}" "${NODE}" "${SCOPE}" "${MESSAGE}";
+  _log_formatter "${LEVEL}" "${EPOCH}" "${NODE}" "${SCOPE}" "${MESSAGE}";
 }
 
 _log_docker_multiple_lines() {
@@ -227,8 +277,7 @@ is_number() {
 
 is_true() {
   local CONFIG="${1}"
-  CONFIG=$(extract_string "${CONFIG}" ' ' 1)
-  echo "${CONFIG}" | grep_q_i "true"
+  echo "${CONFIG}" | grep_q_i "^true$"
 }
 
 first_minus_second() {
@@ -277,7 +326,7 @@ add_unique_to_list() {
   echo -e "${OLD_LIST}\n${NEW_ITEM}" | sort | uniq
 }
 
-# For a givne variable name <VAR>, try to read content of <VAR>_FILE if file exists.
+# For a given variable name <VAR>, try to read content of <VAR>_FILE if file exists.
 # otherwise echo the content of <VAR>.
 read_config() {
   local CONFIG_NAME="${1}"
@@ -338,7 +387,7 @@ eval_cmd() {
   local TAG="${1}"; shift;
   local CMD="${*}"
   [ -z "${CMD}" ] && return 0
-  local OLD_LOG_SCOPE="${LOG_SCOPE}"
+  local OLD_LOG_SCOPE="${LOG_SCOPE:-}"
   LOG_SCOPE=$(attach_tag_to_log_scope "${TAG}")
   export LOG_SCOPE
   log INFO "Run ${TAG} command: ${CMD}"
@@ -492,7 +541,7 @@ _all_tasks_reach_state() {
   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=
-  RETURN_VALUE=$(extract_string "${TASK_RETURN_VALUE:-1}" ' ' 1)
+  RETURN_VALUE=$(_get_first_word "${TASK_RETURN_VALUE:-1}")
   # break
   echo "${RETURN_VALUE}"
   return 0

diff --git a/tests/README.md b/tests/README.md
@@ -29,7 +29,7 @@ bash shellspec --jobs 50
 
 To generate coverage (require [kcov](https://github.com/SimonKagstrom/kcov) installed):
 ```
-bash shellspec --kcov
+bash shellspec --kcov --tag coverage:true
 ```
 
 If you want to test a container image of *Gantry*, you need to specify the image of *Gantry* via the environment variable `GANTRY_TEST_CONTAINER_REPO_TAG`.

diff --git a/tests/spec_gantry_test_helper.sh b/tests/spec_gantry_test_helper.sh
@@ -259,13 +259,12 @@ _login_test_registry() {
 _logout_test_registry() {
   local ENFORCE_LOGIN="${1}"
   local REGISTRY="${2}"
-  if ! _enforce_login_enabled "${ENFORCE_LOGIN}"; then
-    return 0
-  fi
-  echo "Logging out ${REGISTRY}."
   local CONFIG=
   CONFIG=$(_get_docker_config_file "${REGISTRY}") || return 1
-  docker --config "${CONFIG}" logout
+  if _enforce_login_enabled "${ENFORCE_LOGIN}"; then
+    echo "Logging out ${REGISTRY}."
+    docker --config "${CONFIG}" logout
+  fi
   [ -d "${CONFIG}" ] && rm -r "${CONFIG}"
 }