bash环境下开发一个日志模块

一、引言

bash开发在我们运维工作中是不可或缺的一部分，很多时候我们都需要通过跑脚本提高工作效率，日志记录又是一个程序至关重要的一个功能。如果一个复杂的工程，没有一个很好的日志记录功能，那对于开发时的debug或者后续排查问题都是非常痛苦的事情。但是bash在日志记录这块就显得有些无力了，不像python一样有现成的logging模块，所以基本都是通过echo或者print这样的函数进行记录日志，还是比较麻烦的。

本文就简单聊聊，在bash环境下，如何开发一个类似logging这样的功能模块，并当做一个标准函数在工作中使用，以此提高工作效率，降低bash的开发成本。

二、前期准备

假设我们的日志格式是下面这样的：

[ 日志的时间 ] [ 日志的级别 ] [ 产生日志的机器 ] [ 产生日志的文件 ] [ 产生日志的行号 ] [ 日志的详情 ]
[ 2022-03-23 10:15:16 ] [ INFO ] [ 192.168.11.1 ] [ test.sh ] [ pfunc --> sfunc:2 ] [ 这是一行测试日志 ] 

• 可以通过文件名+行号快速定位到打印该行日志的脚本位置，也能知道是哪个函数调用哪个函数产生的日志。
• 可以针对不同级别使用不同颜色显示日志，对错误级别可以起到强调作用。
• 可以通过ip地址知道是哪台机器产生的日志。

1、基础功能的准备

（1）获取产生日志的时间

bash提供了一个date指令，可以直接返回当前时间，可以很方便的实现这个功能。

date "+%F %T"                 #返回这样的时间格式 2022-03-23 10:15:16

如果需要毫秒数可以使用下面这个

date "+%F %T.%N"|cut -c 1-23  #返回这样的时间格式 2022-03-23 10:15:52.583

（2）获取产生日志的IP地址

localhost_ip="$(/sbin/ip a 2>/dev/null|grep inet|grep brd|grep scope|awk '{print $2}'|awk -F'/' 'NR==1{print $1}')" || true

• 后面为什么需要带一个true，后面会有解释
• 如果是多网卡的场景，需要用户自行调试具体获取哪块网卡的ip地址

（3）获取产生日志的文件名

bash提供了一个变量，可以直接返回当前脚本的文件名，可以很方便的实现这个功能。

${BASH_SOURCE}

如果使用绝对路径执行，这个变量的值可能会很长，所以默认仅保留最后一级目录路径，即【/a/b/c/d.sh】会被处理成【c/d.sh】

（4）获取产生日志的行号

bash提供了一个变量，可以直接返回当前行号，可以很方便的实现这个功能。

${LINENO}

• 本文示例中在显示行号的同时会将函数名及父级函数一并展示，所以会结合FUNCNAME变量一起使用，即【pfunc --> sfunc:lineno】，表示pfunc调用sfunc函数在第lineno这个行号产生的日志
• FUNCNAME 是一个数组，第一个值是当前函数名，第二个值是调用方的函数名。

${FUNCNAME[0]} #FUNCNAME[1]是调用方的函数名

2、diy功能的准备

（1）针对不同级别显示不同颜色

    #定义一个关联数组, 预定义各个日志级别的显示颜色
    declare -A mode_color
    mode_color=(
        ["ERROR"]="\033[31m" 
        ["INFO"]="\033[32m"
        ["WARN"]="\033[33m" 
        ["COMMAND"]="\033[34m" 
        ["DEBUG"]="\033[37m" 
    )

定义一个关联数组，预定义好每个级别的显示颜色，默认是DEBUG级别，即不指定就是这个级别

（2）针对不同结束状态实现不同的操作(返回值)

