Re: 402b1b327a: BUG:unable_to_handle_page_fault_for_address

[Chandan Rajendra <chandan@linux.ibm.com>]

On Wednesday, June 26, 2019 2:28:00 PM IST kernel test robot wrote:

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