Re: 2.6.24-rc3 oopses while mounting fs

[Timothy Shimmin <tes@sgi.com>]

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
>> ---------------------------------------------------------------------------- 
>>