UBIFS error: replay_log_leb: first log node at LEB 3:0 is not CS node

UBIFS error: replay_log_leb: first log node at LEB 3:0 is not CS node

[James Nute]

Hello

I'm getting a UBIFS Corruption during a power failure with a fail
signature that I believe is different from what has been seen in the
past.
When I flash a new UBI image onto my device and boot it for the first
time everything comes up as expected. However if I force a power
failure before any major file writes occur the device will crash when
UBIFS attempts to recover during the next reboot. If I force a sync
command before the power failure I am able to successfully avert the
recovery failure. I worry that this indicates something ugly is going
on that I can't detect.

To get more debug messages I have enabled UBIFS debugging and enabled
the recovery and mount messages by booting with
""ubifs.debug_msgs=6144 ignore_loglevel" kernel parameters

Below is a snippet of the debug messages:

Mounting ubifs fileUBIFS DBG (pid 342): ubifs_bg_thread: background
thread "ubifs_bgt0_0" started, PID 342
system on 'ubi0:container'...
UBIFS: recovery needed
UBIFS error (pid 1): replay_log_leb: first log node at LEB 3:0 is not CS node
UBIFS error (pid 1): replay_log_leb: log error detected while
replaying the log at LEB 3:0
       magic          0x6101831
       crc            0x96c5716c
       node_type      8 (reference node)
       group_type     0 (no node group)
       sqnum          4544
       len            64
       lnum           138
       offs           67584
       jhead          1
UBIFS DBG (pid 342): ubifs_bg_thread: background thread "ubifs_bgt0_0" stops
Error: can't mount 'ubi0:container'
Kernel panic - not syncing: Attempted to kill init!
Call Trace:
[c782be40] [c0008224] show_stack+0x4c/0x138 (unreliable)
[c782be80] [c0298040] panic+0xb4/0x1f8
[c782bee0] [c00208c8] do_exit+0x8c/0x648
[c782bf30] [c0020ec4] do_group_exit+0x0/0xdc
[c782bf40] [c000e148] ret_from_syscall+0x0/0x38
--- Exception: c01 at 0x10000eac
   LR = 0x10000a50

A complete log can be viewed here: http://mcreech.com/work/ubifs-2012-05-08.txt

Does anyone have any suggestions?

Thanks,
James Nute

Re: UBIFS error: replay_log_leb: first log node at LEB 3:0 is not CS node

[Artem Bityutskiy]

