细节决定成败——我的日志去哪了？

概述

编写本文档的目的有两点。

• 本周遇到了一个日志丢失的问题，经过分析，觉得挺有意思的。向大家分享一下我的分析及解决思路。应该在很多项目中都会有该问题。
• 领导和我私下讨论过多次，当前的autodomain代码对文件读取的频率太高了,如何去避免这种资源的消耗。本文档也会给出参考解决方案。

问题复现流程—我的日志去哪了？

问题现象

        周三，长城项目提出了一个bug：升级包下载时，断电重启设备，会导致车机处于断电重连界面卡死，无法恢复。

        通过UE同事日志排查，界面卡住的原因是由于，重启后，UC反馈给UE 的状态机为downloading。所以车机界面会处于下载中，但UC没有通知下载进度（实际没有下载任务在进行，肯定不会抛进度给UE的），所有界面一直卡着，没有响应。

图一：UE同事的分析结果

        根据巧玲的分析，已经很到位了。问题在于：为什么重启之后，UC发过来的状态是下载中，而不是下载暂停。

问题分析及解决

        我们的代码框架中，OTA服务主控程序UC的初始化流程有一个状态机处理接口。用于处理重启前状态机，其中的一个逻辑：若当前状态机是downloading,且当前任务是常规任务，则将状态机置为downloadpause。并且这个逻辑是必然会走的。为什么我们反馈给UE downloading的状态呢？

猜测一：UE请求的FSM状态的时序发生错乱

        UE向UC获取FSM状态的时机,在UC初始化之前。此时FSM的状态还是重启前的downloading,因此UE获取到的状态为downloading。时序图如下：

图二：UE请求状态机时序错乱

        这种情况是存在的（因此代码逻辑上还是存在缺陷的，需要修改）。但是真实原因并不是该原因。因为，根据时序分析，最终FSM的状态会变成downloadpause。但实际上FSM的状态机一直处于downloading。

猜测二：分区挂载时序问题

        在我一筹莫展时，我发现了一个奇怪的现象。那就是我们UC版本号打印去哪了？

图三：UC初始化流程，版本号打印

        理论上，UC的版本号是必然会进行打印的。但是我通过日志排查，很多重启流程中，并没有该log打印。原因是什么呢？经过长时间的思考，怀疑到了分区挂载时序问题。

图四：长城车机的分区挂载信息

        上图中，我们可以得出，UC的缓存文件以及日志都是在/dev/block/mmcblk0p23文件系统中。那么是否可能是因为分区挂载实际滞后于UC初始化流程导致的呢？

图五：分区挂载时序异常

        抱着这样的猜测，我在UC代码中添加了该判断:若mmcblk0p23分区未挂载成功，则睡眠10秒，尝试10次。

图六：等待分区加载成功代码逻辑

        经过同事验证，问题终于解决了。并且UC遗失的日志，都完整记录在日志文件中了。

3. 思考，再思考

        本次暴露出来的问题，已经成功解决掉了。但是若再进一步思考，会发现本次问题的根因不是分区加载时序问题，而是分区加载后导致我们的状态机文件被修改导致的。

若用户恶意去修改我们的缓存文件或者其它原因，我们的缓存文件被修改了，一样会出现问题。

        如何从技术上解决这样的难题呢？我想到了互联网经常会用到的一个技术：内存数据库。知乎上有一篇文章写的很好，供参考:

缓存和数据库一致性问题，看这篇就够了 - 知乎 (zhihu.com)

        通过文章的阅读，了解到内存缓存的引入需要考虑并发，分布锁，延迟双删等技术。但是对于我们的业务真的需要吗？我们知道互联网涉及的的访问量及数据是巨大的。但是我们UC的业务很简单，并不涉及到并发（只有UC会进行修改文件内容）。因此我总结出以下方案。

方案一：

1. UC启动时。将磁盘中的数据全量同步至内存中。
2. read操作。从内存中读取，直接反馈。
3. write操作。先更新缓存，再同步至磁盘。

        这样我们避免在运行过程中，文件内容进行修改。导致流程异常。并且拥有磁盘文件自我恢复的能力。

缺点：

• 浪费内存。即使OTA处于空闲状态，我们依旧需要将缓存文件中的全量信息保存到内存中。（虽然可能不到100kb）
• 若不存在write操作。磁盘文件就不会恢复。

优化方案，增加以下两条属性：

• 为缓存信息增加时效性。当较长时间内没有进行访问的数据，我们可以同步到磁盘中，并从内存中删除。
• 定期同步内存至磁盘。

        以上仅是我当前提出的一种解决方案，相信肯定还存在一些遗漏，考虑不全面的地方，需要大家提出来，我们一起讨论。但是引入内存缓存的方式，我觉得是趋势所向。

4. 总结

通过该bug的分析过程。得出的经验如下：

1. 平时发现的异常，应该要及时去分析。

     最初在调试长城其它问题时，我就已经注意到部分启动日志没有打印的情况了。当时咨询过同事，说是安卓系统的原因，就没有深究了。现在想想，若是当时就去研究，提早发现问题，并解决。也不至于在项目收尾阶段再暴露出来，从而影响项目进度。所以，人不能偷懒，欠下的债最终会兜兜转转到自己身上的。哈哈~~~

       2. 依赖写文件记录OTA状态的方式风险较大，建议能够改善优化。