警告背后的use after free

问题背景：

工模测试出现自动重启。

分析过程：

用GAT解开db，并结合对应的vmlinux（该文件必须和db一致，具体请看FAQ06985），利用工具E-Consulter分析（也可以参考FAQ13941），分析里几个db发现都是内存踩坏，随机踩，这种情况要么是软件引入的，要么是硬件故障。

做以下调查：

1. 单体复现还是多台机器出现？
2. 什么时候出现？之前是否就存在？
3. 复现概率？

反馈的结果：

1. 多台机器出现。
2. 最近才出现。
3. 基本上1、2小时即可打出来。

这种情况，最快的是回溯版本，因此建议如下：

1. 检查会复现和不会复现的版本对比，细分版本验证，找出引起问题的改动。
2. 在所有版本导入如下修改，用于抓取内存乱踩故障，加速定位问题：FAQ14614 如何用MMU保护buddy system？
3. 检查2个版本的patch。

在第2步导入，同时切换eng版本，再次抓到问题点，E-Consulter工具分析结果如下：

== 异常报告v1.4(仅供参考) ==
详细描述: 断言失败{主动调用BUG()/BUG_ON()}，请结合崩溃进程调用栈检查相关代码
异常时间: 4182.704223秒, Thu Apr 14 19:00:59 CST 2016

== CPU信息 ==
崩溃CPU信息:
 CPU8: 进程名: hps_main, 进程标识符(pid): 208, 中断: 关
 本地调用栈:
 vmlinux object_err(s=0xFFFFFFC04E601180, page=0xFFFFFFBE016F9618, object=0xFFFFFFC029065400) + 104 <mm/slub.c:738>
 vmlinux free_debug_processing(s=0xFFFFFFC04E601180, page=0xFFFFFFBE016F9618, object=0xFFFFFFC029065400, addr=-274874499176, flags=0xFFFFFFC06A5AB418) + 792 <mm/slub.c:1163>
 vmlinux __slab_free(s=0xFFFFFFC04E601180, page=0xFFFFFFBE016F9618, x=0xFFFFFFC029065400, addr=-274874499176) + 696 <mm/slub.c:2632>
 vmlinux slab_free() + 528 <mm/slub.c:2778>
 vmlinux kfree(x=0xFFFFFFC029065400) + 720 <mm/slub.c:3443>
 vmlinux kobject_cleanup() + 160 <lib/kobject.c:631>
 vmlinux kobject_release(kref=0xFFFFFFC065FC8A90) + 172 <lib/kobject.c:654>
 vmlinux kref_sub() + 24 <include/linux/kref.h:74>
 vmlinux kref_put() + 24 <include/linux/kref.h:99>
 vmlinux kobject_put(kobj=0xFFFFFFC065FC8A58) + 56 <lib/kobject.c:671>
 vmlinux cpufreq_cpu_put(policy=0xFFFFFFC065FC8980) + 12 <drivers/cpufreq/cpufreq.c:239>
 vmlinux cpufreq_cpu_put() + 36 <drivers/cpufreq/cpufreq.c:2197>
 vmlinux cpufreq_get_policy(policy=0xFFFFFFC06A5AB5F8) + 92 <drivers/cpufreq/cpufreq.c:2195>
 vmlinux cpu_hotplug_handler(nb=cpu_hotplug, val=2, data=8) + 236 <drivers/misc/mediatek/sched/rq_stats.c:490>
 vmlinux notifier_call_chain() + 132 <kernel/notifier.c:124>
 vmlinux __raw_notifier_call_chain(nr_to_call=-1, nr_calls=0) + 8 <kernel/notifier.c:445>
 vmlinux __cpu_notify() + 24 <kernel/cpu.c:260>
 vmlinux cpu_notify(val=2, v=8) + 32 <kernel/cpu.c:268>
 vmlinux _cpu_up(cpu=8, tasks_frozen=0) + 520 <kernel/cpu.c:630>
 vmlinux _cpu_up_profile() + 24 <kernel/cpu.c:654>
 vmlinux cpu_up(cpu=8) + 152 <kernel/cpu.c:710>
 vmlinux hps_algo_do_cluster_action(cluster_id=2) + 376 <drivers/misc/mediatek/base/power/mt6797/mt_hotplug_strategy_algo.c:221>
 vmlinux hps_algo_main() + 1512 <drivers/misc/mediatek/base/power/mt6797/mt_hotplug_strategy_algo.c:458>
 vmlinux _hps_task_main(data=0) + 328 <drivers/misc/mediatek/base/power/mt6797/mt_hotplug_strategy_core.c:216>
 vmlinux kthread(_create=0xFFFFFFC06A588200) + 224 <kernel/kthread.c:207>
 vmlinux ret_from_fork() + 16 <arch/arm64/kernel/entry.S:809>
 == 栈结束 ==
 对应汇编指令:
 行号 地址 指令 提示
 mm/slub.c
 738 : FFFFFFC0001D9EBC: MOV X0, #0xDEAD
 FFFFFFC0001D9EC4: STR W1, [X0] ; 进程停止在这里
 当时的寄存器值:
 X0: 000000000000DEAD, X1: 0000000000000AEE, X2: FFFFFFC06A5AB160, X3: 0000000000000003
 X4: 0000000000000007, X5: 0000000000000000, X6: FFFFFFC000115098, X7: 0000000000000001
 X8: 00000000000825F3, X9: 6D2F207461206572, X10: 646F432F61696465, X11: 383035314C412F65
 X12: 2F72657473616D5F, X13: 332D6C656E72656B, X14: 732F6D6D2F38312E, X15: 0000000000000020
 X16: 0000000000000020, X17: 0000000000000000, X18: 0000000000000047, X19: FFFFFFC029065400
 X20: FFFFFFBE016F9618, X21: FFFFFFC04E601180, X22: FFFFFFC04E600F00, X23: FFFFFFC06A5AB418
 X24: FFFFFFC00033FF98, X25: FFFFFFC06A5A8000, X26: FFFFFFC04E601180, X27: FFFFFFC06A5A8000
 X28: FFFFFFC029065400, X29: FFFFFFC06A5AB320, X30: FFFFFFC0001D9EBC, SP: FFFFFFC06A5AB320
 PC: FFFFFFC0001D9EC4

