Quartz 4

分布式调试

13 min read

作者：Jose Javier Gonzalez Ortiz 翻译：hyperv0id (Echo) · GitHub

调试分布式系统是一项艰巨的任务。通过良好的日志记录实践和终端用户界面工具，我们可以让解析分布式日志变得毫不费力，从而简化这项任务。

本学期我在麻省理工学院6.824分布式系统课程担任助教。该课程要求学生逐步实现Raft——一个分布式共识协议。这是一项极具挑战性的任务，尽管Raft号称是”更容易理解的Paxos”，但它仍然是一个复杂的分布式系统，即使经过多次尝试也很难完全正确。当我学习6.824时，我发现完成实验的瓶颈从来不是实现核心功能，真正消耗大部分时间的是获取失败运行的日志，并通过解析日志来理解系统如何失败以及哪里出了问题。

本文不会讨论常见陷阱或Raft实现通常如何出错（如果你对此感兴趣，可以参考精彩的Raft学生指南。我将重点介绍如何构建工具来简化分布式系统调试工作。我们将从头开始构建这些基于终端的工具，最终形成一套调试套件，帮助你更高效地检测、理解和修复6.824实验中的错误。6.824所有实验的调试方式都相同，因此投入时间优化日志收集和解析是值得的。

调试分布式代码的独特挑战

调试分布式系统是许多学生在学习6.824之前从未接触过的任务，它与其他形式的调试有本质区别。这里没有像gdb或pdb这样可以单步执行代码的调试器。传统的_printf调试_也不够用，因为可能有大量并行运行的例程（因此会产生并行输出）。在传统系统中，通过打印语句调试相对简单，因为通常只有一个执行线程，可以快速推理当前状态。

对于像6.824实验中的分布式系统，有N台机器，每台机器都在并发执行多个线程。例如在Raft实验中，N个raft节点并行运行，就像位于不同机器上。每个节点会有多个goroutine并行执行（通常是一到两个定时器、一个应用器和若干RPC处理程序），导致高度并发。虽然添加打印语句很容易，但解析它们可能非常棘手，特别是随着实验复杂性的逐周增加。尽管如此，通过日志分析逻辑错误仍然是最高效的方法。盯着代码看或反复调整不同部分可能在短期内有效，但复杂错误需要更仔细的分析。

此外，在Raft这样的系统中，不仅多个线程同时输出，它们还会打印非常异构的事件，如：定时器重置、日志操作、选举、崩溃恢复或与状态机的通信。关键的是，不同类型事件的发生频率不同，如果不加以控制会导致日志过于冗长。

因此，我们理想情况下需要知道每条日志的来源和主题。我们的目标是设计一种可视化编码这些信息的方式。TL;DR：我们将让Go以特定格式输出普通日志，然后使用Rich Python库来处理美观格式化的终端输出。

Go端实现

虽然大部分工具将使用Python脚本完成，但需要Go端的配合以确保以易解析的格式提供信息。

控制输出详细程度。我实现的一个生活质量改进是无需修改Go代码即可调整日志详细程度。这也有助于自动化脚本控制详细程度。由于6.824测试使用go test，我们不能直接使用命令行参数，但可以使用环境变量。以下代码通过VERBOSE环境变量控制详细程度：

// 从环境变量获取详细级别
func getVerbosity() int {
    v := os.Getenv("VERBOSE")
    level := 0
    if v != "" {
        var err error
        level, err = strconv.Atoi(v)
        if err != nil {
            log.Fatalf("Invalid verbosity %v", v)
        }
    }
    return level
}

按主题分类日志。我修改了printf函数，使其第一个参数为表示消息类别的_主题_。虽然主题本质是字符串，但为了便于重构（且我不喜欢输入引号），我将其声明为常量：

