common/log

   1 ##/bin/bash
   2 #
   3 # Copyright (c) 2000-2002 Silicon Graphics, Inc.  All Rights Reserved.
   4 #
   5 # This program is free software; you can redistribute it and/or
   6 # modify it under the terms of the GNU General Public License as
   7 # published by the Free Software Foundation.
   8 #
   9 # This program is distributed in the hope that it would be useful,
  10 # but WITHOUT ANY WARRANTY; without even the implied warranty of
  11 # MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  12 # GNU General Public License for more details.
  13 #
  14 # You should have received a copy of the GNU General Public License
  15 # along with this program; if not, write the Free Software Foundation,
  16 # Inc.,  51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
  17 #
  18 #
  19 # common routines for log testing
  20 # Created by dxm@sgi.com & tes@sgi.com
  21 #
  22
  23 fulldir=$seqres.fulldir
  24 rm -rf $fulldir
  25
  26 _cleanup_logfiles()
  27 {
  28     if [ $status -eq 0 ]; then
  29         # don't keep these files around unless something went wrong
  30         rm -rf $fulldir
  31     fi
  32 }
  33
  34 _full()
  35 {
  36     echo ""            >>$seqres.full
  37     echo "*** $* ***"  >>$seqres.full
  38     echo ""            >>$seqres.full
  39 }
  40
  41 _echofull()
  42 {
  43     echo ""            | tee -a $seqres.full
  44     echo "*** $* ***"  | tee -a $seqres.full
  45     echo ""            | tee -a $seqres.full
  46 }
  47
  48 # Handle the operations which get split over Log Record
  49 # boundaries.
  50 # Oper (379)..... flags: CONTINUE
  51 # ...
  52 # Oper (0)....... flags: WAS_CONT END
  53 #
  54 # or
  55 #
  56 # Oper (379)..... flags: none
  57 # ...
  58 # Oper (0)....... flags: none
  59 #
  60 _filter_opnum()
  61 {
  62     $AWK_PROG '
  63 BEGIN {
  64         debug = 0
  65         }
  66 /^Oper/ && debug {
  67             printf "line = %s\n", $0
  68         }
  69 /^Oper/ {
  70             was_cont = 0
  71         }
  72 /^Oper/ && /flags: CONTINUE/ {
  73             # this will be the first op of split region
  74             $9 = "none" # overwrite CONTINUE flags
  75             print
  76             print "Not printing rest"
  77             was_cont = 1
  78             next
  79         }
  80 /^Oper/ && /flags: WAS_CONT END/ {
  81             # this will be the last op of split region
  82             # skip over was-continued op
  83             # we assume there can be only 1
  84             was_cont = 1
  85             next
  86         }
  87 (was_cont == 1) {
  88             # skip over any continued op stuff
  89             next
  90         }
  91         {print}
  92     '
  93 }
  94
  95 #
  96 # Filter out things that can change
  97 # We have complexities which change when log is sync'ed at different
  98 # times.
  99 # Example1: DATA FORK EXTENTS
 100 # These will not show up if inode is sync'ed sooner
 101 #       /DATA FORK EXTENTS/d;
 102 #       /INODE:/s/flags:0x5/flags:0x1/g;
 103 # define XFS_ILOG_CORE   0x001   /* log standard inode fields */
 104 # define XFS_ILOG_DEXT   0x004   /* log i_df.if_extents */
 105 #
 106 #
 107
 108 _filter_logprint()
 109 {
 110     _fix_malloc |\
 111     sed '
 112         s/ver:[0-9]/ver:<VERS>/;
 113         s/version [0-9] format [0-9]/version <VERS> format <FORMAT>/;
 114         s/data device: 0x[0-9a-f][0-9a-f]*/data device: <DEVICE>/;
 115         s/log device: 0x[0-9a-f][0-9a-f]*/log device: <DEVICE>/;
 116         s/log file: \".*\"/log device: <DEVICE>/;
 117         s/daddr: [0-9][0-9]*/daddr: <DADDR>/;
 118         s/length: [0-9][0-9]*/length: <LENGTH>/;
 119         s/length: [0-9][0-9]*/length: <LENGTH>/;
 120         s/^cycle num overwrites: .*$/cycle num overwrites: <TIDS>/;
 121         s/tid: [0-9a-f][0-9a-f]*/tid: <TID>/;
 122         s/tid:0x[0-9a-f][0-9a-f]*/tid:<TID>/;
 123         s/q:0x[0-9a-f][0-9a-f]*/q:<Q>/;
 124         s/a:0x[0-9a-f][0-9a-f]*/a:<A>/g;
 125         s/blkno:0x[0-9a-f][0-9a-f]*/blkno:<BLKNO>/g;
 126         s/blkno: *[0-9][0-9]* (0x[0-9a-f]*)/blkno: <BLKNO> (<BLKNO>)/g;
 127         s/blkno: *[0-9][0-9]*/blkno: <BLKNO>/g;
 128         s/boff: [0-9][0-9]*/boff: <BOFF>/g;
 129         s/len: *[0-9][0-9]*/len:<LEN>/g;
 130         /BUF:/s/[       ]*flags:.*$//;
 131         /zeroed blocks/s/[0-9][0-9]*/<COUNT>/g;
 132         /cleared blocks/d;
 133         /log tail/s/[0-9][0-9]*/<COUNT>/g;
 134         s/atime:[0-9a-fx]*  *mtime:[0-9a-fx]*  *ctime:[0-9a-fx]*/atime:<TIME>  mtime:<TIME>  ctime:<TIME>/;
 135         s/atime 0x[0-9a-f]* mtime 0x[0-9a-f]* ctime 0x[0-9a-f]*/atime <TIME>  mtime <TIME>  ctime <TIME>/;
 136         s/block [0-9][0-9]*/block <BLOCK>/;
 137         s/icount: *[0-9][0-9]*  *ifree: *[0-9][0-9]*  *fdblks: *[0-9][0-9]*  *frext: *[0-9][0-9]*/icount:<COUNT> ifree:<FREE> fdblks:<BLOCKS> frext:<COUNT>/;
 138         s/sunit: *[0-9][0-9]*  *swidth: *[0-9][0-9]*/sunit:<SUNIT> swidth:<SWIDTH>/;
 139         s/1st: *[0-9][0-9]*  *last: *[0-9][0-9]*  *cnt: *[0-9][0-9]*  *freeblks: *[0-9][0-9]*  *longest: *[0-9][0-9]*/1st:<NUM> last:<NUM> cnt:<COUNT> freeblks:<COUNT> longest:<NUM>/;
 140         s/^uuid: *[0-9a-f-][0-9a-f-]* *format: *.*$/uuid: <UUID> format: <FORMAT>/;
 141         /flushiter:/d;
 142         /version:/,/h_size:/d;
 143         /override tail/s/[0-9][0-9]*/<TAIL_BLK>/;
 144         /^---*/d;
 145         /^===*/d;
 146         /^~~~*/d;
 147         /extended-header/d;
 148         /LOG REC AT LSN/d;
 149         /DATA FORK EXTENTS/d;
 150         s/BUF: cnt:[1-9][0-9]* total:[1-9][0-9]*.*/BUF: cnt:C total:T/;
 151         s/INO: cnt:[1-9][0-9]* total:[1-9][0-9]*.*/INO: cnt:C total:T/;
 152         s/#regs: *[1-9][0-9]*/#regs:R/;
 153         /INODE:/s/flags:0x5/flags:0x1/g;
 154         s/Oper ([0-9][0-9]*)/Oper (OPNUM)/;
 155         /^[     ]*$/d;
 156         s/  */ /g;
 157         s/ $//;
 158         s/newino: 0x[0-9a-f]*$/newino: <INO>/g
 159         s/newino:0x[0-9a-f]*$/newino:<INO>/g
 160         s/ino: 0x[0-9a-f]* flags:/ino: <INO> flags:/g
 161         s/ino:0x[0-9a-f]* flags:/ino:<INO> flags:/g
 162         s/onlink:[0-9][0-9]*/onlink:<ONLINK>/;
 163         s/gen:-*[0-9][0-9]*/gen:<GEN>/;
 164         s/gen 0x[0-9a-f][0-9a-f]*/gen <GEN>/;
 165     '|\
 166     awk '
 167         # collapse BUF DATA group into 1 line
 168         # for Oper data this can be over separate operations...ughh
 169         /BUF DATA/ {
 170                 if (!buf_data) { # 1st one
 171                     if (oper) {
 172                         print oper
 173                         oper = 0
 174                     }
 175                     print
 176                 }
 177                 buf_data = 1
 178                 oper = 0 # wont need it now
 179                 next
 180         }
 181         /^Oper/ {
 182                 # store it as we dont know if 2nd BUF DATA is to follow
 183                 if (oper) {
 184                     print oper
 185                 }
 186                 oper = $0
 187                 next
 188         }
 189         /^TRANS/ && dummy_rec == 1 {
 190                 # start printing again - dummy transaction over
 191                 dummy_rec = 0
 192         }
 193         /DUMMY1/ {
 194                 # filter out dummy transactions
 195                 dummy_rec = 1
 196                 next
 197         }
 198         {
 199                 if (dummy_rec) {
 200                     next
 201                 }
 202                 buf_data = 0
 203                 if (oper) { # now we can print out oper
 204                     print oper
 205                     oper = 0
 206                 }
 207                 print
 208         }
 209     '
 210 }
 211
 212 _check_log()
 213 {
 214     _full "clean_log : xfs_logprint"
 215     _scratch_xfs_logprint -t | tee -a $seqres.full \
 216         | head | grep -q "<CLEAN>" || _fail "DIRTY LOG"
 217 }
 218
 219 _scratch_xfs_logstate()
 220 {
 221     _scratch_xfs_logprint -t | tee -a $seqres.full | grep -q "<CLEAN>"
 222     echo $?
 223 }
 224
 225 _scratch_f2fs_logstate()
 226 {
 227     $DUMP_F2FS_PROG $SCRATCH_DEV | tee -a $seqres.full | grep -q "unmount"
 228     echo $?
 229 }
 230
 231 _scratch_ext4_logstate()
 232 {
 233     $DUMPE2FS_PROG -h $SCRATCH_DEV 2> /dev/null | tee -a $seqres.full | \
 234         grep "^Filesystem features" | grep -q needs_recovery
 235     test $? -ne 0
 236     echo $?
 237 }
 238
 239 _scratch_dump_log()
 240 {
 241         case "$FSTYP" in
 242         xfs)
 243                 _scratch_xfs_logprint
 244                 ;;
 245         f2fs)
 246                 $DUMP_F2FS_PROG $SCRATCH_DEV
 247                 ;;
 248         ext4)
 249                 $DUMPE2FS_PROG -h $SCRATCH_DEV
 250                 ;;
 251         *)
 252                 ;;
 253         esac
 254 }
 255
 256 _test_dump_log()
 257 {
 258         case "$FSTYP" in
 259         xfs)
 260                 _test_xfs_logprint
 261                 ;;
 262         f2fs)
 263                 $DUMP_F2FS_PROG $TEST_DEV
 264                 ;;
 265         ext4)
 266                 $DUMPE2FS_PROG -h $TEST_DEV
 267                 ;;
 268         *)
 269                 ;;
 270         esac
 271 }
 272
 273 _print_logstate()
 274 {
 275     case "$FSTYP" in
 276     xfs)
 277         dirty=$(_scratch_xfs_logstate)
 278         ;;
 279     f2fs)
 280         dirty=$(_scratch_f2fs_logstate)
 281         ;;
 282     ext4)
 283         dirty=$(_scratch_ext4_logstate)
 284         ;;
 285     *)
 286         ;;
 287     esac
 288
 289     if [ $dirty -ne 0 ]; then
 290         echo "dirty log"
 291     else
 292         echo "clean log"
 293     fi
 294 }
 295
 296 _print_operation()
 297 {
 298     mkdir $fulldir >/dev/null 2>&1
 299     mntopt=`echo $MOUNT_OPTIONS | sed 's/ //g'`
 300     mkfsopt=`echo $MKFS_OPTIONS | sed 's/ //g'`
 301     raw=$fulldir/op.mnt$mntopt.mkfs$mkfsopt$sync_suffix.raw
 302     filtered=$fulldir/op.mnt$mntopt.mkfs$mkfsopt$sync_suffix.filtered
 303
 304     echo "### xfs_logprint output ###" | tee $raw >$filtered
 305     _scratch_xfs_logprint -c  2>&1 \
 306     | tee -a $raw      \
 307     | _filter_logprint \
 308     | _filter_opnum    \
 309     >>$filtered
 310 }
 311
 312 # start at rec#2 "-s 2" so we skip over UMOUNT record which will always
 313 # be a 512b single header at mkfs time
 314 # and may not match with the FS mounted at a different LR size
 315 # => xlog_do_recovery_pass() can not handle the different hdr sizes
 316 #    it assumes them all to be the same between the start..finish
 317
 318 _print_transaction_inode()
 319 {
 320     _start=$1
 321     mkdir $fulldir >/dev/null 2>&1
 322     mntopt=`echo $MOUNT_OPTIONS | sed 's/ //g'`
 323     mkfsopt=`echo $MKFS_OPTIONS | sed 's/ //g'`
 324     raw=$fulldir/trans_inode.mnt$mntopt.mkfs$mkfsopt$sync_suffix.raw
 325     filtered=$fulldir/trans_inode.mnt$mntopt.mkfs$mkfsopt$sync_suffix.filtered
 326
 327     echo "### xfs_logprint -t -i -s START output ###" | tee $raw >$filtered
 328     _scratch_xfs_logprint -t -i -s $_start 2>&1 \
 329     | tee -a $raw      \
 330     | _filter_logprint \
 331     >>$filtered
 332 }
 333
 334 _print_transaction_buf()
 335 {
 336     _start=$1
 337     mkdir $fulldir >/dev/null 2>&1
 338     mntopt=`echo $MOUNT_OPTIONS | sed 's/ //g'`
 339     mkfsopt=`echo $MKFS_OPTIONS | sed 's/ //g'`
 340     raw=$fulldir/trans_buf.mnt$mntopt.mkfs$mkfsopt$sync_suffix.raw
 341     filtered=$fulldir/trans_buf.mnt$mntopt.mkfs$mkfsopt$sync_suffix.filtered
 342
 343     echo "### xfs_logprint -t -b -s START output ###" | tee $raw >$filtered
 344     _scratch_xfs_logprint -t -b -s $_start 2>&1 \
 345     | tee -a $raw      \
 346     | _filter_logprint \
 347     >>$filtered
 348 }
 349
 350 _mkfs_log()
 351 {
 352     # create the FS
 353     # mkfs options to append to log size otion can be specified ($*)
 354     export MKFS_OPTIONS="-l size=2000b -l lazy-count=1 $*"
 355     _full "mkfs"
 356     _scratch_mkfs_xfs >>$seqres.full 2>&1
 357     if [ $? -ne 0 ] ; then
 358         _echofull "Cannot mkfs for this test using option specified: $MKFS_OPTIONS"
 359         return 1
 360     fi
 361
 362     return 0
 363 }
 364
 365
 366 #
 367 # mount fs and create some log traffic
 368 #
 369 _create_log()
 370 {
 371     # mount the FS
 372     _full "mount"
 373     _scratch_mount >>$seqres.full 2>&1
 374     if [ $? -ne 0 ] ; then
 375         _echofull "mount failed: $MOUNT_OPTIONS"
 376         return 1
 377     fi
 378
 379     # generate some log traffic - but not too much - life gets a little
 380     # more complicated if the log wraps around. This traffic is
 381     # pretty much arbitary, but could probably be made better than this.
 382     touch $SCRATCH_MNT/{0,1,2,3,4,5,6,7,8,9}{0,1,2,3,4,5,6,7,8,9}
 383
 384     # unmount the FS
 385     _full "umount"
 386     _scratch_unmount >>$seqres.full 2>&1
 387     if [ $? -ne 0 ] ; then
 388         _echofull "umount failed"
 389         return 1
 390     fi
 391
 392     return 0
 393 }
 394
 395 #
 396 # mount fs and create some log traffic with sync'ing
 397 #
 398 _create_log_sync()
 399 {
 400     # mount the FS
 401     _full " mount"
 402     _scratch_mount >>$seqres.full 2>&1
 403     if [ $? -ne 0 ] ; then
 404         _echofull "mount failed: $MOUNT_OPTIONS"
 405         return 1
 406     fi
 407
 408     # generate some log traffic - but not too much
 409     # add some syncs to get the log flushed to disk
 410     for file in $SCRATCH_MNT/{0,1,2,3,4,5,6,7,8,9}{0,1,2,3,4,5,6,7,8,9}; do
 411         touch $file
 412         sync
 413     done
 414
 415     # unmount the FS
 416     _full "umount"
 417     _scratch_unmount >>$seqres.full 2>&1
 418     if [ $? -ne 0 ] ; then
 419         _echofull "umount failed"
 420         return 1
 421     fi
 422 }
 423
 424 _cmp_output()
 425 {
 426     echo "*** compare logprint: $1 with $2"
 427     if ! diff $1 $2 >/dev/null; then
 428         _fail "logprint output $1 differs to $2"
 429     fi
 430 }
 431
 432 #
 433 # Op data of different Log Record sizes will mean that data is
 434 # split at different points and in op printing it will not
 435 # try and decode the data which has been split up.
 436 # So we do a special diff processing to complain of differences
 437 # if no split is involved.
 438 #
 439 # Example diff with forms of:
 440 # "Left over region from split log item"
 441 # "Not printing rest of data"
 442 #
 443 #   2149c2149
 444 #   < Left over region from split log item
 445 #   ---
 446 #   > BUF DATA
 447 #   2888c2888,2889
 448 #   < INODE: #regs: 3 Not printing rest of data
 449 #   ---
 450 #   > INODE: #regs: 3 ino: 0x80 flags: 0x5 dsize: 16
 451 #   >  blkno: <BLKNO> len:<LEN> boff: <BOFF>
 452 #
 453 _process_op_diff()
 454 {
 455     $AWK_PROG <$1 '
 456         BEGIN { num_splits = 1; max_splits = 50 }
 457         /^[0-9]/ {
 458
 459                 # ensure a split happened in previous difference
 460                 if (num_splits < 1 || num_splits > max_splits) {
 461                         print num_splits, " split(s) found prior to diff cmd: ", $0
 462                         num_splits = 1 # shut-up end condition
 463                         exit 1
 464                 }
 465                 num_splits = 0
 466
 467                 next
 468         }
 469         /Left over region/ || /Not printing rest/ {
 470                 num_splits++
 471                 next
 472         }
 473         { next }
 474         END {
 475                 if (num_splits < 1 || num_splits > max_splits) {
 476                         print num_splits, " split(s) found prior to diff end"
 477                         exit 1
 478                 }
 479         }
 480     '
 481     return $?
 482 }
 483
 484 _cmp_op_output()
 485 {
 486     echo "*** compare logprint: $1 with $2"
 487
 488     diff $1 $2 >$filtered.diff
 489     if ! _process_op_diff $filtered.diff
 490     then
 491         _fail "logprint output $1 differs to $2 considering splits"
 492     fi
 493 }
 494
 495 # return xfs log version of device
 496 # e.g.
 497 #   _log_version /dev/dsk/dks0d1s4
 498 #
 499 _log_version()
 500 {
 501     _dev=$1
 502     vers=`xfs_db -c 'sb 0' -c 'p versionnum' -r $_dev | $AWK_PROG '{print $3}'`
 503     logver=`echo $vers | sed -e 's/0x[0-9a-f]\([0-9a-f]\)[0-9a-f][0-9a-f]/\1/'`
 504     if [ $logver = 4 -o $logver = 5 -o $logver = 6 -o $logver = 7 -o \
 505          $logver = c -o $logver = d -o $logver = e -o $logver = f ]; then
 506         echo 2
 507     else
 508         echo 1
 509     fi
 510 }
 511
 512 _require_v2log()
 513 {
 514     # test out mkfs to see if it supports "-l version=2"
 515     export MKFS_OPTIONS="-l version=2"
 516     if ! _scratch_mkfs_xfs >>$seqres.full 2>&1; then
 517         _notrun "mkfs does not support v2 logs"
 518     fi
 519
 520     # test out mount to see if it mounts a v2 log fs
 521     export MOUNT_OPTIONS="-o logbsize=32k"
 522     if ! _scratch_mount >>$seqres.full 2>&1; then
 523         _notrun "mount/kernel does not support v2 logs"
 524     fi
 525
 526     # check after unmount to see if it is clean
 527     # i.e. it is not a 6.5.25 buggy version checking kernel
 528     touch $SCRATCH_MNT/file
 529     _scratch_unmount >>$seqres.full 2>&1
 530     if _scratch_xfs_logprint -t | tee -a $seqres.full \
 531         | head | grep -q "<DIRTY>"; then
 532         _notrun "kernel does not support v2 logs"
 533     fi
 534
 535     # otherwise presume it does support v2 logs...:)
 536 }
 537
 538 _require_logstate()
 539 {
 540     case "$FSTYP" in
 541     xfs)
 542         if [ -z "$XFS_LOGPRINT_PROG" ]; then
 543             _notrun "This test requires xfs_logprint utility."
 544         fi
 545         ;;
 546     f2fs)
 547         if [ -z "$DUMP_F2FS_PROG" ]; then
 548             _notrun "This test requires dump.f2fs utility."
 549         fi
 550         ;;
 551     ext4)
 552         if [ -z "$DUMPE2FS_PROG" ]; then
 553                 _notrun "This test requires dumpe2fs utility."
 554         fi
 555         ;;
 556     *)
 557         _notrun "$FSTYP does not support log state probing."
 558         ;;
 559     esac
 560 }
 561
 562 _xfs_log_config()
 563 {
 564     echo "# mkfs-opt             mount-opt"
 565     echo "# ------------------------------"
 566     echo "  version=2            logbsize=32k"
 567     echo "  version=2,su=4096    logbsize=32k"
 568     echo "  version=2,su=32768   logbsize=32k"
 569     echo "  version=2,su=32768   logbsize=64k"
 570     echo "  version=2            logbsize=64k"
 571     echo "  version=2,su=64k     logbsize=64k"
 572     echo "  version=2            logbsize=128k"
 573     echo "  version=2,su=128k    logbsize=128k"
 574     echo "  version=2            logbsize=256k"
 575     echo "  version=2,su=256k    logbsize=256k"
 576 }
 577
 578 _f2fs_log_config()
 579 {
 580     echo "# mkfs-opt             mount-opt"
 581     echo "# ------------------------------"
 582     echo "  test1     active_logs=6,background_gc=off"
 583     echo "  test2     active_logs=6,background_gc=off,inline_data"
 584     echo "  test3     active_logs=6,background_gc=off,inline_dentry"
 585     echo "  test4     active_logs=6,background_gc=off,inline_data,inline_dentry"
 586     echo "  test5     active_logs=6,background_gc=off,disable_roll_forward"
 587     echo "  test6     active_logs=6,background_gc=off,discard,inline_data,inline_dentry"
 588     echo "  test7     active_logs=6,background_gc=on"
 589     echo "  test8     active_logs=6,background_gc=on,inline_data"
 590     echo "  test9     active_logs=6,background_gc=on,inline_data,inline_dentry"
 591     echo "  test10    active_logs=6,background_gc=on,discard,inline_data,inline_dentry"
 592 }
 593
 594 _ext4_log_config()
 595 {
 596     echo "# mkfs-opt             mount-opt"
 597     echo "# ------------------------------"
 598     echo "  /dev/null     data=writeback"
 599     echo "  /dev/null     data=ordered"
 600     echo "  /dev/null     data=journal"
 601     echo "  /dev/null     data=ordered,data_err=abort"
 602     echo "  /dev/null     data=writeback,nojournal_checksum"
 603     echo "  /dev/null     data=ordered,nojournal_checksum"
 604     echo "  /dev/null     data=journal,nojournal_checksum"
 605     echo "  /dev/null     data=ordered,data_err=abort,nojournal_checksum"
 606     echo "  /dev/null     data=writeback,journal_checksum"
 607     echo "  /dev/null     data=ordered,journal_checksum"
 608 }
 609
 610 _get_log_configs()
 611 {
 612     case "$FSTYP" in
 613     xfs)
 614         _xfs_log_config
 615         ;;
 616     f2fs)
 617         _f2fs_log_config
 618         ;;
 619     ext4)
 620         _ext4_log_config
 621         ;;
 622     *)
 623         _notrun "$FSTYP does not support log configs."
 624         ;;
 625     esac
 626 }
 627
 628 # make sure this script returns success
 629 /bin/true