diff --git a/src/lib-common.sh b/src/lib-common.sh index 84a97a1..a8451e5 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,117 @@ _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() { + local EPOCH="${1}" # Highlight time within the day in ISO-8601 # \\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="$(date +%s)" + _log_formatter "${LEVEL}" "${EPOCH}" "${LOCAL_NODE}" "${LOCAL_SCOPE}" "${@}"; } -_log_docker_time() { +_log_docker_time_epoch() { # Convert timestamps from `docker service logs` to ISO-8601. 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 - 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}" + date +%s 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-); + local TIME_DOCKER TASK_DOCKER NODE_DOCKER MESSAGE + local EPOCH SCOPE NODE + # 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"); + TIME_DOCKER=$(_get_first_word "${*}"); + TASK_DOCKER=$(echo "${*}" | sed -n "s/^[^ ]\+ \+\([^ ]\+\)@.*/\1/p"); + NODE_DOCKER=$(echo "${*}" | sed -n "s/^.*@\([^ ]\+\) \+.*/\1/p"); + MESSAGE=$(echo "${*}" | sed -n "s/^.*|\(.*\)/\1/p"); + EPOCH=$(_log_docker_time_epoch "${TIME_DOCKER}") + SCOPE="${TASK_DOCKER}" + [ -z "${SCOPE}" ] && SCOPE="${LOCAL_SCOPE}" + NODE="${NODE_DOCKER}" + [ -z "${NODE}" ] && NODE="${LOCAL_NODE}" # 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}; + if _first_word_is_level "${MESSAGE}"; then + LEVEL=$(_get_first_word "${MESSAGE}"); MESSAGE=$(extract_string "${MESSAGE}" ' ' 2-); fi - _log_formatter "${LEVEL}" "${TIME}" "${NODE}" "${SCOPE}" "${MESSAGE}"; + _log_formatter "${LEVEL}" "${EPOCH}" "${NODE}" "${SCOPE}" "${MESSAGE}"; } _log_docker_multiple_lines() { @@ -227,8 +267,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() { @@ -338,7 +377,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 +531,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/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}" }