protobuf序列化出错, 竟是Unreal的锅！

Day1

客户端同学找我，反馈游戏现网和他的开发分支经常出现protobuf序列化数据出错的问题。了解背景后请他在开发分支写一个自动调用测试函数用于重现问题。

Day2

客户端同学提供了已经构建好的程序，该程序运行时必现序列化出错的问题。

首先怀疑是因为内存问题导致的，因为该开发分支没有 ASan 版本，所以使用 Valgrind 工具进行内存测试，但并没有发现任何内存问题。

接着计划使用 GDB 进行调试，首先说一下代码结构:

// state_diff.proto 对应 state_diff.pb.cc 和 state_diff.pb.h
message DiffAIStateInfo {
    // ....
}

// ccs_ai_api.proto 对应 ccs_ai_api.pb.cc 和 ccs_ai_api.pb.h (ccs_ai_api.pb.h中依赖state_diff.pb.h)
message AIStateRequest {
    string episode_id = 1; 
    AIStateInfo state = 2; 
    DiffAIStateInfo diff_state = 3; 
    int64 stamp = 4;                
    bool is_ai = 5;                
}

// 测试代码 XXXProtocolHandlerTest.cpp 和 XXXProtocolHandlerTest.h 提供了测试函数
// XXXProtocolHandlerTest.h 依赖 ccs_ai_api.pb.h
// static int XXXTestOPT = 0;
void XXXTest()
{
    AIStateRequest Encode;
    if (XXXTestOPT < 1)
    {
        // 填充测试数据1
    }
    if (XXXTestOPT < 2)
    {
        // 填充测试数据2
    }
    if (XXXTestOPT < 3)
    {
        // 填充测试数据3
    }
    if (XXXTestOPT < 4)
    {
        // 填充测试数据4
    }

    TArray<uint8> EncodeData
    EncodeData.SetNum(Encode.ByteSizeLong()); 
    if (!Encode.SerializeToArray(EncodeData.GetData(), EncodeData.Num()))
    {
        // ...
        return;
    }

    AIStateRequest Decode;
    if (!Decode.ParseFromArray(EncodeData.GetData(), EncodeData.Num()))
    {
        // ...
        return;
    }
    // 数据校验
}

运行测试函数时，使用GDB修改静态变量 XXXTestOPT，发现当不设置 diff_state 时，数据不出错，一旦设置了序列化的数据就会出错。将序列化的二进制通过 GDB 打印下来，并写了一个简单的测试程序进行分析。

通过测试程序的分析，了解到 PB 序列化规则。相关代码:

// ccs_ai_api.pb.cc 
uint8_t* AIStateRequest::_InternalSerialize(
    uint8_t* target, ::PROTOBUF_NAMESPACE_ID::io::EpsCopyOutputStream* stream) const {
  // @@protoc_insertion_point(serialize_to_array_start:AIStateRequest)
  uint32_t cached_has_bits = 0;
  (void) cached_has_bits;

  // string episode_id = 1;
  if (!this->_internal_episode_id().empty()) {
    // ...
  }

  // .AIStateInfo state = 2;
  if (this->_internal_has_state()) {
    // ...
  }

  // .DiffAIStateInfo diff_state = 3;
  if (this->_internal_has_diff_state()) {
    target = stream->EnsureSpace(target);
    target = ::PROTOBUF_NAMESPACE_ID::internal::WireFormatLite::
      InternalWriteMessage(
        3, _Internal::diff_state(this), target, stream);
  }
  // ...
}

// wire_format_lite.h
template <typename MessageType>
inline uint8_t* WireFormatLite::InternalWriteMessage(
    int field_number, const MessageType& value, uint8_t* target,
    io::EpsCopyOutputStream* stream) {
  target = WriteTagToArray(field_number, WIRETYPE_LENGTH_DELIMITED, target);
  target = io::CodedOutputStream::WriteVarint32ToArrayOutOfLine(
      static_cast<uint32_t>(value.GetCachedSize()), target);
  return value._InternalSerialize(target, stream);
}

如果某个字段没有被赋值，PB 将不序列化该字段(if (this->_internal_has_diff_state()))。如果被赋值了，则其格式如下(WireFormatLite::InternalWriteMessage)：


