* Re: 402b1b327a: BUG:unable_to_handle_page_fault_for_address
2019-07-23 9:38 ` 402b1b327a: BUG:unable_to_handle_page_fault_for_address Chandan Rajendra
@ 2019-07-23 11:38 ` Chandan Rajendra
0 siblings, 0 replies; 2+ messages in thread
From: Chandan Rajendra @ 2019-07-23 11:38 UTC (permalink / raw)
Cc: lkp, linux-ext4, linux-fscrypt, linux-fsdevel
On Tuesday, July 23, 2019 3:08:57 PM IST Chandan Rajendra wrote:
> On Wednesday, June 26, 2019 2:28:00 PM IST kernel test robot wrote:
Adding Ted and Eric on TO list explicitly ...
>
> Hi Ted & Eric,
>
> The subpage encryption patchset assumes that bio->bi_private and
> bh->b_private is set to NULL when reading data for non-encrypted regular
> files. However, there are instances that have come up where this
> assumption does not hold good.
>
> 1. In Btrfs, write_dev_supers() sets bh->b_private to 'struct
> btrfs_device' pointer and submits the buffer head for a write
> operation.
> 1. In the btrfs/146 test, the write operation fails and hence the
> kernel clears the BH_Uptodate flag.
> 2. A read operation initiated later will submit the buffer head to
> the block layer. During endio processing, "read callbacks" state
> machine is initiated because bh->b_private is set to a non-NULL
> value.
> 3. This results in the following call trace,
> ,----
> | [ 255.588689] BUG: unable to handle page fault for address: ffffffffb5f7e399
> | [ 255.591659] #PF: supervisor read access in kernel mode
> | [ 255.593967] #PF: error_code(0x0000) - not-present page
> | [ 255.596113] PGD 465026067 P4D 465026067 PUD 465027063 PMD 0
> | [ 255.598007] Oops: 0000 [#1] SMP DEBUG_PAGEALLOC PTI
> | [ 255.599646] CPU: 8 PID: 0 Comm: swapper/8 Not tainted 5.2.0-rc2-00023-gb98a16901
> | [ 255.602229] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-4
> | [ 255.604998] RIP: 0010:read_callbacks+0xf0/0x190
> | [ 255.606479] Code: e0 04 49 03 47 58 45 85 f6 75 87 8b 50 0c 44 89 e9 89 d3 81 eb
> | [ 255.612608] RSP: 0018:ffff941343338e70 EFLAGS: 00010286
> | [ 255.614316] RAX: 0000000000000329 RBX: ffffffffb5f7e391 RCX: 0000000000000329
> | [ 255.616678] RDX: 000000009396fc38 RSI: 0000000000000001 RDI: ffff8cd792e16f98
> | [ 255.619030] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
> | [ 255.621350] R10: 0000000000000000 R11: 0000000000000000 R12: ffff8cd79396fbd8
> | [ 255.623725] R13: 0000000000001000 R14: 0000000000000329 R15: ffff8cd78fa507c0
> | [ 255.626046] FS: 0000000000000000(0000) GS:ffff8cd79dc00000(0000) knlGS:00000000
> | [ 255.628740] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> | [ 255.630632] CR2: ffffffffb5f7e399 CR3: 0000000615f3a000 CR4: 00000000000006e0
> | [ 255.633004] Call Trace:
> | [ 255.633839] <IRQ>
> | [ 255.634531] read_callbacks_end_bh+0x1b/0x40
> | [ 255.635963] __end_buffer_async_read+0x18/0x60
> | [ 255.637454] end_bio_bh_io_sync+0x26/0x40
> | [ 255.638803] clone_endio+0x90/0x180
> | [ 255.639989] blk_update_request+0x8f/0x360
> | [ 255.641340] blk_mq_end_request+0x1a/0x120
> | [ 255.642685] blk_done_softirq+0x8d/0xc0
> | [ 255.644098] __do_softirq+0xcc/0x3fe
> | [ 255.645029] irq_exit+0xbb/0xc0
> | [ 255.645755] call_function_single_interrupt+0xf/0x20
> | [ 255.646896] </IRQ>
> `----
>
> 2. Another instance is when a metadata block with BH_Uptodate set and
> also part of the in-memory JBD list undergoes the following,
> 1. A sync() syscall is invoked by the userspace and the write
> operation on the metadata block is initiated.
> 2. Due to an I/O failure, the BH_Uptodate flag is cleared by
> end_buffer_async_write(). The bh->b_private member would be
> pointing to a journal head structure.
> 3. In such a case, a read opertion invoked on the block mapped by the buffer
> head will initiate a read from the disk since the buffer head is
> missing the BH_Uptodate flag. E.g. On my test machine, I see the
> following,
> ,----
> | probe-bcache 5185 [008] 230.484959: probe:submit_bh: (ffffffffb845c180) b_private=0xffff8b6b3e1fc008 b_bdev=0xffff8b701c41e1c0 b_state=2279596 bh_x64=0xffff8b6b3a8b86e8 op_u32=0
> | ffffffffb845c181 submit_bh+0x1
> | ([kernel.kallsyms]) ffffffffb845a6fc block_read_full_page+0x29c
> | ([kernel.kallsyms]) ffffffffb845d9c5 blkdev_readpage+0x25
> | ([kernel.kallsyms]) ffffffffb83a1e84 generic_file_read_iter+0x684
> | ([kernel.kallsyms]) ffffffffb8415679 new_sync_read+0x109
> | ([kernel.kallsyms]) ffffffffb841807c vfs_read+0x8c
> | ([kernel.kallsyms]) ffffffffb84185f4 ksys_pread64+0x74
> | ([kernel.kallsyms]) ffffffffb8202720 do_syscall_64+0x50
> | ([kernel.kallsyms]) ffffffffb9000081 entry_SYSCALL_64_after_hwframe+0x49
> | ([kernel.kallsyms]) 7f2512ae0637
> | __libc_pread+0x17 (/lib/x86_64-linux-gnu/libc-2.27.so) 7ffd65bb6e4d
> | [unknown] ([unknown])
> `----
>
> 4. After the read I/O request is submitted, end_buffer_async_read()
> will find a non-NULL value at bh->b_private. Due to the non-NULL
> bh->b_private value, this function initiates "read callbacks"
> state machine.
> This scenario was seen when executing generic/475 test case.
>
> The first case can be handled by setting a NULL value to the bh->b_private
> member in the write operation's endio function. However I don't see a method
> to disassociate the journal head from the buffer head for the second case
> described above.
>
> Hence I propose that we introduce new flags (one each for bio and
> buffer_head structures) to track if the payload needs further processing
> (e.g. decryption). Please let me know your thoughts on this.
>
> > FYI, we noticed the following commit (built with gcc-7):
> >
> > commit: 402b1b327a0b0e8fd23d5866b9585ccc2380f199 ("Add decryption support for sub-pagesized blocks")
> > https://git.kernel.org/cgit/linux/kernel/git/ebiggers/linux.git wip-subpage-encryption
> >
> > in testcase: xfstests
> > with following parameters:
> >
> > disk: 6HDD
> > fs: btrfs
> > test: btrfs-group1
> >
> > test-description: xfstests is a regression test suite for xfs and other files ystems.
> > test-url: git://git.kernel.org/pub/scm/fs/xfs/xfstests-dev.git
> >
> >
> > on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 4G
> >
> > caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
> >
> >
> > +-------------------------------------------------------+------------+------------+
> > | | 31d0610be3 | 402b1b327a |
> > +-------------------------------------------------------+------------+------------+
> > | boot_successes | 1 | 0 |
> > | boot_failures | 43 | 40 |
> > | BUG:kernel_reboot-without-warning_in_test_stage | 41 | 31 |
> > | BUG:kernel_NULL_pointer_dereference,address | 2 | 2 |
> > | Oops:#[##] | 2 | 7 |
> > | RIP:raid#_sse21_gen_syndrome[raid#_pq] | 2 | 2 |
> > | Kernel_panic-not_syncing:Fatal_exception | 2 | 2 |
> > | BUG:unable_to_handle_page_fault_for_address | 0 | 5 |
> > | RIP:read_callbacks | 0 | 5 |
> > | RIP:native_safe_halt | 0 | 5 |
> > | Kernel_panic-not_syncing:Fatal_exception_in_interrupt | 0 | 5 |
> > | BUG:soft_lockup-CPU##stuck_for#s | 0 | 1 |
> > | RIP:__do_softirq | 0 | 1 |
> > | RIP:clear_page_rep | 0 | 1 |
> > | Kernel_panic-not_syncing:softlockup:hung_tasks | 0 | 1 |
> > | BUG:kernel_hang_in_boot_stage | 0 | 1 |
> > +-------------------------------------------------------+------------+------------+
> >
> >
> > If you fix the issue, kindly add following tag
> > Reported-by: kernel test robot <rong.a.chen@intel.com>
> >
> >
> > [ 1439.695830] BUG: unable to handle page fault for address: 0000000003fffe53
> > [ 1439.702109] #PF: supervisor read access in kernel mode
> > [ 1439.705572] #PF: error_code(0x0000) - not-present page
> > [ 1439.709289] PGD 0 P4D 0
> > [ 1439.711570] Oops: 0000 [#1] SMP PTI
> > [ 1439.714095] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.2.0-rc2-00022-g402b1b3 #1
> > [ 1439.717917] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> > [ 1439.722137] RIP: 0010:read_callbacks+0x102/0x170
> > [ 1439.725031] Code: 48 c1 e3 06 48 03 18 eb 80 48 8b 35 a8 9c dd 01 4c 89 e7 e8 20 2c f0 ff 4c 89 ff 5b 5d 41 5c 41 5d 41 5e 41 5f e9 be 8b 12 00 <48> 8b 53 08 48 8d 42 ff 83 e2 01 48 0f 44 c3 f0 80 20 fb f0 80 4b
> > [ 1439.733926] RSP: 0018:ffffb279c06cce58 EFLAGS: 00010282
> > [ 1439.736950] RAX: 0000000000000598 RBX: 0000000003fffe4b RCX: 0000000000000598
> > [ 1439.740608] RDX: 00000000bd464770 RSI: 0000000000000001 RDI: ffff9a68bae02c00
> > [ 1439.744285] RBP: 0000000000000000 R08: 0000000000033850 R09: ffffffffc04738dd
> > [ 1439.747933] R10: 0000000000000000 R11: 0000000000000000 R12: ffff9a68bd6d0a20
> > [ 1439.751612] R13: 0000000000001000 R14: 0000000000000598 R15: ffff9a68bfcf5498
> > [ 1439.755564] FS: 0000000000000000(0000) GS:ffff9a697fd00000(0000) knlGS:0000000000000000
> > [ 1439.761896] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [ 1439.769318] CR2: 0000000003fffe53 CR3: 000000007c628000 CR4: 00000000000406e0
> > [ 1439.777936] Call Trace:
> > [ 1439.788378] <IRQ>
> > [ 1439.790308] read_callbacks_end_bh+0x1b/0x40
> > [ 1439.793087] __end_buffer_async_read+0x18/0x60
> > [ 1439.795949] end_bio_bh_io_sync+0x26/0x40
> > [ 1439.798726] clone_endio+0x90/0x180 [dm_mod]
> > [ 1439.801543] blk_update_request+0x78/0x300
> > [ 1439.804197] blk_mq_end_request+0x1a/0x120
> > [ 1439.806903] blk_done_softirq+0xa1/0xd0
> > [ 1439.809404] __do_softirq+0xe3/0x311
> > [ 1439.811862] irq_exit+0xdd/0xf0
> > [ 1439.814164] call_function_single_interrupt+0xf/0x20
> > [ 1439.817082] </IRQ>
> > [ 1439.819030] RIP: 0010:native_safe_halt+0xe/0x10
> > [ 1439.821795] Code: eb bd 90 90 90 90 90 90 90 90 90 90 e9 07 00 00 00 0f 00 2d 56 de 5a 00 f4 c3 66 90 e9 07 00 00 00 0f 00 2d 46 de 5a 00 fb f4 <c3> 90 66 66 66 66 90 41 55 41 54 55 53 e8 f0 03 6c ff 65 8b 2d 19
> > [ 1439.830746] RSP: 0018:ffffb279c0697eb8 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff04
> > [ 1439.834651] RAX: ffffffffbc85c1d0 RBX: 0000000000000001 RCX: 0000000000000000
> > [ 1439.838373] RDX: 0000000000000001 RSI: 0000000000000087 RDI: 0000000000000001
> > [ 1439.842157] RBP: 0000000000000001 R08: 000002a24abd49ba R09: ffff9a697ffd3328
> > [ 1439.845956] R10: 0000000000000000 R11: 0000000000000b20 R12: 0000000000000000
> > [ 1439.849750] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
> > [ 1439.853563] ? __sched_text_end+0x7/0x7
> > [ 1439.856261] default_idle+0x1c/0x160
> > [ 1439.858875] do_idle+0x1c4/0x280
> > [ 1439.861363] cpu_startup_entry+0x19/0x20
> > [ 1439.864171] start_secondary+0x184/0x1d0
> > [ 1439.867043] secondary_startup_64+0xb6/0xc0
> > [ 1439.869803] Modules linked in: ext4 mbcache jbd2 btrfs xor zstd_decompress zstd_compress raid6_pq libcrc32c dm_flakey dm_mod sr_mod cdrom sg ata_generic pata_acpi bochs_drm ttm crct10dif_pclmul crc32_pclmul drm_kms_helper crc32c_intel ghash_clmulni_intel ppdev snd_pcm syscopyarea snd_timer sysfillrect sysimgblt snd fb_sys_fops drm aesni_intel crypto_simd ata_piix soundcore cryptd glue_helper joydev pcspkr serio_raw libata parport_pc i2c_piix4 parport floppy ip_tables [last unloaded: xor]
> > [ 1439.890150] CR2: 0000000003fffe53
> > [ 1439.892797] ---[ end trace 762467852b11b149 ]---
> >
> >
> > To reproduce:
> >
> > # build kernel
> > cd linux
> > cp config-5.2.0-rc2-00022-g402b1b3 .config
> > make HOSTCC=gcc-7 CC=gcc-7 ARCH=x86_64 olddefconfig
> > make HOSTCC=gcc-7 CC=gcc-7 ARCH=x86_64 prepare
> > make HOSTCC=gcc-7 CC=gcc-7 ARCH=x86_64 modules_prepare
> > make HOSTCC=gcc-7 CC=gcc-7 ARCH=x86_64 SHELL=/bin/bash
> > make HOSTCC=gcc-7 CC=gcc-7 ARCH=x86_64 bzImage
> >
> >
> > git clone https://github.com/intel/lkp-tests.git
> > cd lkp-tests
> > find lib/ | cpio -o -H newc --quiet | gzip > modules.cgz
> > bin/lkp qemu -k <bzImage> -m modules.cgz job-script # job-script is attached in this email
> >
> >
> >
> >
> > Thanks,
> > Rong Chen
> >
> >
>
>
>
--
chandan
^ permalink raw reply [flat|nested] 2+ messages in thread