其他CPU信息:
 CPU0: 进程名: (null), 进程标识符(pid): 0
 寄存器异常: SP(0x0000000000000000)异常
 本地调用栈:
 ...... 0x0000000046011122()
 == 栈结束 ==

slub有问题了，检查kernel log：

[ 4182.646086]-(8)[208:hps_main]=============================================================================
[ 4182.647323]-(8)[208:hps_main]BUG kmalloc-64 (Tainted: G W ): Object already free
[ 4182.648405]-(8)[208:hps_main]-----------------------------------------------------------------------------
[ 4182.648405]
[ 4182.649883]-(8)[208:hps_main]INFO: Allocated in kobject_set_name_vargs+0x40/0xa4 age=2 cpu=8 pid=208
[ 4182.651056]-(8)[208:hps_main] alloc_debug_processing+0x184/0x194
[ 4182.651845]-(8)[208:hps_main] __slab_alloc.isra.57.constprop.66+0x6ac/0x6f4
[ 4182.652755]-(8)[208:hps_main] __kmalloc_track_caller+0x17c/0x2c0
[ 4182.653548]-(8)[208:hps_main] kvasprintf+0x60/0xa4
[ 4182.654187]-(8)[208:hps_main] kobject_set_name_vargs+0x3c/0xa4
[ 4182.654958]-(8)[208:hps_main] kobject_init_and_add+0x78/0xb4
[ 4182.655708]-(8)[208:hps_main] __cpufreq_add_dev.isra.23+0x490/0x870
[ 4182.656531]-(8)[208:hps_main] cpufreq_cpu_callback+0xe4/0x1b4
[ 4182.657289]-(8)[208:hps_main]INFO: Freed in kobject_release+0xb0/0x1a0 age=0 cpu=4 pid=404
[ 4182.658363]-(8)[208:hps_main] free_debug_processing+0x280/0x34c
[ 4182.659144]-(8)[208:hps_main] __slab_free+0x2b8/0x414
[ 4182.659816]-(8)[208:hps_main] kfree+0x2d0/0x318
[ 4182.660424]-(8)[208:hps_main] kobject_release+0xac/0x1a0
[ 4182.661128]-(8)[208:hps_main] kobject_put+0x38/0x6c
[ 4182.661779]-(8)[208:hps_main] cpufreq_cpu_put.part.17+0xc/0x28
[ 4182.662549]-(8)[208:hps_main] cpufreq_cpu_put+0x14/0x24
[ 4182.663243]-(8)[208:hps_main] show_all_time_in_state+0x1c8/0x264
[ 4182.664036]-(8)[208:hps_main]INFO: Slab 0xffffffbe016f9618 objects=16 used=12 fp=0xffffffc029065400 flags=0x0081
[ 4182.665347]-(8)[208:hps_main]INFO: Object 0xffffffc029065400 @offset=1024 fp=0xffffffc029065200
[ 4182.665347]
[ 4182.666694]-(8)[208:hps_main]Bytes b4 ffffffc0290653f0: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ
[ 4182.668102]-(8)[208:hps_main]Object ffffffc029065400: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ 4182.669490]-(8)[208:hps_main]Object ffffffc029065410: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ 4182.670879]-(8)[208:hps_main]Object ffffffc029065420: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ 4182.672267]-(8)[208:hps_main]Object ffffffc029065430: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b a5 kkkkkkkkkkkkkkk.
[ 4182.673655]-(8)[208:hps_main]Redzone ffffffc029065440: bb bb bb bb bb bb bb bb ........
[ 4182.674968]-(8)[208:hps_main]Padding ffffffc0290654c0: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ
[ 4182.676367]-(8)[208:hps_main]Padding ffffffc0290654d0: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ
[ 4182.677766]-(8)[208:hps_main]Padding ffffffc0290654e0: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ
[ 4182.679165]-(8)[208:hps_main]Padding ffffffc0290654f0: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ
[ 4182.680567]-(8)[208:hps_main]CPU: 8 PID: 208 Comm: hps_main Tainted: G B W 3.18.22+ #2
[ 4182.681703]-(8)[208:hps_main]Hardware name: MT6797M (DT)
[ 4182.682408]-(8)[208:hps_main]Call trace:
[ 4182.682942]-(8)[208:hps_main][] dump_backtrace+0x0/0x15c
[ 4182.683841]-(8)[208:hps_main][] show_stack+0x10/0x1c
[ 4182.684700]-(8)[208:hps_main][] dump_stack+0x74/0xb8
[ 4182.685554]-(8)[208:hps_main][] print_trailer+0x140/0x288
[ 4182.686465]-(8)[208:hps_main][] object_err+0x38/0x6c
[ 4182.687322]-(8)[208:hps_main][] free_debug_processing+0x318/0x34c
[ 4182.688320]-(8)[208:hps_main][] __slab_free+0x2b8/0x414
[ 4182.689209]-(8)[208:hps_main][] kfree+0x2d0/0x318
[ 4182.690033]-(8)[208:hps_main][] kobject_release+0xac/0x1a0
[ 4182.690955]-(8)[208:hps_main][] kobject_put+0x38/0x6c
[ 4182.691823]-(8)[208:hps_main][] cpufreq_cpu_put.part.17+0xc/0x28
[ 4182.692810]-(8)[208:hps_main][] cpufreq_get_policy+0x5c/0x78
[ 4182.693756]-(8)[208:hps_main][] cpu_hotplug_handler+0xec/0x190
[ 4182.694721]-(8)[208:hps_main][] notifier_call_chain+0x84/0x2d4
[ 4182.695685]-(8)[208:hps_main][] __raw_notifier_call_chain+0x8/0x14
[ 4182.696694]-(8)[208:hps_main][] cpu_notify+0x20/0x4c
[ 4182.697550]-(8)[208:hps_main][] _cpu_up+0x208/0x504
[ 4182.698396]-(8)[208:hps_main][] cpu_up+0x98/0x2fc
[ 4182.699222]-(8)[208:hps_main][] hps_algo_do_cluster_action+0x178/0x1ac
[ 4182.700272]-(8)[208:hps_main][] hps_algo_main+0x5e8/0xc20
[ 4182.701184]-(8)[208:hps_main][] _hps_task_main+0x148/0x2a8
[ 4182.702105]-(8)[208:hps_main][] kthread+0xe0/0xf8
[ 4182.702931]-(8)[208:hps_main]BUG: failure at /media/Code/AL1508_master/kernel-3.18/mm/slub.c:738/object_err()!

