Re: 2.6.24-rc3 oopses while mounting fs

[Lachlan McIlroy <lachlan@sgi.com>]

Thanks Tim.

Timothy Shimmin wrote:
> 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
>>> ---------------------------------------------------------------------------- 
>>>
> 
> 
>