xfs
[Top] [All Lists]

Re: XFS umount with IO errors seems to lead to memory corruption

To: Dave Chinner <david@xxxxxxxxxxxxx>, xfs@xxxxxxxxxxx
Subject: Re: XFS umount with IO errors seems to lead to memory corruption
From: Alex Lyakas <alex@xxxxxxxxxxxxxxxxx>
Date: Sun, 24 Nov 2013 12:27:08 +0200
Cc: linux-xfs@xxxxxxxxxxxxxxx
Delivered-to: xfs@xxxxxxxxxxx
In-reply-to: <20131121220713.GB6502@dastard>
References: <CAOcd+r3i0mDK2vAnZ-0s6VGnSsJwWxnEB2uMrcz+WSJAxx2bmA@xxxxxxxxxxxxxx> <20131121220713.GB6502@dastard>
Hi Dave,
thank you for your comments.

The test that I am doing is unmounting the XFS, while its underlying
block device returns intermittent IO errors. The block device in
question is a custom DeviceMapper target. It returns -ECANCELED in
this case. Should I return some other errno instead?
The same exact test works alright with ext4. It's unmount finishes,
system seems to continue functioning normally and kmemleak is also
happy.

When doing a simpler reproductoin with "error" Device-Mapper, umount
gets stuck and never returns, while kernel keeps printing:
XFS (dm-0): metadata I/O error: block 0x0 ("xfs_buf_iodone_callbacks")
error 5 numblks 1
XFS (dm-0): metadata I/O error: block 0x0 ("xfs_buf_iodone_callbacks")
error 5 numblks 1
XFS (dm-0): metadata I/O error: block 0x0 ("xfs_buf_iodone_callbacks")
error 5 numblks 1
XFS (dm-0): metadata I/O error: block 0x0 ("xfs_buf_iodone_callbacks")
error 5 numblks 1
XFS (dm-0): metadata I/O error: block 0x0 ("xfs_buf_iodone_callbacks")
error 5 numblks 1
XFS (dm-0): metadata I/O error: block 0x0 ("xfs_buf_iodone_callbacks")
error 5 numblks 1
XFS (dm-0): metadata I/O error: block 0x0 ("xfs_buf_iodone_callbacks")
error 5 numblks 1
...

What is the expected behavior of umount in this case? (when there are
IO errors during it).

This reproduction that I do is:

root@vc-00-00-1075-dev:~# cat /etc/xfs.protofile
dummy                   : bootfilename, not used, backward compatibility
0 0                             : numbers of blocks and inodes, not
used, backward compatibility
d--777 0 0              : set 777 perms for the root dir
$
$

root@vc-00-00-1075-dev:~# mkfs.xfs -f /dev/vde -p /etc/xfs.protofile
meta-data=/dev/vde               isize=256    agcount=4, agsize=1310720 blks
         =                       sectsz=512   attr=2, projid32bit=0
data     =                       bsize=4096   blocks=5242880, imaxpct=25
         =                       sunit=0      swidth=0 blks
naming   =version 2              bsize=4096   ascii-ci=0
log      =internal log           bsize=4096   blocks=2560, version=2
         =                       sectsz=512   sunit=0 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0

root@vc-00-00-1075-dev:~# blockdev --getsz /dev/vde
41943040

root@vc-00-00-1075-dev:~# dmsetup create VDE --table "0 41943040
linear /dev/vde 0"

root@vc-00-00-1075-dev:~# mount -o noatime,sync /dev/mapper/VDE
/export/v122_nas/

copy some files to the mountpoint, then:

dmsetup reload VDE --table "0 41943040 error"
dmsetup resume VDE

umount /export/v122_nas

this never returns and /proc shows:
root@vc-00-00-1075-dev:~# cat /proc/2684/stack
[<ffffffffa033ac6a>] xfs_ail_push_all_sync+0x9a/0xd0 [xfs]
[<ffffffffa0330123>] xfs_unmountfs+0x63/0x160 [xfs]
[<ffffffffa02ee265>] xfs_fs_put_super+0x25/0x60 [xfs]
[<ffffffff8118fd12>] generic_shutdown_super+0x62/0xf0
[<ffffffff8118fdd0>] kill_block_super+0x30/0x80
[<ffffffff811903dc>] deactivate_locked_super+0x3c/0x90
[<ffffffff81190d7e>] deactivate_super+0x4e/0x70
[<ffffffff811ad086>] mntput_no_expire+0x106/0x160
[<ffffffff811ae760>] sys_umount+0xa0/0xe0
[<ffffffff816ab919>] system_call_fastpath+0x16/0x1b
[<ffffffffffffffff>] 0xffffffffffffffff