这里是针对结束需求，就是说写完日志后需要做什么，有时候是需要正常退出，有时候是需要异常退出，有时候是正常返回，有时候是异常返回，所以这个功能就是针对这些结束需求定制化的。

    #定义一个关联数组, 预定义各个退出/返回状态的具体操作
    declare -A exit_state
    exit_state=(
        ["exit0"]="exit 0"
        ["exit1"]="exit 1"
        ["return0"]="return 0"
        ["return1"]="return 1"
    )

定义一个关联数组, 预定义各个退出/返回状态的具体操作。默认是return0，即不指定就正常返回0。

（3）是否需要记录到日志文件

这个功能就比较简单, 通过tee命令即可实现。

    #是否需要写到文件
    tee_mark="tee"
    [ -f "${log_path}" ] && tee_mark="tee -a ${log_file}"
    
    echo ${log_enter} "${enter_opt}${tmp_log}${enter_opt}"|${tee_mark}
    echo -n|${tee_mark}

tee 还有一个功能，将中间结果进行保存。例如：comm1|comm2 |tee -a comm2_out.log|comm3。可以将comm2命令的结果保存到文件，同时还可以传给后面的comm3命令。

3、其他功能的准备

（1）控制脚本的执行

bash默认情况是串行执行脚本的所有操作，即便执行过程中遇到报错（某个操作命令返回非零状态），也会继续串行执行，很多时候我们是希望在脚本执行遇到非预想的结果时就终止后面的操作，这在一定程度上避免了错误的结果的放大。可以看一下下面的示例：

# cat test.sh
#!/bin/bash
aaaa
echo "test"

# bash test.sh
test.sh: line 2: aaaa: command not found
test
# 

可以看到aaaa命令执行失败，但是不影响后面的echo命令的执行，假如aaaa命令是[cd xxx]，echo命令是[rm -f *]，是不是很危险呢。

针对上述这样的需求我们需要对脚本做特殊处理，实现起来也很简单仅需要在脚本开头添加如下命令即可：

set -e

示例如下

# cat test.sh
#!/bin/bash
set -e
aaaa
echo "test"

# bash test.sh
test.sh: line 3: aaaa: command not found
# echo "${?}"
127
# 

可以看到使用了-e参数以后, aaaa命令执行失败后，后面的echo命令就不会被执行了，而且返回状态码是127。

帮助文档对该参数的解释如下：

-e    Exit immediately if a pipeline (which may consist of a single simple command),  a subshell command enclosed in parentheses, or one of  the  com‐mands  executed as part of a command list enclosed by braces (see SHELL GRAMMAR above) exits with a non-zero status.

如果使用了-e参数需要注意，针对grep操作很容易导致意想不到的结果。因为grep在有结果的情况是返回0，没有结果的情况是返回非零，所以在没有查到的情况下，如果不做特殊处理，很容易导致脚本异常退出而终止任务（不细心还很难发现），所以我习惯性的在grep操作的后面加上true，表示强制将该命令的操作返回0，然后单独对grep的结果做判断处理。这也是上文中获取ip地址的命令后面会带一个true。

（2）控制脚本的返回值

在管道操作的场景，bash默认情况是仅获取最后一个管道的执行返回状态码，例如【comm1|comm2|comm3】，如果comm1执行成功，comm2执行失败，但是comm3执行成功，那整个返回状态就是执行成功，这跟我们预想的结果相悖，这也可能会导致意想不到的问题。可以看一下下面的示例：

#!/bin/bash
# cat test.sh
{ cat 1.log|ssh 192.168.11.1 "cat - > 1.log";} && state="${?}" || state="${?}"
echo "${state}"

# bash test.sh 
cat: 1.log: No such file or directory
0
# 

这类通过数据流备份的命令在运维中还是很常见（mysql的xtrabackup远程备份），可以看到cat命令执行失败，但是管道后面的命令的执行成功，整条命令返回状态是成功的，但是实际上整个备份流程是失败的。

针对上述这样的需求我们需要对脚本做特殊处理，实现起来也很简单仅需要在脚本开头添加如下命令即可：

set -o pipefail

示例如下

