init_on_free breaks hibernate

init_on_free breaks hibernate

[Johannes Stezenbach]

Hi,

I upgraded the kernel on one of my machines to 5.3.18 (from 5.2.x)
and found it failed after resume from hibernate due to what seemed
to be memory corruption. I had a hunch it could be related to
CONFIG_INIT_ON_ALLOC_DEFAULT_ON or CONFIG_INIT_ON_FREE_DEFAULT_ON,
and a quick web search found this which seems to confirm:
https://bbs.archlinux.org/viewtopic.php?pid=1877845#p1877845

I rebuilt the kernel with CONFIG_INIT_ON_FREE_DEFAULT_ON disabled,
and hibernate works again.  I'm fine with this workaround and
just wanted to share this information.

The commit that introduces CONFIG_INIT_ON_FREE_DEFAULT_ON:
6471384af2a6 mm: security: introduce init_on_alloc=1 and init_on_free=1 boot options

FWIW, these errors made it into /var/log/kern.log after resume before
I had to press the reset button:


[ 3358.077382][ T6925] PM: hibernation exit
[ 3358.079444][ T7273] date[7273]: segfault at 9 ip 00007f140fac0fae sp 00007ffef896b1d0 error 6 in ld-2.29.so[7f140fabf000+1e000]
[ 3358.079462][ T7273] Code: 74 17 48 83 f8 22 77 d3 48 89 14 c1 48 8b 42 10 48 83 c2 10 48 85 c0 75 e9 49 8b 07 48 85 c0 74 71 49 8b 57 60 48 85 d2 74 04 <48> 01 42 08 49 8b 57 58 48 85 d2 74 04 48 01 42 08 49 8b 57 68 48
[ 3358.082454][ T2290] BUG: unable to handle page fault for address: ffffee07c6b58028
[ 3358.082463][ T2290] #PF: supervisor read access in kernel mode
[ 3358.082467][ T2290] #PF: error_code(0x0000) - not-present page
[ 3358.082470][ T2290] PGD 0 P4D 0 
[ 3358.082476][ T2290] Oops: 0000 [#1] PREEMPT SMP PTI
[ 3358.082481][ T2290] CPU: 3 PID: 2290 Comm: systemd-udevd Not tainted 5.3.18 #1
[ 3358.082484][ T2290] Hardware name: System manufacturer System Product Name/P8H77-V, BIOS 1905 10/27/2014
[ 3358.082491][ T2290] RIP: 0010:copy_page_range+0x412/0xae0
[ 3358.082496][ T2290] Code: f7 d8 48 31 d0 f6 c2 80 48 0f 45 cf 48 21 c8 4c 89 fb 48 c1 e8 06 48 03 05 0b 78 2c 01 48 c1 eb 09 48 21 ca 81 e3 f8 0f 00 00 <48> 8b 68 28 48 8b 05 03 78 2c 01 48 89 ef 48 01 d8 48 01 d0 49 89
[ 3358.082499][ T2290] RSP: 0018:ffffb52f002a7bc0 EFLAGS: 00010202
[ 3358.082504][ T2290] RAX: ffffee07c6b58000 RBX: 0000000000000958 RCX: 000fffffffe00000
[ 3358.082507][ T2290] RDX: 000f8dae52800000 RSI: 000ffffffffff000 RDI: 000fffffffe00000
[ 3358.082510][ T2290] RBP: ffff9c8f9169ce00 R08: 0000000000000001 R09: 0000000000000000
[ 3358.082513][ T2290] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000
[ 3358.082516][ T2290] R13: 000055622792b000 R14: 0000000000000000 R15: 000055622792b000
[ 3358.082520][ T2290] FS:  00007fd608a51880(0000) GS:ffff9c8f97c00000(0000) knlGS:0000000000000000
[ 3358.082523][ T2290] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 3358.082527][ T2290] CR2: ffffee07c6b58028 CR3: 00000002142a0002 CR4: 00000000001606e0
[ 3358.082530][ T2290] Call Trace:
[ 3358.082538][ T2290]  ? sched_clock_cpu+0x10/0xd0
[ 3358.082556][ T2290]  dup_mm+0x3b1/0x500
[ 3358.082566][ T2290]  copy_process+0x1920/0x1e10
[ 3358.082577][ T2290]  _do_fork+0x74/0x450
[ 3358.082584][ T2290]  ? __set_current_blocked+0x2b/0x50
[ 3358.082590][ T2290]  ? sched_clock+0x5/0x10
[ 3358.082594][ T2290]  ? sched_clock_cpu+0x10/0xd0
[ 3358.082598][ T2290]  ? sigprocmask+0x72/0xa0
[ 3358.082604][ T2290]  ? entry_SYSCALL_64_after_hwframe+0x3e/0xbe
[ 3358.082608][ T2290]  ? entry_SYSCALL_64_after_hwframe+0x3e/0xbe
[ 3358.082613][ T2290]  __se_sys_clone+0x6b/0x90
[ 3358.082622][ T2290]  do_syscall_64+0x50/0x120
[ 3358.082626][ T2290]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 3358.082631][ T2290] RIP: 0033:0x7fd608f90c50
[ 3358.082635][ T2290] Code: ed 0f 85 1b 01 00 00 64 4c 8b 0c 25 10 00 00 00 45 31 c0 4d 8d 91 d0 02 00 00 31 d2 31 f6 bf 11 00 20 01 b8 38 00 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 ac 00 00 00 41 89 c5 85 c0 0f 85 b9 00 00
[ 3358.082638][ T2290] RSP: 002b:00007ffc75fc5ab0 EFLAGS: 00000246 ORIG_RAX: 0000000000000038
[ 3358.082642][ T2290] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fd608f90c50
[ 3358.082645][ T2290] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000001200011
[ 3358.082648][ T2290] RBP: 0000000000000000 R08: 0000000000000000 R09: 00007fd608a51880
[ 3358.082652][ T2290] R10: 00007fd608a51b50 R11: 0000000000000246 R12: 0000000000000000
[ 3358.082655][ T2290] R13: 0000000000000000 R14: 0000000000000000 R15: 00007ffc75fc5b00
[ 3358.082664][ T2290] Modules linked in: uas mt76x0u mt76x0_common mt76x02_usb mt76_usb mt76x02_lib mt76 mac80211 kvm_intel cfg80211 kvm irqbypass xhci_pci ehci_pci xhci_hcd ehci_hcd
[ 3358.082679][ T2290] CR2: ffffee07c6b58028
[ 3358.082684][ T2290] ---[ end trace 132618ad38ffc1cb ]---
[ 3358.082689][ T2290] RIP: 0010:copy_page_range+0x412/0xae0
[ 3358.082692][ T2290] Code: f7 d8 48 31 d0 f6 c2 80 48 0f 45 cf 48 21 c8 4c 89 fb 48 c1 e8 06 48 03 05 0b 78 2c 01 48 c1 eb 09 48 21 ca 81 e3 f8 0f 00 00 <48> 8b 68 28 48 8b 05 03 78 2c 01 48 89 ef 48 01 d8 48 01 d0 49 89
[ 3358.082696][ T2290] RSP: 0018:ffffb52f002a7bc0 EFLAGS: 00010202
[ 3358.082699][ T2290] RAX: ffffee07c6b58000 RBX: 0000000000000958 RCX: 000fffffffe00000
[ 3358.082703][ T2290] RDX: 000f8dae52800000 RSI: 000ffffffffff000 RDI: 000fffffffe00000
[ 3358.082706][ T2290] RBP: ffff9c8f9169ce00 R08: 0000000000000001 R09: 0000000000000000
[ 3358.082708][ T2290] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000
[ 3358.082711][ T2290] R13: 000055622792b000 R14: 0000000000000000 R15: 000055622792b000
[ 3358.082715][ T2290] FS:  00007fd608a51880(0000) GS:ffff9c8f97c00000(0000) knlGS:0000000000000000
[ 3358.082718][ T2290] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 3358.082721][ T2290] CR2: ffffee07c6b58028 CR3: 00000002142a0002 CR4: 00000000001606e0
[ 3362.924200][ T3635] general protection fault: 0000 [#2] PREEMPT SMP PTI
[ 3362.924210][ T3635] CPU: 3 PID: 3635 Comm: xscreensaver Tainted: G      D           5.3.18 #1
[ 3362.924213][ T3635] Hardware name: System manufacturer System Product Name/P8H77-V, BIOS 1905 10/27/2014
[ 3362.924222][ T3635] RIP: 0010:copy_page_range+0x3ba/0xae0
[ 3362.924226][ T3635] Code: 83 e0 fb 48 83 f8 63 0f 85 a3 05 00 00 48 8b 44 24 38 48 c7 84 24 f8 00 00 00 00 00 00 00 48 c7 84 24 00 01 00 00 00 00 00 00 <48> 8b 10 48 f7 c2 9f ff ff ff 0f 84 9c 03 00 00 48 b9 00 f0 ff ff
[ 3362.924230][ T3635] RSP: 0018:ffffb52f003d7bc0 EFLAGS: 00010246
[ 3362.924234][ T3635] RAX: 000f9c8d3c0daf28 RBX: ffff9c8f9290c528 RCX: 0000000191c80067
[ 3362.924238][ T3635] RDX: fff0000000000fff RSI: 000ffffffffff000 RDI: ffff9c8f9434ef28
[ 3362.924241][ T3635] RBP: ffff9c8f91698d00 R08: 0000000000000001 R09: 0000000000000000
[ 3362.924244][ T3635] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000
[ 3362.924247][ T3635] R13: 00007f297cb60000 R14: 0000000000000000 R15: 00007f297cb60000
[ 3362.924250][ T3635] FS:  00007f297d20b7c0(0000) GS:ffff9c8f97c00000(0000) knlGS:0000000000000000
[ 3362.924254][ T3635] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 3362.924257][ T3635] CR2: 00007fe8b5d67000 CR3: 0000000214352005 CR4: 00000000001606e0
[ 3362.924260][ T3635] Call Trace:
[ 3362.924281][ T3635]  dup_mm+0x3b1/0x500
[ 3362.924290][ T3635]  copy_process+0x1920/0x1e10
[ 3362.924301][ T3635]  _do_fork+0x74/0x450
[ 3362.924308][ T3635]  ? preempt_count_sub+0xa1/0xe0
[ 3362.924315][ T3635]  ? _raw_spin_unlock_irq+0x34/0x50
[ 3362.924319][ T3635]  ? do_sigaction+0xf2/0x240
[ 3362.924324][ T3635]  ? entry_SYSCALL_64_after_hwframe+0x3e/0xbe
[ 3362.924328][ T3635]  ? entry_SYSCALL_64_after_hwframe+0x3e/0xbe
[ 3362.924334][ T3635]  __se_sys_clone+0x6b/0x90
[ 3362.924342][ T3635]  do_syscall_64+0x50/0x120
[ 3362.924346][ T3635]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 3362.924351][ T3635] RIP: 0033:0x7f297d763c50
[ 3362.924355][ T3635] Code: ed 0f 85 1b 01 00 00 64 4c 8b 0c 25 10 00 00 00 45 31 c0 4d 8d 91 d0 02 00 00 31 d2 31 f6 bf 11 00 20 01 b8 38 00 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 ac 00 00 00 41 89 c5 85 c0 0f 85 b9 00 00
[ 3362.924358][ T3635] RSP: 002b:00007ffd29757910 EFLAGS: 00000246 ORIG_RAX: 0000000000000038
[ 3362.924363][ T3635] RAX: ffffffffffffffda RBX: 0000000040800000 RCX: 00007f297d763c50
[ 3362.924366][ T3635] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000001200011
[ 3362.924369][ T3635] RBP: 0000000000000000 R08: 0000000000000000 R09: 00007f297d20b7c0
[ 3362.924372][ T3635] R10: 00007f297d20ba90 R11: 0000000000000246 R12: 0000000000000000
[ 3362.924375][ T3635] R13: 00005616a1027840 R14: 0000000000000000 R15: 00005616a1007620
[ 3362.924384][ T3635] Modules linked in: uas mt76x0u mt76x0_common mt76x02_usb mt76_usb mt76x02_lib mt76 mac80211 kvm_intel cfg80211 kvm irqbypass xhci_pci ehci_pci xhci_hcd ehci_hcd
[ 3362.924400][ T3635] ---[ end trace 132618ad38ffc1cc ]---
[ 3362.924404][ T3635] RIP: 0010:copy_page_range+0x412/0xae0
[ 3362.924408][ T3635] Code: f7 d8 48 31 d0 f6 c2 80 48 0f 45 cf 48 21 c8 4c 89 fb 48 c1 e8 06 48 03 05 0b 78 2c 01 48 c1 eb 09 48 21 ca 81 e3 f8 0f 00 00 <48> 8b 68 28 48 8b 05 03 78 2c 01 48 89 ef 48 01 d8 48 01 d0 49 89
[ 3362.924412][ T3635] RSP: 0018:ffffb52f002a7bc0 EFLAGS: 00010202
[ 3362.924416][ T3635] RAX: ffffee07c6b58000 RBX: 0000000000000958 RCX: 000fffffffe00000
[ 3362.924419][ T3635] RDX: 000f8dae52800000 RSI: 000ffffffffff000 RDI: 000fffffffe00000
[ 3362.924422][ T3635] RBP: ffff9c8f9169ce00 R08: 0000000000000001 R09: 0000000000000000
[ 3362.924425][ T3635] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000
[ 3362.924428][ T3635] R13: 000055622792b000 R14: 0000000000000000 R15: 000055622792b000
[ 3362.924431][ T3635] FS:  00007f297d20b7c0(0000) GS:ffff9c8f97c00000(0000) knlGS:0000000000000000
[ 3362.924435][ T3635] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 3362.924438][ T3635] CR2: 00007fe8b5d67000 CR3: 0000000214352005 CR4: 00000000001606e0
[ 3422.347880][ T7277] traps: modprobe[7277] general protection fault ip:7f2bff44c3d2 sp:7ffde3b51f80 error:0 in ld-2.29.so[7f2bff44a000+1e000]
[ 3422.358926][ T7280] traps: run-parts[7280] general protection fault ip:7f2d45220a25 sp:7ffcb8f33a10 error:0 in libc-2.29.so[7f2d451c3000+147000]
[ 3450.922042][ T7287] traps: htop[7287] general protection fault ip:7f5f03536026 sp:7ffd371abcc0 error:0 in libc-2.29.so[7f5f0352b000+147000]
[ 3456.097730][ T6796] general protection fault: 0000 [#3] PREEMPT SMP PTI
[ 3456.097796][ T6796] CPU: 2 PID: 6796 Comm: apt-compat Tainted: G      D           5.3.18 #1
[ 3456.097860][ T6796] Hardware name: System manufacturer System Product Name/P8H77-V, BIOS 1905 10/27/2014
[ 3456.097934][ T6796] RIP: 0010:copy_page_range+0x3ba/0xae0
[ 3456.097979][ T6796] Code: 83 e0 fb 48 83 f8 63 0f 85 a3 05 00 00 48 8b 44 24 38 48 c7 84 24 f8 00 00 00 00 00 00 00 48 c7 84 24 00 01 00 00 00 00 00 00 <48> 8b 10 48 f7 c2 9f ff ff ff 0f 84 9c 03 00 00 48 b9 00 f0 ff ff
[ 3456.098115][ T6796] RSP: 0018:ffffb52f00fe3bc0 EFLAGS: 00010246
[ 3456.098163][ T6796] RAX: 000f2a3bd1864888 RBX: ffff9c8f9287a4f8 RCX: 0000000215980067
[ 3456.098221][ T6796] RDX: fff0000000000fff RSI: 000ffffffffff000 RDI: ffff9c8f9178f888
[ 3456.098280][ T6796] RBP: ffff9c8f9203e180 R08: 0000000000000001 R09: 0000000000000000
[ 3456.098338][ T6796] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000
[ 3456.098397][ T6796] R13: 00005627e236e000 R14: 0000000000000000 R15: 00005627e236e000
[ 3456.098456][ T6796] FS:  00007fbb47190580(0000) GS:ffff9c8f97a00000(0000) knlGS:0000000000000000
[ 3456.098521][ T6796] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 3456.098571][ T6796] CR2: 00007fbb47188ca0 CR3: 0000000191d6a001 CR4: 00000000001606e0
[ 3456.098630][ T6796] Call Trace:
[ 3456.098676][ T6796]  dup_mm+0x3b1/0x500
[ 3456.098715][ T6796]  copy_process+0x1920/0x1e10
[ 3456.098759][ T6796]  _do_fork+0x74/0x450
[ 3456.098798][ T6796]  ? entry_SYSCALL_64_after_hwframe+0x3e/0xbe
[ 3456.098845][ T6796]  ? entry_SYSCALL_64_after_hwframe+0x3e/0xbe
[ 3456.098895][ T6796]  __se_sys_clone+0x6b/0x90
[ 3456.098936][ T6796]  do_syscall_64+0x50/0x120
[ 3456.098973][ T6796]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 3456.099020][ T6796] RIP: 0033:0x7fbb47096c50
[ 3456.099057][ T6796] Code: ed 0f 85 1b 01 00 00 64 4c 8b 0c 25 10 00 00 00 45 31 c0 4d 8d 91 d0 02 00 00 31 d2 31 f6 bf 11 00 20 01 b8 38 00 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 ac 00 00 00 41 89 c5 85 c0 0f 85 b9 00 00
[ 3456.099192][ T6796] RSP: 002b:00007fff1d417530 EFLAGS: 00000246 ORIG_RAX: 0000000000000038
[ 3456.099255][ T6796] RAX: ffffffffffffffda RBX: 00005627e26619c0 RCX: 00007fbb47096c50
[ 3456.099314][ T6796] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000001200011
[ 3456.099372][ T6796] RBP: 0000000000000000 R08: 0000000000000000 R09: 00007fbb47190580
[ 3456.099430][ T6796] R10: 00007fbb47190850 R11: 0000000000000246 R12: 0000000000000000
[ 3456.099489][ T6796] R13: 0000000000000000 R14: 00007fff1d4175f0 R15: 0000000000000001
[ 3456.099554][ T6796] Modules linked in: uas mt76x0u mt76x0_common mt76x02_usb mt76_usb mt76x02_lib mt76 mac80211 kvm_intel cfg80211 kvm irqbypass xhci_pci ehci_pci xhci_hcd ehci_hcd
[ 3456.099705][ T6796] ---[ end trace 132618ad38ffc1cd ]---
[ 3456.099753][ T6796] RIP: 0010:copy_page_range+0x412/0xae0
[ 3456.099798][ T6796] Code: f7 d8 48 31 d0 f6 c2 80 48 0f 45 cf 48 21 c8 4c 89 fb 48 c1 e8 06 48 03 05 0b 78 2c 01 48 c1 eb 09 48 21 ca 81 e3 f8 0f 00 00 <48> 8b 68 28 48 8b 05 03 78 2c 01 48 89 ef 48 01 d8 48 01 d0 49 89
[ 3456.099935][ T6796] RSP: 0018:ffffb52f002a7bc0 EFLAGS: 00010202
[ 3456.099982][ T6796] RAX: ffffee07c6b58000 RBX: 0000000000000958 RCX: 000fffffffe00000
[ 3456.100041][ T6796] RDX: 000f8dae52800000 RSI: 000ffffffffff000 RDI: 000fffffffe00000
[ 3456.100100][ T6796] RBP: ffff9c8f9169ce00 R08: 0000000000000001 R09: 0000000000000000
[ 3456.100159][ T6796] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000
[ 3456.100217][ T6796] R13: 000055622792b000 R14: 0000000000000000 R15: 000055622792b000
[ 3456.100277][ T6796] FS:  00007fbb47190580(0000) GS:ffff9c8f97a00000(0000) knlGS:0000000000000000
[ 3456.100342][ T6796] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 3456.100392][ T6796] CR2: 00007fbb47188ca0 CR3: 0000000191d6a001 CR4: 00000000001606e0