And after some time, hung task warning shows:
INFO: task kworker/2:1:39 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/2:1     D ffffffff8180cf00     0    39      2 0x00000000
 ffff88007c54db38 0000000000000046 000000027d003700 ffff88007fd03fc0
 ffff88007c54dfd8 ffff88007c54dfd8 ffff88007c54dfd8 0000000000013e40
 ffff88007c9e9710 ffff88007c4bdc40 00000000000000b8 7fffffffffffffff
Call Trace:
 [<ffffffff816a1b99>] schedule+0x29/0x70
 [<ffffffff816a02d5>] schedule_timeout+0x1e5/0x250
 [<ffffffffa02f3987>] ? kmem_zone_alloc+0x67/0xe0 [xfs]
 [<ffffffff816798e6>] ? kmemleak_alloc+0x26/0x50
 [<ffffffff816a0f1b>] __down_common+0xa0/0xf0
 [<ffffffffa032f37c>] ? xfs_getsb+0x3c/0x70 [xfs]
 [<ffffffff816a0fde>] __down+0x1d/0x1f
 [<ffffffff81084591>] down+0x41/0x50
 [<ffffffffa02dcd44>] xfs_buf_lock+0x44/0x110 [xfs]
 [<ffffffffa032f37c>] xfs_getsb+0x3c/0x70 [xfs]
 [<ffffffffa033b4bc>] xfs_trans_getsb+0x4c/0x140 [xfs]
 [<ffffffffa032f06e>] xfs_mod_sb+0x4e/0xc0 [xfs]
 [<ffffffffa02e3b24>] xfs_fs_log_dummy+0x54/0x90 [xfs]
 [<ffffffffa0335bf8>] xfs_log_worker+0x48/0x50 [xfs]
 [<ffffffff81077a11>] process_one_work+0x141/0x4a0
 [<ffffffff810789e8>] worker_thread+0x168/0x410
 [<ffffffff81078880>] ? manage_workers+0x120/0x120
 [<ffffffff8107df10>] kthread+0xc0/0xd0
 [<ffffffff813a3ea4>] ? acpi_get_child+0x47/0x4d
 [<ffffffff813a3fb7>] ? acpi_platform_notify.part.0+0xbb/0xda
 [<ffffffff8107de50>] ? flush_kthread_worker+0xb0/0xb0
 [<ffffffff816ab86c>] ret_from_fork+0x7c/0xb0
 [<ffffffff8107de50>] ? flush_kthread_worker+0xb0/0xb0


[3] contains some of information that wiki asks for, right before
doing the unmount in the original test. I have also re-ran the
original test with slub_debug=FZ, but it did not show up any warnings
(perhaps I am missing something on how to enable the red-zone
debugging).

Thanks,
Alex.

[3]
root@vc-00-00-1075-dev:/mnt/work/alex# uname -a
Linux vc-00-00-1075-dev 3.8.13-557-generic #1382000791 SMP Thu Oct 17
11:22:20 IST 2013 x86_64 x86_64 x86_64 GNU/Linux

this is a manually-compiled 3.8.13 kernel, in which:
CONFIG_HAVE_DEBUG_KMEMLEAK=y
CONFIG_DEBUG_KMEMLEAK=y
but no code changes.

root@vc-00-00-1075-dev:/mnt/work/alex# xfs_repair -V
xfs_repair version 3.1.7

number of CPUs: 4