# cat test.sh
#!/bin/bash
set -o pipefail
{ cat 1.log|ssh 192.168.11.1 "cat - > 1.log";} && state="${?}" || state="${?}"
echo "${state}"

# bash test.sh
cat: 1.log: No such file or directory
1
# 

可以看到使用了-o参数以后, cat命令执行失败后，整个命令返回值就是非零了。

帮助文档对该参数的解释如下：

-o    If set, the return value of a pipeline is the value of the last (rightmost) command to exit with a non-zero status, or zero if all  com‐mands in the pipeline exit successfully.  This option is disabled by default.

另外 -u 参数用的可能也比较多。即在使用未定义的变量，立即退出。帮助文档对该参数的解释如下：

-u    When the variable is assigned a value, all lower-case characters are converted to upper-case.  The lower-case attribute is disabled.

set还有很多功能，感兴趣的可以通过【man set】进行查询更加详细的帮助信息。

（3）在脚本中引用别名

有过相关经历的同学估计知道，直接在脚本里面使用alias命令去定义别名是没法正常使用的，原因是alias功能在交互模式是开启的，在非交互模式是关闭状态的，如下示例

# cat test.sh
#!/bin/bash
alias ll="ls -l"
ll 1.log

# bash test.sh 
test.sh: line 3: ll: command not found
# 

如果需要在脚本中使用alias功能，需要通过shopt命令进行开启。

shopt -s expand_aliases

# cat test.sh
#!/bin/bash
shopt -s expand_aliases
alias ll="ls -l"
ll 1.log

# bash test.sh 
-rw-r--r-- 1 root root 4754 Apr  6 15:19 1.log
# 

• shopt 命令用于显示和设置shell中的行为选项，通过这些选项以增强shell易用性。-s是打开，-u是关闭，-p是列出所有可配置的行为选项。
• 具体支持哪些行为选项，可以man一下。

这里再提供一个方式实现引用别名，这个方式本质不是别名，而是解析变量，将解析后的值当做命令执行。

# t="date"
# eval ${t}
Wed Apr  6 16:11:00 CST 2022
# 

eval会解析t变量，然后会将解析后的值当做命令执行。

有同学可能会有疑惑，针对上面的示例，其实直接把t当做变量引用其实也是可以达到预期效果，为什么还要用eval多此一举呢。大家可以看下面两个案例：

# t="date '+%F %T'"
# ${t}
date: extra operand ‘%T'’
Try 'date --help' for more information.
# eval ${t}
2022-04-06 16:09:19
# 

# a="ls 1.log|cat"
# ${a}
ls: cannot access 1.log|cat: No such file or directory
# eval ${a}
1.log
# 

可以看到对于复杂一些的变量，比如带一些参数，带一些管道，离开eval就没法达到预期的效果。总之记住一句话，eval 会首先扫描并解析然后进行所有参数的置换，然后再把解析置换后当做命令执行。

至此所有准备工作已经完成，下面就可以进行开发日志模块了。

三、功能实现

1、开发环境介绍

• 内核 : 3.10.0-693.el7.x86_64
• 系统 : CentOS Linux release 7.4.1708 (Core)
• bash : GNU bash, version 4.2.46(2)-release (x86_64-redhat-linux-gnu)

2、日志模块的实现

