> On Jul 2, 2024, at 5:33 PM, David Wysochanski <dwysocha@xxxxxxxxxx> wrote:
>
> On Tue, Jul 2, 2024 at 5:17 PM Chuck Lever III <chuck.lever@xxxxxxxxxx> wrote:
>>
>>
>>
>>> On Jul 2, 2024, at 4:59 PM, David Wysochanski <dwysocha@xxxxxxxxxx> wrote:
>>>
>>> Sorry for the late reply, more below.
>>>
>>> On Wed, Jun 19, 2024 at 4:46 PM Chuck Lever III <chuck.lever@xxxxxxxxxx> wrote:
>>>>
>>>> Hi Dave-
>>>>
>>>> I'm testing pNFS SCSI layouts with tracing enabled on the
>>>> client, and I hit this BUG twice today:
>>>>
>>>> BUG: kernel NULL pointer dereference, address: 0000000000000000
>>>> #PF: supervisor read access in kernel mode
>>>> #PF: error_code(0x0000) - not-present page
>>>> PGD 0 P4D 0 Oops: Oops: 0000 [#1] PREEMPT SMP PTI
>>>> CPU: 0 PID: 52230 Comm: fio Not tainted 6.10.0-rc4-g9f1e0e495093 #5
>>>> Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.3-2.fc40 04/01/2014
>>>> RIP: 0010:nfs_folio_length+0x29/0x170 [nfs]
>>>> Code: 90 41 56 41 55 41 54 55 53 48 89 fb 48 83 ec 08 48 8b 07 a9 00 00 04 00 74 0c 48 8b 07 f6 c4 08 0f 85 89 00 00 00 48 8b 43 18 <48> 8b 00 48 8b 68 50 48 85 ed 7e 66 48 8b 03 a8 40 74 7c 4c 8b 6b
>>>> RSP: 0018:ffffb0800c2abb28 EFLAGS: 00010246
>>>> RAX: 0000000000000000 RBX: ffffe5d8c44f4a00 RCX: ffffffffa8525000
>>>> RDX: 0017ffffd0000028 RSI: 000000000000004e RDI: ffffe5d8c44f4a00
>>>> RBP: ffff9871911501b8 R08: ffff987191150020 R09: 0000000000000003
>>>> R10: 0000000000000006 R11: 0000000000000000 R12: ffffe5d8c44f4a00
>>>> R13: ffffb0800c2abb60 R14: 0000000000000000 R15: ffffe5d8c44f4a00
>>>> FS: 00007f1d25d6f080(0000) GS:ffff987277c00000(0000) knlGS:0000000000000000
>>>> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>>>> CR2: 0000000000000000 CR3: 000000013cce0005 CR4: 0000000000170ef0
>>>> Call Trace:
>>>> <TASK>
>>>> ? __die_body.cold+0x19/0x27
>>>> ? page_fault_oops+0xca/0x2a0
>>>> ? search_module_extables+0x19/0x60
>>>> ? search_bpf_extables+0x5f/0x80
>>>> ? exc_page_fault+0x7e/0x180
>>>> ? asm_exc_page_fault+0x26/0x30
>>>> ? nfs_folio_length+0x29/0x170 [nfs]
>>>> trace_event_raw_event_nfs_folio_event_done+0xdc/0x170 [nfs]
>>>> nfs_read_folio+0x16d/0x260 [nfs]
>>>> ? __pfx_nfs_read_folio+0x10/0x10 [nfs]
>>>> filemap_read_folio+0x43/0xe0
>>>> filemap_fault+0x70d/0xd00
>>>> __do_fault+0x35/0x120
>>>> do_fault+0xbb/0x470
>>>> __handle_mm_fault+0x7e9/0x1060
>>>> ? mt_find+0x21c/0x570
>>>> handle_mm_fault+0xf0/0x300
>>>> do_user_addr_fault+0x217/0x620
>>>> exc_page_fault+0x7e/0x180
>>>> asm_exc_page_fault+0x26/0x30
>>>> RIP: 0033:0x7f1d25ecedb7
>>>> Code: 7e 6f 44 16 e0 48 29 fe 48 83 e1 e0 48 01 ce 0f 1f 40 00 c5 fe 6f 4e 60 c5 fe 6f 56 40 c5 fe 6f 5e 20 c5 fe 6f 26 48 83 c6 80 <c5> fd 7f 49 60 c5 fd 7f 51 40 c5 fd 7f 59 20 c5 fd 7f 21 48 83 c1
>>>> RSP: 002b:00007ffd92df7f58 EFLAGS: 00010203
>>>> RAX: 00007f1d1d0e6000 RBX: 000056211867f6c0 RCX: 00007f1d1d0e6f60
>>>> RDX: 0000000000001000 RSI: 0000562118699ee0 RDI: 00007f1d1d0e6000
>>>> RBP: 00007ffd92df7f70 R08: 0000000000000000 R09: 0000000000000000
>>>> R10: 0000562118688f30 R11: 0000000000000001 R12: 00007f1d1d16aac0
>>>> R13: 00007ffd92df8030 R14: 0000000000000001 R15: 0000000000001000
>>>> </TASK>
>>>> Modules linked in: blocklayoutdriver rpcsec_gss_krb5 auth_rpcgss nfsv4 dns_resolver nfs lockd grace iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_c>
>>>> CR2: 0000000000000000
>>>> ---[ end trace 0000000000000000 ]---
>>>> RIP: 0010:nfs_folio_length+0x29/0x170 [nfs]
>>>> Code: 90 41 56 41 55 41 54 55 53 48 89 fb 48 83 ec 08 48 8b 07 a9 00 00 04 00 74 0c 48 8b 07 f6 c4 08 0f 85 89 00 00 00 48 8b 43 18 <48> 8b 00 48 8b 68 50 48 85 ed 7e 66 48 8b 03 a8 40 74 7c 4c 8b 6b
>>>> RSP: 0018:ffffb0800c2abb28 EFLAGS: 00010246
>>>> RAX: 0000000000000000 RBX: ffffe5d8c44f4a00 RCX: ffffffffa8525000
>>>> RDX: 0017ffffd0000028 RSI: 000000000000004e RDI: ffffe5d8c44f4a00
>>>> RBP: ffff9871911501b8 R08: ffff987191150020 R09: 0000000000000003
>>>> R10: 0000000000000006 R11: 0000000000000000 R12: ffffe5d8c44f4a00
>>>> R13: ffffb0800c2abb60 R14: 0000000000000000 R15: ffffe5d8c44f4a00
>>>> FS: 00007f1d25d6f080(0000) GS:ffff987277c00000(0000) knlGS:0000000000000000
>>>> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>>>> CR2: 0000000000000000 CR3: 000000013cce0005 CR4: 0000000000170ef0
>>>>
>>>> cel@renoir:linux$ scripts/faddr2line fs/nfs/nfs.ko nfs_folio_length+0x29
>>>> nfs_folio_length+0x29/0x170:
>>>> nfs_folio_length at /home/cel/src/kdevops/cel/linux/fs/nfs/internal.h:824 (discriminator 1)
>>>>
>>>> Which in my version of the source code is:
>>>>
>>>> 822 static inline size_t nfs_folio_length(struct folio *folio)
>>>> 823 {
>>>> 824 loff_t i_size = i_size_read(folio_file_mapping(folio)->host);
>>>>
>>>
>>> Ok so looks like we need to go deeper to know what the NULL pointer
>>> represented in the BUG statement.
>>> Decoding the oops:
>>> $ ~/git/kernel/scripts/decodecode < ./oops.txt
>>> Code: 90 41 56 41 55 41 54 55 53 48 89 fb 48 83 ec 08 48 8b 07 a9 00
>>> 00 04 00 74 0c 48 8b 07 f6 c4 08 0f 85 89 00 00 00 48 8b 43 18 <48> 8b
>>> 00 48 8b 68 50 48 85 ed 7e 66 48 8b 03 a8 40 74 7c 4c 8b 6b
>>> All code
>>> ========
>>> 0: 90 nop
>>> 1: 41 56 push %r14
>>> 3: 41 55 push %r13
>>> 5: 41 54 push %r12
>>> 7: 55 push %rbp
>>> 8: 53 push %rbx
>>> 9: 48 89 fb mov %rdi,%rbx
>>> c: 48 83 ec 08 sub $0x8,%rsp
>>> 10: 48 8b 07 mov (%rdi),%rax
>>> 13: a9 00 00 04 00 test $0x40000,%eax
>>> 18: 74 0c je 0x26
>>> 1a: 48 8b 07 mov (%rdi),%rax
>>> 1d: f6 c4 08 test $0x8,%ah
>>> 20: 0f 85 89 00 00 00 jne 0xaf
>>> 26: 48 8b 43 18 mov 0x18(%rbx),%rax
>>> 2a:* 48 8b 00 mov (%rax),%rax <-- trapping instruction
>>> 2d: 48 8b 68 50 mov 0x50(%rax),%rbp
>>> 31: 48 85 ed test %rbp,%rbp
>>> 34: 7e 66 jle 0x9c
>>> 36: 48 8b 03 mov (%rbx),%rax
>>> 39: a8 40 test $0x40,%al
>>> 3b: 74 7c je 0xb9
>>> 3d: 4c rex.WR
>>> 3e: 8b .byte 0x8b
>>> 3f: 6b .byte 0x6b
>>>
>>> Code starting with the faulting instruction
>>> ===========================================
>>> 0: 48 8b 00 mov (%rax),%rax
>>> 3: 48 8b 68 50 mov 0x50(%rax),%rbp
>>> 7: 48 85 ed test %rbp,%rbp
>>> a: 7e 66 jle 0x72
>>> c: 48 8b 03 mov (%rbx),%rax
>>> f: a8 40 test $0x40,%al
>>> 11: 74 7c je 0x8f
>>> 13: 4c rex.WR
>>> 14: 8b .byte 0x8b
>>> 15: 6b .byte 0x6b
>>>
>>>
>>> Snip out the essential instructions, which shows we just have read an
>>> address at an offset of 0x18, then that must have been NULL and we
>>> tried to dereference NULL which led to the BUG:
>>> 9: 48 89 fb mov %rdi,%rbx
>>> ...
>>> 26: 48 8b 43 18 mov 0x18(%rbx),%rax
>>> 2a:* 48 8b 00 mov (%rax),%rax <-- trapping instruction
>>>
>>> So the question is what is at offset 0x18 in the above code in
>>> nfs_folio_length()?
>>> Now folio_file_mapping() returns an address_space pointer ,and
>>> address_space->host is at offset 0.
>>> So if 'mapping' is at offset 0x18 of folio, then mapping is NULL. And
>>> from the code, this seems to fit.
>>>
>>> 310 struct folio {
>>> 311 /* private: don't document the anon union */
>>> 312 union {
>>> 313 struct {
>>> 314 /* public: */
>>> 315 unsigned long flags;
>>> 316 union {
>>> 317 struct list_head lru;
>>> 318 /* private: avoid cluttering the output */
>>> 319 struct {
>>> 320 void *__filler;
>>> 321 /* public: */
>>> 322 unsigned int mlock_count;
>>> 323 /* private: */
>>> 324 };
>>> 325 /* public: */
>>> 326 };
>>> 327 struct address_space *mapping;
>>> 328 pgoff_t index;
>>>
>>>
>>> 445 static inline struct address_space *folio_file_mapping(struct folio *folio)
>>> 446 {
>>> 447 if (unlikely(folio_test_swapcache(folio)))
>>> 448 return swapcache_mapping(folio);
>>> 449
>>> 450 return folio->mapping;
>>> 451 }
>>>
>>> So it seems folio->mapping == NULL and that is why we BUG.
>>>
>>>
>>>> I'm pinging you first about this because you changed the
>>>> code around the trace_nfs_aop_read_done() call site in
>>>> commit 000dbe0bec05 ("NFS: Convert buffered read paths to
>>>> use netfs when fscache is enabled").
>>>>
>>>
>>> If I have the above analysis right, then maybe this patch would fix it?
>>> Also I wonder if nfs_page_length() might have the same issue?
>>>
>>> diff --git a/fs/nfs/internal.h b/fs/nfs/internal.h
>>> index 9f0f4534744b..832f07994b88 100644
>>> --- a/fs/nfs/internal.h
>>> +++ b/fs/nfs/internal.h
>>> @@ -821,7 +821,12 @@ unsigned int nfs_page_length(struct page *page)
>>> */
>>> static inline size_t nfs_folio_length(struct folio *folio)
>>> {
>>> - loff_t i_size = i_size_read(folio_file_mapping(folio)->host);
>>> + loff_t i_size;
>>> +
>>> + if (!folio->mapping)
>>> + return 0;
>>> +
>>> + i_size = i_size_read(folio_file_mapping(folio)->host);
>>>
>>> if (i_size > 0) {
>>> pgoff_t index = folio_index(folio) >> folio_order(folio);
>>
>> Execution passed trace_nfs_aop_readpage() without incident,
>> so folio->mapping was a valid pointer as we entered
>> nfs_read_folio().
>>
>> What I don't understand is whether you expect folio->mapping
>> to become NULL while nfs_read_folio() is running.
>>
>
> Was your test running both reads and truncates on the same file in parallel?
I didn't record it in my notes, but IIRC I was running fstests.
I'm pretty sure one or more of the fsx-based tests will do this.
--
Chuck Lever