type logTopic string
const (
    dClient  logTopic = "CLNT"
    dCommit  logTopic = "CMIT"
    dDrop    logTopic = "DROP"
    dError   logTopic = "ERRO"
    dInfo    logTopic = "INFO"
    dLeader  logTopic = "LEAD"
    dLog     logTopic = "LOG1"
    dLog2    logTopic = "LOG2"
    dPersist logTopic = "PERS"
    dSnap    logTopic = "SNAP"
    dTerm    logTopic = "TERM"
    dTest    logTopic = "TEST"
    dTimer   logTopic = "TIMR"
    dTrace   logTopic = "TRCE"
    dVote    logTopic = "VOTE"
    dWarn    logTopic = "WARN"
)

打印函数。Go端的最后一个组件是实际的打印函数。我将其命名为Debug，它会输出消息及其主题和运行开始后的毫秒数。禁用日期时间记录是因为这些信息冗余（所有测试必须在几分钟内完成）。仅打印毫秒数在检查定时事件频率时很有用：

var debugStart time.Time
var debugVerbosity int
 
func init() {
    debugVerbosity = getVerbosity()
    debugStart = time.Now()
 
    log.SetFlags(log.Flags() &^ (log.Ldate | log.Ltime))
}
 
func Debug(topic logTopic, format string, a ...interface{}) {
    if debug >= 1 {
        time := time.Since(debugStart).Microseconds()
        time /= 100
        prefix := fmt.Sprintf("%06d %v ", time, string(topic))
        format = prefix + format
        log.Printf(format, a...)
    }
}

示例用法：

Debug(dTimer, "S%d Leader, checking heartbeats", rf.me)

启用详细模式（如VERBOSE=1 go test -run TestBackup2B）的输出示例如下：

008258 LOG2 S2 Saved Log (-1, 0) [{<nil> 0}]
008256 VOTE S3 Granting Vote to S1 at T1
008258 VOTE S1 <- S0 Got vote
008258 VOTE S4 Granting Vote to S1 at T1
008259 PERS S4 Saved State T:1 VF:1
008258 PERS S3 Saved State T:1 VF:1
008259 LOG2 S3 Saved Log (-1, 0) [{<nil> 0}]
008259 VOTE S1 <- S2 Got vote
008260 LEAD S1 Achieved Majority for T1 (3), converting to Leader
008260 TIMR S1 Broadcast, reseting HBT
008260 LOG1 S1 -> S0 Sending PLI: 0 PLT: 0 N: 0 LC: 0 - []
008260 LOG1 S1 -> S2 Sending PLI: 0 PLT: 0 N: 0 LC: 0 - []
008259 LOG2 S4 Saved Log (-1, 0) [{<nil> 0}]
008261 LOG1 S1 -> S3 Sending PLI: 0 PLT: 0 N: 0 LC: 0 - []
008262 LOG1 S1 -> S4 Sending PLI: 0 PLT: 0 N: 0 LC: 0 - []
008262 TIMR S1 Leader, checking heartbeats
008263 TIMR S0 Resetting ELT, received AppEnt T1
008263 TIMR S3 Resetting ELT, received AppEnt T1
008264 TIMR S2 Resetting ELT, received AppEnt T1
008264 LOG2 S2 LOG: (-1, 0) [{<nil> 0}]
...

美化日志

当前的日志输出仍然不够直观。我们需要用Python编写日志解析器、过滤器和美化打印机。Rich和Typer这两个库可以轻松创建终端用户界面。

以下是核心Python代码片段（完整脚本见此处）：

# [...] 省略部分导入
 
# 主题到颜色的映射
TOPICS = {
    "TIMR": "bright_black",
    "VOTE": "bright_cyan",
    "LEAD": "yellow",
    "TERM": "green",
    "LOG1": "blue",
    "LOG2": "cyan",
    "CMIT": "magenta",
    "PERS": "white",
    "SNAP": "bright_blue",
    "DROP": "bright_red",
    "CLNT": "bright_green",
    "TEST": "bright_magenta",
    "INFO": "bright_white",
    "WARN": "bright_yellow",
    "ERRO": "red",
    "TRCE": "red",
}
 
# [...] 省略命令行解析
 
input_ = file if file else sys.stdin
if just:
    topics = just
if ignore:
    topics = [lvl for lvl in topics if lvl not in set(ignore)]
 
