2022-05-20 23:46:17

by Tadeusz Struk

[permalink] [raw]
Subject: Re: kernel BUG in ext4_writepages

On 5/20/22 02:50, Jan Kara wrote:
> On Thu 19-05-22 16:14:17, Tadeusz Struk wrote:
>> On 5/19/22 05:23, Jan Kara wrote:
>>> Hi!
>>>
>>> On Tue 10-05-22 15:28:38, Tadeusz Struk wrote:
>>>> Syzbot found another BUG in ext4_writepages [1].
>>>> This time it complains about inode with inline data.
>>>> C reproducer can be found here [2]
>>>> I was able to trigger it on 5.18.0-rc6
>>>>
>>>> [1] https://syzkaller.appspot.com/bug?id=a1e89d09bbbcbd5c4cb45db230ee28c822953984
>>>> [2] https://syzkaller.appspot.com/text?tag=ReproC&x=129da6caf00000
>>>
>>> Thanks for report. This should be fixed by:
>>>
>>> https://lore.kernel.org/all/[email protected]/
>>
>>
>> In case of the syzbot bug there is something messed up with PAGE DIRTY flags
>> and the way syzbot sets up the write. This is what triggers the crash:
>
> Can you tell me where exactly we hit the bug? I've now noticed that this is
> on 5.10 kernel and on vanilla 5.10 there's no BUG_ON on line 2753.

We are hiting this bug:
https://elixir.bootlin.com/linux/latest/source/fs/ext4/inode.c#L2707
Syzbot found it in v5.10, but I recreated it on 5.18-rc7, that's why
the line number mismatch. But this is the same bug.
On 5.10 it's in line 2739:
https://elixir.bootlin.com/linux/v5.10.117/source/fs/ext4/inode.c#L2739

>
>> $ ftrace -f ./repro
>> ...
>> [pid 2395] open("./bus", O_RDWR|O_CREAT|O_SYNC|O_NOATIME, 000 <unfinished ...>
>> [pid 2395] <... open resumed> ) = 6
>> ...
>> [pid 2395] write(6, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 22 <unfinished ...>
>> ...
>> [pid 2395] <... write resumed> ) = 22
>>
>> One way I could fix it was to clear the PAGECACHE_TAG_DIRTY on the mapping in
>> ext4_try_to_write_inline_data() after the page has been updated:
>>
>> diff --git a/fs/ext4/inline.c b/fs/ext4/inline.c
>> index 9c076262770d..e4bbb53fa26f 100644
>> --- a/fs/ext4/inline.c
>> +++ b/fs/ext4/inline.c
>> @@ -715,6 +715,7 @@ int ext4_try_to_write_inline_data(struct address_space *mapping,
>> put_page(page);
>> goto out_up_read;
>> }
>> + __xa_clear_mark(&mapping->i_pages, 0, PAGECACHE_TAG_DIRTY);
>> }
>> ret = 1;
>>
>> Please let me know it if makes sense any I will send a proper patch.
>
> No, this looks really wrong... We need to better understand what's going
> on.

So I was afraid. I'm trying to diverge the ext4_writepages() to go to the
out_writepages path before we hit this BOG_ON().
Any hints will be much appreciated.

--
Thanks,
Tadeusz


2022-07-26 22:47:04

by Tadeusz Struk

[permalink] [raw]
Subject: [PATCH] ext4: try to flush inline data before calling BUG in writepages

Fix a syzbot issue, which triggers a BUG in ext4_writepags.
The syzbot creates and monuts an ext4 fs image on /dev/loop0.
The image is corrupted, which is probably the source of the
problems, but the mount operation finishes successfully.
Then the repro program creates a file on the mounted fs, and
eventually it writes a buff of 22 zero bytes to it as below:

memfd_create("syzkaller", 0) = 3
ftruncate(3, 2097152) = 0
pwrite64(3, " \0\0\0\0\2\0\0\31\0\0\0\220\1\0\0\17\0\0\0\0\0\0\0\2\0\0\0\6\0\0\0"..., 102, 1024) = 102
pwrite64(3, "\0\0\0\0\0\0\0\0\0\0\0\0\202\343g$\306\363L\252\204n\322\345'p3x\1\[email protected]", 31, 1248) = 31
pwrite64(3, "\2\0\0\0\3\0\0\0\4\0\0\0\31\0\17\0\3\0\4\0\0\0\0\0\0\0\0\0\17\0.i", 32, 4096) = 32
pwrite64(3, "\177\0\0\0\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377"..., 4098, 8192) = 4098
pwrite64(3, "\355A\0\0\20\0\0\0\332\364e_\333\364e_\333\364e_\0\0\0\0\0\0\4\0\200\0\0\0"..., 61, 17408) = 61
openat(AT_FDCWD, "/dev/loop0", O_RDWR) = 4
ioctl(4, LOOP_SET_FD, 3) = 0
mkdir("./file0", 0777) = -1 EEXIST (File exists)
mount("/dev/loop0", "./file0", "ext4", 0, ",errors=continue") = 0
openat(AT_FDCWD, "./file0", O_RDONLY|O_DIRECTORY) = 5
ioctl(4, LOOP_CLR_FD) = 0
close(4) = 0
close(3) = 0
chdir("./file0") = 0
creat("./bus", 000) = 3
open("./bus", O_RDWR|O_CREAT|O_NONBLOCK|O_SYNC|O_DIRECT|O_LARGEFILE|O_NOATIME, 000) = 4
openat(AT_FDCWD, "/proc/self/exe", O_RDONLY) = 6
sendfile(4, 6, NULL, 2147483663) = 1638400
open("./bus", O_RDWR|O_CREAT|O_SYNC|O_NOATIME, 000) = 7
write(7, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 22) <unfinished ...>

This triggers a BUG in ext4_writepages(), where it checks if
the inode has inline data, just before deleting it:

kernel BUG at fs/ext4/inode.c:2721!
invalid opcode: 0000 [#1] PREEMPT SMP KASAN
CPU: 0 PID: 359 Comm: repro Not tainted 5.19.0-rc8-00001-g31ba1e3b8305-dirty #15
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.0-1.fc36 04/01/2014
RIP: 0010:ext4_writepages+0x363d/0x3660
RSP: 0018:ffffc90000ccf260 EFLAGS: 00010293
RAX: ffffffff81e1abcd RBX: 0000008000000000 RCX: ffff88810842a180
RDX: 0000000000000000 RSI: 0000008000000000 RDI: 0000000000000000
RBP: ffffc90000ccf650 R08: ffffffff81e17d58 R09: ffffed10222c680b
R10: dfffe910222c680c R11: 1ffff110222c680a R12: ffff888111634128
R13: ffffc90000ccf880 R14: 0000008410000000 R15: 0000000000000001
FS: 00007f72635d2640(0000) GS:ffff88811b000000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000565243379180 CR3: 000000010aa74000 CR4: 0000000000150eb0
Call Trace:
<TASK>
do_writepages+0x397/0x640
filemap_fdatawrite_wbc+0x151/0x1b0
file_write_and_wait_range+0x1c9/0x2b0
ext4_sync_file+0x19e/0xa00
vfs_fsync_range+0x17b/0x190
ext4_buffered_write_iter+0x488/0x530
ext4_file_write_iter+0x449/0x1b90
vfs_write+0xbcd/0xf40
ksys_write+0x198/0x2c0
__x64_sys_write+0x7b/0x90
do_syscall_64+0x3d/0x90
entry_SYSCALL_64_after_hwframe+0x63/0xcd
</TASK>

This can be prevented by forcing the inline data to be converted
and/or flushed beforehand.
This patch adds a call to ext4_convert_inline_data() just before
the BUG, which fixes the issue.

Link: https://syzkaller.appspot.com/bug?id=a1e89d09bbbcbd5c4cb45db230ee28c822953984
Reported-by: [email protected]
Signed-off-by: Tadeusz Struk <[email protected]>
---
fs/ext4/inode.c | 4 ++++
1 file changed, 4 insertions(+)

diff --git a/fs/ext4/inode.c b/fs/ext4/inode.c
index 84c0eb55071d..de2aa2e79052 100644
--- a/fs/ext4/inode.c
+++ b/fs/ext4/inode.c
@@ -2717,6 +2717,10 @@ static int ext4_writepages(struct address_space *mapping,
ret = PTR_ERR(handle);
goto out_writepages;
}
+
+ if (ext4_test_inode_state(inode, EXT4_STATE_MAY_INLINE_DATA))
+ WARN_ON(ext4_convert_inline_data(inode));
+
BUG_ON(ext4_test_inode_state(inode,
EXT4_STATE_MAY_INLINE_DATA));
ext4_destroy_inline_data(handle, inode);
--
2.37.1

2022-07-27 16:01:21

by Jan Kara

[permalink] [raw]
Subject: Re: [PATCH] ext4: try to flush inline data before calling BUG in writepages

On Tue 26-07-22 15:44:28, Tadeusz Struk wrote:
> Fix a syzbot issue, which triggers a BUG in ext4_writepags.
> The syzbot creates and monuts an ext4 fs image on /dev/loop0.
> The image is corrupted, which is probably the source of the
> problems, but the mount operation finishes successfully.
> Then the repro program creates a file on the mounted fs, and
> eventually it writes a buff of 22 zero bytes to it as below:
>
> memfd_create("syzkaller", 0) = 3
> ftruncate(3, 2097152) = 0
> pwrite64(3, " \0\0\0\0\2\0\0\31\0\0\0\220\1\0\0\17\0\0\0\0\0\0\0\2\0\0\0\6\0\0\0"..., 102, 1024) = 102
> pwrite64(3, "\0\0\0\0\0\0\0\0\0\0\0\0\202\343g$\306\363L\252\204n\322\345'p3x\1\[email protected]", 31, 1248) = 31
> pwrite64(3, "\2\0\0\0\3\0\0\0\4\0\0\0\31\0\17\0\3\0\4\0\0\0\0\0\0\0\0\0\17\0.i", 32, 4096) = 32
> pwrite64(3, "\177\0\0\0\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377"..., 4098, 8192) = 4098
> pwrite64(3, "\355A\0\0\20\0\0\0\332\364e_\333\364e_\333\364e_\0\0\0\0\0\0\4\0\200\0\0\0"..., 61, 17408) = 61
> openat(AT_FDCWD, "/dev/loop0", O_RDWR) = 4
> ioctl(4, LOOP_SET_FD, 3) = 0
> mkdir("./file0", 0777) = -1 EEXIST (File exists)
> mount("/dev/loop0", "./file0", "ext4", 0, ",errors=continue") = 0
> openat(AT_FDCWD, "./file0", O_RDONLY|O_DIRECTORY) = 5
> ioctl(4, LOOP_CLR_FD) = 0
> close(4) = 0
> close(3) = 0
> chdir("./file0") = 0
> creat("./bus", 000) = 3
> open("./bus", O_RDWR|O_CREAT|O_NONBLOCK|O_SYNC|O_DIRECT|O_LARGEFILE|O_NOATIME, 000) = 4
> openat(AT_FDCWD, "/proc/self/exe", O_RDONLY) = 6
> sendfile(4, 6, NULL, 2147483663) = 1638400
> open("./bus", O_RDWR|O_CREAT|O_SYNC|O_NOATIME, 000) = 7
> write(7, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 22) <unfinished ...>
>
> This triggers a BUG in ext4_writepages(), where it checks if
> the inode has inline data, just before deleting it:

Thanks for your persistence looking into this! :) I'll note that you
actually miss one important call in the trace: ftruncate(3, 1)

