xfs_repair fails after trying to format log cycle?
Andrew Ryder
tireman at shaw.ca
Tue Apr 12 22:02:37 CDT 2016
Is it possible the location its searching for at block
02:34:43.887528 pread64(4, 0x7fb8f53e0200, 2097152, 3001552175104) = -1
EIO (Input/output error)
is not where the log actually is?
If I run xfs_db in r/o mode it returns:
xfs_db> blockget
xfs_db: error - read only 950272 of 2097152 bytes
failed to find log head
xlog_is_dirty: cannot find log head/tail (xlog_find_tail=-5)
ERROR: cannot find log head/tail, run xfs_repair
The value of 950272 is the same if I multiply the 232 lines by 4096 of
pread in the "strace_xfs_io.txt" file I get 950272 bytes as well.
Yet if I run xfs_logprint it dump about 727MB of log info.. before
throwing an error.
xfs_logprint:
data device: 0x902
log device: 0x902 daddr: 5860130880 length: 4173824
cycle: 63 version: 2 lsn: 63,2283776 tail_lsn: 63,2283456
length of Log Record: 32256 prev offset: 2283712 num ops: 376
uuid: 14bc270b-e658-4f85-b1db-673642ab9d67 format: little endian linux
h_size: 32768
----------------------------------------------------------------------------
Oper (0): tid: 6dd14bc1 len: 8 clientid: TRANS flags: WAS_CONT END
Left over region from split log item
----------------------------------------------------------------------------
Oper (1): tid: 6dd14bc1 len: 32 clientid: TRANS flags: none
EFD: #regs: 1 num_extents: 1 id: 0xffff88044f10abc0
----------------------------------------------------------------------------
Oper (2): tid: 6dd14bc1 len: 56 clientid: TRANS flags: none
INODE: #regs: 2 ino: 0x360f8c437 flags: 0x1 dsize: 0
blkno: 9905273888 len: 32 boff: 11776
Oper (3): tid: 6dd14bc1 len: 176 clientid: TRANS flags: none
INODE CORE
magic 0x494e mode 0100644 version 3 format 2
nlink 1 uid 1000 gid 100
atime 0x56d8c8e2 mtime 0x56d8c8e2 ctime 0x56d8c8e2
size 0x0 nblocks 0x0 extsize 0x0 nextents 0x0
< ... skipping to end .... >
Oper (0): tid: edbd9f49 len: 0 clientid: TRANS flags: START
----------------------------------------------------------------------------
Oper (1): tid: edbd9f49 len: 16 clientid: TRANS flags: none
TRAN: type: CHECKPOINT tid: edbd9f49 num_items: 2
----------------------------------------------------------------------------
Oper (2): tid: edbd9f49 len: 24 clientid: TRANS flags: none
BUF: #regs: 2 start blkno: 0 (0x0) len: 1 bmap size: 1 flags: 0x9000
Oper (3): tid: edbd9f49 len: 128 clientid: TRANS flags: none
SUPER BLOCK Buffer:
icount: 6360863066640355328 ifree: 1465036800 fdblks: 0 frext: 0
----------------------------------------------------------------------------
Oper (4): tid: edbd9f49 len: 0 clientid: TRANS flags: COMMIT
============================================================================
**********************************************************************
* ERROR: header cycle=0 block=5120 *
**********************************************************************
and if I pull the byte offset value from the daddr value below I get:
xfs_db> daddr 5860130880
xfs_db> stack
1:
byte offset 3000387010560, length 512
buffer block 5860130880 (fsbno 1073741832), 1 bb
inode -1, dir inode -1, type data
which is where when xfs_repair actually traverses the fs on the 3rd
iteration and it fails after formatting the log to a size of 434,896,896
bytes (1659 iterations of
262144 byte successful writes before error)
On 04/12/2016 04:16 PM, Andrew Ryder wrote:
> On 04/12/2016 10:05 AM, Brian Foster wrote:
>> On Tue, Apr 12, 2016 at 01:53:17AM -0400, Andrew Ryder wrote:
>>>
>>>
>>> On 03/28/2016 04:55 AM, Brian Foster wrote:
>>>> On Sat, Mar 26, 2016 at 03:09:27PM -0400, Andrew Ryder wrote:
>>>>> Hello,
>>>>>
>>>>> I have an mdadm array with a xfs v5 filesystem on it and its begun
>>>>> to give
>>>>> me issues when trying to mount it as well as complete xfs_repair.
>>>>> Not sure
>>>>> if anyone might be able to shed some light on what is going on or
>>>>> how to
>>>>> correct the issue?
>>>>>
>>>>> When I try and mount the fs, it complains with:
>>>>>
>>>>> [ 388.479847] XFS (md2): Mounting V5 Filesystem
>>>>> [ 388.494686] XFS (md2): metadata I/O error: block 0x15d6d39c0
>>>>> ("xlog_bread_noalign") error 5 numblks 8192
>>>>> [ 388.495013] XFS (md2): failed to find log head
>>>>> [ 388.495018] XFS (md2): log mount/recovery failed: error -5
>>>>> [ 388.495090] XFS (md2): log mount failed
>>>>>
>>>>
>>>> So a read I/O error from the kernel...
>>>>
>>>>>
>>>>> This is where its not making any sense for me, If I try and run
>>>>> "xfs_repair
>>>>> /dev/md2" it fails with:
>>>>>
>>>>> Phase 1 - find and verify superblock...
>>>>> - reporting progress in intervals of 15 minutes
>>>>> Phase 2 - using internal log
>>>>> - zero log...
>>>>> xfs_repair: read failed: Input/output error
>>>>> failed to find log head
>>>>> zero_log: cannot find log head/tail (xlog_find_tail=-5)
>>>>>
>>>>> fatal error -- ERROR: The log head and/or tail cannot be
>>>>> discovered. Attempt
>>>>> to mount the
>>>>> filesystem to replay the log or use the -L option to destroy the
>>>>> log and
>>>>> attempt a repair.
>>>>>
>>>>
>>>> ... similar read error from xfsprogs...
>>>>
>>>>>
>>>>> But if I run "xfs_repair -L /dev/md2" which gives:
>>>>>
>>>>> Phase 1 - find and verify superblock...
>>>>> - reporting progress in intervals of 15 minutes
>>>>> Phase 2 - using internal log
>>>>> - zero log...
>>>>> xfs_repair: read failed: Input/output error
>>>>> failed to find log head
>>>>> zero_log: cannot find log head/tail (xlog_find_tail=-5)
>>>>> xfs_repair: libxfs_device_zero write failed: Input/output error
>>>>>
>>>>
>>>> ... and it looks like it fails to write as well when trying to zero the
>>>> log...
>>>>
>>>>> then try and re-run "xfs_repair /dev/md2" it starts traversing the
>>>>> filesystem all the way to "Phase 7" then errors with:
>>>>>
>>>>> Phase 7 - verify and correct link counts...
>>>>> - 14:36:55: verify and correct link counts - 33 of 33
>>>>> allocation
>>>>> groups done
>>>>> Maximum metadata LSN (64:2230592) is ahead of log (0:0).
>>>>> Format log to cycle 67.
>>>>> xfs_repair: libxfs_device_zero write failed: Input/output error
>>>>>
>>>>>
>>>>> Yet at this point I can now mount the filesystem..
>>>>>
>>>>
>>>> ... and this is effectively a repeat of the write error as we try to
>>>> format the log with a correct LSN based on the metadata LSN tracked by
>>>> the repair process. Your kernel is old enough that runtime probably
>>>> won't complain either way (note that 3.19 might be considered a fairly
>>>> early kernel for using CRC support). Perhaps the first write attempt
>>>> zeroed enough of the log before it failed that log recovery wasn't
>>>> required, and thus these problematic I/Os were avoided.
>>>>
>>>> What's the history of this fs? Has it been working for some time, just
>>>> recently formatted? What lead to the need for log recovery? What's the
>>>> mdadm --detail info, member device size, total array size, xfs_info of
>>>> the filesystem, etc..?
>>>>
>>>> Does xfs_repair run clean at this point? If so, does 'xfs_repair -L'
>>>> still reproduce the write error (note that I'm assuming you have a
>>>> clean
>>>> log such that this command will not cause data loss). If so, an strace
>>>> of the repair process might be interesting...
>>>>
>>>> Brian
>>>
>>>
>>> The filesystem is about a year old as I had one of the Addonics
>>> backplane
>>> boards go bad and after the replacement all was good again.. until the
>>> RocketRaid 2722 card and its obscure "Task File error" error message
>>> came up
>>> again.
>>>
>>> Everything up to this point had been working smoothly since end of
>>> Sept 2015
>>> after the rebuild. All disks are 2TB in size, partitioned via
>>> 'parted' with
>>> 0% and 100% used for partition boundaries on each drive. Everything
>>> had been
>>> working wonderfully long before but the array was taken out due to some
>>> issues I had with 3 hitachi drives that refused to work on the RR2722
>>> card/drivers. Long story.
>>>
>>> I've swapped out two drives in the array and no luck yet as it
>>> doesn't seem
>>> to be hardware failure related.. I've not had any signs of data
>>> corruption,
>>> just meta-data corruption/errors.
>>>
>>> If I remember correct, the format applied to the array was done under
>>> 3.6.11
>>> kernel as
>>> I'm still going through the same xfs_repair as above to get the array to
>>> mount. It keeps failing after it tries to format the log to cycle 67.
>>>
>>> I'll see if I can get you an strace of things.
>>>
>>
>> FWIW, I created an md array of similar geometry and ran through some
>> fsstress/xfs_repair sequences just to see if there was anything
>> obviously broken in the stack here, but I don't hit any issues.
>> xfs_repair can zero the log and reformat it successfully. This is on a
>> 4.6.0-rc1 kernel.
>>
>> So I think the big question here is why are these certain I/Os failing?
>> This might ultimately require investigation at the md layer and/or
>> further down to your storage controller driver, etc. Anyways, here's the
>> first failed I/O from strace_2.1.txt:
>>
>> 02:34:36.309704 pread64(4, 0x7fe772ec0200, 2097152, 3001552175104) =
>> -1 EIO (Input/output error)
>>
>> That's a 2MB read during phase 2, which is probably what leads to the
>> "failed to find log head" error. The read offset is right around the
>> middle of the array where the internal log resides. What's also
>> interesting is that it is preceded by a bunch of other read I/Os that
>> all appear to complete fine, but those are all 512b I/Os.
>>
>> What happens if you manually issue the read call that failed? E.g.,
>> umount the filesystem and run the following command directly against the
>> array:
>>
>> xfs_io -dc "pread 3001552175104 2097152" /dev/md2
>>
>> Brian
>
> It failed with the same error. I've attached the strace output for the
> command.
>
> The array is fairly full so I'm wondering if something is out of
> alignment somewhere thats causing this?
>
> /dev/md2 5858060288 5245630392 612429896 90% /mnt/md2
>
> When I had the array plugged into another controller which isn't a
> rocketraid card, it did complain about all the drives not being aligned
> properly? Somehow it looks like sdk wasn't partitioned the same as the
> rest, I'm wondering if thats screwing things up?
>
> GNU Parted 3.2
> Using /dev/sdi
> Welcome to GNU Parted! Type 'help' to view a list of commands.
> (parted) p
> Model: ATA ST2000NC000-1CX1 (scsi)
> Disk /dev/sdi: 2000GB
> Sector size (logical/physical): 512B/512B
> Partition Table: gpt
> Disk Flags:
>
> Number Start End Size File system Name Flags
> 1 1049kB 2000GB 2000GB
> Number Start End Size File system Name Flags
> 1 2048s 3907028991s 3907026944s
>
>
> GNU Parted 3.2
> Using /dev/sdk
> Welcome to GNU Parted! Type 'help' to view a list of commands.
> (parted) p
> Model: ATA ST2000DL001-9VT1 (scsi)
> Disk /dev/sdk: 2000GB
> Sector size (logical/physical): 512B/512B
> Partition Table: msdos
> Disk Flags:
>
> Number Start End Size Type File system Flags
> 1 512B 2000GB 2000GB primary raid
> Number Start End Size Type File system Flags
> 1 1s 3907029167s 3907029167s primary raid
>
>
> GNU Parted 3.2
> Using /dev/sdh
> Welcome to GNU Parted! Type 'help' to view a list of commands.
> (parted) p
> Model: ATA ST2000DL001-9VT1 (scsi)
> Disk /dev/sdh: 2000GB
> Sector size (logical/physical): 512B/512B
> Partition Table: gpt
> Disk Flags:
>
> Number Start End Size File system Name Flags
> 1 1049kB 2000GB 2000GB
> Number Start End Size File system Name Flags
> 1 2048s 3907028991s 3907026944s
>
>
> GNU Parted 3.2
> Using /dev/sdm
> Welcome to GNU Parted! Type 'help' to view a list of commands.
> (parted) p
> Model: ATA ST2000NC000-1CX1 (scsi)
> Disk /dev/sdm: 2000GB
> Sector size (logical/physical): 512B/512B
> Partition Table: gpt
> Disk Flags:
>
> Number Start End Size File system Name Flags
> 1 1049kB 2000GB 2000GB
> Number Start End Size File system Name Flags
> 1 2048s 3907028991s 3907026944s
>
>
>
>>
>>>
>>> This all began when the RR2722 driver running under 3.18.15
>>> complained and
>>> ..
>>>
>>> Mar 14 07:23:07 Bigmouth kernel: [7177248.090541] /dev/vmnet: port on
>>> hub 0
>>> successfully opened
>>> Mar 14 07:26:03 Bigmouth kernel: [7177424.552323] device eth1 left
>>> promiscuous mode
>>> Mar 14 07:26:03 Bigmouth kernel: [7177424.552786] bridge-eth1: disabled
>>> promiscuous mode
>>> Mar 14 20:10:20 Bigmouth kernel: [7223317.069464] rr272x_1x:Task file
>>> error,
>>> StatusReg=0x51, ErrReg=0x84, LBA[0-3]=0x747dc92f,LBA[4-7]=0x0.
>>> Mar 14 20:10:20 Bigmouth kernel: [7223317.179811] sd 5:0:1:0: [sdg]
>>> Mar 14 20:10:21 Bigmouth kernel: [7223317.690439] Result:
>>> hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
>>> Mar 14 20:10:21 Bigmouth kernel: [7223317.700480] sd 5:0:1:0: [sdg] CDB:
>>> Mar 14 20:10:21 Bigmouth kernel: [7223318.211147] Write(10): 2a 00 74
>>> 7d c9
>>> 00 00 00 40 00
>>> Mar 14 20:10:21 Bigmouth kernel: [7223318.211167] blk_update_request:
>>> I/O
>>> error, dev sdg, sector 1954400512
>>> Mar 14 20:10:21 Bigmouth kernel: [7223318.211203] sd 5:0:3:0: [sdi]
>>> Mar 14 20:10:21 Bigmouth kernel: [7223318.211206] Result:
>>> hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
>>> Mar 14 20:10:21 Bigmouth kernel: [7223318.211209] sd 5:0:3:0: [sdi] CDB:
>>> Mar 14 20:10:21 Bigmouth kernel: [7223318.211211] Write(10): 2a 00 74
>>> 7d c9
>>> 00 00 00 40 00
>>> Mar 14 20:10:21 Bigmouth kernel: [7223318.211223] blk_update_request:
>>> I/O
>>> error, dev sdi, sector 1954400512
>>> Mar 14 20:10:23 Bigmouth kernel: [7223319.957052] XFS (md2): metadata
>>> I/O
>>> error: block 0x15d6d4900 ("xlog_iodone") error 5 numblks 64
>>> Mar 14 20:10:23 Bigmouth kernel: [7223319.957064] XFS (md2):
>>> xfs_do_force_shutdown(0x2) called from line 1181 of file
>>> fs/xfs/xfs_log.c.
>>> Return address = 0xffffffff812fdf96
>>> Mar 14 20:10:23 Bigmouth kernel: [7223319.957080] XFS (md2): Log I/O
>>> Error
>>> Detected. Shutting down filesystem
>>> Mar 14 20:10:23 Bigmouth kernel: [7223319.957083] XFS (md2): Please
>>> umount
>>> the filesystem and rectify the problem(s)
>>> Mar 14 20:10:23 Bigmouth kernel: [7223319.957093] XFS (md2):
>>> xfs_log_force:
>>> error -5 returned.
>>> Mar 14 20:10:50 Bigmouth kernel: [7223347.087272] XFS (md2):
>>> xfs_log_force:
>>> error -5 returned.
>>> Mar 14 20:11:20 Bigmouth kernel: [7223377.190469] XFS (md2):
>>> xfs_log_force:
>>> error -5 returned.
>>> Mar 14 20:11:50 Bigmouth kernel: [7223407.293952] XFS (md2):
>>> xfs_log_force:
>>> error -5 returned.
>>> Mar 14 20:12:20 Bigmouth kernel: [7223437.397444] XFS (md2):
>>> xfs_log_force:
>>> error -5 returned.
>>> Mar 14 20:12:23 Bigmouth kernel: [7223439.791407] nfsd: last server has
>>> exited, flushing export cache
>>> Mar 14 20:12:50 Bigmouth kernel: [7223467.500928] XFS (md2):
>>> xfs_log_force:
>>> error -5 returned.
>>> Mar 14 20:13:20 Bigmouth kernel: [7223497.604420] XFS (md2):
>>> xfs_log_force:
>>> error -5 returned.
>>> Mar 14 20:13:50 Bigmouth kernel: [7223527.707899] XFS (md2):
>>> xfs_log_force:
>>> error -5 returned.
>>> Mar 14 20:14:21 Bigmouth kernel: [7223557.811399] XFS (md2):
>>> xfs_log_force:
>>> error -5 returned.
>>> Mar 14 20:14:51 Bigmouth kernel: [7223587.914932] XFS (md2):
>>> xfs_log_force:
>>> error -5 returned.
>>> Mar 14 20:15:21 Bigmouth kernel: [7223618.018362] XFS (md2):
>>> xfs_log_force:
>>> error -5 returned.
>>> Mar 14 20:15:51 Bigmouth kernel: [7223648.121779] XFS (md2):
>>> xfs_log_force:
>>> error -5 returned.
>>> Mar 14 20:16:19 Bigmouth kernel: [7223676.401069] XFS (md2):
>>> xfs_log_force:
>>> error -5 returned.
>>> Mar 14 20:16:21 Bigmouth kernel: [7223678.225334] XFS (md2):
>>> xfs_log_force:
>>> error -5 returned.
>>> Mar 14 20:16:27 Bigmouth kernel: [7223684.541305] XFS (md2):
>>> xfs_log_force:
>>> error -5 returned.
>>> Mar 14 20:16:27 Bigmouth kernel: [7223684.572176] XFS (md2):
>>> xfs_log_force:
>>> error -5 returned.
>>> Mar 14 20:16:38 Bigmouth kernel: [7223694.918565] md2: unknown
>>> partition
>>> table
>>> Mar 14 20:16:43 Bigmouth kernel: [7223700.425290] XFS (md2): Mounting V5
>>> Filesystem
>>> Mar 14 20:16:43 Bigmouth kernel: [7223700.545669] XFS (md2): Starting
>>> recovery (logdev: internal)
>>> Mar 14 20:16:44 Bigmouth kernel: [7223701.874245] XFS (md2): Ending
>>> recovery
>>> (logdev: internal)
>>> Mar 14 20:30:31 Bigmouth kernel: [7224529.528678] md2: unknown
>>> partition
>>> table
>>>
>>>
>>>
>>> /dev/md2:
>>> Version : 1.2
>>> Creation Time : Tue Oct 13 22:21:27 2015
>>> Raid Level : raid5
>>> Array Size : 5860147200 (5588.67 GiB 6000.79 GB)
>>> Used Dev Size : 1953382400 (1862.89 GiB 2000.26 GB)
>>> Raid Devices : 4
>>> Total Devices : 4
>>> Persistence : Superblock is persistent
>>>
>>> Intent Bitmap : Internal
>>>
>>> Update Time : Tue Apr 12 01:19:43 2016
>>> State : clean
>>> Active Devices : 4
>>> Working Devices : 4
>>> Failed Devices : 0
>>> Spare Devices : 0
>>>
>>> Layout : left-symmetric
>>> Chunk Size : 512K
>>>
>>> Name : Bigmouth:2 (local to host Bigmouth)
>>> UUID : ed979276:3459155c:a32f63da:0c684042
>>> Events : 62846
>>>
>>> Number Major Minor RaidDevice State
>>> 5 8 193 0 active sync /dev/sdm1
>>> 6 8 129 1 active sync /dev/sdi1
>>> 2 8 177 2 active sync /dev/sdl1
>>> 4 8 113 3 active sync /dev/sdh1
>>>
>>>
>>> meta-data=/dev/md2 isize=512 agcount=33,
>>> agsize=45782272
>>> blks
>>> = sectsz=512 attr=2, projid32bit=1
>>> = crc=1 finobt=1 spinodes=0
>>> data = bsize=4096 blocks=1465036800,
>>> imaxpct=5
>>> = sunit=128 swidth=384 blks
>>> naming =version 2 bsize=4096 ascii-ci=0 ftype=1
>>> log =internal bsize=4096 blocks=521728, version=2
>>> = sectsz=512 sunit=8 blks,
>>> lazy-count=1
>>> realtime =none extsz=4096 blocks=0, rtextents=0
>>>
>>>
>>>>
>>>>>
>>>>> Checking the drives with smartctl shows no errors nor does 'dmesg'
>>>>> show any
>>>>> hardware i/o or controller related errors...
>>>>>
>>>>> I've tried scrubbing the array and no bad sectors are found either..
>>>>>
>>>>> I'm running kernel 3.19.8 with xfsprogs 4.5.
>>>>>
>>>>> Thanks,
>>>>> Andrew
>>>>>
>>>>> _______________________________________________
>>>>> xfs mailing list
>>>>> xfs at oss.sgi.com
>>>>> http://oss.sgi.com/mailman/listinfo/xfs
>>>>
>>
>
>
> _______________________________________________
> xfs mailing list
> xfs at oss.sgi.com
> http://oss.sgi.com/mailman/listinfo/xfs
>
More information about the xfs
mailing list