Re: [syzbot] [mm?] BUG: Bad page state in iomap_write_begin

[David Hildenbrand <david@redhat.com>]

On 21.11.24 10:46, David Hildenbrand wrote:
> On 21.11.24 10:26, David Hildenbrand wrote:
>> On 20.11.24 09:37, syzbot wrote:
>>> Hello,
>>>
>>> syzbot found the following issue on:
>>>
>>> HEAD commit:    e8bdb3c8be08 Merge tag 'riscv-for-linus-6.12-rc8' of git:/..
>>> git tree:       upstream
>>> console output: https://syzkaller.appspot.com/x/log.txt?x=1644d2c0580000
>>> kernel config:  https://syzkaller.appspot.com/x/.config?x=d2aeec8c0b2e420c
>>> dashboard link: https://syzkaller.appspot.com/bug?extid=c317c107c68f8bc257d9
>>> compiler:       Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40
>>> syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=1144d2c0580000
>>> C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=176252e8580000
>>>
>>> Downloadable assets:
>>> disk image (non-bootable): https://storage.googleapis.com/syzbot-assets/7feb34a89c2a/non_bootable_disk-e8bdb3c8.raw.xz
>>> vmlinux: https://storage.googleapis.com/syzbot-assets/fcae16ff0e0f/vmlinux-e8bdb3c8.xz
>>> kernel image: https://storage.googleapis.com/syzbot-assets/758973beace8/bzImage-e8bdb3c8.xz
>>> mounted in repro #1: https://storage.googleapis.com/syzbot-assets/a097a300c8a9/mount_0.gz
>>> mounted in repro #2: https://storage.googleapis.com/syzbot-assets/36b9fff6ab5e/mount_6.gz
>>>
>>> IMPORTANT: if you fix the issue, please add the following tag to the commit:
>>> Reported-by: syzbot+c317c107c68f8bc257d9@syzkaller.appspotmail.com
>>>
>>> BUG: Bad page state in process syz-executor315  pfn:49e01
>>> page: refcount:0 mapcount:0 mapping:0000000000000000 index:0x1 pfn:0x49e01
>>> head: order:0 mapcount:0 entire_mapcount:0 nr_pages_mapped:0 pincount:-1
>>
>> So, we have a pincount underflow on a large folio (order-9). We
>> allocated the folio in iomap_write_begin()->__iomap_get_folio(). Nothing
>> special.
>>
>> [...]
>>
>>>     </TASK>
>>> BUG: Bad page state in process syz-executor315  pfn:49e00
>>> page: refcount:0 mapcount:0 mapping:0000000000000000 index:0x0 pfn:0x49e00
>>> head: order:0 mapcount:0 entire_mapcount:0 nr_pages_mapped:0 pincount:0
>>> flags: 0x4fff0000000004d(locked|referenced|uptodate|head|node=1|zone=1|lastcpupid=0x7ff)
>>> raw: 04fff0000000004d dead000000000100 dead000000000122 0000000000000000
>>> raw: 0000000000000000 0000000000000000 00000000ffffffff 0000000000000000
>>> head: 04fff0000000004d dead000000000100 dead000000000122 0000000000000000
>>> head: 0000000000000000 0000000000000000 00000000ffffffff 0000000000000000
>>> head: 04fff00000000000 0000000000000000 ffffffffffffffff 0000000000000000
>>> head: 0000000000000200 0000000000000000 00000000ffffffff 0000000000000000
>>> page dumped because: PAGE_FLAGS_CHECK_AT_FREE flag(s) set
>>
>> And we seem to have an unexpected flag set on the head page of the same
>> large folio. Likely PG_locked.
>>
>> ...
>>
>>> XFS (loop0): Unmounting Filesystem 9f1cad42-11bd-4e12-8f0b-f07876b81d9a
>>> BUG: Bad page state in process syz-executor315  pfn:49c01
>>> page: refcount:0 mapcount:0 mapping:0000000000000000 index:0x1 pfn:0x49c01
>>> head: order:0 mapcount:0 entire_mapcount:0 nr_pages_mapped:0 pincount:-1
>>> flags: 0x4fff0000000004d(locked|referenced|uptodate|head|node=1|zone=1|lastcpupid=0x7ff)
>>> raw: 04fff00000000000 ffffea0001270001 ffffffffffffffff ffffffff00000000
>>> raw: 0000000000000200 0000000000000000 00000000ffffffff 0000000000000000
>>> head: 04fff0000000004d dead000000000100 dead000000000122 0000000000000000
>>> head: 0000000000000000 0000000000000000 00000000ffffffff 0000000000000000
>>> head: 04fff00000000000 ffffea0001270001 ffffffffffffffff ffffffff00000000
>>> head: 0000000000000200 0000000000000000 00000000ffffffff 0000000000000000
>>> page dumped because: nonzero pincount
>>
>> [...]
>>
>>>     </TASK>
>>> BUG: Bad page state in process syz-executor315  pfn:49c00
>>> page: refcount:0 mapcount:0 mapping:0000000000000000 index:0x0 pfn:0x49c00
>>> head: order:0 mapcount:0 entire_mapcount:0 nr_pages_mapped:0 pincount:0
>>> flags: 0x4fff0000000004d(locked|referenced|uptodate|head|node=1|zone=1|lastcpupid=0x7ff)
>>> raw: 04fff0000000004d dead000000000100 dead000000000122 0000000000000000
>>> raw: 0000000000000000 0000000000000000 00000000ffffffff 0000000000000000
>>> head: 04fff0000000004d dead000000000100 dead000000000122 0000000000000000
>>> head: 0000000000000000 0000000000000000 00000000ffffffff 0000000000000000
>>> head: 04fff00000000000 0000000000000000 ffffffffffffffff 0000000000000000
>>> head: 0000000000000200 0000000000000000 00000000ffffffff 0000000000000000
>>> page dumped because: PAGE_FLAGS_CHECK_AT_FREE flag(s) set
>>> page_owner tracks the page as allocated
>>
>> Same thing, different folio.
>>
>>
>> So we seem to be repeatedly freeing a large folio that
>> (a) Is locked
>> (b) Has a pincount underflow
>>
>> Likely because we have an unbalanced unpin, that happens before
>> evicting/truncating the folio. If we then evict/truncate the (locked)
>> folio, we free the folio before unlocking it and dropping the actual
>> last reference.
>>
>> Not sure why we see a comparable thing with small folios (pincount part
>> of refcount, but on unpin our refcount should seriously underflow
>> immediately)
>>
>> CCing David
> 
> If I get the reproducer right, it does:
> 
> (1) Create a temporary folder and chdir into it
> 
> (2) Mounts an (XFS?) image (syz_mount_image() magic )
> 
> (3) Opens a file1 in there
> 
> (4) Writes some data into it using write(). Likely this allocates the
> folios.
> 
> (5) Mmaps the file1 (MAP_UNINITIALIZED|MAP_LOCKED|MAP_FIXED|MAP_SHARED)
> 
> (6) Creates a socket -- socket() -- and binds it -- bind().
> 
> (7) Writes some more data into the mmap of file1 using memcpy.
> 
> (8) Mounts another (?) image (syz_mount_image() magic )
> 
> (9) Opens a file2 in there with O_SYNC|O_DIRECT|O_CREAT|O_RDWR.
> 
> (10) Calls ioctl(0xc0185879) on the file2
> 
> (11) Calls sendmsg() on the socket. msghdr and all data seems to reside
> completely in the mmap of file1.
> 
> (12) Calls symlink(0,0)
> 
> (13) Calls rename(0,0)
> 
> 
> I doubt 12+13 are relevant. Likely (11) is the problematic bit: we are
> performing direct-io on folios allocated during (4) from file1 into file2.
> 
> I have not deciphered yet what the ioctl in (10) does.

Seems to be FITRIM.

-- 
Cheers,

David / dhildenb