function f_logging()
{
    #日志函数, 接收五个参数, 其中第一个是必选, 其余四个是可选
    #第一个表示日志内容
    #第二个表示日志级别, 包含脚本名, 函数名(包含父函数), 行号等信息
    #第三个表示是否需要回车(line0|line1|line2, line0表示不需要换行, 即记录完日志后不换行, line1表示需要换行, 这是正常的选项), line2表示两个换行，即前后需要一个换行
    #第四个控制退出/返回 现在仅支持exit0 exit1 return0 return1这四个状态, 分别对应正常退出, 异常退出, 正常返回, 异常返回
    #第五个控制是否写到日志文件, 接收一个日志路径，可以为空表示不写文件

    #f_logging "这是一个测试日志" "$(eval echo ${log_addr}):INFO" "line1" "return0" "/path/xxx.log"

    [ -z "${1}" ] && return 1

    declare pfun_name fun_name log_mode log_info enter_mark enter_opt exit_opt line_num localhost_ip tee_mark

    #获取本机ip地址(其中一块网卡)
    localhost_ip="$(/sbin/ip a 2>/dev/null|grep inet|grep brd|grep scope|awk '{print $2}'|awk -F'/' 'NR==1{print $1}')" || true

    log_info="${1}"     #日志信息
    file_name="$(awk -F: '{$0=$1;FS="/";gsub("^/","",$0);print (NF>=2?$(NF-1)"/"$NF:$NF)}' <<< "${2}")"    #文件名
    fun_name="$(awk -F: '{print $2}' <<< "${2}")"     #函数名
    [ -z "${fun_name}" ] && fun_name="${FUNCNAME[1]}" #没指定就默认以本函数名的父函数

    pfun_name="$(awk -F: '{print $3}' <<< "${2}")"    #函数名被调用的函数
    line_num="$(awk -F: '{print $4}' <<< "${2}")"     #文件行号
    log_mode="$(awk -F: '{print $5}' <<< "${2}")"     #日志级别
    [ -z "${line_num}" ] && line_num="NULL"           #没指定行号就置为空
    [ -z "${log_mode}" ] && log_mode="REMAIND"        #没指定日志级别就使用默认值, 即提示信息

    enter_opt="${3}"    #日志行前后是否需要空行

    exit_opt="${4}"     #是否需要退出任务
    [ -z "${exit_opt}" ] && exit_opt="return0"        #没指定退出就使用默认值, 即正常退出

    log_path="${5}"     #是否需要写到日志, 这里接收一个日志路径

    #定义一个关联数组, 预定义各个日志级别的显示颜色
    declare -A mode_color
    mode_color=(
        ["ERROR"]="\033[31m" 
        ["INFO"]="\033[32m"
        ["WARN"]="\033[33m" 
        ["COMMAND"]="\033[34m" 
        ["DEBUG"]="\033[37m" 
    )

    #定义一个关联数组, 预定义各个退出/返回状态的具体操作
    declare -A exit_state
    exit_state=(
        ["exit0"]="exit 0"
        ["exit1"]="exit 1"
        ["return0"]="return 0"
        ["return1"]="return 1"
    )

    #是否需要写到文件
    tee_mark="tee"
    [ -f "${log_path}" ] && tee_mark="tee -a ${log_file}"

    echo -en "${mode_color["${log_mode}"]}"|${tee_mark} #这里颜色输出不仅会显示在终端还会写到日志文件，如果不希望写到文件改成 echo -en "${mode_color["${log_mode}"]}"即可

    #是否需要前后空行
    enter_mark=""        #表示回车的动作, 初始化为空
    [ "${enter_opt}x" == "line2x" ] && enter_mark="\n"

    [ -z "${pfun_name}" ] && pfun_name="main"
    [ -z "${fun_name}" ] && fun_name="main"
    localhost_ip="192.168.11.1"
    log_info="[ $(date "+%F %T") ] [ ${log_mode} ] [ ${localhost_ip} ] [ ${file_name} ] [ ${pfun_name} --> ${fun_name}:${line_num} ] [ ${log_info} ]"

    echo -e "${enter_mark}${log_info}${enter_mark}"|${tee_mark}
    echo -n|${tee_mark}

    eval ${exit_state["${exit_opt}"]}
}

四、调用测试

1、准备测试目录

# cd /tmp
# mkdir -p test/{func,log}

2、准备日志函数

# vim test/func/f_logging.sh

贴上上文写好的日志模块代码。

3、准备测试脚本

# vim test/main.sh

#!/bin/bash

set -e -o pipefail