root@vc-00-00-1075-dev:/mnt/work/alex# cat /proc/meminfo
MemTotal:        2050940 kB
MemFree:          996376 kB
Buffers:           32836 kB
Cached:           389208 kB
SwapCached:            0 kB
Active:           490232 kB
Inactive:         239988 kB
Active(anon):     311336 kB
Inactive(anon):     1336 kB
Active(file):     178896 kB
Inactive(file):   238652 kB
Unevictable:        4632 kB
Mlocked:            4632 kB
SwapTotal:        522236 kB
SwapFree:         522236 kB
Dirty:                96 kB
Writeback:             0 kB
AnonPages:        312920 kB
Mapped:            46656 kB
Shmem:              1456 kB
Slab:             224640 kB
SReclaimable:      30040 kB
SUnreclaim:       194600 kB
KernelStack:        3632 kB
PageTables:        14584 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:     1547704 kB
Committed_AS:    1667900 kB
VmallocTotal:   34359738367 kB
VmallocUsed:       30860 kB
VmallocChunk:   34359648832 kB
HardwareCorrupted:     0 kB
AnonHugePages:         0 kB
HugePages_Total:       0
HugePages_Free:        0
HugePages_Rsvd:        0
HugePages_Surp:        0
Hugepagesize:       2048 kB
DirectMap4k:      153588 kB
DirectMap2M:     1943552 kB


root@vc-00-00-1075-dev:/mnt/work/alex# cat /proc/mounts
rootfs / rootfs rw 0 0
sysfs /sys sysfs rw,nosuid,nodev,noexec,relatime 0 0
proc /proc proc rw,nosuid,nodev,noexec,relatime 0 0
udev /dev devtmpfs rw,relatime,size=1016840k,nr_inodes=254210,mode=755 0 0
devpts /dev/pts devpts rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000 0 0
tmpfs /run tmpfs rw,nosuid,relatime,size=410188k,mode=755 0 0
/dev/disk/by-uuid/c2a6ff28-cf03-4785-9ac8-60dd4ed7d3af / ext4
rw,relatime,errors=remount-ro,data=ordered 0 0
none /sys/fs/fuse/connections fusectl rw,relatime 0 0
none /sys/kernel/debug debugfs rw,relatime 0 0
none /sys/kernel/security securityfs rw,relatime 0 0
none /run/lock tmpfs rw,nosuid,nodev,noexec,relatime,size=10256k 0 0
none /run/shm tmpfs rw,nosuid,nodev,relatime 0 0
rpc_pipefs /run/rpc_pipefs rpc_pipefs rw,relatime 0 0
172.16.0.12:/export2/work /mnt/work nfs4
rw,relatime,vers=4.0,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,port=0,timeo=600,retrans=2,sec=sys,clientaddr=172.16.0.35,local_lock=none,addr=172.16.0.12
0 0
172.16.0.12:/export2/share /mnt/share nfs4
rw,relatime,vers=4.0,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,port=0,timeo=600,retrans=2,sec=sys,clientaddr=172.16.0.35,local_lock=none,addr=172.16.0.12
0 0
nfsd /proc/fs/nfsd nfsd rw,relatime 0 0
cgroup_root /sys/fs/cgroup tmpfs rw,relatime 0 0
blkio /sys/fs/cgroup/blkio cgroup
rw,relatime,perf_event,blkio,freezer,devices,cpuacct,cpu,cpuset 0 0
/dev/mapper/vpart-1 /mnt/bootdir ext4 rw,relatime,(null),debug,data=ordered 0 0
/dev/dm-20 /btrfs/pool-00000007 btrfs
rw,noatime,nodatasum,nodatacow,notreelog,nospace_cache,clear_cache 0 0
/dev/dm-22 /export/v122_nas xfs rw,sync,noatime,wsync,attr2,inode64,noquota 0 0

root@vc-00-00-1075-dev:/mnt/work/alex# cat /proc/partitions
major minor  #blocks  name

 254        0   52428800 vda
 254       16   52428800 vdb
 254       32   20971520 vdc
 254       48   20971520 vdd
 254       64   20971520 vde
 254       80     512000 vdf
 254       96     512000 vdg
 254      112     512000 vdh
 254      128     512000 vdi
 254      144     512000 vdj
 254      160    1048576 vdk
 254      176    1048576 vdl
 254      192     312320 vdm
 254      208     312320 vdn
   8        0    5242880 sda
   8        1    4717568 sda1
   8        2          1 sda2
   8        5     522240 sda5
  11        0    1048575 sr0
 253        0 140737488355327 dm-0
 253        1     512000 dm-1
 253        2     512000 dm-2
 253        3     512000 dm-3
   9        1     511988 md1
 253        4     511988 dm-4
 253        5    1048576 dm-5
 253        7     312320 dm-7
 253        6   20971520 dm-6
 253        8   52428800 dm-8
 253        9   20971520 dm-9
 253       10    1048576 dm-10
 253       11     312320 dm-11
 253       12   52428800 dm-12
   9        5   18872320 md5
   9        2    1048564 md2
   9        3     312308 md3
   9        4   50329600 md4
 253       13   18872320 dm-13
 253       14     312308 dm-14
 253       15    1048564 dm-15
 253       16   50329600 dm-16
 253       17   49283072 dm-17
 253       18   49283072 dm-18
 253       19   49283072 dm-19
 253       20   49283072 dm-20
 253       21  127926272 dm-21
 253       22  127926272 dm-22