字段Tag	数据大小	子字段1	子字段…
`WriteTagToArray`	`GetCachedSize`	_InternalSerialize	…

当 diff_state 没有被赋值时，序列化数据中没有 diff_state 数据，因此反序列化没有问题。

但是当 diff_state 被赋值时，其数据大小却为 0，这导致在反序列化时，diff_state 的子字段会重设 episode_id 的值，从而导致错误。

对应以上代码，有两种可能:

执行target = io::CodedOutputStream::WriteVarint32ToArrayOutOfLine(static_cast<uint32_t>(value.GetCachedSize()), target);时写入了0
后续有逻辑导致地址target指向的数据被改写为0。

依旧怀疑是内存越界问题，由于开启了优化，很多变量无法查看，所以建议关掉优化OptimizeCode = CodeOptimization.Never;，做个版本再看一下, 然而禁用优化后，新版本测试程序没有出错。

今日结论:

已经找到了序列化错误偶现的原因：即在包含diff_state字段的情况下，序列化出的数据会出现错误；
需要继续查找 diff_state 序列化数据大小为零的问题；
经过模块禁用优化后，无法再次重现出问题；
后续需要在启用了优化的版本上进行更多验证，因此需要申请分支权限和搭建本地构建环境。

Day3

今天主要在取版本、编译和构建项目。

在等待的过程中，将代码集成到 UE 的小工程中，然而并没能重现问题。

为了能发现潜在的问题，还编译了ASan版本并执行了测试，也没有发现异常。

Day4

今天计划在本机构建机上重现问题, 查diff_state序列化数据大小为0的问题.

目前，在开发分支上的版本已删除了测试函数。

本地构建成功后，重新启用测试函数，但无法重现问题；
尝试回滚到之前出现问题的版本，但仍然无法重现问题；
因此，请客户端同学重新提交带有测试函数的代码，构建机编译版本重现问题；
紧接着将本地代码更新到最新版，本地环境也成功地重现了问题。

为了进一步排查问题，首先修改XXXTest函数，在调用 Encode.SerializeToArray 前通过日志输出diffstate的GetCachedSize()。编译运行后问题依旧存在，并且GetCachedSize()返回值为11，是正确的数值。

接着修改了ccs_ai_api.pb.cc，在序列化diff_state前，使用日志输出了diffstate的GetCachedSize()，编译运行后发现问题不再重现。

本地的所有更改回滚，再次编译运行，发现问题也不再重现。

此处省略了几个小时在本机尝试如何重现问题的过程，比如: 对比构建机和本机的构建参数，尝试在本机上重现问题; 在本机回滚所有改动依旧无法重现时, 尝试删除构建缓存之类方法, 但都没有获得有效结果。

幸好现在已经有了相同代码的有问题版本和无问题版本，当前问题是, 到底是WriteVarint32ToArrayOutOfLine写入了0呢? 还是写入了正确的数据大小, 但后面的逻辑修改这块内存呢?

首先在Encode.SerializeToArray前将EncodeData的缓冲区全设置为0, 这样方便我使用GDB观察当前内存的变化, 其次查看反汇编代码, 这样方便知道哪行指令时出错了。

经过一番调试, 确定是WriteVarint32ToArrayOutOfLine写入了0,

; 正确版本, 执行该语句后%edi值为11
mov    0x12c(%r12),%edi
; 出错版本, 执行该语句后%edi值为0, 此时将%edi设置为11, 得到的序列化数据正确
mov    0x114(%r12),%edi

这句话的意思是将diffstate成员变量_cached_size_得值放在%edi中， %r12是diffstate的地址， 0x114(十进制276)或0x12c(十进制300)是变量的偏移值。

当前版本的sizeof(DiffAIStateInfo)为304，所以偏移0x12c是对的，但是为什么错误版本的偏移是0x114呢（反推出sizeof(DiffAIStateInfo)为280）？

我留意到Day2的测试程序中sizeof(DiffAIStateInfo)为280，从而推断应当是数据结构定义不一致导致的。

通过objdump反汇编.o文件，找到0x12c(%r12)存在于ccs_ai_api.pb.cc.o中。

