UBIFS: Possible on-flash metadata corruption

UBIFS: Possible on-flash metadata corruption

[Arnout Vandecappelle]

Hi,

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

>From one moment to the other (not sure if there was a reboot or power-cut
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

Re: UBIFS: Possible on-flash metadata corruption

[Richard Weinberger]

Hi Philip, hi Arnout,

On Mon, Jul 6, 2015 at 4:02 PM, Arnout Vandecappelle
<arnout.vandecappelle@essensium.com> wrote:
> From one moment to the other (not sure if there was a reboot or power-cut
> 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.

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

> 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?

Not really.

> 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?

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

Re: UBIFS: Possible on-flash metadata corruption

[Arnout Vandecappelle]

 Hi Richard,

On 07/06/15 21:49, Richard Weinberger wrote:
> Hi Philip, hi Arnout,
> 
> On Mon, Jul 6, 2015 at 4:02 PM, Arnout Vandecappelle
> <arnout.vandecappelle@essensium.com> wrote:
[snip]
>> 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.
> 
> Yeah.
> Does LEB 23 contain only valid nodes or is something broken or odd too?

 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]
>> 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?
> 
> First we have to figure out what exactly is broken. It looks like a
> wrong LEB->PEB mapping.

 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.

> Can you please share the image?

 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

Re: UBIFS: Possible on-flash metadata corruption

[Richard Weinberger]

Am 08.07.2015 um 17:28 schrieb Arnout Vandecappelle:
>> Can you please share the image?
> 
>  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 :-(
> 

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

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

Okay.

Thanks,
//richard