root@vc-00-00-1075-dev:/mnt/work/alex# xfs_info /export/v122_nas/
meta-data=/dev/dm-22             isize=256    agcount=4, agsize=7995392 blks
         =                       sectsz=512   attr=2
data     =                       bsize=4096   blocks=31981568, imaxpct=25
         =                       sunit=0      swidth=0 blks
naming   =version 2              bsize=4096   ascii-ci=0
log      =internal               bsize=4096   blocks=15616, version=2
         =                       sectsz=512   sunit=0 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0






On Fri, Nov 22, 2013 at 12:07 AM, Dave Chinner <david@xxxxxxxxxxxxx> wrote:
> [cc'd the correct xfs list. PLease use xfs@xxxxxxxxxxx in future.]
>
> On Thu, Nov 21, 2013 at 08:04:36PM +0200, Alex Lyakas wrote:
>> Greetings,
>> I am using stock XFS from kernel 3.8.13, compiled with kmemleak
>> enabled. I am testing a particular scenario, in which the underlying
>> block device returns IO errors during XFS umount. Almost in all cases
>> this results in kernel crashes in various places, and sometimes
>> kmemleak complains, and sometimes CPU soft lockup happens. It always
>> happens after XFS messages like:
>
> What testing are you doing?
>
> http://xfs.org/index.php/XFS_FAQ#Q:_What_information_should_I_include_when_reporting_a_problem.3F
>
>>  kernel: [  600.190509] XFS (dm-22): metadata I/O error: block
>> 0x7600030 ("xlog_iodone") error 125 numblks 64
>>  kernel: [  600.192267] XFS (dm-22): xfs_do_force_shutdown(0x2) called
>> from line 1115 of file
>> /mnt/compile/linux-stable/source/fs/xfs/xfs_log.c.  Return address =
>> 0xffffffffa05cffa1
>>  kernel: [  600.192319] XFS (dm-22): Log I/O Error Detected.  Shutting
>> down filesystem
>>  kernel: [  600.192392] XFS (dm-22): Unable to update superblock
>> counters. Freespace may not be correct on next mount.
>>  kernel: [  600.192398] XFS (dm-22): xfs_log_force: error 5 returned.
>>  kernel: [  600.193687] XFS (å.Z): Please umount the filesystem and
>> rectify the problem(s)
>>
>> you can see here the garbage that XFS prints instead of the block device 
>> name.
>> In [1] and [2] I am attaching more kernel log from two such crashes.
>
> So, something is corrupting memory and stamping all over the XFS
> structures.
>
> What's error 125?
>
> #define ECANCELED       125     /* Operation Canceled */
>
> I can't find an driver that actually returns that error to
> filesystems, which....
>
>
>>  kernel: [  600.227881] Modules linked in: xfs raid1 xfrm_user
>> xfrm4_tunnel tunnel4 ipcomp xfrm_ipcomp esp4 ah4 scst_vdisk(O)
>> iscsi_scst(O) scst(O) dm_zcache(O) dm_btrfs(O) btrfs(O) libcrc32c
>> dm_iostat(O)
>
> .... given you have a bunch of out of tree modules loaded (and some which
> are experiemental) suggests that you have a problem with your
> storage...
>
> So, something is corrupting memory across a large number of
> subsystems, and the trigger is some custom code to run error
> injection. Can you reproduce the problem with something like
> dm-faulty?
>
> Cheers,
>
> Dave.
> --
> Dave Chinner
> david@xxxxxxxxxxxxx

<Prev in Thread] Current Thread [Next in Thread>