Android Native中SO库日志被liblog替代的原因排查

核心现象 #

你的wnsservice模块日志偶发被liblog的日志（如I liblog : 8、I liblog : 1）替代，线程运行正常但日志输出异常，这种情况大概率和以下几个原因相关：

可能原因 #

1. 日志打印频率过高引发缓冲区竞争/溢出 #

从你提供的日志来看，10ms内就有多条wnsservice日志输出，频率确实很高。Android的liblog内部维护了日志缓冲区，当短时间内大量日志写入时：

• 缓冲区可能出现溢出，导致部分日志被截断，liblog会输出异常标识（那些数字可能是内部错误码或溢出后的残留值）；
• 高频率下多线程调用日志打印函数，即使函数本身线程安全，也可能触发内部缓冲区的并发处理bug，导致日志的模块标识（tag）被错误替换为liblog。

2. 日志格式化参数不匹配 #

如果SO中的日志打印代码存在格式化字符串与参数不匹配的情况（比如用%d却传入字符串、参数数量少于格式化占位符），会导致liblog解析日志时出错，偶发输出异常内容。这种情况因为只影响日志打印，不会中断线程运行，所以会出现线程正常但日志异常的现象。

3. 系统liblog版本兼容性问题 #

不同Android版本的liblog实现存在差异，部分旧版本或特定版本的liblog在处理高频日志、特殊格式日志时存在bug，会导致日志tag被错误替换为liblog。

排查建议 #

• 降低日志频率：把高频调试日志改成条件输出（如仅debug模式打印、间隔固定时间打印），验证是否还出现异常，确认是否由频率过高导致；
• 检查日志代码：逐行核对wnsservice的日志打印函数，确保格式化字符串和参数完全匹配，无类型错误或参数遗漏；
• 跨版本测试：在不同Android版本的设备上测试，排查是否为特定系统版本的兼容性问题；
• 优化日志输出：改用批量日志缓存后统一输出的方式，减少直接调用liblog的次数，降低并发冲突概率。

附用户提供的异常日志 #

16:32:00.141 210 1713 D wnsservice: Thread-Working(active): cur.pion
16:32:00.141   210  1713 D wnsservice: Thread-Working(active): cur.ler
16:32:00.141   210  1713 D wnsservice: Thread-Working(active): end one time calculate
16:32:00.141   210  1713 D wnsservice: Thread-Working(active): resultQueue(in)
16:32:00.151   210  1713 I liblog  : 8
16:32:00.151   210  1713 D wnsservice: Thread-Working(active): rec
16:32:00.151   210  1713 D wnsservice: Thread-Working(active): cur.veoc
16:32:00.151   210  1713 D wnsservice: Thread-Working(active): cur.pion
16:32:00.151   210  1713 D wnsservice: Thread-Working(active): end one time calculate
16:32:00.151   210  1713 D wnsservice: Thread-Working(active): resultQueue(in)
16:32:00.151   210  1713 I liblog  : 1
16:32:00.160   210  1713 D wnsservice: Thread-Working(active): datasqueue(out)
16:32:00.160   210  1713 D wnsservice: Thread-Working(active): calculate ler by data
16:32:00.160   210  1713 D wnsservice: Thread-Working(active): time gap

内容的提问来源于stack exchange，提问作者李跃禄