ubifs: replay log error · kernelthread

hujianyang

author

2014-06-10 09:16 UTC #0 lore raw

Hi Artem,

I meet a serious problem when I was mounting an ubifs partition in v3.10.

[  938.975707] UBIFS: background thread "ubifs_bgt0_0" started, PID 2222
[  938.992994] UBIFS: recovery needed
[  939.005971] UBIFS error (pid 2220): replay_log_leb: first log node at LEB 4:0 is not CS node
[  939.006004] UBIFS error (pid 2220): replay_log_leb: log error detected while replaying the log at LEB 4:0
[  939.006024]  magic          0x6101831
[  939.006046]  crc            0x81e22cd5
[  939.006063]  node_type      8 (reference node)
[  939.006084]  group_type     0 (no node group)
[  939.006105]  sqnum          2375337
[  939.006123]  len            64
[  939.006144]  lnum           5273
[  939.006164]  offs           122880
[  939.006181]  jhead          2
[  939.006279] UBIFS: background thread "ubifs_bgt0_0" stops

I found a similar problem fixed by commit c6727932, Do you think they are related?

In my environment, system will be shutdown by high temperature. So the filesystem would be unclean umount several times.

Besides, do we have some tools like fsck to re-valid the partition after this error happen? I can't mount this partition now and format it again is the only way I know to deal with this situation.

Thanks.

Hu

hujianyang

author

2014-06-19 08:39 UTC #1 lore raw

Now I have reproduced this failure many times. Once the partition mounted, there are lots of IOs. Power off the system several times may case this failure.

I dump the first node in each LOG leb and found none cs node exist.

[  808.022004] UBIFS error (pid 1643): replay_log_leb: first log node at LEB 6:0
 is not CS node
[  808.121044] UBIFS error (pid 1643): replay_log_leb: log error detected while
replaying the log at LEB 6:0
[  808.235548]  magic          0x6101831
[  808.279264]  crc            0x70b8d9be
[  808.324030]  node_type      8 (reference node)
[  808.377137]  group_type     0 (no node group)
[  808.429181]  sqnum          536414
[  808.469779]  len            64
[  808.506224]  lnum           5609
[  808.544735]  offs           124928
[  808.585336]  jhead          1
[  808.620762] UBIFS error (pid 1643): ubifs_show_log: HUJY: start to dump log L
EB
[  808.708185] UBIFS error (pid 1643): ubifs_show_log: HUJY: fs(cmt_no) = 308
[  808.790439] UBIFS error (pid 1643): ubifs_show_log: HUJY: replay log LEB 3
[  808.884122] UBIFS error (pid 1643): ubifs_show_log: HUJY: ref_node, sqnum = 5
35991
[  808.972764] UBIFS error (pid 1643): ubifs_show_log: HUJY: replay log LEB 4
[  809.066455] UBIFS error (pid 1643): ubifs_show_log: HUJY: ref_node, sqnum = 5
36115
[  809.155097] UBIFS error (pid 1643): ubifs_show_log: HUJY: replay log LEB 5
[  809.248787] UBIFS error (pid 1643): ubifs_show_log: HUJY: ref_node, sqnum = 5
36239
[  809.337410] UBIFS error (pid 1643): ubifs_show_log: HUJY: replay log LEB 6
[  809.431098] UBIFS error (pid 1643): ubifs_show_log: HUJY: ref_node, sqnum = 5
36414
[  809.519734] UBIFS error (pid 1643): ubifs_show_log: HUJY: replay log LEB 7
[  809.613376] UBIFS error (pid 1643): ubifs_show_log: HUJY: ref_node, sqnum = 5
36671
[  809.702002] UBIFS error (pid 1643): ubifs_show_log: HUJY: replay log LEB 8
[  809.795697] UBIFS error (pid 1643): ubifs_show_log: HUJY: ref_node, sqnum = 5
36795
[  809.884332] UBIFS error (pid 1643): ubifs_show_log: HUJY: replay log LEB 9
[  809.978025] UBIFS error (pid 1643): ubifs_show_log: HUJY: ref_node, sqnum = 5
37164
[  810.066650] UBIFS error (pid 1643): ubifs_show_log: HUJY: replay log LEB 10
[  810.161384] UBIFS error (pid 1643): ubifs_show_log: HUJY: ref_node, sqnum = 5
37533
[  810.250025] UBIFS error (pid 1643): ubifs_show_log: HUJY: replay log LEB 11
[  810.344749] UBIFS error (pid 1643): ubifs_show_log: HUJY: ref_node, sqnum = 5
37657
[  810.433385] UBIFS error (pid 1643): ubifs_show_log: HUJY: replay log LEB 12
[  810.528145] UBIFS error (pid 1643): ubifs_show_log: HUJY: ref_node, sqnum = 5
37813
[  810.616790] UBIFS error (pid 1643): ubifs_show_log: HUJY: replay log LEB 13
[  810.711451] UBIFS error (pid 1643): ubifs_show_log: HUJY: ref_node, sqnum = 5
38211
[  810.800068] UBIFS error (pid 1643): ubifs_show_log: HUJY: dump log LEB finish

