MIT 6.5840 构建 Raft 调试工具
工欲善其事，必先利其器。
目标
本文参考这篇博客，对代码做了一些调整。
在实现 Labs 的过程中，为了弄清楚系统究竟在干什么，以及哪里出了问题，需要找到一种比较方便的方法。在分布式系统中，我们没法像单体应用程序那样可以用gdb或者pdb做调试，传统的print语句也帮不上什么忙，我们需要依赖对日志的分析。
用于调试的日志最重要的是要包含什么角色 在什么时间 做了什么类型 的事情，然后我们就可以设计工具来对日志的输出进行排版上的美化。简单来说，我们会让 Go 代码输出特定格式的日志，然后通过 Python 的 Rich 库解析日志，输出下图这样的结果。
图中包含三个维度的信息，纵轴自上而下代表时间的先后顺序（生产环境上使用需要保证各节点的时间进行同步，本例中都是单机运行无所谓），横轴代表不同的角色（节点），不同的颜色代表不同类型的事件。
Go 日志代码
为了方便 Python 脚本的处理，日志需要用指定的格式生成。我们定义一个单独的包来编写相关代码，方便其他包来调用。
$ cd src
$ mkdir dlog
$ cd dlog
$ touch dlog.go topic.go
控制日志是否输出
需要能够在运行的时候控制日志是否输出。习惯的做法是使用命令行参数，但是 6.5840 主要用go test命令做测试，不能直接使用命令行参数，所以我们通过环境变量来进行控制。下面的代码读取VERBOSE环境变量来决定是否输出日志。
// Retrieve the verbosity level from an environment variable
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
}
不同主题的日志
这边的主题指的是上面提到的不同类型的事情，不同系统中的主题也各不相同，在单独的文件中进行定义，这边以 lab3A 为例：
package dlog
type logTopic string
const (
Vote LogTopic = "VOTE"
Election LogTopic = "ELEC"
Heartbeat LogTopic = "HEAR"
Ticker LogTopic = "TICK"
)
日志输出函数
最后一部分是实际执行输出的函数，函数名叫Debug，其他包可以通过dlog.Debug来调用。这个函数会输出从运行开始一直到现在的时间（毫秒）、主题以及具体的日志内容。因为所有的 Lab 基本上几分钟就能运行完，所以不用输出日期、小时这些前缀（因为全都一样），用毫秒输出也方便观察那些固定时间间隔的操作是不是正确。
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 debugVerbosity >= 1 {
time := time.Since(debugStart).Microseconds()
time /= 100
prefix := fmt.Sprintf("%06d %v ", time, string(topic))
format = prefix + format
log.Printf(format, a...)
}
}
对于 Raft 这个例子来说，我们可能还希望输出 state、term 等信息，这些信息的读取前需要加锁，因此我们定义一个辅助方法：
func (rf *Raft) debug(topic dlog.LogTopic, msg string) {
rf.mu.Lock()
dlog.Debug(topic, "S%d %s %03d "+msg, rf.me, rf.state, rf.currentTerm)
rf.mu.Unlock()
}
在需要加日志的地方（注意不能是临界区）可以这么用：
rf.debug(dlog.Election, "election failed, receive a larget term")
现在如果在终端输入VERBOSE=1 go test -race -run TestReElection3A，会看到下面的结果：
Test (3A): election after network failure (reliable network)...
008517 ELEC S1 FOLLOW 000 election timeout, start election
008565 HEAR S1 LEADER 001 win election, start heartbeat
015605 HEAR S1 LEADER 001 heartbeat failed, timeout
015610 TICK S1 FOLLOW 001 heartbeat end, become follower
019573 ELEC S0 FOLLOW 001 election timeout, start election
019608 HEAR S0 LEADER 002 win election, start heartbeat
022419 ELEC S1 FOLLOW 001 election timeout, start election
022433 ELEC S1 CANDID 002 election failed, do not voted by majority
024620 HEAR S0 LEADER 002 heartbeat failed, timeout
024621 TICK S0 FOLLOW 002 heartbeat end, become follower
030970 ELEC S2 FOLLOW 002 election timeout, start election
030980 HEAR S2 LEADER 003 win election, start heartbeat
040033 HEAR S2 LEADER 003 heartbeat failed, timeout
040034 TICK S2 FOLLOW 003 heartbeat end, become follower
046916 ELEC S0 FOLLOW 003 election timeout, start election
047283 ELEC S2 FOLLOW 003 election timeout, start election
053894 ELEC S1 FOLLOW 003 election timeout, start election
057390 ELEC S0 CANDID 004 election failed, timeout
057401 HEAR S0 LEADER 005 win election, start heartbeat
057403 ELEC S1 FOLLOW 005 election failed, find a larger term or receive AppendEntries PRC
058890 ELEC S2 CANDID 004 election failed, timeout
062412 HEAR S0 LEADER 005 heartbeat failed, timeout
062412 TICK S0 FOLLOW 005 heartbeat end, become follower
068753 ELEC S2 CANDID 005 election failed, timeout
068758 HEAR S2 LEADER 006 win election, start heartbeat
... Passed -- time 7.0s #peers 3 #RPCs 44 #Ops 0
PASS
070777 HEAR S2 LEADER 006 heartbeat failed, do not reach majority
070777 TICK S2 FOLLOW 006 heartbeat end, become follower
ok 6.5840/raft1 8.249s
前五列分别代表事件的发生时间、所属的主题、当前的 server、server 当前的状态、server 当前的 term，剩下的是日志的具体内容。
Python 处理代码
对于终端富文本输出的任务，Go 不太合适，而 Python 因为有 Rich 和 Typer 这样的第三方库，实现起来比较轻松。
人的大脑处理视觉信息的能力很强，给上面的日志加上颜色，按表格排版一下就能达到很好的效果。相关代码如下：
#!/usr/bin/env python
import sys
from typing import Optional
import typer
from rich import print
from rich.columns import Columns
from rich.console import Console
# fmt: off
# Mapping from topics to colors
TOPICS = {
"ELEC": "#4878bc",
"VOTE": "#67a0b2",
"HEAR": "#d0b343",
"TICK": "#70c43f",
}
# fmt: on
def list_topics(value: Optional[str]):
if value is None:
return value
topics = value.split(",")
for topic in topics:
if topic not in TOPICS:
raise typer.BadParameter(f"topic {topic} not recognized")
return topics
def main(
file: typer.FileText = typer.Argument(None, help="File to read, stdin otherwise"),
colorize: bool = typer.Option(True, "--no-color"),
n_columns: Optional[int] = typer.Option(None, "--columns", "-c"),
ignore: Optional[str] = typer.Option(None, "--ignore", "-i", callback=list_topics),
just: Optional[str] = typer.Option(None, "--just", "-j", callback=list_topics),
):
topics = list(TOPICS)
# We can take input from a stdin (pipes) or from a file
input_ = file if file else sys.stdin
# Print just some topics or exclude some topics (good for avoiding verbose ones)
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
role_pos = {} # arrange different columns for different roles
for line in input_:
try:
time, topic, *msg = line.strip().split(" ")
# To ignore some topics
if topic not in topics:
continue
if not msg[0] in role_pos:
pos = len(role_pos)
role_pos[msg[0]] = pos
msg_content = " ".join(msg)
# Colorize output by using rich syntax when needed
if colorize and topic in TOPICS:
color = TOPICS[topic]
msg_content = f"[{color}]{msg_content}[/{color}]"
# Single column printing. Always the case for debug stmts in tests
if not n_columns or topic == "TEST":
print(time, msg_content)
# Multi column printing, timing is dropped to maximize horizontal
# space. Heavylifting is done through rich.column.Columns object
else:
cols = ["" for _ in range(n_columns)]
msg_content = "" + msg_content
cols[role_pos[msg[0]]] = msg_content
col_width = int(width / n_columns)
cols = Columns(cols, width=col_width - 1, equal=True, expand=True)
print(cols)
except:
# Code from tests or panics does not follow format
# so we print it as is
if line.startswith("panic"):
panic = True
# Output from tests is usually important so add a
# horizontal line with hashes to make it more obvious
if not panic:
print("#" * console.width)
print(line, end="")
if __name__ == "__main__":
typer.run(main)
用法如下所示
# You can just pipe the go test output into the script
$ VERBOSE=1 go test -run InitialElection | python ../dlog/log_parser.py
# ... colored output will be printed
# We can use -c flag to enable multiple columns if we know how many roles included
$ VERBOSE=1 go test -run ReElection3A | python ../dlog/log_parser.py -c 3
# ... colored output in 3 columns