Corrupted large file ?

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Hello Everybody,

                I am facing some issues with XFS. I do not really know what went wrong and how to diagnose the issue I'm having, but here are the symptoms:
. My kernel is: Linux proxmox1 4.13.13-2-pve #1 SMP PVE 4.13.13-32. It's a 40 cores server that features 160Tb storage (with RAID-6) and 384G RAM.                                                                                             
. /dev/sdb1 is a raid array that is roughly 128Tb big
. It contains mainly virtual machine disks for a proxmox instance
. After a regular halt / restart in which nothing was odd, I could not start anymore one of my VM, kvm timing out.
. Tried a few things, one of which was "head -n 1 <name of the image>.qcow2 . The image being a single 30Tb file.
. The console freezes after that. It seems that I cannot do anything with the qcow2 image. I tried to dd it into another file, but no change. After that, I tried rebooting again, and it told me upon process termination:

"echo 0" > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Print_req_error: I/O error, dev sdb, sector 241349552640
XFS (sdb1): metadata I/O error: block 0x38818de200 ("xfs_trans_read_buf_map") error 5 numblks 8

. Tried to run after that xfs_repair with default parameters on my /dev/sdb1. Nothing's getting out of that, it's almost like xfs_repair doesn't detect anything. It has ran 3 times now, always with the same output which you can see there:

root@proxmox1:~/xfsprogs-4.17.0# xfs_repair -e /dev/sdb1
Phase 1 - find and verify superblock...
        - reporting progress in intervals of 15 minutes
Phase 2 - using internal log
        - zero log...
        - scan filesystem freespace and inode maps...
        - 15:30:39: scanning filesystem freespace - 128 of 128 allocation groups done
        - found root inode chunk
Phase 3 - for each AG...
        - scan and clear agi unlinked lists...
        - 15:30:39: scanning agi unlinked lists - 128 of 128 allocation groups done
        - process known inodes and perform inode discovery...
        - agno = 0
        - agno = 15
        - agno = 30
        - agno = 60
        - agno = 45
        - agno = 75
        - agno = 90
        - agno = 105
        - agno = 120
        - agno = 31
        - agno = 46
        - agno = 76
        - agno = 91
        - agno = 106
        - agno = 61
        - agno = 47
        - agno = 121
        - agno = 32
        - agno = 48
        - agno = 77
        - agno = 92
        - agno = 49
        - agno = 33
        - agno = 78
        - agno = 62
        - agno = 34
        - agno = 50
        - agno = 63
        - agno = 35
        - agno = 51
        - agno = 36
        - agno = 93
        - agno = 79
        - agno = 64
        - agno = 37
        - agno = 94
        - agno = 95
        - agno = 65
        - agno = 52
        - agno = 53
        - agno = 66
        - agno = 38
        - agno = 96
        - agno = 54
        - agno = 67
        - agno = 39
        - agno = 55
        - agno = 40
        - agno = 68
        - agno = 56
        - agno = 97
        - agno = 57
        - agno = 69
        - agno = 80
        - agno = 81
        - agno = 98
        - agno = 82
        - agno = 70
        - agno = 122
        - agno = 123
        - agno = 83
        - agno = 58
        - agno = 71
        - agno = 84
        - agno = 99
        - agno = 100
        - agno = 72
        - agno = 85
        - agno = 124
        - agno = 59
        - agno = 73
        - agno = 101
        - agno = 74
        - agno = 86
        - agno = 102
        - agno = 125
        - agno = 87
        - agno = 103
        - agno = 88
        - agno = 126
        - agno = 104
        - agno = 127
        - agno = 41
        - agno = 42
        - agno = 43
        - agno = 44
        - agno = 89
        - agno = 16
        - agno = 17
        - agno = 18
        - agno = 19
        - agno = 20
        - agno = 21
        - agno = 22
        - agno = 23
        - agno = 24
        - agno = 25
        - agno = 26
        - agno = 27
        - agno = 28
        - agno = 29
        - agno = 1
        - agno = 2
        - agno = 3
        - agno = 4
        - agno = 5
        - agno = 6
        - agno = 7
        - agno = 8
        - agno = 9
        - agno = 10
        - agno = 11
        - agno = 12
        - agno = 13
        - agno = 14
        - agno = 107
        - agno = 108
        - agno = 109
        - agno = 110
        - agno = 111
        - agno = 112
        - agno = 113
        - agno = 114
        - agno = 115
        - agno = 116
        - agno = 117
        - agno = 118
        - agno = 119
        - 16:01:01: process known inodes and inode discovery - 8320 of 8320 inodes done
        - process newly discovered inodes...
        - 16:01:01: process newly discovered inodes - 128 of 128 allocation groups done