原因是hps_main要去调用cpufreq_cpu_put()函数时，发现kobject已经被释放掉了。

被谁释放掉呢？因为是eng版本，每个object都有记录分配和释放的调用栈，前面的log(上面的log)打印出了释放调用栈：

[ 4182.657289]-(8)[208:hps_main]INFO: Freed in kobject_release+0xb0/0x1a0 age=0 cpu=4 pid=404
[ 4182.658363]-(8)[208:hps_main] free_debug_processing+0x280/0x34c
[ 4182.659144]-(8)[208:hps_main] __slab_free+0x2b8/0x414
[ 4182.659816]-(8)[208:hps_main] kfree+0x2d0/0x318
[ 4182.660424]-(8)[208:hps_main] kobject_release+0xac/0x1a0
[ 4182.661128]-(8)[208:hps_main] kobject_put+0x38/0x6c
[ 4182.661779]-(8)[208:hps_main] cpufreq_cpu_put.part.17+0xc/0x28
[ 4182.662549]-(8)[208:hps_main] cpufreq_cpu_put+0x14/0x24
[ 4182.663243]-(8)[208:hps_main] show_all_time_in_state+0x1c8/0x264

是在show_all_time_in_state()里释放的，而申请的调用栈是：

[ 4182.649883]-(8)[208:hps_main]INFO: Allocated in kobject_set_name_vargs+0x40/0xa4 age=2 cpu=8 pid=208
[ 4182.651056]-(8)[208:hps_main] alloc_debug_processing+0x184/0x194
[ 4182.651845]-(8)[208:hps_main] __slab_alloc.isra.57.constprop.66+0x6ac/0x6f4
[ 4182.652755]-(8)[208:hps_main] __kmalloc_track_caller+0x17c/0x2c0
[ 4182.653548]-(8)[208:hps_main] kvasprintf+0x60/0xa4
[ 4182.654187]-(8)[208:hps_main] kobject_set_name_vargs+0x3c/0xa4
[ 4182.654958]-(8)[208:hps_main] kobject_init_and_add+0x78/0xb4
[ 4182.655708]-(8)[208:hps_main] __cpufreq_add_dev.isra.23+0x490/0x870
[ 4182.656531]-(8)[208:hps_main] cpufreq_cpu_callback+0xe4/0x1b4

