Overview

FSM panic’ed couple of times until cvfsck has been run repairing the Inode FreeList

Assertion

An assertion is a statement that a predicate (Boolean-valued function, a true–false expression) is expected to always be true at that point in the code. If an assertion evaluates to false at run time, an assertion failure results, which typically causes the program to crash, or to throw an assertion exception.

The best info is a stack trace from the corefile. Have the customer run gdb against the corefile and get the stack traces. 

Example:

script gdb.output

gdb fsm corefile

> thread apply all bt

Exit

The file gdb.output now contains backtraces for all threads.

Symptoms & Identifying the problem

## 1 ## Log Review:

The System Message and cvlog contain the Panic String, however do not exhibit any other Error Conditions such

as eg.:  IO failures or HW failures

 /var/log/messages

Jul  9 11:02:19 strawberry fsm[2679]: StorNext FSS 'EuroStor[0]': PANIC: /usr/cvfs/bin/fsm ASSERT failed "free_ip->i_idinode.idi_flags & InodeFlagFree" file /scm/nightly/VM-0-RedHat60AS-26x86-64-SP0/sn/snfs/fsm/inode.c, line 2040

Jul  9 11:02:19 strawberry fsm[2679]: PANIC: /usr/cvfs/bin/fsm ASSERT failed "free_ip->i_idinode.idi_flags & InodeFlagFree" file /scm/nightly/VM-0-RedHat60AS-26x86-64-SP0/sn/snfs/fsm/inode.c, line 2040

Cvlog

[0709 11:02:19] 0x7f5603f3c700 (**FATAL**) PANIC: /usr/cvfs/bin/fsm ASSERT failed "free_ip->i_idinode.idi_flags & InodeFlagFree" file /scm/nightly/VM-0-RedHat60AS-26x86-64-SP0/sn/snfs/fsm/inode.c, line 2040

## 2 ## Troubleshooting:

1.)  Print backtrace

#0  0x00000035b220c8ac in pthread_kill () from /lib64/libpthread.so.0

#1  0x00000000004bfed3 in ThreadAbort (core=<value optimized out>) at /scm/nightly/VM-0-RedHat60AS-26x86-64-SP0/sn/snfs/fsmlib/mthread_panic.c:350

#2  0x00000000004c02a8 in MthreadPanic (str1=0x5dea6a "ASSERT failed ", str2=0x5efb00 "free_ip->i_idinode.idi_flags & InodeFlagFree", core=1,

    file=0x5ed3d0 "/scm/nightly/VM-0-RedHat60AS-26x86-64-SP0/sn/snfs/fsm/inode.c", line=2040) at /scm/nightly/VM-0-RedHat60AS-26x86-64-SP0/sn/snfs/fsmlib/mthread_panic.c:236

#3  0x00000000004ed6ab in DoPanic (str1=<value optimized out>, str2=<value optimized out>, core=<value optimized out>, file=<value optimized out>, line=<value optimized out>)

    at /scm/nightly/VM-0-RedHat60AS-26x86-64-SP0/sn/snfs/libutil/dopanic.c:47

#4  0x000000000046c0f1 in dinodecreate (new_inum=0x7ffee20558e8, cookie=0, ipp=0x7ffee2055c38, tp=0x110e830, creds=0x7ffee2056d30, wait_ok=<value optimized out>, error=0x7ffee2056d24)

    at /scm/nightly/VM-0-RedHat60AS-26x86-64-SP0/sn/snfs/fsm/inode.c:2040

#5  0x000000000046c50d in InodecreateCookie (tp=<value optimized out>, cookie=<value optimized out>, ipp=0x7ffee2055c38, creds=<value optimized out>, wait_ok=<value optimized out>,

    error=0x7ffee2056d24) at /scm/nightly/VM-0-RedHat60AS-26x86-64-SP0/sn/snfs/fsm/inode.c:6646

