UBIFS: Possible on-flash metadata corruption

Hi,

We're facing something that looks like on-flash metadata corruption with UBI/UBIFS.

in-between) I was not able to list the content of a specific directory on a UBI partition anymore, getting the following kernel error messages:

UBIFS error (pid 1824): ubifs_read_node_wbuf: bad node type (0 but expected 2) UBIFS error (pid 1824): ubifs_read_node_wbuf: bad node at LEB 23:120832 Not a node, first 24 bytes:
00000000: 64 8f 2e c3 40 23 2e c3 b0 f5 1a c0 00 00 00 00 00 00 00 00 00 00 00 00

So instead of finding a direntry node, UBIFS found an inode node. After flashing a new kernel with dynamic debugging enabled the error message changed into the following where it appears that UBIFS has reused the node in the meantime for a data node:

UBIFS error (pid 458): ubifs_read_node: bad node type (1 but expected 2) UBIFS error (pid 458): ubifs_read_node: bad node at LEB 23:120832, LEB mapping status 1

[<c00131b8>] (unwind_backtrace) from [<c0011350>] (show_stack+0x10/0x14) [<c0011350>] (show_stack) from [<c0122f34>] (ubifs_read_node+0x290/0x2e4) [<c0122f34>] (ubifs_read_node) from [<c0141a28>] (ubifs_tnc_read_node+0x60/0x1cc) [<c0141a28>] (ubifs_tnc_read_node) from [<c0123d7c>] (tnc_read_node_nm+0xb4/0x1c8) [<c0123d7c>] (tnc_read_node_nm) from [<c0127cdc>] (ubifs_tnc_next_ent+0x1dc/0x244) [<c0127cdc>] (ubifs_tnc_next_ent) from [<c011977c>] (ubifs_readdir+0x438/0x52c) [<c011977c>] (ubifs_readdir) from [<c00c41d0>] (iterate_dir+0x60/0x98) [<c00c41d0>] (iterate_dir) from [<c00c45dc>] (SyS_getdents64+0x78/0xe4) [<c00c45dc>] (SyS_getdents64) from [<c000e540>] (ret_fast_syscall+0x0/0x30)

The PEB related to LEB 23 contains all data nodes. AFAIK, UBIFS separates data nodes and other nodes on two different jheads, effectively putting them on separate PEBs? So, it would be weird why it would even look for a direntry node on LEB 23.

In our application, files are changed atomically as suggested by
http://www.linux-mtd.infradead.org/faq/ubifs.html#L_atomic_change. The file with the corrupt metadata is one of the files that is changed this way. These files are updated at a rate of roughly once every 10-60 seconds.

This problem has now appeared out of the blue after running the application for months. A few dozen other units have not shown this problem at all.

UBI does not report any bad blocks or any other event around the time it happened - but debugging output was pretty limited at the time so I don't think any scrubbing event would have been logged. We're not using fastmap. At the UBI level, everything seems to be OK.

The used kernel version is 3.14.39. I've checked for upstream bug-fixes, but couldn't spot any targeting this problem. Further, I copied the UBI partition from the target device to my PC with a 4.0 kernel and used nandsim to mount the corrupted UBIFS volume. The same error happens there as well when listing the 'bad' directory.

The original ubifs was created with ubinize + mkfs.ubifs under a 3.4 kernel, but since all the files and directories have been overwritten several times under the 3.14 kernel, there is probably not much left from the original creation.

Is this already an identified issue?

I have not been able to locate the node that refers to LEB 23:120832 - it would seem that that is the one that is corrupt. Is there any tool or debug trace that will help me find the referring node?

Is there any way that would allow me to automatically recover from such an issue if it occurs again?

We would be grateful for any help!

Regards,
Philip & Arnout

Arnout Vandecappelle      arnout dot vandecappelle at essensium dot com
Senior Embedded Software Architect . . . . . . +32-478-010353 (mobile)
Essensium, Mind division . . . . . . . . . . . . . . http://www.mind.be
G.Geenslaan 9, 3001 Leuven, Belgium . . . . . BE 872 984 063 RPR Leuven
LinkedIn profile: http://www.linkedin.com/in/arnoutvandecappelle
GPG fingerprint:  7493 020B C7E3 8618 8DEC 222C 82EB F404 F9AC 0DDF

Hi Philip, hi Arnout,

Yeah.
Does LEB 23 contain only valid nodes or is something broken or odd too?

Not really.

First we have to figure out what exactly is broken. It looks like a wrong LEB->PEB mapping.
Can you please share the image?

Thanks,
//richard

Hi Richard,

[snip]

It looks like it only contains valid data nodes, corresponding to the data that
is frequently updated. At least the node type looks OK, but that's just from looking at the hexdump so not a very exhaustive check.

[snip]

We thought of that as well. However, the UBI partition contains 1800 PEBs, of
which about 1000 are in use and only 34 are used by this particular ubifs volume. So it seems to me that it would be quite unlikely that a bad LEB->PEB mapping would happen to point to the right volume.

Unfortunately, no. It took me so long to reply because I had to find out if
this was possible or not.

We could extract the PEB headers from the image, and the internal volume, and
that could be shared. We could also erase everything in the other volumes. But all that takes time which we don't really have at the moment :-(

So no progress at the moment. We'll do some more debugging next week and report
the results.

Regards,
Arnout

Arnout Vandecappelle      arnout dot vandecappelle at essensium dot com
Senior Embedded Software Architect . . . . . . +32-478-010353 (mobile)
Essensium, Mind division . . . . . . . . . . . . . . http://www.mind.be
G.Geenslaan 9, 3001 Leuven, Belgium . . . . . BE 872 984 063 RPR Leuven
LinkedIn profile: http://www.linkedin.com/in/arnoutvandecappelle
GPG fingerprint:  7493 020B C7E3 8618 8DEC 222C 82EB F404 F9AC 0DDF

Am 08.07.2015 um 17:28 schrieb Arnout Vandecappelle:

:-(

Please no mangled images. This would be a waste of both my and your time.

Okay.

Thanks,
//richard