是在__cpufreq_add_dev()申请的。

逻辑明显有问题，正常情况下释放应该是cpu_hotplug_handler()函数释放的。但是却在show_all_time_in_state提前释放了。怎么回事？仔细看了kernel log，发现前面紧跟一个warning：

[ 4182.626788]-(4)[404:sh]------------[ cut here ]------------
[ 4182.627533]-(4)[404:sh]WARNING: CPU: 4 PID: 404 at /media/Code/AL1508_master/kernel-3.18/include/linux/kref.h:47 kobject_get+0x60/0x6c()
[ 4182.629100]-(4)[404:sh]CPU: 4 PID: 404 Comm: sh Tainted: G W 3.18.22+ #2
[ 4182.630102]-(4)[404:sh]Hardware name: MT6797M (DT)
[ 4182.630744]-(4)[404:sh]Call trace:
[ 4182.631215]-(4)[404:sh][] dump_backtrace+0x0/0x15c
[ 4182.632049]-(4)[404:sh][] show_stack+0x10/0x1c
[ 4182.632841]-(4)[404:sh][] dump_stack+0x74/0xb8
[ 4182.633633]-(4)[404:sh][] warn_slowpath_common+0x8c/0xb8
[ 4182.634531]-(4)[404:sh][] warn_slowpath_null+0x14/0x20
[ 4182.635410]-(4)[404:sh][] kobject_get+0x5c/0x6c
[ 4182.636213]-(4)[404:sh][] cpufreq_cpu_get+0x84/0xd0
[ 4182.637058]-(4)[404:sh][] show_all_time_in_state+0x150/0x264
[ 4182.638000]-(4)[404:sh][] kobj_attr_show+0x10/0x24
[ 4182.638838]-(4)[404:sh][] sysfs_kf_seq_show+0xb0/0x184
[ 4182.639714]-(4)[404:sh][] kernfs_seq_show+0x24/0x30
[ 4182.640562]-(4)[404:sh][] seq_read+0x1ac/0x414
[ 4182.641351]-(4)[404:sh][] kernfs_fop_read+0x104/0x178
[ 4182.642222]-(4)[404:sh][] vfs_read+0x80/0x1a4
[ 4182.643000]-(4)[404:sh][] SyS_read+0x40/0xa0
[ 4182.643770]-(4)[404:sh]---[ end trace cb4b760c22a5de87 ]---

我们看下这个warning是哪里产生的，是kobject_get()，看下对应代码：

577struct kobject *kobject_get(struct kobject *kobj)
578{
579 if (kobj)
580 kref_get(&kobj->kref);
581 return kobj;
582}

41static inline void kref_get(struct kref *kref)
42{
43 /* If refcount was 0 before incrementing then we have a race
44 * condition when this kref is freeing by some other thread right now.
45 * In this case one should use kref_get_unless_zero()
46 */
47 WARN_ON_ONCE(atomic_inc_return(&kref->refcount) < 2);
48}