-----------------------------------------------------------------------------------

by this function

@@ -812,6 +812,40 @@ static int validate_ref(struct ubifs_info *c, const struct ubifs_ref_node *ref)
return 0;
}

+static void ubifs_show_log(struct ubifs_info *c, void *sbuf) +{
+ struct ubifs_scan_leb *sleb;
+ struct ubifs_scan_node *snod;
+ int lnum = UBIFS_LOG_LNUM;
+
+ ubifs_err("HUJY: start to dump log LEB");
+ ubifs_err("HUJY: fs(cmt_no) = %llu", c->cmt_no);
+ do {
+ ubifs_err("HUJY: replay log LEB %d", lnum);
+ sleb = ubifs_scan(c, lnum, 0, sbuf, 0);
+ if (!sleb->nodes_cnt) {
+ ubifs_err("HUJY: empty leb");
+ goto free;
+ }
+ snod = list_entry(sleb->nodes.next, struct ubifs_scan_node, list);
+ if (snod->type == UBIFS_CS_NODE) {
+ const struct ubifs_cs_node *node;
+
+ node = sleb->buf;
+ ubifs_err("HUJY: cs_node, cmt_no = %llu", node->cmt_no);
+ ubifs_err("HUJY: cs_sqnum = %llu", node->ch.sqnum);
+ } else if (snod->type == UBIFS_REF_NODE) {
+ ubifs_err("HUJY: ref_node, sqnum = %llu", snod->sqnum);
+ } else {
+ ubifs_err("HUJY: wrong type node");
+ }
+free:
+ ubifs_scan_destroy(sleb);
+ lnum = ubifs_next_log_lnum(c, lnum);
+ } while (lnum != UBIFS_LOG_LNUM);
+ ubifs_err("HUJY: dump log LEB finish");
+}
+
/**
* replay_log_leb - replay a log logical eraseblock.
* @c: UBIFS file-system description object
@@ -959,6 +993,7 @@ out_dump:
lnum, offs + snod->offs);
ubifs_dump_node(c, snod->node); ubifs_scan_destroy(sleb);
+ ubifs_show_log(c, sbuf);
return -EINVAL;
}

hujianyang

author

2014-06-19 08:59 UTC #2 lore raw

In reply to hujianyang

I found there might be a race in do_commit(). If we perform ubifs_log_end_commit() before write master node, another process which run ubifs_add_bud_to_log() may destroy the old cs_node in the next or latter leb. Because log_end_commit() will change @c->ltail_lnum by new @ltail_lnum. If power off happens before we write either master node, we will read the old master nodes and find no cs node exist in the leb which master node indicate in the next mount.

Am I right?

So I want to remove the operations in ubifs_log_end_commit() after write master nodes to avoid the old cs node being covered by new ref node.

Now I would like to show the undone patch.

fs/ubifs/commit.c +6 -6

@@ -108,7 +108,7 @@ static int nothing_to_commit(struct ubifs_info *c)
  */
 static int do_commit(struct ubifs_info *c)
 {
-	int err, new_ltail_lnum, old_ltail_lnum, i;
+	int err, new_ltail_lnum, i;
 	struct ubifs_zbranch zroot;
 	struct ubifs_lp_stats lst;

@@ -166,10 +166,10 @@ static int do_commit(struct ubifs_info *c)
 	err = ubifs_orphan_end_commit(c);
 	if (err)
 		goto out;
-	old_ltail_lnum = c->ltail_lnum;
-	err = ubifs_log_end_commit(c, new_ltail_lnum);
-	if (err)
-		goto out;
+//	old_ltail_lnum = c->ltail_lnum;
+//	err = ubifs_log_end_commit(c, new_ltail_lnum);
+//	if (err)
+//		goto out;
 	err = dbg_check_old_index(c, &zroot);
 	if (err)
 		goto out;

@@ -208,7 +208,7 @@ static int do_commit(struct ubifs_info *c)
 	if (err)
 		goto out;
 
-	err = ubifs_log_post_commit(c, old_ltail_lnum);
+	err = ubifs_log_post_commit(c, new_ltail_lnum);
 	if (err)
 		goto out;
 	err = ubifs_gc_end_commit(c);

fs/ubifs/log.c +17 -1

index 36bd4ef..d263642 100644
@@ -495,9 +495,10 @@ int ubifs_log_end_commit(struct ubifs_info *c, int ltail_lnum)
  *
  * This function returns %0 on success and a negative error code on failure.
  */
-int ubifs_log_post_commit(struct ubifs_info *c, int old_ltail_lnum)
+int ubifs_log_post_commit(struct ubifs_info *c, int new_ltail_lnum)
 {
 	int lnum, err = 0;
+	int old_ltail_lnum;
 
 	while (!list_empty(&c->old_buds)) {
 		struct ubifs_bud *bud;

@@ -510,6 +511,14 @@ int ubifs_log_post_commit(struct ubifs_info *c, int old_ltail_lnum)
 		kfree(bud);
 	}
 	mutex_lock(&c->log_mutex);
+
+	dbg_log("old tail was LEB %d:0, new tail is LEB %d:0",
+		c->ltail_lnum, new_ltail_lnum);
+
+	old_ltail_lnum = c->ltail_lnum;
+	c->ltail_lnum = new_ltail_lnum;
+	c->min_log_bytes = c->leb_size;	
+
 	for (lnum = old_ltail_lnum; lnum != c->ltail_lnum;
 	     lnum = ubifs_next_log_lnum(c, lnum)) {
 		dbg_log("unmap log LEB %d", lnum);

@@ -517,6 +526,13 @@ int ubifs_log_post_commit(struct ubifs_info *c, int old_ltail_lnum)
 		if (err)
 			goto out;
 	}
+
+	spin_lock(&c->buds_lock);
+	c->bud_bytes -= c->cmt_bud_bytes;
+	spin_unlock(&c->buds_lock);
+
+	err = dbg_check_bud_bytes(c);
+
 out:
 	mutex_unlock(&c->log_mutex);
 	return err;

hujianyang

author

2014-06-24 12:44 UTC #3 lore raw

I've tested this patch for 4 days and this error didn't come out again. But I don't know if it is really work.

I would like to send a formal patch this week if this error didn't be reproduced in these days.

What's your opinion?

Artem Bityutskiy

2014-06-29 13:40 UTC #4 lore raw

In reply to hujianyang

Quoted 10 lines · hujianyang

I found there might be a race in do_commit(). If we perform ubifs_log_end_commit() before write master node, another process which run ubifs_add_bud_to_log() may destroy the old cs_node in the next or latter leb. Because log_end_commit() will change @c->ltail_lnum by new @ltail_lnum. If power off happens before we write either master node, we will read the old master nodes and find no cs node exist in the leb which master node indicate in the next mount.
Am I right?

Frankly, I did not fully understand your explanation, but after spending some time looking at the code and trying to recall what is going on there, I see the race condition.

Excellent analysis, well done, thank you!

Quoted 1 line

Now I would like to show the undone patch.

Not sure this patch is the best way to fix the issue.

How about the following patch (also attached), which I did not test, and did not even compile-check.

Quoted 1 line

From 31c07463f4c475976723986d7ec46bf961ed46e5 Mon Sep 17 00:00:00 2001

From: Artem Bityutskiy <[email protected]>
Date: Sun, 29 Jun 2014 16:32:21 +0300
Subject: [PATCH] UBIFS: fix fatal race condition

Hu ([email protected]) discovered a race condition which leads to a situation when UBIFS is unable to mount the file-system after an unclean reboot. On top of that, Hu analysed it and proposed a solution. This patch is based on his work, but solves the problem a little bit differently.

Here is an attempt to shed some light on the problem.

In UBIFS, we have the log, which basically a set of LEBs in a certain area. The log has the tail and the head.

Every time user writes data to the file-system, the UBIFS journal grows, and the log grows as well, because we append new reference nodes to the head of the log. So the head moves forward all the time, while the log tail stays at the same position.

At any time, the UBIFS master node points to the tail of the log. When we mount the file-system, we scan the log, and we always start from its tail, because this is where the master node points to. The only occasion when the tail of the log changes is the commit operation.

The commit operation has 2 phases - "commit start" and "commit end". The former is relatively short, and does not involve much I/O. During this phase we mostly just build various in-memory lists of the things which have to be written to the flash media during "commit end" phase.

During the commit start phase, what we do is we "clean" the log. Indeed, the commit operation will index all the data in the journal, so the entire journal "disappears", and therefore the data in the log become unneeded. So we just move the head of the log to the next LEB, and write the CS node there. This LEB will be the tail of the new log when the commit operation finishes.

When the "commit start" phase finishes, users may write more data to the file-system, in parallel with the ongoing "commit end" operation. At this point the log tail was not changed yet, it is the same as it had been before we started the commit. The log head keeps moving forward, though.

The commit operation now needs to write the new master node, and the new master node should point to the new log tail. After this the LEBs between the old log tail and the new log tail can be unmapped and re-used again.

And here is the problem. We do 2 operations: (a) We first update the log tail position in memory (see 'ubifs_log_end_commit()'). (b) And then we write the master node (see the big lock of code in 'do_commit()').

But nothing prevents the log head from moving forward between (a) and (b), and the log head may "wrap" now to the old log tail. And when the "wrap" happens, the contends of the log tail gets erased. Now a power cut happens and we are in trouble. We end up with the old master node pointing to the old tail, which was erased. And replay fails because it expects the master node to point to the correct log tail at all times.

The symptoms of the mount failure are:

UBIFS: background thread "ubifs_bgt0_0" started, PID 2222
UBIFS: recovery needed
UBIFS error (pid 2220): replay_log_leb: first log node at LEB 4:0 is not CS node UBIFS error (pid 2220): replay_log_leb: log error detected while replaying the log at LEB 4:0

 magic          0x6101831
 crc            0x81e22cd5
 node_type      8 (reference node)
 group_type     0 (no node group)
 sqnum          2375337
 len            64
 lnum           5273
 offs           122880
 jhead          2

UBIFS: background thread "ubifs_bgt0_0" stops

This fix merges the abovementioned (a) and (b) operations by moving the master node change code to the 'ubifs_log_end_commit()' function, so that it runs with the log mutex locked, which will prevent the log from being changed benween operations (a) and (b).

Reported-by hujianyang <[email protected]>

Signed-off-by Artem Bityutskiy <[email protected]>

Cc [email protected]

---
 fs/ubifs/commit.c | 37 ++-----------------------------------
 fs/ubifs/log.c    | 50 +++++++++++++++++++++++++++++++++++++++++++++++---
 2 files changed, 49 insertions(+), 38 deletions(-)

fs/ubifs/commit.c +2 ~~-35~~

index ff82293..51a673c 100644
@@ -166,45 +166,12 @@ static int do_commit(struct ubifs_info *c)
 	err = ubifs_orphan_end_commit(c);
 	if (err)
 		goto out;
-	old_ltail_lnum = c->ltail_lnum;
-	err = ubifs_log_end_commit(c, new_ltail_lnum);
-	if (err)
-		goto out;
 	err = dbg_check_old_index(c, &zroot);
 	if (err)
 		goto out;
 
-	mutex_lock(&c->mst_mutex);
-	c->mst_node->cmt_no      = cpu_to_le64(c->cmt_no);
-	c->mst_node->log_lnum    = cpu_to_le32(new_ltail_lnum);
-	c->mst_node->root_lnum   = cpu_to_le32(zroot.lnum);
-	c->mst_node->root_offs   = cpu_to_le32(zroot.offs);
-	c->mst_node->root_len    = cpu_to_le32(zroot.len);
-	c->mst_node->ihead_lnum  = cpu_to_le32(c->ihead_lnum);
-	c->mst_node->ihead_offs  = cpu_to_le32(c->ihead_offs);
-	c->mst_node->index_size  = cpu_to_le64(c->bi.old_idx_sz);
-	c->mst_node->lpt_lnum    = cpu_to_le32(c->lpt_lnum);
-	c->mst_node->lpt_offs    = cpu_to_le32(c->lpt_offs);
-	c->mst_node->nhead_lnum  = cpu_to_le32(c->nhead_lnum);
-	c->mst_node->nhead_offs  = cpu_to_le32(c->nhead_offs);
-	c->mst_node->ltab_lnum   = cpu_to_le32(c->ltab_lnum);
-	c->mst_node->ltab_offs   = cpu_to_le32(c->ltab_offs);
-	c->mst_node->lsave_lnum  = cpu_to_le32(c->lsave_lnum);
-	c->mst_node->lsave_offs  = cpu_to_le32(c->lsave_offs);
-	c->mst_node->lscan_lnum  = cpu_to_le32(c->lscan_lnum);
-	c->mst_node->empty_lebs  = cpu_to_le32(lst.empty_lebs);
-	c->mst_node->idx_lebs    = cpu_to_le32(lst.idx_lebs);
-	c->mst_node->total_free  = cpu_to_le64(lst.total_free);
-	c->mst_node->total_dirty = cpu_to_le64(lst.total_dirty);
-	c->mst_node->total_used  = cpu_to_le64(lst.total_used);
-	c->mst_node->total_dead  = cpu_to_le64(lst.total_dead);
-	c->mst_node->total_dark  = cpu_to_le64(lst.total_dark);
-	if (c->no_orphs)
-		c->mst_node->flags |= cpu_to_le32(UBIFS_MST_NO_ORPHS);
-	else
-		c->mst_node->flags &= ~cpu_to_le32(UBIFS_MST_NO_ORPHS);
-	err = ubifs_write_master(c);
-	mutex_unlock(&c->mst_mutex);
+	old_ltail_lnum = c->ltail_lnum;
+	err = ubifs_log_end_commit(c, new_ltail_lnum);
 	if (err)
 		goto out;

fs/ubifs/log.c +47 -3

63 lines not on this page · raw message

Signature · 6 lines

1.9.3


-- 
Best Regards,
Artem Bityutskiy