📚 课程目录第4章加解密流程日志

4. 加解密流程日志：加密前、解密后与中间状态

说实话，排查加解密问题最怕什么？最怕日志不全。

你拿到一个加密失败的报错，打开日志一看，只有一行“解密失败”。这是让人抓狂的。我这些年处理过的类似 case，十有八九都是日志细节不够，导致排查时间翻了好几倍。

所以今天我们就好好聊聊，加解密流程里的日志到底该怎么打。我会把加密前数据、解密后数据、还有中间状态（比如 IV 生成）这三个关键节点的记录方法，掰开了讲清楚。

4.1 加密前数据记录：别漏掉上下文

加密前数据，说白了就是你要保护的原始内容。记录它的时候，有几点必须注意。

记录原始长度：光看内容还不够，长度往往是发现问题的线索。我曾经遇到一个 case，加密前数据末尾有个不可见字符，长度跟接口文档差了 1 个字节，直接导致解密后末尾多了一段乱码。
记录数据来源：是来自网络请求、本地文件、还是内存分配？我在项目中遇到过一个 bug，同样的数据从不同模块来，加密结果居然不一样——后来发现其中一个模块做了隐式的编码转换。
避免记录敏感信息：嗯，这里要注意。明文密钥、用户密码之类的，千万别直接打出来。我习惯对敏感数据做部分掩码处理，比如只显示前 4 个字节的 hex 值。

避坑指南：加密前日志不要包含完整的明文密码或私钥。我曾经在一个合规审计中发现某系统直接在日志里打印了 RSA 私钥，后果非常严重。建议在记录前用哈希或掩码处理。

// 伪代码示例：加密前数据记录
void log_before_encrypt(const uint8_t* data, size_t len, const char* source) {
    // 记录来源和长度
    printf("[ENCRYPT_PRE] source=%s, len=%zu\n", source, len);
    
    // 记录前16字节的hex，用于追踪
    size_t display_len = (len > 16) ? 16 : len;
    printf("[ENCRYPT_PRE] data_preview(hex): ");
    for (size_t i = 0; i < display_len; i++) {
        printf("%02x", data[i]);
    }
    printf("\n");
    
    // 记录完整数据的哈希值，用于一致性校验
    uint8_t hash[SHA256_DIGEST_LENGTH];
    sha256(data, len, hash);
    printf("[ENCRYPT_PRE] sha256: ");
    for (int i = 0; i < SHA256_DIGEST_LENGTH; i++) {
        printf("%02x", hash[i]);
    }
    printf("\n");
}

4.2 解密后数据校验：让问题暴露更早

解密完成后，很多人直接就把数据用了，日志只打个“成功”。我的习惯是，解密后必须做三重校验。

校验类型	日志内容	常见异常模式
长度校验	解密后数据长度	长度与预期不符 → 可能是填充错误
哈希校验	解密后数据的 SHA256	与加密前哈希不一致 → 数据被篡改或 IV 不对
格式校验	是否是合法 JSON/二进制协议头	格式解析失败 → 算法或密钥不匹配

你想想看，如果解密后的数据长度都多出来 16 字节，那肯定是 PKCS7 填充的问题，根本不需要去看算法代码。

实用技巧：我习惯在解密后立刻做一次哈希对比。如果加密前日志记录了原始数据的哈希，解密后立刻算一下，两行日志排在一起，一眼就能看出有没有出问题。这比事后分析快得多。

4.3 中间状态日志：IV 生成是重灾区

中间状态里，IV（初始化向量）是最容易出问题的。我遇到过的坑包括：IV 重复使用、IV 长度不对、IV 生成方式不一致。

IV 生成方式：是随机生成？还是基于计数器？还是固定值？这些都要在日志里明确记录。我记得有一次排查一个跨平台的加密 bug，Windows 端和 Linux 端用了不同的 IV 生成策略，结果两边加解密出来的数据对不上。
IV 的具体值：把 IV 的 hex 值打出来。哪怕只打印前 8 字节，也足够定位问题。我习惯把完整的 IV 打印到日志里，因为它本身不是秘密，但又是解密的关键。
IV 的关联数据：这个 IV 是跟哪个密文绑定的？如果是一个会话里有多个加密操作，IV 必须跟对应的数据块一一对应。我曾经见过一个 MQTT 消息系统，每条消息的 IV 居然是从全局计数器里取的，结果并发一高，IV 重复了，整个通道全乱套。

// 伪代码示例：IV生成日志记录
void log_iv_generation(iv_ctx_t* ctx, const uint8_t* iv, size_t iv_len) {
    printf("[IV_GEN] method=%s", ctx->method);  // 随机/计数器/固定
    printf(", iv_len=%zu", iv_len);
    printf(", iv_hex=");
    for (size_t i = 0; i < iv_len; i++) {
        printf("%02x", iv[i]);
    }
    printf("\n");
    
    // 如果是基于计数器的IV，记录计数器值
    if (ctx->method == IV_COUNTER) {
        printf("[IV_GEN] counter=%llu\n", ctx->counter);
    }
}

4.4 核心流程：三级日志闭环体系

说了这么多，我总结一下自己常用的三级日志闭环体系。说白了，就是加密前、中间态、解密后各打一条日志，三条日志通过一个唯一的 transaction ID 串联起来。

  核心思想：每一条加密操作，都生成一个全局唯一的 trans_id，加密前、IV生成、解密后三条日志都要带上这个 ID。这样不管日志散落在多少个文件里，用 grep 一搜 trans_id，整个链路就出来了。

下面这张图展示了我常用的加解密日志流程结构：

出了问题时，我一般这么查：先按 trans_id 把三条日志找出来，然后逐一核对。加密前数据的哈希跟解密后数据的哈希对不上？那就是加解密流程出了偏差。IV 日志里发现生成方式跟预期的不一样？那问题大概率出在调用的接口上。

我的习惯：我一般在项目的日志配置里专门加一个 "CRYPTO_TRACE" 的日志级别，比 DEBUG 还低一级。这样平时默认不打印，一旦需要排查问题，动态调一下日志级别，所有加密细节就全出来了。不影响生产性能，又能保证排查手段。

4.5 实战中常见的日志异常模式

最后列几个我实际遇到过的问题模式，你们排查时可以参考：

加密前日志显示长度 64，解密后日志显示长度 80：典型填充问题。我遇到过一次是因为调用方用了 PKCS7 填充，但日志里看填充模式写的是 NoPadding。
IV 日志显示生成方法为 "random"，但多次加密的 IV 值完全相同：伪随机数生成器没有正确初始化。我曾经在一个嵌入式项目里发现，系统启动时没有给 RNG 喂熵源，结果每次加密都产生相同的 IV。
加密前日志里有数据，解密后日志里直接"解密失败"：大概率是密钥问题。我建议在日志里记录密钥的 ID 或版本号，而不是密钥本身。这样一眼就能看出是不是密钥轮转导致的。
解密后的格式校验通过，但哈希比对失败：这个比较隐蔽。我遇到过的是加密前数据在传输过程中被中间件做了隐式的换行符转换，所以解密后的数据虽然格式正确，但跟原始内容差了几个字节。

先记下这些套路。后面几章我们还会结合实际代码，一步步把这些日志逻辑落地到项目里。