With that I can indeed reproduce the crash (after some more tweaking
because for me /proc/self/exe does not have size which is multiple of 4k
and so sendfile() was failing for me initially).

> kernel BUG at fs/ext4/inode.c:2721!
> invalid opcode: 0000 [#1] PREEMPT SMP KASAN
> CPU: 0 PID: 359 Comm: repro Not tainted 5.19.0-rc8-00001-g31ba1e3b8305-dirty #15
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.0-1.fc36 04/01/2014
> RIP: 0010:ext4_writepages+0x363d/0x3660
> RSP: 0018:ffffc90000ccf260 EFLAGS: 00010293
> RAX: ffffffff81e1abcd RBX: 0000008000000000 RCX: ffff88810842a180
> RDX: 0000000000000000 RSI: 0000008000000000 RDI: 0000000000000000
> RBP: ffffc90000ccf650 R08: ffffffff81e17d58 R09: ffffed10222c680b
> R10: dfffe910222c680c R11: 1ffff110222c680a R12: ffff888111634128
> R13: ffffc90000ccf880 R14: 0000008410000000 R15: 0000000000000001
> FS: 00007f72635d2640(0000) GS:ffff88811b000000(0000) knlGS:0000000000000000
> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 0000565243379180 CR3: 000000010aa74000 CR4: 0000000000150eb0
> Call Trace:
> <TASK>
> do_writepages+0x397/0x640
> filemap_fdatawrite_wbc+0x151/0x1b0
> file_write_and_wait_range+0x1c9/0x2b0
> ext4_sync_file+0x19e/0xa00
> vfs_fsync_range+0x17b/0x190
> ext4_buffered_write_iter+0x488/0x530
> ext4_file_write_iter+0x449/0x1b90
> vfs_write+0xbcd/0xf40
> ksys_write+0x198/0x2c0
> __x64_sys_write+0x7b/0x90
> do_syscall_64+0x3d/0x90
> entry_SYSCALL_64_after_hwframe+0x63/0xcd
> </TASK>
>
> This can be prevented by forcing the inline data to be converted
> and/or flushed beforehand.
> This patch adds a call to ext4_convert_inline_data() just before
> the BUG, which fixes the issue.

This is just papering over the real problem, which is that direct IO that
allocated blocks to the file did not clear EXT4_STATE_MAY_INLINE_DATA. I'll
send a better fix.

Honza

>
> Link: https://syzkaller.appspot.com/bug?id=a1e89d09bbbcbd5c4cb45db230ee28c822953984
> Reported-by: [email protected]
> Signed-off-by: Tadeusz Struk <[email protected]>
> ---
> fs/ext4/inode.c | 4 ++++
> 1 file changed, 4 insertions(+)
>
> diff --git a/fs/ext4/inode.c b/fs/ext4/inode.c
> index 84c0eb55071d..de2aa2e79052 100644
> --- a/fs/ext4/inode.c
> +++ b/fs/ext4/inode.c
> @@ -2717,6 +2717,10 @@ static int ext4_writepages(struct address_space *mapping,
> ret = PTR_ERR(handle);
> goto out_writepages;
> }
> +
> + if (ext4_test_inode_state(inode, EXT4_STATE_MAY_INLINE_DATA))
> + WARN_ON(ext4_convert_inline_data(inode));
> +
> BUG_ON(ext4_test_inode_state(inode,
> EXT4_STATE_MAY_INLINE_DATA));
> ext4_destroy_inline_data(handle, inode);
> --
> 2.37.1
--
Jan Kara <[email protected]>
SUSE Labs, CR

2022-07-27 18:34:07

by Lukas Czerner

[permalink] [raw]
Subject: Re: [PATCH] ext4: try to flush inline data before calling BUG in writepages

On Tue, Jul 26, 2022 at 03:44:28PM -0700, Tadeusz Struk wrote:
> Fix a syzbot issue, which triggers a BUG in ext4_writepags.
> The syzbot creates and monuts an ext4 fs image on /dev/loop0.
> The image is corrupted, which is probably the source of the
> problems, but the mount operation finishes successfully.
> Then the repro program creates a file on the mounted fs, and
> eventually it writes a buff of 22 zero bytes to it as below:
>
> memfd_create("syzkaller", 0) = 3
> ftruncate(3, 2097152) = 0
> pwrite64(3, " \0\0\0\0\2\0\0\31\0\0\0\220\1\0\0\17\0\0\0\0\0\0\0\2\0\0\0\6\0\0\0"..., 102, 1024) = 102
> pwrite64(3, "\0\0\0\0\0\0\0\0\0\0\0\0\202\343g$\306\363L\252\204n\322\345'p3x\1\[email protected]", 31, 1248) = 31
> pwrite64(3, "\2\0\0\0\3\0\0\0\4\0\0\0\31\0\17\0\3\0\4\0\0\0\0\0\0\0\0\0\17\0.i", 32, 4096) = 32
> pwrite64(3, "\177\0\0\0\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377"..., 4098, 8192) = 4098
> pwrite64(3, "\355A\0\0\20\0\0\0\332\364e_\333\364e_\333\364e_\0\0\0\0\0\0\4\0\200\0\0\0"..., 61, 17408) = 61
> openat(AT_FDCWD, "/dev/loop0", O_RDWR) = 4
> ioctl(4, LOOP_SET_FD, 3) = 0
> mkdir("./file0", 0777) = -1 EEXIST (File exists)
> mount("/dev/loop0", "./file0", "ext4", 0, ",errors=continue") = 0
> openat(AT_FDCWD, "./file0", O_RDONLY|O_DIRECTORY) = 5
> ioctl(4, LOOP_CLR_FD) = 0
> close(4) = 0
> close(3) = 0
> chdir("./file0") = 0
> creat("./bus", 000) = 3
> open("./bus", O_RDWR|O_CREAT|O_NONBLOCK|O_SYNC|O_DIRECT|O_LARGEFILE|O_NOATIME, 000) = 4
> openat(AT_FDCWD, "/proc/self/exe", O_RDONLY) = 6
> sendfile(4, 6, NULL, 2147483663) = 1638400
> open("./bus", O_RDWR|O_CREAT|O_SYNC|O_NOATIME, 000) = 7
> write(7, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 22) <unfinished ...>
>
> This triggers a BUG in ext4_writepages(), where it checks if
> the inode has inline data, just before deleting it:
>
> kernel BUG at fs/ext4/inode.c:2721!
> invalid opcode: 0000 [#1] PREEMPT SMP KASAN
> CPU: 0 PID: 359 Comm: repro Not tainted 5.19.0-rc8-00001-g31ba1e3b8305-dirty #15
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.0-1.fc36 04/01/2014
> RIP: 0010:ext4_writepages+0x363d/0x3660
> RSP: 0018:ffffc90000ccf260 EFLAGS: 00010293
> RAX: ffffffff81e1abcd RBX: 0000008000000000 RCX: ffff88810842a180
> RDX: 0000000000000000 RSI: 0000008000000000 RDI: 0000000000000000
> RBP: ffffc90000ccf650 R08: ffffffff81e17d58 R09: ffffed10222c680b
> R10: dfffe910222c680c R11: 1ffff110222c680a R12: ffff888111634128
> R13: ffffc90000ccf880 R14: 0000008410000000 R15: 0000000000000001
> FS: 00007f72635d2640(0000) GS:ffff88811b000000(0000) knlGS:0000000000000000
> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 0000565243379180 CR3: 000000010aa74000 CR4: 0000000000150eb0
> Call Trace:
> <TASK>
> do_writepages+0x397/0x640
> filemap_fdatawrite_wbc+0x151/0x1b0
> file_write_and_wait_range+0x1c9/0x2b0
> ext4_sync_file+0x19e/0xa00
> vfs_fsync_range+0x17b/0x190
> ext4_buffered_write_iter+0x488/0x530
> ext4_file_write_iter+0x449/0x1b90
> vfs_write+0xbcd/0xf40
> ksys_write+0x198/0x2c0
> __x64_sys_write+0x7b/0x90
> do_syscall_64+0x3d/0x90
> entry_SYSCALL_64_after_hwframe+0x63/0xcd
> </TASK>
>
> This can be prevented by forcing the inline data to be converted
> and/or flushed beforehand.
> This patch adds a call to ext4_convert_inline_data() just before
> the BUG, which fixes the issue.
>
> Link: https://syzkaller.appspot.com/bug?id=a1e89d09bbbcbd5c4cb45db230ee28c822953984
> Reported-by: [email protected]
> Signed-off-by: Tadeusz Struk <[email protected]>
> ---
> fs/ext4/inode.c | 4 ++++
> 1 file changed, 4 insertions(+)
>
> diff --git a/fs/ext4/inode.c b/fs/ext4/inode.c
> index 84c0eb55071d..de2aa2e79052 100644
> --- a/fs/ext4/inode.c
> +++ b/fs/ext4/inode.c
> @@ -2717,6 +2717,10 @@ static int ext4_writepages(struct address_space *mapping,
> ret = PTR_ERR(handle);
> goto out_writepages;
> }
> +
> + if (ext4_test_inode_state(inode, EXT4_STATE_MAY_INLINE_DATA))
> + WARN_ON(ext4_convert_inline_data(inode));
> +

Hi Tadeusz,

I don't think this is the right fix. We're in ext4_writepages, so at
this point I don't think an inode should have any actual inline data in
it. If it does it's a bug and the question is how did this get here?

The inode is likely corrupted and it should have been noticed earliler
and it should never get here.

-Lukas

> BUG_ON(ext4_test_inode_state(inode,
> EXT4_STATE_MAY_INLINE_DATA));
> ext4_destroy_inline_data(handle, inode);
> --
> 2.37.1
>

2022-07-27 18:44:40

by Tadeusz Struk

[permalink] [raw]
Subject: Re: [PATCH] ext4: try to flush inline data before calling BUG in writepages

Hi Lukas,
On 7/27/22 10:25, Lukas Czerner wrote:
> I don't think this is the right fix. We're in ext4_writepages, so at
> this point I don't think an inode should have any actual inline data in
> it. If it does it's a bug and the question is how did this get here?
>
> The inode is likely corrupted and it should have been noticed earliler
> and it should never get here.

Yes, that was just an attempt fix something that I'm not quite familiar
with.

Jan sent already a patch for that fixes it:
https://lore.kernel.org/all/[email protected]/

--
Thanks,
Tadeusz

2022-07-27 19:04:37

by Lukas Czerner

[permalink] [raw]
Subject: Re: [PATCH] ext4: try to flush inline data before calling BUG in writepages

On Wed, Jul 27, 2022 at 10:40:25AM -0700, Tadeusz Struk wrote:
> Hi Lukas,
> On 7/27/22 10:25, Lukas Czerner wrote:
> > I don't think this is the right fix. We're in ext4_writepages, so at
> > this point I don't think an inode should have any actual inline data in
> > it. If it does it's a bug and the question is how did this get here?
> >
> > The inode is likely corrupted and it should have been noticed earliler
> > and it should never get here.
>
> Yes, that was just an attempt fix something that I'm not quite familiar
> with.
>
> Jan sent already a patch for that fixes it:
> https://lore.kernel.org/all/[email protected]/
>
> --
> Thanks,
> Tadeusz
>

Yeah, I just noticed sorry about that. I was missing the email context
for some reason.

Thanks!
-Lukas