Kernel crash in free_pipe_info()

From: Cong Wang
Date: Mon Oct 30 2017 - 16:59:00 EST


Hi, Linus


We got more than a dozen of kernel crashes at free_pipe_info() on our
4.1 kernel, they are all very similar to this one (with slightly
different faulty addresses):


[433948.755473] BUG: unable to handle kernel paging request at 000000010000000d
[433948.762570] IP: [<ffffffff8117660c>] free_pipe_info+0x54/0x85
[433948.768493] PGD 0
[433948.770537] Oops: 0000 [#1] SMP
[433948.773768] Modules linked in: sch_htb cls_basic act_mirred
cls_u32 veth sch_ingress fuse cpufreq_ondemand intel_rapl iosf_mbi
x86_pkg_temp_thermal coretemp kvm_intel kvm iTCO_wdt
iTCO_vendor_support dcdbas microcode sb_edac wmi edac_core i2c_i801
hed lpc_ich mfd_core ioatdma shpchp lp parport tcp_diag inet_diag
ipmi_si ipmi_devintf ipmi_msghandler acpi_cpufreq sch_fq_codel xfs
libcrc32c crc32c_intel igb ptp pps_core i2c_algo_bit dca i2c_core ipv6
[433948.813421] CPU: 10 PID: 50667 Comm: rsync Not tainted 4.1.41.el7.x86_64 #1
[433948.821498] Hardware name: Dell Inc. PowerEdge C6220/03C9JJ, BIOS
2.2.3 11/07/2013
[433948.829247] task: ffff880f47fde240 ti: ffff880d282d8000 task.ti:
ffff880d282d8000
[433948.836770] RIP: 0010:[<ffffffff8117660c>] [<ffffffff8117660c>]
free_pipe_info+0x54/0x85
[433948.845088] RSP: 0018:ffff880d282dbd98 EFLAGS: 00010202
[433948.850473] RAX: 00000000fffffffd RBX: ffff8817e7692240 RCX:
00000000000002c5
[433948.857603] RDX: 00000000000002c6 RSI: ffff8817c30be540 RDI:
ffff8817e7692240
[433948.864881] RBP: ffff880d282dbda8 R08: 0000000000000000 R09:
0000000000000000
[433948.871988] R10: ffff880c474a0c60 R11: ffff8812c3c44310 R12:
0000000000000008
[433948.879224] R13: ffff88182d8a9100 R14: ffff880c47b981a0 R15:
ffff88182d8a9100
[433948.886514] FS: 0000000000000000(0000) GS:ffff88184ee80000(0000)
knlGS:0000000000000000
[433948.894678] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[433948.900609] CR2: 000000010000000d CR3: 0000000001a0b000 CR4:
00000000000406e0
[433948.907840] Stack:
[433948.909876] ffff88182d8a9100 ffff8817e7692240 ffff880d282dbdc8
ffffffff8117668e
[433948.917331] ffff8817e7692240 ffff8812c3c44300 ffff880d282dbdf8
ffffffff8117672a
[433948.924799] 0000000000000000 ffff8812c3c44300 0000000000000010
ffff88182d8a9100
[433948.932234] Call Trace:
[433948.934780] [<ffffffff8117668e>] put_pipe_info+0x51/0x56
[433948.940320] [<ffffffff8117672a>] pipe_release+0x97/0xa1
[433948.945734] [<ffffffff811707ff>] __fput+0xf9/0x1b8
[433948.950747] [<ffffffff811708f6>] ____fput+0xe/0x10
[433948.955665] [<ffffffff8107f118>] task_work_run+0x8a/0xa1
[433948.961121] [<ffffffff8106acb6>] do_exit+0x400/0x8ba
[433948.966224] [<ffffffff8116f057>] ? fdput_pos.isra.10+0x29/0x30
[433948.972306] [<ffffffff8106b1eb>] do_group_exit+0x44/0x98
[433948.977847] [<ffffffff8106b253>] SyS_exit_group+0x14/0x14
[433948.983423] [<ffffffff81527757>] system_call_fastpath+0x12/0x6a
[433948.989477] Code: 8b bb 88 00 00 00 e8 73 a5 ef ff 44 3b 63 48 73
22 49 63 f4 48 6b f6 28 48 03 b3 80 00 00 00 48 8b 46 10 48 85 c0 74
06 48 89 df <ff> 50 10 41 ff c4 eb d8 48 8b 7b 68 48 85 ff 74 07 31 f6
e8 be
[433949.008413] RIP [<ffffffff8117660c>] free_pipe_info+0x54/0x85
[433949.014335] RSP <ffff880d282dbd98>
[433949.017850] CR2: 000000010000000d
[433949.021820] ---[ end trace 95f92776b6f34085 ]---


For this one, the IP maps to fs/pipe.c:651

642 void free_pipe_info(struct pipe_inode_info *pipe)
643 {
644 int i;
645
646 account_pipe_buffers(pipe, pipe->buffers, 0);
647 free_uid(pipe->user);
648 for (i = 0; i < pipe->buffers; i++) {
649 struct pipe_buffer *buf = pipe->bufs + i;
650 if (buf->ops)
651 buf->ops->release(pipe, buf);
652 }
653 if (pipe->tmp_page)
654 __free_page(pipe->tmp_page);
655 kfree(pipe->bufs);
656 kfree(pipe);
657 }

And the faulty instruction is:

All code
========
0: 8b bb 88 00 00 00 mov 0x88(%rbx),%edi
6: e8 73 a5 ef ff callq 0xffffffffffefa57e
b: 44 3b 63 48 cmp 0x48(%rbx),%r12d
f: 73 22 jae 0x33
11: 49 63 f4 movslq %r12d,%rsi
14: 48 6b f6 28 imul $0x28,%rsi,%rsi
18: 48 03 b3 80 00 00 00 add 0x80(%rbx),%rsi
1f: 48 8b 46 10 mov 0x10(%rsi),%rax
23: 48 85 c0 test %rax,%rax
26: 74 06 je 0x2e
28: 48 89 df mov %rbx,%rdi
2b:* ff 50 10 callq *0x10(%rax) <--
trapping instruction
2e: 41 ff c4 inc %r12d
31: eb d8 jmp 0xb
33: 48 8b 7b 68 mov 0x68(%rbx),%rdi
37: 48 85 ff test %rdi,%rdi
3a: 74 07 je 0x43
3c: 31 f6 xor %esi,%esi

It looks like pipe->bufs was already freed for some reason. The code
is pretty solid, I can't find out any bug, as there should be only one
thread could invoke free_pipe_info().

Kdump is not properly setup on this host, so unfortunately I can't
inspect further on struct pipe_inode_info in memory.

Although it is too early to blame your commit b0d8d2292160 ("vfs: fix
subtle use-after-free of pipe_inode_info"), it is probably related.

Please let me know if I could provide any other information.

BTW, there is a similar (if not same) bug report on a much newer kernel:
https://www.spinics.net/lists/kernel/msg2616441.html

Thanks!