work_dir="/tmp/test"

export LANG=en_US.UTF-8

log_addr='${BASH_SOURCE}:${FUNCNAME[0]}:${FUNCNAME[1]}:${LINENO}' #eval echo ${log_addr}

log_file="${work_dir}/log/info.log"

[ ! -f "${log_file}" ] && touch ${log_file}

. ${work_dir}/func/f_logging.sh

function func1() 
{
    f_logging "这是func1第一条测试日志" "$(eval echo ${log_addr}):INFO" "line1" "return0" "${log_file}"

    f_logging "这是func1一条告警日志" "$(eval echo ${log_addr}):WARN" "line1" "return0" "${log_file}"
}

function func2() 
{
    f_logging "这是func2一条错误日志" "$(eval echo ${log_addr}):ERROR" "line2" "return1" "${log_file}"
}

function f_main()
{
    f_logging "这是f_main一条DEBUG日志" "$(eval echo ${log_addr}):DEBUG" "line1" "return0" "${log_file}"

    if ! func1
    then
        f_logging "这是f_main的日志，记录func1执行失败" "$(eval echo ${log_addr}):ERROR" "line1" "return0" ""
    fi

    if ! func2
    then
        f_logging "这是f_main的日志，记录func2执行失败" "$(eval echo ${log_addr}):ERROR" "line1" "return0" ""
    fi
}

f_main

• 准备两个测试函数func1 func2。
• func1准备一条INFO(输出颜色绿色)和一条WARN(输出颜色黄色)级别，返回值：return 0。
• func2准备一条ERROR(输出颜色红色)级别，且前后带空行，返回值：return 1。
• f_main函数负责调用func1和fun2，并判断其是否执行成功。
• fun1和fun2那几行日志都记录到日志，f_main的几行日志不用记录到日志。

整体目录结构如下

# tree -L 2 test/
test/
├── func
│   └── f_logging.sh
├── log
│   └── info.log
└── main.sh

2 directories, 3 files
# 

4、开始测试

# bash test/main.sh 
[ 2022-04-07 11:02:56 ] [ INFO ] [ 192.168.11.1 ] [ test/main.sh ] [ f_main --> func1:19 ] [ 这是func1第一条测试日志 ]
[ 2022-04-07 11:02:56 ] [ WARN ] [ 192.168.11.1 ] [ test/main.sh ] [ f_main --> func1:21 ] [ 这是func1一条告警日志 ]

[ 2022-04-07 11:02:56 ] [ ERROR ] [ 192.168.11.1 ] [ test/main.sh ] [ f_main --> func2:26 ] [ 这是func2一条错误日志 ]

[ 2022-04-07 11:02:57 ] [ ERROR ] [ 192.168.11.1 ] [ test/main.sh ] [ main --> f_main:38 ] [ func2执行失败 ]
# 

# cat test/log/info.log 
[ 2022-04-07 11:02:56 ] [ INFO ] [ 192.168.11.1 ] [ test/main.sh ] [ f_main --> func1:19 ] [ 这是func1第一条测试日志 ]
[ 2022-04-07 11:02:56 ] [ WARN ] [ 192.168.11.1 ] [ test/main.sh ] [ f_main --> func1:21 ] [ 这是func1一条告警日志 ]

[ 2022-04-07 11:02:56 ] [ ERROR ] [ 192.168.11.1 ] [ test/main.sh ] [ f_main --> func2:26 ] [ 这是func2一条错误日志 ]

# 

实际效果如下：

可以看到跟预期的一样，各个级别的日志按按照预定义的颜色展示，需要写文件的也写到日志文件中，不需要写文件的也没有写到文件。

bash环境下的日志模块测试完成，以后就可以当做一个标准的函数在其他工程中导入使用了。

五、写在最后

本文档仅做交流分享，因各自环境不同，shell兼容度较低，在使用文中代码时可能碰上未知的问题。如有线上环境操作需求，请在测试环境充分测试。