topics = set(topics)
console = Console()
width = console.size.width
 
panic = False
for line in input_:
    try:
        time = int(line[:6])
        topic = line[7:11]
        msg = line[12:].strip()
        if topic not in topics:
            continue
 
        if topic != "TEST" and n_columns:
            i = int(msg[1])
            msg = msg[3:]
 
        if colorize and topic in TOPICS:
            color = TOPICS[topic]
            msg = f"[{color}]{msg}[/{color}]"
 
        if n_columns is None or topic == "TEST":
            print(time, msg)
        else:
            cols = ["" for _ in range(n_columns)]
            msg = "" + msg
            cols[i] = msg
            col_width = int(width / n_columns)
            cols = Columns(cols, width=col_width - 1,
                           equal=True, expand=True)
            print(cols)
    except:
        if line.startswith("panic"):
            panic = True
        if not panic:
            print("-" * console.width)
        print(line, end="")

使用示例：

# 直接管道传输go test输出
$ VERBOSE=1 go test -run TestInitialElection | dslogs
 
# 过滤冗长主题
$ VERBOSE=1 go test -run TestBackup | dslogs -c 5 -i TIMR,DROP,LOG2
 
# 保存日志文件
$ VERBOSE=1 go test -run TestFigure8Unreliable > output.log
$ dslogs output.log -j CMIT,PERS

美化前后的对比：

原始输出：

美化输出：

捕获罕见错误

对于偶现错误，我们编写自动化脚本：

#!/usr/bin/env bash
 
trap 'exit 1' INT
 
echo "Running test $1 for $2 iters"
for i in $(seq 1 $2); do
    echo -ne "\r$i / $2"
    LOG="$1_$i.txt"
    go test -run $1 &> $LOG
    if [[ $? -eq 0 ]]; then
        rm $LOG
    else
        echo "Failed at iter $i, saving log at $LOG"
    fi
done

Python并行测试脚本核心（完整代码见此处）：

def run_test(test: str, race: bool):
    test_cmd = ["go", "test", f"-run={test}"]
    if race:
        test_cmd.append("-race")
    f, path = tempfile.mkstemp()
    start = time.time()
    proc = subprocess.run(test_cmd, stdout=f, stderr=f)
    runtime = time.time() - start
    os.close(f)
    return test, path, proc.returncode, runtime
 
with ThreadPoolExecutor(max_workers=workers) as executor:
    futures = []
    while completed < total:
        n = len(futures)
        if n < workers:
            for test in itertools.islice(tests, workers-n):
                futures.append(executor.submit(run_test, test, race))
        done, not_done = wait(futures, return_when=FIRST_COMPLETED)
        # [...] 结果处理

运行效果：

现在开始构建你的工具吧

希望这篇概述能为你提供必要的背景知识和示例，帮助你构建既美观又实用的终端调试工具。如果没有Rich开发者的杰出工作，开发这些工具的时间成本将呈数量级增长——在此向Rich团队致以崇高敬意。

免责声明：真彩色支持

需要特别说明日志解析脚本对色彩支持的要求。大多数终端默认支持8位色彩（即256色模式），而现代UI调色板通常每个通道使用8位，总共24位色彩（约1677万色）。

Rich为所有8位颜色提供了命名颜色，如果你使用8位调色板可以直接使用这些名称。若想启用24位色彩模式，需要确保你的工具链支持真彩色。多数现代终端工具都支持更广的色域，但有时需要手动启用。注意真彩色需要所有相关组件都支持：

  • 终端模拟器：如Terminal.app、iTerm、GNOME Terminal、kitty、alacritty、Windows Terminal等。多数现代终端支持真彩色，但有时需要设置TERM环境变量为xterm-256color
  • 终端复用器：如使用tmux，通常需要修改.tmux.conf配置文件
  • 远程客户端：如ssh基本都支持，但mosh、Eternal Terminal或PuTTY等需要额外确认
  • 编辑器：若vim/neovim仅显示256色，可能需要启用真彩色支持

Graph View