Re: 2.6.24-rc3 oopses while mounting fs

Timothy Shimmin
2007-12-05T06:36:26Z

Lachlan,

An aside...

I think I see why we couldn't get "xfs_logprint -t" to work on a file (-f).
> xfs_logprint -t -f ~/debug/sdc.xlg
xfs_logprint:
data device: 0xffffffffffffffff
log device: 0xffffffffffffffff daddr: 0 length: 262144

XFS: Log inconsistent (didn't find previous header)
XFS: failed to find log head
xfs_logprint: failed to find head and tail, error: 5

The problem is that it is using the superblock to determine if it is version 1
or version 2 logs in order to find out the maximum size of the iclog (log record).
And for -f there is no superblock to look at. The version number is, however, in the
log record header.
So when it looks in the undefined data it comes up with _not_ version 2,
and so assumes to look back for the hdr to only 32K when it really needs
to look back to 64k (for v2 it would limit at 256K).
Hence, it can't find the magic# in the header.

The debugging...

====================================================
Breakpoint 1, xlog_find_verify_log_record (log=0x607ffffffea96be0, start_blk=5312, last_blk=0x607ffffffea96bc0, extra_bblks=0)
at xfs_log_recover.c:234
234 if (!(bp = xlog_get_bp(log, num_blks))) {
(gdb) bt
#0 xlog_find_verify_log_record (log=0x607ffffffea96be0, start_blk=5312, last_blk=0x607ffffffea96bc0, extra_bblks=0) at xfs_log_recover.c:234
#1 0x4000000000092020 in xlog_find_head (log=0x607ffffffea96be0, return_head_blk=0x607ffffffea96bd0) at xfs_log_recover.c:527
#2 0x4000000000094000 in xlog_find_tail (log=0x607ffffffea96be0, head_blk=0x607ffffffea96bd0, tail_blk=0x607ffffffea96bd8, readonly=0)
at xfs_log_recover.c:616
#3 0x40000000000100a0 in xfs_log_print_trans (log=0x607ffffffea96be0, print_block_start=-1) at log_print_trans.c:49
#4 0x4000000000003600 in main (argc=<value optimized out>, argv=<value optimized out>) at logprint.c:240

(gdb) print *last_blk
$1 = 5376

start_blk = 5312
last_blk = 5376
extra_bblks = 0

Goes from 5376..5312 looking for magic# at start of sector.
Errors out if can't find one.
Which is true since the next magic# is at 5248.

logprint -d output:
4992 HEADER Cycle 154 tail 153:253056 len 61440 ops 105
5120 HEADER Cycle 154 tail 153:253056 len 61440 ops 344
5248 HEADER Cycle 154 tail 153:253056 len 61440 ops 303 <--- previous block
5376 HEADER Cycle 153 tail 153:253056 len 0 ops 0 <--- hdr
[00000 - 05376] Cycle 0x0000009a New Cycle 0x00000099
5377 HEADER Cycle 153 tail 153:253056 len 0 ops 0
5378 HEADER Cycle 153 tail 153:253056 len 0 ops 0

So why is it using a start_blk of 5312?

522 num_scan_bblks = XLOG_REC_SHIFT(log);
523 if (head_blk >= num_scan_bblks) {
524 start_blk = head_blk - num_scan_bblks; /* don't read head_blk */
525
526 /* start ptr at last block ptr before head_blk */
->527 if ((error = xlog_find_verify_log_record(log, start_blk,
528 &head_blk, 0)) == -1) {

#define XLOG_REC_SHIFT(log) \
BTOBB(1 << (XFS_SB_VERSION_HASLOGV2(&log->l_mp->m_sb) ? \
XLOG_MAX_RECORD_BSHIFT : XLOG_BIG_RECORD_BSHIFT))

#define XLOG_BIG_RECORD_BSHIFT 15 /* 32k == 1 << 15 */
#define XLOG_MAX_RECORD_BSHIFT 18 /* 256k == 1 << 18 */

Number of blocks between rec-hdrs from -d output:
5376-5248 = 128 BB

Looks like it used 5312 = 5376 - num_scan_bblks
=> num_scan_bblks = 64

Yep
(gdb) p num_scan_bblks
$3 = 64
32K
i.e. it thinks it has v1 logs

(gdb) p *(log->l_mp)
$9 = {m_sb = {sb_magicnum = 0, sb_blocksize = 0, sb_dblocks = 0, sb_rblocks = 0, sb_rextents = 0, sb_uuid = '\0' <repeats 15 times>,
sb_logstart = 2305843009213997776, sb_rootino = 6953557824646229696, sb_rbmino = 6953557824646229688, sb_rsumino = 6953557824646229680,
sb_rextsize = 284472, sb_agblocks = 536870912, sb_agcount = 4281151176, sb_rbmblocks = 1619001343, sb_logblocks = 0, sb_versionnum = 0,
sb_sectsize = 0, sb_inodesize = 38256, sb_inopblock = 4, sb_fname = "\000\000\000 H?\a\000\000\000\000 ", sb_blocklog = 0 '\0',
etc...
it is not set

Okay, need to file a bug for this part so that -f can be useful here.
It needs to be using a LR h_version number for this somehow.

--Tim

Lachlan McIlroy wrote:
>> ============================================================================
>>
>> cycle: 154 version: 2 lsn: 154,5248 tail_lsn: 153,253056
>> length of Log Record: 61440 prev offset: 5120 num ops: 303
>> uuid: b02fc6bd-662f-40a5-8f0c-e260a881a3e7 format: little endian linux
>> h_size: 262144
>> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
>>
>> extended-header: cycle: 154
>> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
>>
>> extended-header: cycle: 154
>> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
>>
>> extended-header: cycle: 154
>> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
>>
>> extended-header: cycle: 154
>> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
>>
>> extended-header: cycle: 154
>> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
>>
>> extended-header: cycle: 154
>> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
>>
>> extended-header: cycle: 154
>> ----------------------------------------------------------------------------
>>
>> Oper (0): tid: 5769cd60 len: 0 clientid: TRANS flags: START
>> ----------------------------------------------------------------------------
>>
>> Oper (1): tid: 5769cd60 len: 16 clientid: TRANS flags: none
>> TRAN: type: STRAT_WRITE tid: 0 num_items: 5
>> ----------------------------------------------------------------------------
>>
>> Oper (2): tid: 5769cd60 len: 56 clientid: TRANS flags: none
>> INODE: #regs: 3 ino: 0x1400005c flags: 0x5 dsize: 16
>> blkno: 610338736 len: 16 boff: 4096
>> Oper (3): tid: 5769cd60 len: 96 clientid: TRANS flags: none
>> INODE CORE
>> magic 0x494e mode 0100600 version 1 format 2
>> nlink 1 uid 14029 gid 1474
>> atime 0x4716b870 mtime 0x4716bade ctime 0x4716bade
>> size 0x1ce00000 nblocks 0x1c840 extsize 0x0 nextents 0x1
>> naextents 0x0 forkoff 0 dmevmask 0x0 dmstate 0x0
>> flags 0x0 gen 0x4
>> Oper (4): tid: 5769cd60 len: 16 clientid: TRANS flags: none
>> EXTENTS inode data
>> ----------------------------------------------------------------------------
>
>
> Another interesting point is that the transaction id has changed between
> these operations from 5769cd60 to 5769cf18. It should stay the same.
> We may be reading old log data.
>
>>
>> Oper (5): tid: 5769cf18 len: 24 clientid: TRANS flags: none
>> BUF: #regs: 2 start blkno: 610338561 (0x24610701) len: 1 bmap
>> size: 1 flags: 0x0
>> Oper (6): tid: 5769cf18 len: 128 clientid: TRANS flags: none
>> AGF Buffer: XAGF
>> ver: 1 seq#: 5 len: 15258464
>> root BNO: 1 CNT: 2
>> level BNO: 1 CNT: 1
>> 1st: 0 last: 3 cnt: 4 freeblks: 2491090 longest: 581471
>> ----------------------------------------------------------------------------
>>
>> Oper (7): tid: 5769cf18 len: 28 clientid: TRANS flags: none
>> BUF: #regs: 2 start blkno: 610338568 (0x24610708) len: 8 bmap
>> size: 2 flags: 0x0
>> Oper (8): tid: 5769cf18 len: 128 clientid: TRANS flags: none
>> BUF DATA
>> ----------------------------------------------------------------------------
>>