Skip to content

Commit

Permalink
[lib-common] increase docker log speed.
Browse files Browse the repository at this point in the history
  • Loading branch information
@shizunge
shizunge committed Nov 24, 2024
1 parent 1f030ec commit f2469d6
Show file tree
Hide file tree
Showing 2 changed files with 112 additions and 74 deletions.
177 changes: 108 additions & 69 deletions src/lib-common.sh
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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;
}

Expand All @@ -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 <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
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 <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-);
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() {
Expand All @@ -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() {
Expand Down Expand Up @@ -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}"
Expand Down Expand Up @@ -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
Expand Down
9 changes: 4 additions & 5 deletions tests/spec_gantry_test_helper.sh
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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}"
}

Expand Down

0 comments on commit f2469d6

Please sign in to comment.