Phase 4 - check for duplicate blocks...
        - setting up duplicate extent list...
        - 16:01:01: setting up duplicate extent list - 128 of 128 allocation groups done
        - check for inodes claiming duplicate blocks...
        - agno = 0
        - agno = 1
        - agno = 2
        - agno = 3
        - agno = 5
        - agno = 6
        - agno = 4
        - agno = 7
        - agno = 8
        - agno = 9
        - agno = 12
        - agno = 10
        - agno = 15
        - agno = 21
        - agno = 16
        - agno = 24
        - agno = 20
        - agno = 18
        - agno = 29
        - agno = 23
        - agno = 28
        - agno = 22
        - agno = 14
        - agno = 27
        - agno = 11
        - agno = 17
        - agno = 13
        - agno = 19
        - agno = 61
        - agno = 39
        - agno = 55
        - agno = 42
        - agno = 31
        - agno = 26
        - agno = 80
        - agno = 46
        - agno = 44
        - agno = 86
        - agno = 35
        - agno = 87
        - agno = 88
        - agno = 25
        - agno = 90
        - agno = 36
        - agno = 32
        - agno = 92
        - agno = 30
        - agno = 69
        - agno = 85
        - agno = 89
        - agno = 45
        - agno = 91
        - agno = 43
        - agno = 38
        - agno = 93
        - agno = 71
        - agno = 37
        - agno = 95
        - agno = 96
        - agno = 41
        - agno = 98
        - agno = 97
        - agno = 76
        - agno = 77
        - agno = 78
        - agno = 79
        - agno = 83
        - agno = 82
        - agno = 81
        - agno = 57
        - agno = 54
        - agno = 52
        - agno = 65
        - agno = 34
        - agno = 64
        - agno = 40
        - agno = 66
        - agno = 49
        - agno = 70
        - agno = 72
        - agno = 63
        - agno = 48
        - agno = 51
        - agno = 56
        - agno = 59
        - agno = 68
        - agno = 60
        - agno = 94
        - agno = 53
        - agno = 73
        - agno = 99
        - agno = 74
        - agno = 58
        - agno = 67
        - agno = 101
        - agno = 62
        - agno = 33
        - agno = 100
        - agno = 102
        - agno = 75
        - agno = 84
        - agno = 50
        - agno = 104
        - agno = 105
        - agno = 47
        - agno = 107
        - agno = 108
        - agno = 111
        - agno = 116
        - agno = 122
        - agno = 123
        - agno = 109
        - agno = 115
        - agno = 113
        - agno = 118
        - agno = 117
        - agno = 119
        - agno = 103
        - agno = 121
        - agno = 120
        - agno = 124
        - agno = 112
        - agno = 125
        - agno = 114
        - agno = 126
        - agno = 110
        - agno = 106
        - agno = 127
        - 16:01:11: check for inodes claiming duplicate blocks - 8320 of 8320 inodes done
Phase 5 - rebuild AG headers and trees...
        - 16:01:12: rebuild AG headers and trees - 128 of 128 allocation groups done
        - reset superblock...
Phase 6 - check inode connectivity...
        - resetting contents of realtime bitmap and summary inodes
        - traversing filesystem ...
        - traversal finished ...
        - moving disconnected inodes to lost+found ...
Phase 7 - verify and correct link counts...
        - 16:01:13: verify and correct link counts - 128 of 128 allocation groups done
done
root@proxmox1:~/xfsprogs-4.17.0# echo $?
0


. I was willing to try xfs_scrub, but the kernel cannot do that apparently, so I did not run it at this point.
. Here is my dmesg output regarding XFS

root@proxmox1:~# dmesg | grep -i xfs
[    4.203326] SGI XFS with ACLs, security attributes, realtime, no debug enabled
[    4.219735] XFS (dm-0): Mounting V5 Filesystem
[    4.268027] XFS (dm-0): Ending clean mount
[    6.819537] XFS (sdb1): Mounting V5 Filesystem
[    7.654455] XFS (sdb1): Starting recovery (logdev: internal)
[    8.806812] XFS (sdb1): Ending recovery (logdev: internal)
[  229.712694] XFS (sdb1): Unmounting Filesystem
[  386.826450] XFS (sdb1): Mounting V5 Filesystem
[  387.397634] XFS (sdb1): Ending clean mount
[  503.408649] XFS (sdb1): Unmounting Filesystem


Here is the output of dmesg after a ls was blocked:


[ 3384.280537] INFO: task ls:21392 blocked for more than 120 seconds.
[ 3384.280592]       Not tainted 4.13.13-2-pve #1
[ 3384.280626] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this                                                                                              message.
[ 3384.280682] ls              D    0 21392   3298 0x00000004
[ 3384.280687] Call Trace:
[ 3384.280700]  __schedule+0x3cc/0x860
[ 3384.280788]  ? xfs_ilock_attr_map_shared+0x34/0x40 [xfs]
[ 3384.280796]  schedule+0x36/0x80
[ 3384.280800]  rwsem_down_read_failed+0x10a/0x170
[ 3384.280804]  call_rwsem_down_read_failed+0x18/0x30
[ 3384.280807]  ? call_rwsem_down_read_failed+0x18/0x30
[ 3384.280880]  ? xfs_trans_roll+0xc0/0xc0 [xfs]
[ 3384.280884]  down_read+0x20/0x40
[ 3384.280938]  xfs_ilock+0xe0/0x110 [xfs]
[ 3384.280984]  xfs_ilock_attr_map_shared+0x34/0x40 [xfs]
[ 3384.281017]  xfs_attr_get+0xb6/0x110 [xfs]
[ 3384.281068]  xfs_xattr_get+0x4b/0x70 [xfs]
[ 3384.281072]  __vfs_getxattr+0x57/0x70
[ 3384.281075]  vfs_getxattr+0x8d/0xa0
[ 3384.281078]  getxattr+0xb0/0x1a0
[ 3384.281083]  ? __check_object_size+0xb3/0x190
[ 3384.281087]  path_getxattr+0x6c/0xb0
[ 3384.281090]  SyS_lgetxattr+0x11/0x20
[ 3384.281094]  entry_SYSCALL_64_fastpath+0x1e/0xa9
[ 3384.281097] RIP: 0033:0x7fd487e0634a
[ 3384.281099] RSP: 002b:00007ffed0bedb98 EFLAGS: 00000202 ORIG_RAX: 00000000000                                                                                             000c0
[ 3384.281103] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007fd487e0634a
[ 3384.281104] RDX: 00005638063a2ce0 RSI: 00007fd4880dc262 RDI: 00007ffed0bedc30
[ 3384.281106] RBP: 0000000000000000 R08: 00007fd4880b8c68 R09: 0000000000000110
[ 3384.281107] R10: 00000000000000ff R11: 0000000000000202 R12: 00007fd4884fb270
[ 3384.281109] R13: 00005638063a53c0 R14: 00005638063a2de0 R15: 0000000000000000


Here is a strace output when trying to "cat" into the qcow image:

root@proxmox1:~# strace cat /export/sdb1/brick/images/111/vm-111-disk-1.qcow2
execve("/bin/cat", ["cat", "/export/sdb1/brick/images/111/vm"...], [/* 16 vars */]) = 0
brk(NULL)                               = 0x561059d8c000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f55cfb39000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=38304, ...}) = 0
mmap(NULL, 38304, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f55cfb2f000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\4\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1689360, ...}) = 0
mmap(NULL, 3795296, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f55cf57a000
mprotect(0x7f55cf70f000, 2097152, PROT_NONE) = 0
mmap(0x7f55cf90f000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x195000) = 0x7f55cf90f000
mmap(0x7f55cf915000, 14688, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f55cf915000
close(3)                                = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f55cfb2d000
arch_prctl(ARCH_SET_FS, 0x7f55cfb2d700) = 0
mprotect(0x7f55cf90f000, 16384, PROT_READ) = 0
mprotect(0x561058540000, 4096, PROT_READ) = 0
mprotect(0x7f55cfb3c000, 4096, PROT_READ) = 0
munmap(0x7f55cfb2f000, 38304)           = 0
brk(NULL)                               = 0x561059d8c000
brk(0x561059dad000)                     = 0x561059dad000
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=1679776, ...}) = 0
mmap(NULL, 1679776, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f55cf992000
close(3)                                = 0
fstat(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(136, 2), ...}) = 0
open("/export/sdb1/brick/images/111/vm-111-disk-1.qcow2", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0600, st_size=32218780991488, ...}) = 0
fadvise64(3, 0, 0, POSIX_FADV_SEQUENTIAL) = 0
mmap(NULL, 139264, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f55cf970000
read(3,


Would you happen to have any clue on where to go from now ?

Thank you in advance for the time you'll offer me regarding this !

Kind regards,

Yannick Boursin



[Index of Archives]     [XFS Filesystem Development (older mail)]     [Linux Filesystem Development]     [Linux Audio Users]     [Yosemite Trails]     [Linux Kernel]     [Linux RAID]     [Linux SCSI]


  Powered by Linux