去构建机上发现，ccs_ai_api.pb.cc.o修改日期是5月24日，但是ccs_ai_state.pb.cc.o的修改日期是5月26日, 因为客户端同学5月26日修改了ccs_ai_state.pb.cc和ccs_ai_state.pb.h。

因为ccs_ai_api.pb.h依赖了ccs_ai_state.pb.h, 所以在5月26日应当重新生成ccs_ai_api.pb.cc.o，但并没有重新编译，所以产生了链接了偏移值不正确的程序。

今日结论:

已确定 diff_state 序列化数据大小为零的原因是 ccs_ai_api.pb.cc 在 ccs_ai_state.pb.h 变更后未能触发重新编译导致的。

Day5

今天的主要分析 ccs_ai_api.pb.cc 在依赖头文件发生更改后，没有重新编译的问题。

在 UBT 中，函数 IsActionOutdated 用来判断是否需要重新编译源文件，其判断条件有三个：

编译命令是否变化；
源文件是否变化；
依赖的头文件是否有变化(变量CachedIncludePaths)；

然而，*.cc 的缓存依赖头文件变量 CachedIncludePaths 为 null，因为在 CachePCHUsageForModuleSourceFiles 中只会给扩展名为 .cpp 的源文件赋值该变量。

通过给函数 GatherAllOutdatedActions 增加下面的日志，验证此问题的确存在。

void GatherAllOutdatedActions(BuildConfiguration BuildConfiguration, UEBuildTarget Target, CPPHeaders Headers, ActionHistory ActionHistory, ref Dictionary<Action, bool> OutdatedActions, Dictionary<UEBuildTarget, List<FileItem>> TargetToOutdatedPrerequisitesMap)
{
    DateTime CheckOutdatednessStartTime = DateTime.UtcNow;

    foreach (Action Action in AllActions)
    {
        var bIsOutdated = IsActionOutdated(BuildConfiguration, Target, Headers, Action, OutdatedActions, ActionHistory, TargetToOutdatedPrerequisitesMap);
        // 验证日志
        if (Action.StatusDescription.Contains("pb.cc"))
        {
            Log.TraceInformation("pb Action:{0} CachedIncludePaths:{1} bIsOutdated:{2}", 
                Action.StatusDescription,
                Action.PrerequisiteItems[0].CachedIncludePaths != null? Action.PrerequisiteItems[0].CachedIncludePaths.ToString() : "null",
                bIsOutdated
            );
        }
    }

    if (UnrealBuildTool.bPrintPerformanceInfo)
    {
        double CheckOutdatednessTime = (DateTime.UtcNow - CheckOutdatednessStartTime).TotalSeconds;
        Log.TraceInformation("Checking actions for " + Target.GetTargetName() + " took " + CheckOutdatednessTime + "s");
    }
}

在 Day2 中，禁用了优化模块的尝试，导致编译命令的改变，从而触发了 *.pb.cc 的重编。(重编条件1)

原因分析清楚后，找到了必现该问题的方法：

回滚代码到 ccs_ai_state.pb.cc 改动前的版本；
删除 Intermediate\Build\Linux\...\*.pb.cc.o 目录中的编译好的 object 文件；
编译代码，并记录下 ccs_ai_api.pb.cc.o 和 ccs_ai_state.pb.cc.o 的编译时间；
将代码更新到 ccs_ai_state.pb.cc 改动后的版本；
再次编译代码，此时 ccs_ai_api.pb.cc.o 的编译时间不应该改变，但是 ccs_ai_state.pb.cc.o 的编译时间应该是当前时间。

今日结论:

在 UE4.18 中，UBT 对于 *.cc 的头文件依赖没有准确处理，这会导致增量编译存在问题。具体而言，如果某个 *.cc 文件依赖的头文件发生了变化，将不会触发该文件的重新编译，从而导致编译结果不正确。

修复方案

UE4.21已经简单地修复这个问题，因此尝试将UE4.21的更改合并到项目中。

github 修复提交记录: Fix CachedIncludePaths not being set correctly for modules which do n…

本文链接, 未经许可，禁止转载