Johannes

Re: init_on_free breaks hibernate

[Johannes Stezenbach]

Hi,

On Mon, Dec 23, 2019 at 10:13:09PM +0100, Johannes Stezenbach wrote:
> I upgraded the kernel on one of my machines to 5.3.18 (from 5.2.x)
> and found it failed after resume from hibernate due to what seemed
> to be memory corruption. I had a hunch it could be related to
> CONFIG_INIT_ON_ALLOC_DEFAULT_ON or CONFIG_INIT_ON_FREE_DEFAULT_ON,
> and a quick web search found this which seems to confirm:
> https://bbs.archlinux.org/viewtopic.php?pid=1877845#p1877845
> 
> I rebuilt the kernel with CONFIG_INIT_ON_FREE_DEFAULT_ON disabled,
> and hibernate works again.  I'm fine with this workaround and
> just wanted to share this information.
> 
> The commit that introduces CONFIG_INIT_ON_FREE_DEFAULT_ON:
> 6471384af2a6 mm: security: introduce init_on_alloc=1 and init_on_free=1 boot options

I tested 5.4.11 and current git master (b07f636fca1c8)
in Qemu and was able to reproduce the issue in both.

Basically I followed the description here
http://ncmiller.github.io/2016/05/14/linux-and-qemu.html
to build a minimal image using busybox (I'm using
the binary from Debian's busybox-static package),
then added s swap image (-drive file=disk.img,if=virtio),
do "mkswap /dev/vda" the first time.

hibernate: swapon /dev/vda; echo disk >/sys/power/state
resume: echo 254:0 >/sys/power/resume

Since busybox is very light on memory usage it doesn't
trigger immediately, but these commands seem to do it
reliably:

  dmesg | gzip >/dev/null
  find /sys | bzip2 | sha512sum


my initramfs:
  6012997      4 drwxr-xr-x   4 js       js           4096 Jan  8 21:25 initramfs
  6022584      4 drwxr-xr-x   2 js       js           4096 Jan  8 21:21 initramfs/dev
  5909013      4 -rwxr-xr-x   1 js       js            514 Jan  8 21:25 initramfs/init
  6012998      4 drwxr-xr-x   2 js       js           4096 Jan  8 20:41 initramfs/bin
  5909011   1904 -rwxr-xr-x   1 js       js        1945856 Apr  1  2019 initramfs/bin/busybox
  5909012      0 lrwxrwxrwx   1 js       js              7 Feb 14  2018 initramfs/bin/sh -> busybox

my /init:
#!/bin/sh

PATH=/bin
export PATH

# Create dirs
/bin/busybox mkdir -p /proc /sys /etc /tmp /usr
/bin/busybox ln -s /bin /sbin
/bin/busybox ln -s /bin /usr/bin
/bin/busybox ln -s /bin /usr/sbin
# Create all the symlinks to busybox
/bin/busybox --install -s

mount -t proc proc /proc
mount -t sysfs sysfs /sys
mount -t devtmpfs devtmpfs /dev

echo -e "\nBoot took $(cut -d' ' -f1 /proc/uptime) seconds\n"

# shell where ^C works
setsid busybox cttyhack sh
# avoid "PID 1 exited" oops
poweroff -f
---------


qemu-system-x86_64 -m 128 -enable-kvm \
  -kernel ../linux/arch/x86/boot/bzImage \
  -initrd initramfs.cpio \
  -drive file=disk.img,if=virtio \
  -nographic -append "console=ttyS0 init_on_alloc=1 init_on_free=1"


Johannes

Re: init_on_free breaks hibernate

[Rafael J. Wysocki]

On Monday, January 13, 2020 10:26:04 AM CET Johannes Stezenbach wrote:
> Hi,
> 
> On Mon, Dec 23, 2019 at 10:13:09PM +0100, Johannes Stezenbach wrote:
> > I upgraded the kernel on one of my machines to 5.3.18 (from 5.2.x)
> > and found it failed after resume from hibernate due to what seemed
> > to be memory corruption. I had a hunch it could be related to
> > CONFIG_INIT_ON_ALLOC_DEFAULT_ON or CONFIG_INIT_ON_FREE_DEFAULT_ON,
> > and a quick web search found this which seems to confirm:
> > https://bbs.archlinux.org/viewtopic.php?pid=1877845#p1877845
> > 
> > I rebuilt the kernel with CONFIG_INIT_ON_FREE_DEFAULT_ON disabled,
> > and hibernate works again.  I'm fine with this workaround and
> > just wanted to share this information.
> > 
> > The commit that introduces CONFIG_INIT_ON_FREE_DEFAULT_ON:
> > 6471384af2a6 mm: security: introduce init_on_alloc=1 and init_on_free=1 boot options
> 
> I tested 5.4.11 and current git master (b07f636fca1c8)
> in Qemu and was able to reproduce the issue in both.

Let's add more people and the LKML to the CC.

Alex, Kees, Michal, any comments?

> Basically I followed the description here
> http://ncmiller.github.io/2016/05/14/linux-and-qemu.html
> to build a minimal image using busybox (I'm using
> the binary from Debian's busybox-static package),
> then added s swap image (-drive file=disk.img,if=virtio),
> do "mkswap /dev/vda" the first time.
> 
> hibernate: swapon /dev/vda; echo disk >/sys/power/state
> resume: echo 254:0 >/sys/power/resume
> 
> Since busybox is very light on memory usage it doesn't
> trigger immediately, but these commands seem to do it
> reliably:
> 
>   dmesg | gzip >/dev/null
>   find /sys | bzip2 | sha512sum
> 
> 
> my initramfs:
>   6012997      4 drwxr-xr-x   4 js       js           4096 Jan  8 21:25 initramfs
>   6022584      4 drwxr-xr-x   2 js       js           4096 Jan  8 21:21 initramfs/dev
>   5909013      4 -rwxr-xr-x   1 js       js            514 Jan  8 21:25 initramfs/init
>   6012998      4 drwxr-xr-x   2 js       js           4096 Jan  8 20:41 initramfs/bin
>   5909011   1904 -rwxr-xr-x   1 js       js        1945856 Apr  1  2019 initramfs/bin/busybox
>   5909012      0 lrwxrwxrwx   1 js       js              7 Feb 14  2018 initramfs/bin/sh -> busybox
> 
> my /init:
> #!/bin/sh
> 
> PATH=/bin
> export PATH
> 
> # Create dirs
> /bin/busybox mkdir -p /proc /sys /etc /tmp /usr
> /bin/busybox ln -s /bin /sbin
> /bin/busybox ln -s /bin /usr/bin
> /bin/busybox ln -s /bin /usr/sbin
> # Create all the symlinks to busybox
> /bin/busybox --install -s
> 
> mount -t proc proc /proc
> mount -t sysfs sysfs /sys
> mount -t devtmpfs devtmpfs /dev
> 
> echo -e "\nBoot took $(cut -d' ' -f1 /proc/uptime) seconds\n"
> 
> # shell where ^C works
> setsid busybox cttyhack sh
> # avoid "PID 1 exited" oops
> poweroff -f
> ---------
> 
> 
> qemu-system-x86_64 -m 128 -enable-kvm \
>   -kernel ../linux/arch/x86/boot/bzImage \
>   -initrd initramfs.cpio \
>   -drive file=disk.img,if=virtio \
>   -nographic -append "console=ttyS0 init_on_alloc=1 init_on_free=1"
> 
> 
> Johannes
> 

Re: init_on_free breaks hibernate

[Alexander Potapenko]

On Mon, Jan 13, 2020 at 12:07 PM Rafael J. Wysocki <rjw@rjwysocki.net> wrote:
>
> On Monday, January 13, 2020 10:26:04 AM CET Johannes Stezenbach wrote:
> > Hi,
> >
> > On Mon, Dec 23, 2019 at 10:13:09PM +0100, Johannes Stezenbach wrote:
> > > I upgraded the kernel on one of my machines to 5.3.18 (from 5.2.x)
> > > and found it failed after resume from hibernate due to what seemed
> > > to be memory corruption. I had a hunch it could be related to
> > > CONFIG_INIT_ON_ALLOC_DEFAULT_ON or CONFIG_INIT_ON_FREE_DEFAULT_ON,
> > > and a quick web search found this which seems to confirm:
> > > https://bbs.archlinux.org/viewtopic.php?pid=1877845#p1877845
> > >
> > > I rebuilt the kernel with CONFIG_INIT_ON_FREE_DEFAULT_ON disabled,
> > > and hibernate works again.  I'm fine with this workaround and
> > > just wanted to share this information.
> > >
> > > The commit that introduces CONFIG_INIT_ON_FREE_DEFAULT_ON:
> > > 6471384af2a6 mm: security: introduce init_on_alloc=1 and init_on_free=1 boot options
> >
> > I tested 5.4.11 and current git master (b07f636fca1c8)
> > in Qemu and was able to reproduce the issue in both.
>
> Let's add more people and the LKML to the CC.
>
> Alex, Kees, Michal, any comments?
Hm, I cannot think of a reason for initialization to break hibernate
off the top of my head.
Maybe after hibernation certain pages land in the page freelist
without being wiped?
I'll try to reproduce this problem locally.

> > Basically I followed the description here
> > http://ncmiller.github.io/2016/05/14/linux-and-qemu.html
> > to build a minimal image using busybox (I'm using
> > the binary from Debian's busybox-static package),
> > then added s swap image (-drive file=disk.img,if=virtio),
> > do "mkswap /dev/vda" the first time.
> >
> > hibernate: swapon /dev/vda; echo disk >/sys/power/state
> > resume: echo 254:0 >/sys/power/resume
> >
> > Since busybox is very light on memory usage it doesn't
> > trigger immediately, but these commands seem to do it
> > reliably:
> >
> >   dmesg | gzip >/dev/null
> >   find /sys | bzip2 | sha512sum
> >
> >
> > my initramfs:
> >   6012997      4 drwxr-xr-x   4 js       js           4096 Jan  8 21:25 initramfs
> >   6022584      4 drwxr-xr-x   2 js       js           4096 Jan  8 21:21 initramfs/dev
> >   5909013      4 -rwxr-xr-x   1 js       js            514 Jan  8 21:25 initramfs/init
> >   6012998      4 drwxr-xr-x   2 js       js           4096 Jan  8 20:41 initramfs/bin
> >   5909011   1904 -rwxr-xr-x   1 js       js        1945856 Apr  1  2019 initramfs/bin/busybox
> >   5909012      0 lrwxrwxrwx   1 js       js              7 Feb 14  2018 initramfs/bin/sh -> busybox
> >
> > my /init:
> > #!/bin/sh
> >
> > PATH=/bin
> > export PATH
> >
> > # Create dirs
> > /bin/busybox mkdir -p /proc /sys /etc /tmp /usr
> > /bin/busybox ln -s /bin /sbin
> > /bin/busybox ln -s /bin /usr/bin
> > /bin/busybox ln -s /bin /usr/sbin
> > # Create all the symlinks to busybox
> > /bin/busybox --install -s
> >
> > mount -t proc proc /proc
> > mount -t sysfs sysfs /sys
> > mount -t devtmpfs devtmpfs /dev
> >
> > echo -e "\nBoot took $(cut -d' ' -f1 /proc/uptime) seconds\n"
> >
> > # shell where ^C works
> > setsid busybox cttyhack sh
> > # avoid "PID 1 exited" oops
> > poweroff -f
> > ---------
> >
> >
> > qemu-system-x86_64 -m 128 -enable-kvm \
> >   -kernel ../linux/arch/x86/boot/bzImage \
> >   -initrd initramfs.cpio \
> >   -drive file=disk.img,if=virtio \
> >   -nographic -append "console=ttyS0 init_on_alloc=1 init_on_free=1"
> >
> >
> > Johannes
> >
>
>
>
>


-- 
Alexander Potapenko
Software Engineer

Google Germany GmbH
Erika-Mann-Straße, 33
80636 München

Geschäftsführer: Paul Manicle, Halimah DeLaine Prado
Registergericht und -nummer: Hamburg, HRB 86891
Sitz der Gesellschaft: Hamburg

Re: init_on_free breaks hibernate

[Alexander Potapenko]

On Mon, Jan 13, 2020 at 10:26 AM Johannes Stezenbach <js@sig21.net> wrote:
>
> Hi,
Hi Johannes,

> On Mon, Dec 23, 2019 at 10:13:09PM +0100, Johannes Stezenbach wrote:
> > I upgraded the kernel on one of my machines to 5.3.18 (from 5.2.x)
> > and found it failed after resume from hibernate due to what seemed
> > to be memory corruption. I had a hunch it could be related to
> > CONFIG_INIT_ON_ALLOC_DEFAULT_ON or CONFIG_INIT_ON_FREE_DEFAULT_ON,
> > and a quick web search found this which seems to confirm:
> > https://bbs.archlinux.org/viewtopic.php?pid=1877845#p1877845
> >
> > I rebuilt the kernel with CONFIG_INIT_ON_FREE_DEFAULT_ON disabled,
> > and hibernate works again.  I'm fine with this workaround and
> > just wanted to share this information.
> >
> > The commit that introduces CONFIG_INIT_ON_FREE_DEFAULT_ON:
> > 6471384af2a6 mm: security: introduce init_on_alloc=1 and init_on_free=1 boot options
>
> I tested 5.4.11 and current git master (b07f636fca1c8)
> in Qemu and was able to reproduce the issue in both.
>
> Basically I followed the description here
> http://ncmiller.github.io/2016/05/14/linux-and-qemu.html
> to build a minimal image using busybox (I'm using
> the binary from Debian's busybox-static package),
> then added s swap image (-drive file=disk.img,if=virtio),
> do "mkswap /dev/vda" the first time.
>
> hibernate: swapon /dev/vda; echo disk >/sys/power/state
> resume: echo 254:0 >/sys/power/resume

Resuming doesn't work for me in your setup with upstream kernel and
init_on_alloc/init_on_free disabled.
To hibernate, I did:

# mkswap /dev/vda
Setting up swapspace version 1, size = 268431360 bytes
[   17.128392] random: mkswap: uninitialized urandom read (16 bytes read)
# swapon /dev/vda
[   19.191236] Adding 262140k swap on /dev/vda.  Priority:-2 extents:1
across:262140k
# echo disk >/sys/power/state

, which succeeded:

[   19.867905] PM: hibernation entry
[   19.876320] Filesystems sync: 0.000 seconds
...
[   20.278736] PM: Image saving progress: 100%
[   20.279739] PM: Image saving done
[   20.280232] PM: Wrote 44036 kbytes in 0.12 seconds (366.96 MB/s)
[   20.281340] PM: S|

Then QEMU stopped, so I had to restart it.
Simply running:

# echo 254:0 >/sys/power/resume

didn't do the trick, I saw the following line in dmesg:

[   57.558499] PM: Image not found (code -5)

I tried doing swapon again, but it also didn't work:

# swapon /dev/vda
[  105.415845] Unable to find swap-space signature
swapon: /dev/vda: Invalid argument

Could it be so that the contents of /dev/vda didn't survive the reboot?

Re: init_on_free breaks hibernate

[Alexander Potapenko]

> Resuming doesn't work for me in your setup with upstream kernel and
> init_on_alloc/init_on_free disabled.
> To hibernate, I did:

Ok, I've managed to resume by running QEMU with -append "... resume=/dev/vda".
The memory corruption is also reproducible for me, taking a look.



-- 
Alexander Potapenko
Software Engineer

Google Germany GmbH
Erika-Mann-Straße, 33
80636 München

Geschäftsführer: Paul Manicle, Halimah DeLaine Prado
Registergericht und -nummer: Hamburg, HRB 86891
Sitz der Gesellschaft: Hamburg

Re: init_on_free breaks hibernate

[Johannes Stezenbach]

On Mon, Jan 13, 2020 at 04:41:27PM +0100, Alexander Potapenko wrote:
> > Resuming doesn't work for me in your setup with upstream kernel and
> > init_on_alloc/init_on_free disabled.
> > To hibernate, I did:
> 
> Ok, I've managed to resume by running QEMU with -append "... resume=/dev/vda".

Strange about the resume=/dev/vda, it worked for me the way I described it.
Maybe device numbers are dynamic, 254:0 is what I got from ls -l /dev/vda.

> The memory corruption is also reproducible for me, taking a look.

Great!

Johannes

Re: init_on_free breaks hibernate

[Alexander Potapenko]

On Mon, Jan 13, 2020 at 6:16 PM Johannes Stezenbach <js@sig21.net> wrote:
>
> On Mon, Jan 13, 2020 at 04:41:27PM +0100, Alexander Potapenko wrote:
> > > Resuming doesn't work for me in your setup with upstream kernel and
> > > init_on_alloc/init_on_free disabled.
> > > To hibernate, I did:
> >
> > Ok, I've managed to resume by running QEMU with -append "... resume=/dev/vda".
>
> Strange about the resume=/dev/vda, it worked for me the way I described it.
> Maybe device numbers are dynamic, 254:0 is what I got from ls -l /dev/vda.
Indeed, for me it's 253:0, and resuming from console works with that number.

> > The memory corruption is also reproducible for me, taking a look.
>
> Great!
>
> Johannes



-- 
Alexander Potapenko
Software Engineer

Google Germany GmbH
Erika-Mann-Straße, 33
80636 München

Geschäftsführer: Paul Manicle, Halimah DeLaine Prado
Registergericht und -nummer: Hamburg, HRB 86891
Sitz der Gesellschaft: Hamburg

Re: init_on_free breaks hibernate

[Alexander Potapenko]

> > Strange about the resume=/dev/vda, it worked for me the way I described it.
> > Maybe device numbers are dynamic, 254:0 is what I got from ls -l /dev/vda.
> Indeed, for me it's 253:0, and resuming from console works with that number.
>
> > > The memory corruption is also reproducible for me, taking a look.
> >

I think I know what is causing the problem.
Upon resume the free pages may contain stale information from the
kernel that initiated the resume.
There's clear_free_pages()
(https://elixir.bootlin.com/linux/latest/source/kernel/power/snapshot.c#L1148)
that clears the pages in the case CONFIG_PAGE_POISONING_ZERO is
enabled, we just need to reuse it for init_on_free.
See the potential fix below.

Rafael, Pavel, I've noticed that in the setup suggested by Johannes
even the defconfig kernel with heap initialization cannot hibernate
more than twice, the third hibernate hangs.
Is that a known problem?

diff --git a/kernel/power/snapshot.c b/kernel/power/snapshot.c
index 26b9168321e7..d65f2d5ab694 100644
--- a/kernel/power/snapshot.c
+++ b/kernel/power/snapshot.c
@@ -1147,24 +1147,24 @@ void free_basic_memory_bitmaps(void)

 void clear_free_pages(void)
 {
-#ifdef CONFIG_PAGE_POISONING_ZERO
        struct memory_bitmap *bm = free_pages_map;
        unsigned long pfn;

        if (WARN_ON(!(free_pages_map)))
                return;

-       memory_bm_position_reset(bm);
-       pfn = memory_bm_next_pfn(bm);
-       while (pfn != BM_END_OF_MAP) {
-               if (pfn_valid(pfn))
-                       clear_highpage(pfn_to_page(pfn));
-
+       if (IS_ENABLED(CONFIG_PAGE_POISONING_ZERO) || want_init_on_free()) {
+               memory_bm_position_reset(bm);
                pfn = memory_bm_next_pfn(bm);
+               while (pfn != BM_END_OF_MAP) {
+                       if (pfn_valid(pfn))
+                               clear_highpage(pfn_to_page(pfn));
+
+                       pfn = memory_bm_next_pfn(bm);
+               }
+               memory_bm_position_reset(bm);
+               pr_info("free pages cleared after restore\n");
        }
-       memory_bm_position_reset(bm);
-       pr_info("free pages cleared after restore\n");
-#endif /* PAGE_POISONING_ZERO */
 }

Re: init_on_free breaks hibernate

[Rafael J. Wysocki]

On Tuesday, January 14, 2020 12:38:53 PM CET Alexander Potapenko wrote:
> > > Strange about the resume=/dev/vda, it worked for me the way I described it.
> > > Maybe device numbers are dynamic, 254:0 is what I got from ls -l /dev/vda.
> > Indeed, for me it's 253:0, and resuming from console works with that number.
> >
> > > > The memory corruption is also reproducible for me, taking a look.
> > >
> 
> I think I know what is causing the problem.
> Upon resume the free pages may contain stale information from the
> kernel that initiated the resume.
> There's clear_free_pages()
> (https://elixir.bootlin.com/linux/latest/source/kernel/power/snapshot.c#L1148)
> that clears the pages in the case CONFIG_PAGE_POISONING_ZERO is
> enabled, we just need to reuse it for init_on_free.
> See the potential fix below.
> 
> Rafael, Pavel, I've noticed that in the setup suggested by Johannes
> even the defconfig kernel with heap initialization cannot hibernate
> more than twice, the third hibernate hangs.
> Is that a known problem?

No, it is not.

Re: init_on_free breaks hibernate

[Alexander Potapenko]

On Tue, Jan 14, 2020 at 11:36 PM Rafael J. Wysocki <rjw@rjwysocki.net> wrote:
>
> On Tuesday, January 14, 2020 12:38:53 PM CET Alexander Potapenko wrote:
> > > > Strange about the resume=/dev/vda, it worked for me the way I described it.
> > > > Maybe device numbers are dynamic, 254:0 is what I got from ls -l /dev/vda.
> > > Indeed, for me it's 253:0, and resuming from console works with that number.
> > >
> > > > > The memory corruption is also reproducible for me, taking a look.
> > > >
> >
> > I think I know what is causing the problem.
> > Upon resume the free pages may contain stale information from the
> > kernel that initiated the resume.
> > There's clear_free_pages()
> > (https://elixir.bootlin.com/linux/latest/source/kernel/power/snapshot.c#L1148)
> > that clears the pages in the case CONFIG_PAGE_POISONING_ZERO is
> > enabled, we just need to reuse it for init_on_free.
> > See the potential fix below.
> >
> > Rafael, Pavel, I've noticed that in the setup suggested by Johannes
> > even the defconfig kernel with heap initialization cannot hibernate
> > more than twice, the third hibernate hangs.
> > Is that a known problem?
>
> No, it is not.

Sorry for the typo. Actually, the defconfig _without_ heap
initialization cannot hibernate more than twice.