#6  0x00000000004552f8 in Filecreate (rtp=0x7ffee2056128, numfiles=1, parent_inode=281475029700595, f_type=0x7ffee20560ec, f_lookupname=0x7ffee2056d18, f_creds=<value optimized out>,

    orig_node=4, error=0x7ffee2056d24, op_flags=2, ret_ino_struct=0x7ffee20567a0, ret_parent=0x7ffee2056230, bulk_create_flags=0, f_bulk_parms=0x0, stripe_align=0, evt=0x0, cookie=0,

    qd=0x7ffee20560f0) at /scm/nightly/VM-0-RedHat60AS-26x86-64-SP0/sn/snfs/fsm/dir.c:1237

#7  0x000000000045b546 in VopCreate (pmsgq=0x7ffe8c0008c0, filetype=2, msg_version=<value optimized out>) at /scm/nightly/VM-0-RedHat60AS-26x86-64-SP0/sn/snfs/fsm/dirops.c:686

#8  0x0000000000495901 in VopsRequest (pmsgq=0x7ffe8c0008c0) at /scm/nightly/VM-0-RedHat60AS-26x86-64-SP0/sn/snfs/fsm/vops.c:558

#9  0x000000000047ae0e in MsgDecoderClassFSM (arg=0x7ffe8c0008c0) at /scm/nightly/VM-0-RedHat60AS-26x86-64-SP0/sn/snfs/fsm/msgdecode.c:352

• We see that a Client issues a VopRequest in specific a VopCreate indicating the Client want to create a new File
• Therefore the routine Filecreate is being called which call other routines to allocate\ create the inode from the FreeInode List
• We Panic during diks inode create operation

2.) Identifying where we assert in the code

The Panic String exhibit the Assertion in /sn/snfs/fsm/inode.c, line 2040

* dinodecreate routine

* Using the next free inode number, create a new inod

* Return this inode WRITE locked to the caller.

    if ( ! (free_ip->i_idinode.idi_flags & InodeFlagFree) ) {

              ASSERT(free_ip->i_idinode.idi_flags & InodeFlagFree);

    }

The Condition for the Assertion can be read as “if the InodeFlagFree bit is off” ( bitwise operation )

3.) What inode did the client get from the FreeList and what flags are being set

We know the routine dinodecreate asserts, so let’s have a closer look into frame 4

(gdb) frame 4

#4  0x000000000046c0f1 in dinodecreate (new_inum=0x7ffee20558e8, cookie=0, ipp=0x7ffee2055c38, tp=0x110e830, creds=0x7ffee2056d30, wait_ok=<value optimized out>, error=0x7ffee2056d24)

    at /scm/nightly/VM-0-RedHat60AS-26x86-64-SP0/sn/snfs/fsm/inode.c:2040

(gdb) print/x free_ip->i_inode_number

$18 = 0x80000329dc24

(gdb) print/x free_ip->i_idinode.idi_flags

$17 = 0x840

Note: You can also print the whole structure using the pointer variable  *free_ip

(gdb) print/x *free_ip

$6 = {i_inode_number = 0x80000329dc24, i_tid = 0x0, i_pbufblk = 0x194ee, i_last_inlog_lsn = 0x0, i_policy_key = 0x0, i_stripegroup = 0x0

…}

You can also print the struct type of the pointer variable using ptype

(gdb) ptype free_ip

