Infinite Loop?

[tianon]

Hi! 👋

I've got a fairly small cluster (I wish I could give better stats on number of chunks, etc, but it's currently down; more details shortly). There was a power outage today which took out my master -- I've had this a few times before, and usually mfsmaster restore brings me right back without much fanfare (either on the master's data or on a metalogger's data).

This time however, my mfsmaster restore process has been running for five hours, which seemed kind of suspicious, so I copied the metalogger directory on a different machine and tried it there, this time with -xx so I could get some indication of what's happening, and the logs show a bunch of what I can only assume are replaying changelog ops, and it stops at a line like changelog_ml.23.mfs: change1619308908|EMPTYTRASH(457):1,0,45513 where it just hangs.

I attached gdb (after doing strace and seeing nothing), and found that this is the code it's stuck in:

moosefs/mfsmaster/datacachemgr.c

Lines 180 to 248 in b42f16e

	while (p<DCM_TAB_LENG) {
	if (dcm_tab[p].inode == inode && dcm_tab[p].sessionid != sessionid) {
	/* move to the beginning of LRU chain */
	if (p!=dcm_lru_first) {
	/* remove from LRU chain */
	pp = dcm_tab[p].lruprev;
	np = dcm_tab[p].lrunext;
	if (pp<DCM_TAB_LENG) {
	dcm_tab[pp].lrunext = np;
	} else {
	dcm_lru_first = np;
	}
	if (np<DCM_TAB_LENG) {
	dcm_tab[np].lruprev = pp;
	} else {
	dcm_lru_last = pp;
	}
	/* add at the beginning of LRU chain */
	dcm_tab[p].lruprev = DCM_NIL;
	dcm_tab[p].lrunext = dcm_lru_first;
	dcm_tab[dcm_lru_first].lruprev = p;
	dcm_lru_first = p;
	}
	/* remove from INODE chain */
	pp = dcm_tab[p].iprev;
	np = dcm_tab[p].inext;
	if (pp<DCM_TAB_LENG) {
	dcm_tab[pp].inext = np;
	} else {
	dcm_inodehash[ih] = np;
	}
	if (np<DCM_TAB_LENG) {
	dcm_tab[np].iprev = pp;
	}
	/* mark as 'empty' */
	dcm_tab[p].inode = 0;
	dcm_tab[p].inext = DCM_NIL;
	dcm_tab[p].iprev = DCM_NIL;
	// elcount--;
	/* p = INODE_NEXT(p) */
	p = np;
	} else {
	if (dcm_tab[p].inode == inode && dcm_tab[p].sessionid == sessionid) {
	/* move element to the end of LRU list */
	if (dcm_lru_last!=p) { /* do it only if needed */
	/* remove from LRU chain */
	pp = dcm_tab[p].lruprev;
	np = dcm_tab[p].lrunext;
	if (pp<DCM_TAB_LENG) {
	dcm_tab[pp].lrunext = np;
	} else {
	dcm_lru_first = np;
	}
	if (np<DCM_TAB_LENG) {
	dcm_tab[np].lruprev = pp;
	} else {
	dcm_lru_last = pp;
	}
	/* add at the end of LRU chain */
	dcm_tab[p].lruprev = dcm_lru_last;
	dcm_tab[p].lrunext = DCM_NIL;
	dcm_tab[dcm_lru_last].lrunext = p;
	dcm_lru_last = p;
	}
	dcm_tab[p].cacheok = 1;
	}
	p = dcm_tab[p].inext;
	}
	}

The weird thing is that p is zero, dcm_inodehash[ih] is zero, and every value of dcm_tab[p] is also zero ({inode = 0, cacheok = 0, sessionid = 0, iprev = 0, inext = 0, lruprev = 0, lrunext = 0}), so it's looping infinitely on p = dcm_tab[p].inext followed by checking whether p is still smaller than DCM_TAB_LENG, over and over and over.

Does this sound familiar to anyone? Any clues/ideas for how to get my instance back online or at least recover something?

What notes I can provide, while it's offline:

• running mfsmaster restore on version 3.0.115
• two physical systems, each running metalogger (and one running master also)
• 3 and 4 chunkservers each, respectively, with one hard drive per chunkserver process
• I had semi-recently set CHANGELOG_SAVE_MODE to 2, hoping that doing so would make doing a restore on unexpected power less less necessary (boy does that feel silly now 🤕)

Non-verbose output of mfsmaster restore before it hangs:

loading metadata ...
loading sessions data ... ok (0.0000)
loading storage classes data ... ok (0.0000)
loading objects (files,directories,etc.) ... ok (0.3845)
loading names ... ok (2.4939)
loading deletion timestamps ... ok (0.0001)
loading quota definitions ... ok (0.0000)
loading xattr data ... ok (0.0281)
loading posix_acl data ... ok (0.0000)
loading open files data ... ok (0.0000)
loading flock_locks data ... ok (0.0000)
loading posix_locks data ... ok (0.0000)
loading chunkservers data ... ok (0.0000)
loading chunks data ... ok (0.1120)
checking filesystem consistency ... ok
connecting files and chunks ... ok
all inodes: 1587912
directory inodes: 683676
file inodes: 862586
chunks: 947345

Edit: just to confirm that it doesn't just "need a little more time", my original restore is still going strong 14 hours later, and my two other attempts on other machines are at 9 hours 😬

[tianon]

By copying metadata.mfs.back to metadata.mfs, I can get the master to start back up, but I'm still really curious how it got into this situation and would love to help dig into it more. 😅 ❤️

(I'm comfortable applying patches and/or testing from a branch/commit, but I don't have any familiarity with the code block it's stuck in, so I'm hesitant to attempt to make any changes myself 😄)

[chogata]

Do you still have an intact copy of the metadata file and the changelogs that caused this situation? This would be the best (and frankly the only) way to find out what happened.

[tianon]

Yep, definitely - 3 copies of both. 😄

[chogata]

If you are willing to share it, then contact support@moosefs.pro to find out how you can send them over to us. We will then attempt to load them in our lab and find out what happened to hang your master. I suspect there might be a problem with the changelogs due to the power outage and some info not being recorded correctly, however, if this is the case, it still should result in an error message, not in the process hanging indefinitely.

[tianon]

In case anyone had any doubts, the MooseFS team is top notch -- I just tested f7a3c56, and doing a restore on that same corrupted metadata directory completed in 3.4 seconds. 😄 🥳