From ac65da39f3995db12f053f3299321698244d338b Mon Sep 17 00:00:00 2001 From: Shizun Ge Date: Sat, 23 Nov 2024 18:21:09 -0800 Subject: [PATCH] [lib-common] increase docker log speed. --- src/lib-common.sh | 199 +++++++++++++++++++------------ tests/README.md | 2 +- tests/spec_gantry_test_helper.sh | 9 +- 3 files changed, 129 insertions(+), 81 deletions(-) diff --git a/src/lib-common.sh b/src/lib-common.sh index 84a97a1..0c923e8 100755 --- 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 # 2023-06-22T01:20:54.535860111Z @ | 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 # 2023-06-22T01:20:54.535860111Z @ | _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: + # 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/^[^ ]\+ \+\([^ ]\+\)@\([^ ]\+\) \+| \?\(.*\)/\2/p"); + MESSAGE=$(echo "${*}" | sed -n "s/^[^ ]\+ \+\([^ ]\+\)@\([^ ]\+\) \+| \?\(.*\)/\3/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 , try to read content of _FILE if file exists. +# For a given variable name , try to read content of _FILE if file exists. # otherwise echo the content of . 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 index 1da24c1..b334374 100644 --- 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 index 04787fd..0d4be29 100644 --- 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}" }