type = struct inodestruct {

  uint64_t i_inode_number;

   ..

   idinode_t i_idinode;

   ..

Now that we know the value of free_ip->i_idinode.idi.flags, we can use bitmasks to easily check the state of InodeFlagFree bit regardless of the other bits.

To do this, turning off all the other bits using the bitwise AND is done and the value is compared with 0. If it is equal to 0, then the bit was off, but if the value is any other value, then the bit was on

Source: https://en.wikipedia.org/wiki/Mask_(computing)#Querying_the_status_of_a_bit

Value from free_ip->i_idinode.idi.flags

(gdb) print/x free_ip->i_idinode.idi_flags

$17 = 0x840

Inode.h

* On disk inode structure.

* The mate to this structure is idinode_t.

#define InodeFlagExtender              0x0001              /* Is an extender inode */

#define InodeFlagStream               0x0002               /* Is the head of a Named Stream */

#define InodeFlagMetaData              0x0004              /* Is a meta data inode */

#define InodeFlagCvBtree              0x0008              /* Directory is a btree */

#define InodeFlagFree              0x0010              /* Is a free inode */

#define InodeFlagPerfectFit              0x0020              /* Allocations must fit perfectly    */

#define InodeFlagPendFree              0x0040  /* Inode is root of a pending free */

#define InodeFlagNewHash              0x0080              /* Use new directory hash algorithm */

#define InodeFlagFsckFree              0x0100              /* Inode needs freeing after FSCK */

#define InodeFlagWasZeroed              0x0200              /* OnDisk Inode was zeroed first */

#define InodeFlagGappedFile              0x0400              /* File is designated gapped */

#define InodeFlagCrtTime     0x0800  /* Creation time valid */

#define InodeFlagTrimClose              0x1000  /* Trim extents > EOF on last close */

#define InodeFlagFsckPendFree 0x2000              /* pend inode needs cleanup after FSCK */

#define InodeFlagXattr       0x8000  /* Inode is an xattr extender */

Hence it seems obvious using this Bitwise Calculator makes it more understandable

http://www.miniwebtool.com/bitwise-calculator/?data_type=16&number1=840&number2=10&operator=AND

Note: Repeat this exercise if you like with other flags and compare your results

Conclusion: The InodeFlagFree Bit is not set causing the Assertion in the dinodecreate routine

4.) Verify Inode Information

The CoreDump already provided insight into the Inode we got from the FreeList using (gdb) print/x *free_ip

Let’s take a look into cvfsdb, since the customer ran cvfsck which repaired the InodeFreeList.

cvfsdb> show inode 0x80000329dc24

ShowInode 0x80000329dc24 (IelKey: 0x194ee, Sg: 0, Block: 0x194ee, ByteOffset: 36864)

  idi_marker_st     = 0x4e6f [No]

  idi_attr_flags    = 0x10

  idi_user_flags    = 0x0

  idi_expandsize    = 0x0

  idi_flags         = 0x840 ß We see InodeFlagPendFree set

  idi_mode          = 0100666

  idi_nchildren     = 0x0

  idi_nsubdirs      = 0x0

  idi_uid           = 0x0

  idi_gid           = 0x0

  idi_gen           = 0x1

  idi_dm_events     = 0x0

  idi_atime.tv_sec  = 0x558d9bb7 (Fri Jun 26 20:36:39 2015)  ß Access Time followed by Modification & Creation Time

  idi_atime.tv_nsec = 0x34104218

  idi_mtime.tv_sec  = 0x558d9bb7 (Fri Jun 26 20:36:39 2015)

  idi_mtime.tv_nsec = 0x34104218

  idi_ctime.tv_sec  = 0x558d9bb7 (Fri Jun 26 20:36:39 2015)

  idi_ctime.tv_nsec = 0x34104218

  idi_crttime       = 0x558d9bb7 (Fri Jun 26 20:36:39 2015)

  idi_affinity      = 0x0

  idi_size          = 0x0

  idi_blocks        = 0x0

  idi_nextiel       = 0x19541   (0x6550400 / 106234880)

  idi_seqno         = 0xa

  idi_xattr_blk     = 0x0

  idi_ntsec_key     = 0x0

  Extended attribute area =