[-- Attachment #1: Type: text/plain, Size: 1542 bytes --]

On Wed, 2012-05-09 at 09:45 -0400, James Nute wrote:
> Hello
> 
> I'm getting a UBIFS Corruption during a power failure with a fail
> signature that I believe is different from what has been seen in the
> past.
> When I flash a new UBI image onto my device and boot it for the first
> time everything comes up as expected. However if I force a power
> failure before any major file writes occur the device will crash when
> UBIFS attempts to recover during the next reboot. If I force a sync
> command before the power failure I am able to successfully avert the
> recovery failure. I worry that this indicates something ugly is going
> on that I can't detect.

Unfortunately you did not really enable the debugging messages or you
forgot to type "dmesg". Anyway, they are absent.

> 
> To get more debug messages I have enabled UBIFS debugging and enabled
> the recovery and mount messages by booting with
> ""ubifs.debug_msgs=6144 ignore_loglevel" kernel parameters

Can you actually enable them and share the log? Or may be you can dump
the image and share it - I should be able to put it to nandsim and try
to mount and see.

Looks like old master node was for some reason selected for some reason
- I'd first looked to the master area. But most probably it was already
cleaned-up when you tried to mounted for the very first time after the
power cut. Do you have kernel logs of that ? Are there messages about
corrupted master node?

Is this problem reproducible?

-- 
Best Regards,
Artem Bityutskiy

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: UBIFS error: replay_log_leb: first log node at LEB 3:0 is not CS node

[James Nute]

On Fri, May 11, 2012 at 10:03 AM, Artem Bityutskiy <dedekind1@gmail.com> wrote:
> On Wed, 2012-05-09 at 09:45 -0400, James Nute wrote:
>> Hello
>>
>> I'm getting a UBIFS Corruption during a power failure with a fail
>> signature that I believe is different from what has been seen in the
>> past.
>> When I flash a new UBI image onto my device and boot it for the first
>> time everything comes up as expected. However if I force a power
>> failure before any major file writes occur the device will crash when
>> UBIFS attempts to recover during the next reboot. If I force a sync
>> command before the power failure I am able to successfully avert the
>> recovery failure. I worry that this indicates something ugly is going
>> on that I can't detect.
>
> Unfortunately you did not really enable the debugging messages or you
> forgot to type "dmesg". Anyway, they are absent.
>
>>
>> To get more debug messages I have enabled UBIFS debugging and enabled
>> the recovery and mount messages by booting with
>> ""ubifs.debug_msgs=6144 ignore_loglevel" kernel parameters
>
> Can you actually enable them and share the log?

I did the following to enable debugging:
1. "CONFIG_UBIFS_FS_DEBUG=y" in kernel config
2. Added "ubifs.debug_msgs=6144" to the kernel command line
3. Added "ignore_loglevel" to the kernel command line
4. Captured all console output with putty and uploaded to
http://mcreech.com/work/ubifs-2012-05-08.txt

I'm not sure what step I missed to enable the full debugging messages.
I am getting some UBIFS DBG messages in my log but not many.


> Or may be you can dump
> the image and share it - I should be able to put it to nandsim and try
> to mount and see.

I will look into dumping the image for you but I have not done this before.
Do you want a dump from before the power fail or after?


> Is this problem reproducible?
Yes I have had no trouble recreating this fail.

I will continue to try to figure out why I am not getting all the
debug messages.
Thank you for help

Re: UBIFS error: replay_log_leb: first log node at LEB 3:0 is not CS node

[Artem Bityutskiy]

[-- Attachment #1: Type: text/plain, Size: 3567 bytes --]

On Fri, 2012-05-11 at 14:56 -0400, James Nute wrote:
> On Fri, May 11, 2012 at 10:03 AM, Artem Bityutskiy <dedekind1@gmail.com> wrote:
> > On Wed, 2012-05-09 at 09:45 -0400, James Nute wrote:
> >> Hello
> >>
> >> I'm getting a UBIFS Corruption during a power failure with a fail
> >> signature that I believe is different from what has been seen in the
> >> past.
> >> When I flash a new UBI image onto my device and boot it for the first
> >> time everything comes up as expected. However if I force a power
> >> failure before any major file writes occur the device will crash when
> >> UBIFS attempts to recover during the next reboot. If I force a sync
> >> command before the power failure I am able to successfully avert the
> >> recovery failure. I worry that this indicates something ugly is going
> >> on that I can't detect.
> >
> > Unfortunately you did not really enable the debugging messages or you
> > forgot to type "dmesg". Anyway, they are absent.
> >
> >>
> >> To get more debug messages I have enabled UBIFS debugging and enabled
> >> the recovery and mount messages by booting with
> >> ""ubifs.debug_msgs=6144 ignore_loglevel" kernel parameters
> >
> > Can you actually enable them and share the log?
> 
> I did the following to enable debugging:
> 1. "CONFIG_UBIFS_FS_DEBUG=y" in kernel config
> 2. Added "ubifs.debug_msgs=6144" to the kernel command line
> 3. Added "ignore_loglevel" to the kernel command line
> 4. Captured all console output with putty and uploaded to
> http://mcreech.com/work/ubifs-2012-05-08.txt
> 
> I'm not sure what step I missed to enable the full debugging messages.
> I am getting some UBIFS DBG messages in my log but not many.

Did you pull the latest UBIFS from the back-port trees? In the latest
UBIFS we switch to dynamic debugging. I did not do good documentation
how to use it because of lack of time. But you can read the general
instructions in the Documentation directory.

You may as well hack ubifs and force it to use printk with KERN_ERROR to
make sure everything goes to your serial console. See the debug.h file.

> > the image and share it - I should be able to put it to nandsim and try
> > to mount and see.
> 
> I will look into dumping the image for you but I have not done this before.
> Do you want a dump from before the power fail or after?

After the failure. The ideal is the one after the failure but _before_
you first mount it.

> > Is this problem reproducible?
> Yes I have had no trouble recreating this fail.

Hmm, then I suspect you have issues on driver level. Did you validate
your driver with MTD tests?

> I will continue to try to figure out why I am not getting all the
> debug messages.

Depends on your version. If it uses printk - I described various things
here:
http://www.linux-mtd.infradead.org/faq/ubi.html#L_how_debug

It is for UBI, but the information about printk and and log buffer is
generic.

The newest UBIFS used dynamic debugging infrastructure instead:

Documentation/dynamic-debug-howto.txt

You can enable various debugging messages using that infrastructure. See
the debug.h file in ubifs - it prefixes messages from various subsystems
- you can use them to see the messages.

Not that dynamic prints have KERN_DEBUG level and they do not go to your
serial console. You can boot with ignore_loglevel kernel option to see
_all_ the messages.

This stuff needs good documentation on the web site - many people get
confused ... :-(

-- 
Best Regards,
Artem Bityutskiy

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: UBIFS error: replay_log_leb: first log node at LEB 3:0 is not CS node

[James Nute]

On Tue, May 15, 2012 at 3:22 AM, Artem Bityutskiy <dedekind1@gmail.com> wrote:
> On Fri, 2012-05-11 at 14:56 -0400, James Nute wrote:
>> On Fri, May 11, 2012 at 10:03 AM, Artem Bityutskiy <dedekind1@gmail.com> wrote:
>> > On Wed, 2012-05-09 at 09:45 -0400, James Nute wrote:
>> >> Hello
>> >>
>> >> I'm getting a UBIFS Corruption during a power failure with a fail
>> >> signature that I believe is different from what has been seen in the
>> >> past.
>> >> When I flash a new UBI image onto my device and boot it for the first
>> >> time everything comes up as expected. However if I force a power
>> >> failure before any major file writes occur the device will crash when
>> >> UBIFS attempts to recover during the next reboot. If I force a sync
>> >> command before the power failure I am able to successfully avert the
>> >> recovery failure. I worry that this indicates something ugly is going
>> >> on that I can't detect.
>> >
>> > Unfortunately you did not really enable the debugging messages or you
>> > forgot to type "dmesg". Anyway, they are absent.
>> >
>> >>
>> >> To get more debug messages I have enabled UBIFS debugging and enabled
>> >> the recovery and mount messages by booting with
>> >> ""ubifs.debug_msgs=6144 ignore_loglevel" kernel parameters
>> >
>> > Can you actually enable them and share the log?
>>
>> I did the following to enable debugging:
>> 1. "CONFIG_UBIFS_FS_DEBUG=y" in kernel config
>> 2. Added "ubifs.debug_msgs=6144" to the kernel command line
>> 3. Added "ignore_loglevel" to the kernel command line
>> 4. Captured all console output with putty and uploaded to
>> http://mcreech.com/work/ubifs-2012-05-08.txt
>>
>> I'm not sure what step I missed to enable the full debugging messages.
>> I am getting some UBIFS DBG messages in my log but not many.
>
> Did you pull the latest UBIFS from the back-port trees? In the latest
> UBIFS we switch to dynamic debugging. I did not do good documentation
> how to use it because of lack of time. But you can read the general
> instructions in the Documentation directory.
>
> You may as well hack ubifs and force it to use printk with KERN_ERROR to
> make sure everything goes to your serial console. See the debug.h file.
>
>> > the image and share it - I should be able to put it to nandsim and try
>> > to mount and see.
>>
>> I will look into dumping the image for you but I have not done this before.
>> Do you want a dump from before the power fail or after?
>
> After the failure. The ideal is the one after the failure but _before_
> you first mount it.
>
>> > Is this problem reproducible?
>> Yes I have had no trouble recreating this fail.
>
> Hmm, then I suspect you have issues on driver level. Did you validate
> your driver with MTD tests?

This particular product has been all through the MTD tests and has
been running uboot and and UBIFS for several years.
We always try to stay up to date with the latest of both the kernel
and uboot. Because of this I was able to track back to a kernel that
did not exhibit the issue and followed that back to the free space
fixup function.

I wrote a quick patch to remove the call to the ubifs_fixup_free_space
function from fs/ubifs/super.c and the problem goes away.
I currently do not understand enough of the UBIFS internal to see why
this particular function is at fault. Is it possible that it is
incorrectly erasing the new master node?

>> I will continue to try to figure out why I am not getting all the
>> debug messages.
>
> Depends on your version. If it uses printk - I described various things
> here:
> http://www.linux-mtd.infradead.org/faq/ubi.html#L_how_debug
>
> It is for UBI, but the information about printk and and log buffer is
> generic.
>
> The newest UBIFS used dynamic debugging infrastructure instead:
>
> Documentation/dynamic-debug-howto.txt
>
> You can enable various debugging messages using that infrastructure. See
> the debug.h file in ubifs - it prefixes messages from various subsystems
> - you can use them to see the messages.
>
> Not that dynamic prints have KERN_DEBUG level and they do not go to your
> serial console. You can boot with ignore_loglevel kernel option to see
> _all_ the messages.
>
> This stuff needs good documentation on the web site - many people get
> confused ... :-(

Thanks,
James Nute

Re: UBIFS error: replay_log_leb: first log node at LEB 3:0 is not CS node

[Artem Bityutskiy]

[-- Attachment #1: Type: text/plain, Size: 585 bytes --]

On Mon, 2012-06-04 at 16:05 -0400, James Nute wrote:
> I wrote a quick patch to remove the call to the ubifs_fixup_free_space
> function from fs/ubifs/super.c and the problem goes away.
> I currently do not understand enough of the UBIFS internal to see why
> this particular function is at fault. Is it possible that it is
> incorrectly erasing the new master node?

Is it please possible to either provide the faulty image or enable all
debugging messages and providing the full log. Do not forget about the
ignore_loglevel options.

-- 
Best Regards,
Artem Bityutskiy

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]