warning是kref_get()产生的，原因是kref->refcount = 0导致（如果为1，那么atomic_inc_return()返回的就是2了）。为0表示当前kobject可能正在被释放（竞争条件），代码的注释写的很清楚。

这个warning引起的后果很严重，很可能kobject_get()之后去使用了这个kobj（很可能被释放了）。

我们看下show_all_time_in_state()函数：

171static ssize_t show_all_time_in_state(struct kobject *kobj,
172 struct kobj_attribute *attr, char *buf)
173{
......
188 for (i = 0; i < all_freq_table->table_size; i++) {
189     freq = all_freq_table->freq_table[i];
190     len += scnprintf(buf + len, PAGE_SIZE - len, "\n%u\t\t", freq);
191     for_each_possible_cpu(cpu) {
192         policy = cpufreq_cpu_get(cpu);
193         if (policy == NULL)
194             continue;
195         all_stat = per_cpu(all_cpufreq_stats, policy->cpu);
196         index = get_index_all_cpufreq_stat(all_stat, freq);
197         if (index != -1) {
198             len += scnprintf(buf + len, PAGE_SIZE - len, "%llu\t\t", (unsigned long long)
200             cputime64_to_clock_t(all_stat->time_in_state[index]));
201         } else {
202             len += scnprintf(buf + len, PAGE_SIZE - len, "N/A\t\t");
204         }
205         cpufreq_cpu_put(policy);
206     }
207 }

cpufreq_cpu_get()和cpufreq_cpu_put()是成对出现的，并且这2个函数都是有cpufreq_driver_lock读写锁保护和cpufreq_rwsem信号量保护，代码没有问题啊。如果在这里的cpufreq_cpu_put()就将kobject给释放了，那么后面再去cpufreq_cpu_get()就是错误的内存了，必然导致踩内存问题，也就导致了这题随机KE。

我们再次回到创建kobject的地方：__cpufreq_add_dev()函数：

static int __cpufreq_add_dev(struct device *dev, struct subsys_interface *sif)
{
......
1192 policy = recover_policy ? cpufreq_policy_restore(cpu) : NULL;
1193 if (!policy) {
1194     recover_policy = false;
1195     policy = cpufreq_policy_alloc();
1196     if (!policy)
1197         goto nomem_out;
1198 }
1199
1240 down_write(&policy->rwsem);
1241 write_lock_irqsave(&cpufreq_driver_lock, flags);
1242 aee_record_cpufreq_cb_wrap(12);
1243 for_each_cpu(j, policy->cpus)
1244     per_cpu(cpufreq_cpu_data, j) = policy;
1245 write_unlock_irqrestore(&cpufreq_driver_lock, flags);
......
1299 if (!recover_policy) {
1300     ret = cpufreq_add_dev_interface(policy, dev);
1301     if (ret)
1302         goto err_out_unregister;
1303     blocking_notifier_call_chain(&cpufreq_policy_notifier_list, CPUFREQ_CREATE_POLICY, policy);
1305 }
......
}

911static int cpufreq_add_dev_interface(struct cpufreq_policy *policy, struct device *dev)
913{
914 struct freq_attr **drv_attr;
915 int ret = 0;
916
917 /* prepare interface data */
918 ret = kobject_init_and_add(&policy->kobj, &ktype_cpufreq, &dev->kobj, "cpufreq");
920 if (ret)
921     return ret;
......
}

代码明显有问题，在1244行就对cpufreq_cpu_data赋值了，而kobject在1300行才初始化。

有可能出现这样的场景：

1. 在1244行和1300行中间执行了show_all_time_in_state()函数的cpufreq_cpu_get()函数，导致kobject_get()产生warning。
2. 接着执行1300行的kobject的初始化。
3. 再执行show_all_time_in_state()函数的cpufreq_cpu_put()函数，将kobject释放。
4. 其他地方调用cpufreq_cpu_get()函数，由于该内存被释放，这里再去读写就变成了use after free了。内存被踩坏了。
5. 在cpu hotplug执行cpu_hotplug_handler()时会释放kobject，此时slub检查到已经被释放了，触发slub BUG_ON!!!

根本原因：

kernel BUG，已修复，git check in记录在这里。

解决方法：

初始化完policy后再去对cpufreq_cpu_data赋值。

结语：

对kernel任何异常都要仔细检查，很可能就是引起问题的凶手。