000:  0101 6001 2b04 032a 5250 4c00 0080 0000  |..`.+..*RPL.....

010:  0f91 1a32 3031 352e 3036 2e32 365f 3230  |...2015.06.26_20

020:  2e33 362e 3339 2d33 3730 322d 3337 3636  |.36.39-3702-3766

030:  2d33 3737 3300 0000 0000 0000 0000 0000  |-3773...........

..

Extents =

idi_marker_en     = 0x4465 [De]

Let’s re-review the Logs around that Time & Date

Cvlog

This is a hard-copy as cut&paste was not possible. This strange cvlog-insertion might not be related, but looking into the timestamps

We can see that the last sane message was posted 26.06 18.oo and then a FSM restart on 27.06 13:03. This is a single Node without a peer Node!

/var/log/messages

Jun 26 19:47:57 strawberry fsm[2770]: StorNext FSS 'Fibrenetix[0]': Node [30] [10.0.0.123:49239] Client Logout (active 3).

Jun 26 19:49:03 strawberry fsm[2769]: StorNext FSS 'EuroStor[0]': Node [30] [10.0.0.123:49241] Client Logout (active 3).

Jun 26 19:50:07 strawberry fsm[2770]: StorNext FSS 'Fibrenetix[0]': Node [28] [10.0.0.122:49603] Client Logout (active 2).

Jun 26 19:50:13 strawberry fsm[2769]: StorNext FSS 'EuroStor[0]': Node [28] [10.0.0.122:49605] Client Logout (active 2).

Jun 27 13:03:20 strawberry kernel: imklog 5.8.10, log source = /proc/kmsg started.

Nssdbg.out

[0626 13:24:41] 0x7fc0f9743700 (debug) NSS: FSS mount list for client 10.0.0.125 (id 10.0.0.125) - Fibrenetix, EuroStor

[0626 19:48:24] 0x7fc0f9743700 (debug) PortMapper: Deleting stale mapping for id 192.168.0.123

[0626 19:50:30] 0x7fc0f9743700 (debug) PortMapper: Deleting stale mapping for id 192.168.0.122

[0627 13:03:26] 0x7f24dac54700 INFO StorNext PortMapper (FSMPM) starting.

Fsmpm.out

[2015/06/27 13:03:42] [EuroStor:3009] Begin: 'snactivated strawberry 46474 EuroStor None'.

The other Logs backup, that something happen during this timeframe. Portmapper delete stale mapping for the clients and have no other activity afterwards until the FSM got restarted the day after.

Resolutions/workarounds/fixes:

Running a Filesystemcheck with the 4.3.3 Version did detect a FreeList mismatch but didn’t detect the incorrect

State of our Inode in question.

Note: you can get the cvfsck 4.7.2 binaries from CSWEB

https://qsweb.quantum.com/wiki/tiki-index.php?page=StorNext%20Products%20-%20StorNext%20Software

We ran again with cvfsck Version 4.7.2  which claims the Inode in question is not within the pend free list when

It should be!

Checking free list. 675840 ( 86%).

Inode 0x80000329dc24 not in pend free list but should be.

Repairing free list.

Repairing free list. 780288 (100%)

Verifying Free List Extents.

Cvfsck 4.7.2 corrected this state, so the inode could be processed by the clean_inode() routine and set the InodeFlagFree

cvfsdb> show inode 0x80000329dc24

ShowInode 0x80000329dc24 (IelKey: 0x194ee, Sg: 0, Block: 0x194ee, ByteOffset: 36864)

  idi_marker_st     = 0x4e6f [No]

  idi_attr_flags    = 0x0

  idi_user_flags    = 0x0

  idi_expandsize    = 0x0

  idi_flags         = 0x10  ß The inode had been cleaned and the InodeFlagFree was correctly set

  idi_mode          = 00

  idi_nchildren     = 0x0

  idi_nsubdirs      = 0x0

  idi_uid           = 0x0

  idi_gid           = 0x0

  idi_gen           = 0x2

  idi_dm_events     = 0x0

  idi_atime.tv_sec  = 0x00000000 (Thu Jan  1 01:00:00 1970)

  idi_atime.tv_nsec = 0x00000000

  idi_mtime.tv_sec  = 0x00000000 (Thu Jan  1 01:00:00 1970)

  idi_mtime.tv_nsec = 0x00000000

  idi_ctime.tv_sec  = 0x00000000 (Thu Jan  1 01:00:00 1970)

  idi_ctime.tv_nsec = 0x00000000

  idi_crttime       = 0x00000000 (not set)

  idi_affinity      = 0x0

  idi_size          = 0x0

  idi_blocks        = 0x0

  idi_nextiel       = 0x19541   (0x6550400 / 106234880)

  idi_seqno         = 0xc

  idi_xattr_blk     = 0x0

  idi_ntsec_key     = 0x0

This might be a potential match for

Bug 40050 - FSM panic - PANIC: /usr/cvfs/bin/fsm ASSERT failed "free_ip->i_idinode.idi_flags & InodeFlagFree" sn/snfs/fsm/inode.c

What we learn from this case:

• Analyse backtrace and Review the corresponding Code Sections
• Always use the cvfsck 4.7.2 binary on 4.X Systems