记一次protobuf字符串故障排查

c0d3n4m

前言

鲁迅先生说过，一切程序的玄学本质上都是代码出了bug。
背景介绍

昨天凌晨，公司的服务器出现了一堆诡异的报错，接到报警后赶紧起床排查这个问题。错误内容很简单，是一个字符串编码的错误：通过报错可以知道是一个不该用ascii编码的字符串用了encode("ascii")的编码方式。具体错误如下。
Traceback (most recent call last):
  File "tmp.py", line 15, in <module>
    handle(a)
  File "tmp.py", line 10, in handle
    v = key.encode("ascii")
UnicodeDecodeError: 'ascii' codec can't decode byte 0xe4 in position 3: ordinal not in range(128)本身这是一个很简单的问题，可以基本推测调用这个微服务的同学传了不支持的非ascii字符，所以出现了大量报错。不过很快该线上的报错就消失了，应该是该同学查看了文档，发现了用法上的问题并且修复了。
但是仔细一看这个报错，诡异的事情发生了。按照代码逻辑，理论上在上一行代码 key='{}'.format(package.module_name) 就会发生报错。而根据日志，错误却发生在了后面的v=key.encode("ascii") 这一行。我们来看下完整代码的片段。
# encoding:utf8

def handle(package):
    print(type(package.module_name)) # unicode
    # ...other code
    key = 'v2.{}'.format(package.module_name)
    # ...other code
    v = key.encode("ascii")
    # ...在看代码前，首先介绍一下package这个变量。这个变量类型是公司内部微服务之间通讯用的消息结构，使用的是google的protobuf。该数据结构很简单，只含有一个参数，是一个string类型的module_name，简单来说就是一个utf8或者是ascii编码的字符串。
message TestPackage {
    required string module_name = 1;
}

string的定义：
string：A string must always contain UTF-8 encoded or 7-bit ASCII text.

这个函数在收到参数以后执行了一个format的操作，给这个字符串增加了一个 "v2."的前缀，接着将这个值用ascii编码，准备进行后续的数据传输操作。
问题分析

首先，解释一下为什么我认为报错应该在上一行的 format 那里。
第一点是因为从“UnicodeDecodeError”这个错误可以得出传进来的是一个非ascii编码的字符串，否则就不会报错了。第二点是实际模拟测试了print(type(package.module_name)) ，输出的结果都是 "unicode"。所以从这两点可以推测传进来的数据是类似是 u"你好" 这样的unicode字符串。
分析一：
但是我们知道format是一个很基本的函数，能执行format操作只有ascii编码的unicode。一个简单的例子：执行 'v2.{}'.format(u"你好") 时一定会报错。而正确的方式是通过 'v2.{}'.format(u"你好".encode("utf8")) 编码后再format。  
所以这里出现了第一个矛盾，'v2.{}'.format(package.module_name) 和 key.encode("ascii")。假设真如上述的unicode假设，这里的package.module_name是一个非ascii的unicode那么早就在这一行 'v2.{}'.format(package.module_name) 就报错了，而不会再后一行报错。所以我们可以知道出错的时候这里的package.module_name一定是一个str类型，而不是unicode类型。
分析二：
既然推测 package.module_name 出错的时候是str类型，但是在实际正常运行中却都是unicode类型。说明上游服务通信的时候传递了一个奇怪格式的消息过来，而google的protobuf因为无法用 utf8 来 decode，所以也就保留这个encode后 str 格式的数据。
实测一：
既然问题查明了，满心欢喜地准备复现一下这个错误。复现的思路很简单，因为protobuf编码的时候强制要求的是utf8或者是ascii。那么只要我随意用一个别的编码，比如这里的gb2312，就能复现这个错误了。
name = u"你好".encode("gb2312")
package = TestPackage()
package.module_name = name结果被啪啪啪打脸了，报了如下的错误。说明了protobuf是做了编码是否为utf-8的检查的，也就是说上游服务不可能发送无法识别的数据过来。
Traceback (most recent call last):
    package.module_name = name
ValueError: '\xc4\xe3\xba\xc3' has type str, but isn't valid UTF-8 encoding. Non-UTF-8 strings must be converted to unicode objects before being added.实测二：
正当一筹莫展之际，想到了某些坊间的小故事。比如某种稳定的宇宙射线干扰了机房的电脑，导致了二进制位在执行到具体代码时出现了突变。或者一个无聊的黑客写了程序随机破坏内存中的数据。。。还好这时鲁迅先生拯救了我，想起了他的格言“一切程序的玄学本质上都是代码出了bug”
所以，猛然间我想到了一直被忽略的人：“写上游服务的那个程序员”。以上的分析都是基于他正确调用服务的假设，有没有可能是他除了把消息格式写错了，然后还用了错误的编码？
message TestPackage {
    required bytes module_name = 1;
}想到这点我马上改动了一下这个格式，将其中的string改成了bytes，然后再用下面的代码测试了一下，果然问题复现成功了，出现了相同的报错~
name = u"你好".encode("gb2312")
package = TestPackage()
package.module_name = name后记

问题终于查明了，很开心。但是也想到了一些问题。我们平常写代码的时候，都一定会依赖底层的架构，比如这里用到的protobuf来做消息通信。所以很多时候我们都会默认底层的架构不会出错，而事实底层架构也会有一些考虑不周全的地方，比如这里protobuf的错误处理。我觉得较好的设计应该是当规定了string类型一定是utf8或者ascii时，就要严格执行，在任何时候果断的抛出异常。在这个案例中我们可以看到 protobuf 仅仅在发送的时候做检查，但是对于接收方却忽略这个错误，保留了未decode的数据让业务方自行处理。而这里更Nice的做法应该是protobuf直接抛出异常，因为你完全不知道发送方会做什么奇怪的操作 ~