记录昨天定位一个诡异 bug 的过程，我耗费了不少精力，你若有兴趣，请带着一点耐心看完它。
我们使用 go-redis-server 开发具有 redis 协议的服务。 按照文档，我们实现了如下接口，其背后访问的是 AWS 的 Dynamodb，我们的服务也开发了监控接口，以供我们这些程序狗知道它发生了什么。
1
2
3
func (handler *RedisHandler) Get(key string) (result string, err error)
func (handler *RedisHandler) Set(key string, val string) (err error)
func (handler *RedisHandler) Del(key string) (count int, err error)
这样，我们就能通过 redis 客户端来执行 Get，Set，Del 操作。
问题背景
我在批量写入几千条数据时，通过监控接口，我看到服务突然卡住的样子，没有 Get，Set的统计信息了。但我能肯定的是客户端一直有数据在往服务写入，或者读写。
同时从 AWS 监控得到的反馈是 Dynamodb 使用超过预设值，我调高了读写预设值，重启服务，就恢复可用（重启大法好）。
程序试运行十多天，只发生过一次异常，之后再无重现。
这个事情没有搞清楚，就成为我一个心结。
重现问题
我们来看看代码
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
func (handler *RedisHandler)
Set(key string, val string) (err error) {
...
m, err := JSONToMap(val)
_, err = table.PutItem(m)
if err != nil {
log.Log.Errorf("PutItem failed,
table: %s, primary key: %s, value: %+v,
err: %s",
tableName, primaryVal, m, err.Error())
return
}
return
}
Set接口，简单的将数据写入 Dynamodb，Dynamodb 如果异常就返回错误，然后通过redis协议返回给客户端。
我很大程度确定那时候是因为 AWS Dynamodb 的异常导致这个错误的。除非这个巧合太牛逼了，难道 go-redis-server 接口不支持返回错误不成吗？这个猜想很快就被我们用实验否定了。
我想重新触发 AWS Dynamodb 返回写容量超标的错误，测试了一阵子，并不容易重现。有点沮丧，这个时候我回忆起 aws-go-sdk 的特点，如果给Dynamodb 字段 赋予空值，是会有异常返回的，
类似如下：
1
2
3
ValidationException: One or more parameter values were invalid:
An AttributeValue may not contain an empty string
status code: 400
空值的测试明显容易制造。我在本地也开启服务，端口是1234，用 pyredis 作为客户端做测试。
测试脚本
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
import redis
import json
import random
r = redis.Redis(host='localhost',port=1234,db=0)
table_name = 'test'
primary_key = 'a'
i = 0
while True:
if i > 2:
break
data = {
'a': str(random.random()),
'b': ‘’,
}
key = '{0}:{1}:{2}'.format(table_name, primary_key, data[primary_key])
value = json.dumps(data)
r.set(key, value)
i = i + 1
发现测试程序卡在终端，一动不动，strace 测试程序
1
2
3
$ sudo strace -p 22404
Process 22404 attached
recvfrom(3,
感觉像是在等待服务器返回，但是等不到回报的样子。
试着解决问题
难道 go-redis-server 这个框架有猫腻，我就开始了一下午的看源码之旅。不得不说源码写的真好。回头看我们出错的代码片段，我试着修改 err 信息，修改成自己定义的错误字符串。
1
2
3
4
5
6
7
8
9
10
11
func (handler *RedisHandler) Set(key string, val string) (err error) {
...
m, err := JSONToMap(val)
_, err = table.PutItem(m)
if err != nil {
err = errors.New("I am a Custom Error")
return
}
return
}
再次执行测试脚本，这一次。2条测试数据很快就执行结束，并无阻塞。
好像看到了一丝曙光：error 内容的不一样，导致不一样的结果。类型一样，那么我能怀疑的就是格式，或者长度了。
1
2
3
4
5
6
7
AWS 错误信息的格式：
ValidationException: One or more parameter values were invalid:
An AttributeValue may not contain an empty string
status code: 400
我自定义错误信息的格式：
I am a Custom Error
我特意加长了自定义错误的长度，结果也是能顺利执行不阻塞客户端。但是我给自定义错误字符串加入了换行符，果然客户端再次测试会出现阻塞。当出现错误的时候，源码中是调用了 ErrorReply.WriteTo 这个函数，特别的。返回错误的协议格式是
第一个字节将是“-”,并以CR + LF 结尾
配合源码，以下是 go-redis-server 最核心的逻辑调度代码。
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
for {
request, err := parseRequest(conn)
if err != nil {
return err
}
request.Host = clientAddr
request.ClientChan = clientChan
reply, err := srv.Apply(request)
if err != nil {
return err
}
if _, err = reply.WriteTo(conn); err != nil {
return err
}
}
return nil
}
func (er *ErrorReply) WriteTo(w io.Writer) (int64, error) {
n, err := w.Write([]byte("-" + er.code + " " + er.message + "\r\n"))
return int64(n), err
}
从 Redis协议官方文档 ，可以确定客户端与服务器端之间传输的每个 Redis 命令或者数据都以 \r\n 结尾。 我们的错误信息中间杀出了 \n，导致协议错乱，redis 客户端不能理解协议，就阻塞了。
一点感悟
以后我们使用 go-redis-server 的服务时候，要记得检查返回的字符串或者错误信息有没有包含换行符，如果有，最好做一次过滤替换。
出现这个bug,我和同事都觉得不可思议，非常神奇。在没有其他直观线索的条件下，阅读使用的库的源码，并在源码加上一些输出验证语言加以辅助，收到了效果，的确需要一些耐心。但我觉得是值得的。
李笑来说有效阅读就是精度，这次阅读代码过程中我还有意外的收获，我发现了 reflect 的妙用，以及函数注册在框架可以那么用，读完觉得很满足的样子，值得再记录一番。
附链接：