All the mail mirrored from lore.kernel.org
 help / color / mirror / Atom feed
* UBIFS errors when file-system is full
@ 2015-07-13 13:55 Bhuvanchandra DV
  2015-07-13 14:09 ` Richard Weinberger
  0 siblings, 1 reply; 34+ messages in thread
From: Bhuvanchandra DV @ 2015-07-13 13:55 UTC (permalink / raw)
  To: linux-mtd

Hello,

Facing some issues with UBIFS mounting when NAND flash is almost near to full.

Hardware:
SOC: Freescale Vybrid
COM: Colibri VF50
Flash: Macronic NAND 128MB, 3.3V, 8-Bit

By default the Linux Image flashed on the NAND flash almost occupies ~93% of the flash.
Observed this issue when power resetting the module for about 500 times, with journalctl
enabled, after around 500 power cycles the debug log fills up the nand flash. When the
flash menory is about to full, the ubifs partation is un-mountable.

The nand flash controller driver is under review and passed all MTD tests.
https://lkml.org/lkml/2015/6/18/847


Debug log during UBIFS mounting from U-Boot:

U-Boot 2015.04 (May 18 2015 - 15:37:34)

CPU: Freescale Vybrid VF500 at 396 MHz
Reset cause: POWER ON RESET
DRAM:  128 MiB
NAND:  128 MiB
MMC:   FSL_SDHC: 0
*** Warning - bad CRC, using default environment

In:    serial
Out:   serial
Err:   serial
Model: Toradex Colibri VF50 128MB V1.1A, Serial# 04815679
Net:   FEC
Hit any key to stop autoboot:  0
Booting from NAND...
UBI: default fastmap pool size: 50
UBI: default fastmap WL pool size: 25
UBI: attaching mtd1 to ubi0
UBI: attached by fastmap
UBI: fastmap pool size: 50
UBI: fastmap WL pool size: 25
UBI: attached mtd1 (name "mtd=3", size 126 MiB) to ubi0
UBI: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
UBI: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
UBI: VID header offset: 2048 (aligned 2048), data offset: 4096
UBI: good PEBs: 996, bad PEBs: 12, corrupted PEBs: 0
UBI: user volume: 1, internal volumes: 1, max. volumes count: 128
UBI: max/mean erase counter: 16/1, WL threshold: 4096, image sequence number: 0
UBI: available PEBs: 0, total reserved PEBs: 996, PEBs reserved for bad PEB handling: 8
Error reading superblock on volume 'ubi0:rootfs' errno=-22!
ubifsmount - mount UBIFS volume

Usage:
ubifsmount <volume-name>
     - mount 'volume-name' volume
..

When trying to mount the rootfs from kernel, below are the debug logs:
...
[    2.536651] UBIFS: recovery needed
[    2.748418] UBIFS error (pid 1): ubifs_read_node: bad node type (255 but expected 3)
[    2.766263] UBIFS error (pid 1): ubifs_read_node: bad node at LEB 174:31456, LEB mapping status 1
[    2.785776] Not a node, first 24 bytes:
[    2.789677] 00000000: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff                          ............
[    2.819565] CPU: 0 PID: 1 Comm: swapper Not tainted 4.0.5-00308-g3f4ae5a-dirty #137
[    2.838793] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
[    2.851246] Backtrace:
[    2.859669] [<80011d48>] (dump_backtrace) from [<80011f68>] (show_stack+0x18/0x1c)
[    2.878978]  r7:00000003 r6:00000001 r5:000000ae r4:00007ae0
[    2.890910] [<80011f50>] (show_stack) from [<80659e58>] (dump_stack+0x24/0x28)
[    2.909771] [<80659e34>] (dump_stack) from [<8022fc7c>] (ubifs_read_node+0x270/0x2e8)
[    2.929306] [<8022fa0c>] (ubifs_read_node) from [<8024cc2c>] (ubifs_tnc_read_node+0x128/0x134)
[    2.949832]  r10:85c33800 r9:85c50100 r8:85c33800 r7:87b05000 r6:00000003 r5:85c50100
[    2.970066]  r4:85c33830
[    2.978797] [<8024cb04>] (ubifs_tnc_read_node) from [<80230c80>] (tnc_read_node_nm+0xcc/0x1e4)
[    2.999938]  r7:87b051c0 r6:87b05000 r5:85c50100 r4:85c33830
[    3.012198] [<80230bb4>] (tnc_read_node_nm) from [<80234768>] (ubifs_tnc_next_ent+0x140/0x1a4)
[    3.033218]  r7:87b051c0 r6:87b05000 r5:87849c38 r4:00000030
[    3.045605] [<80234628>] (ubifs_tnc_next_ent) from [<80234880>] (ubifs_tnc_remove_ino+0xb4/0x144)
[    3.067083]  r10:87b05000 r9:00004fa8 r8:ffffffff r7:00000000 r6:0000035a r5:87b05000
[    3.087798]  r4:85c2dda0
[    3.096558] [<802347cc>] (ubifs_tnc_remove_ino) from [<80237338>] (ubifs_replay_journal+0xe68/0x13e4)
[    3.118169]  r10:87b05000 r9:87849d08 r8:85c2dd80 r7:87b05930 r6:0000035a r5:00000000
[    3.138751]  r4:85c2dda0
[    3.147487] [<802364d0>] (ubifs_replay_journal) from [<8022c2d4>] (ubifs_mount+0x10a4/0x165c)
[    3.168197]  r10:87b05190 r9:00000000 r8:00000000 r7:87ba2e00 r6:87b05000 r5:00000000
[    3.188556]  r4:00000000
[    3.197100] [<8022b230>] (ubifs_mount) from [<800c0090>] (mount_fs+0x1c/0xac)
[    3.210325]  r10:00008001 r9:00000060 r8:808ab5fc r7:808ab5fc r6:00008001 r5:87bf9b40
[    3.230371]  r4:87bad240
[    3.238886] [<800c0074>] (mount_fs) from [<800d72b0>] (vfs_kern_mount+0x50/0xfc)
[    3.258022]  r8:00000000 r7:808ab5fc r6:00008001 r5:87bf9b40 r4:87bad240
[    3.271099] [<800d7260>] (vfs_kern_mount) from [<800d9f7c>] (do_mount+0x19c/0x9a4)
[    3.290436]  r9:00000060 r8:87bf9b00 r7:87bf9b40 r6:808a3700 r5:00000000 r4:808ab5fc
[    3.310434] [<800d9de0>] (do_mount) from [<800daac0>] (SyS_mount+0x7c/0xa8)
[    3.323536]  r10:87bf7000 r9:80890ac8 r8:00008001 r7:807b13c8 r6:00000000 r5:87bf9b40
[    3.343701]  r4:87bf9b00
[    3.352210] [<800daa44>] (SyS_mount) from [<808631f0>] (mount_block_root+0x144/0x270)
[    3.371858]  r8:87de9ee0 r7:87bf7000 r6:80890ab8 r5:87bf7000 r4:00008001
[    3.385037] [<808630ac>] (mount_block_root) from [<808635d0>] (prepare_namespace+0xb0/0x1dc)
[    3.405619]  r10:80890a94 r9:808625ec r8:000000bc r7:808d0f80 r6:80890ac8 r5:80890ab8
[    3.425843]  r4:80890ab8
[    3.434380] [<80863520>] (prepare_namespace) from [<80862e98>] (kernel_init_freeable+0x1bc/0x1d0)
[    3.455407]  r6:808d0f80 r5:00000008 r4:80899580
[    3.466313] [<80862cdc>] (kernel_init_freeable) from [<8065755c>] (kernel_init+0x18/0xf0)
[    3.486629]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80657544
[    3.507136]  r4:808d0f80
[    3.515803] [<80657544>] (kernel_init) from [<8000e8c8>] (ret_from_fork+0x14/0x2c)
[    3.535434]  r5:80657544 r4:00000000
...

Does any one observed the same issue with UBIFS when the flash memory is full?

Best regards,
Bhuvan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-07-13 13:55 UBIFS errors when file-system is full Bhuvanchandra DV
@ 2015-07-13 14:09 ` Richard Weinberger
  2015-07-14  4:23   ` Bhuvanchandra DV
  0 siblings, 1 reply; 34+ messages in thread
From: Richard Weinberger @ 2015-07-13 14:09 UTC (permalink / raw)
  To: Bhuvanchandra DV; +Cc: linux-mtd@lists.infradead.org

On Mon, Jul 13, 2015 at 3:55 PM, Bhuvanchandra DV
<bhuvanchandradv@gmail.com> wrote:
> Hello,
>
> Facing some issues with UBIFS mounting when NAND flash is almost near to
> full.
>
> Hardware:
> SOC: Freescale Vybrid
> COM: Colibri VF50
> Flash: Macronic NAND 128MB, 3.3V, 8-Bit
>
> By default the Linux Image flashed on the NAND flash almost occupies ~93% of
> the flash.
> Observed this issue when power resetting the module for about 500 times,
> with journalctl
> enabled, after around 500 power cycles the debug log fills up the nand
> flash. When the
> flash menory is about to full, the ubifs partation is un-mountable.
>
> The nand flash controller driver is under review and passed all MTD tests.
> https://lkml.org/lkml/2015/6/18/847
>
>
> Debug log during UBIFS mounting from U-Boot:
>
> U-Boot 2015.04 (May 18 2015 - 15:37:34)
>
> CPU: Freescale Vybrid VF500 at 396 MHz
> Reset cause: POWER ON RESET
> DRAM:  128 MiB
> NAND:  128 MiB
> MMC:   FSL_SDHC: 0
> *** Warning - bad CRC, using default environment
>
> In:    serial
> Out:   serial
> Err:   serial
> Model: Toradex Colibri VF50 128MB V1.1A, Serial# 04815679
> Net:   FEC
> Hit any key to stop autoboot:  0
> Booting from NAND...
> UBI: default fastmap pool size: 50
> UBI: default fastmap WL pool size: 25
> UBI: attaching mtd1 to ubi0
> UBI: attached by fastmap

Is this a recent kernel with all fastmap fixes applied?

-- 
Thanks,
//richard

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-07-13 14:09 ` Richard Weinberger
@ 2015-07-14  4:23   ` Bhuvanchandra DV
  2015-07-14  6:13     ` Richard Weinberger
  0 siblings, 1 reply; 34+ messages in thread
From: Bhuvanchandra DV @ 2015-07-14  4:23 UTC (permalink / raw)
  To: Richard Weinberger; +Cc: Bhuvanchandra DV, linux-mtd@lists.infradead.org

Hello Richard,

On 07/13/2015 07:39 PM, Richard Weinberger wrote:

> On Mon, Jul 13, 2015 at 3:55 PM, Bhuvanchandra DV
> <bhuvanchandradv@gmail.com> wrote:
>> Hello,
>>
>> Facing some issues with UBIFS mounting when NAND flash is almost near to
>> full.
>>
>> Hardware:
>> SOC: Freescale Vybrid
>> COM: Colibri VF50
>> Flash: Macronic NAND 128MB, 3.3V, 8-Bit
>>
>> By default the Linux Image flashed on the NAND flash almost occupies ~93% of
>> the flash.
>> Observed this issue when power resetting the module for about 500 times,
>> with journalctl
>> enabled, after around 500 power cycles the debug log fills up the nand
>> flash. When the
>> flash menory is about to full, the ubifs partation is un-mountable.
>>
>> The nand flash controller driver is under review and passed all MTD tests.
>> https://lkml.org/lkml/2015/6/18/847
>>
>>
>> Debug log during UBIFS mounting from U-Boot:
>>
>> U-Boot 2015.04 (May 18 2015 - 15:37:34)
>>
>> CPU: Freescale Vybrid VF500 at 396 MHz
>> Reset cause: POWER ON RESET
>> DRAM:  128 MiB
>> NAND:  128 MiB
>> MMC:   FSL_SDHC: 0
>> *** Warning - bad CRC, using default environment
>>
>> In:    serial
>> Out:   serial
>> Err:   serial
>> Model: Toradex Colibri VF50 128MB V1.1A, Serial# 04815679
>> Net:   FEC
>> Hit any key to stop autoboot:  0
>> Booting from NAND...
>> UBI: default fastmap pool size: 50
>> UBI: default fastmap WL pool size: 25
>> UBI: attaching mtd1 to ubi0
>> UBI: attached by fastmap
> Is this a recent kernel with all fastmap fixes applied?

I'm sorry! I didn't mention about the kernel version before.

Tested with 4.0.5 kernel[1]. I think your fastmap fixes[2] are not available with
this kernel version.

Lately also tested on 4.1.1 kernel[3], observed the same issues.

[1]http://git.toradex.com/cgit/linux-toradex.git/log/?h=toradex_vf_4.0
[2]http://lists.infradead.org/pipermail/linux-mtd/2015-April/058747.html
[3]http://git.toradex.com/cgit/linux-toradex.git/log/?h=toradex_vf_4.1-next

>
>
Best regards,
Bhuvan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-07-14  4:23   ` Bhuvanchandra DV
@ 2015-07-14  6:13     ` Richard Weinberger
  2015-07-14  6:30       ` Bhuvanchandra DV
  0 siblings, 1 reply; 34+ messages in thread
From: Richard Weinberger @ 2015-07-14  6:13 UTC (permalink / raw)
  To: Bhuvanchandra DV; +Cc: linux-mtd@lists.infradead.org

Am 14.07.2015 um 06:23 schrieb Bhuvanchandra DV:
> Hello Richard,
> 
> On 07/13/2015 07:39 PM, Richard Weinberger wrote:
> 
>> On Mon, Jul 13, 2015 at 3:55 PM, Bhuvanchandra DV
>> <bhuvanchandradv@gmail.com> wrote:
>>> Hello,
>>>
>>> Facing some issues with UBIFS mounting when NAND flash is almost near to
>>> full.
>>>
>>> Hardware:
>>> SOC: Freescale Vybrid
>>> COM: Colibri VF50
>>> Flash: Macronic NAND 128MB, 3.3V, 8-Bit
>>>
>>> By default the Linux Image flashed on the NAND flash almost occupies ~93% of
>>> the flash.
>>> Observed this issue when power resetting the module for about 500 times,
>>> with journalctl
>>> enabled, after around 500 power cycles the debug log fills up the nand
>>> flash. When the
>>> flash menory is about to full, the ubifs partation is un-mountable.
>>>
>>> The nand flash controller driver is under review and passed all MTD tests.
>>> https://lkml.org/lkml/2015/6/18/847
>>>
>>>
>>> Debug log during UBIFS mounting from U-Boot:
>>>
>>> U-Boot 2015.04 (May 18 2015 - 15:37:34)
>>>
>>> CPU: Freescale Vybrid VF500 at 396 MHz
>>> Reset cause: POWER ON RESET
>>> DRAM:  128 MiB
>>> NAND:  128 MiB
>>> MMC:   FSL_SDHC: 0
>>> *** Warning - bad CRC, using default environment
>>>
>>> In:    serial
>>> Out:   serial
>>> Err:   serial
>>> Model: Toradex Colibri VF50 128MB V1.1A, Serial# 04815679
>>> Net:   FEC
>>> Hit any key to stop autoboot:  0
>>> Booting from NAND...
>>> UBI: default fastmap pool size: 50
>>> UBI: default fastmap WL pool size: 25
>>> UBI: attaching mtd1 to ubi0
>>> UBI: attached by fastmap
>> Is this a recent kernel with all fastmap fixes applied?
> 
> I'm sorry! I didn't mention about the kernel version before.
> 
> Tested with 4.0.5 kernel[1]. I think your fastmap fixes[2] are not available with
> this kernel version.
> 
> Lately also tested on 4.1.1 kernel[3], observed the same issues.

I'm confused. Does this mean that you can _reproduce_ the issue from a clean
working UBI image also with 4.1.1?
Or does it mean that the already broken image does also not work with 4.1.1?

Thanks,
//richard

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-07-14  6:13     ` Richard Weinberger
@ 2015-07-14  6:30       ` Bhuvanchandra DV
  2015-07-14  6:32         ` Richard Weinberger
  0 siblings, 1 reply; 34+ messages in thread
From: Bhuvanchandra DV @ 2015-07-14  6:30 UTC (permalink / raw)
  To: Richard Weinberger, Bhuvanchandra DV; +Cc: linux-mtd@lists.infradead.org

On 07/14/2015 11:43 AM, Richard Weinberger wrote:

> Am 14.07.2015 um 06:23 schrieb Bhuvanchandra DV:
>> Hello Richard,
>>
>> On 07/13/2015 07:39 PM, Richard Weinberger wrote:
>>
>>> On Mon, Jul 13, 2015 at 3:55 PM, Bhuvanchandra DV
>>> <bhuvanchandradv@gmail.com> wrote:
>>>> Hello,
>>>>
>>>> Facing some issues with UBIFS mounting when NAND flash is almost near to
>>>> full.
>>>>
>>>> Hardware:
>>>> SOC: Freescale Vybrid
>>>> COM: Colibri VF50
>>>> Flash: Macronic NAND 128MB, 3.3V, 8-Bit
>>>>
>>>> By default the Linux Image flashed on the NAND flash almost occupies ~93% of
>>>> the flash.
>>>> Observed this issue when power resetting the module for about 500 times,
>>>> with journalctl
>>>> enabled, after around 500 power cycles the debug log fills up the nand
>>>> flash. When the
>>>> flash menory is about to full, the ubifs partation is un-mountable.
>>>>
>>>> The nand flash controller driver is under review and passed all MTD tests.
>>>> https://lkml.org/lkml/2015/6/18/847
>>>>
>>>>
>>>> Debug log during UBIFS mounting from U-Boot:
>>>>
>>>> U-Boot 2015.04 (May 18 2015 - 15:37:34)
>>>>
>>>> CPU: Freescale Vybrid VF500 at 396 MHz
>>>> Reset cause: POWER ON RESET
>>>> DRAM:  128 MiB
>>>> NAND:  128 MiB
>>>> MMC:   FSL_SDHC: 0
>>>> *** Warning - bad CRC, using default environment
>>>>
>>>> In:    serial
>>>> Out:   serial
>>>> Err:   serial
>>>> Model: Toradex Colibri VF50 128MB V1.1A, Serial# 04815679
>>>> Net:   FEC
>>>> Hit any key to stop autoboot:  0
>>>> Booting from NAND...
>>>> UBI: default fastmap pool size: 50
>>>> UBI: default fastmap WL pool size: 25
>>>> UBI: attaching mtd1 to ubi0
>>>> UBI: attached by fastmap
>>> Is this a recent kernel with all fastmap fixes applied?
>> I'm sorry! I didn't mention about the kernel version before.
>>
>> Tested with 4.0.5 kernel[1]. I think your fastmap fixes[2] are not available with
>> this kernel version.
>>
>> Lately also tested on 4.1.1 kernel[3], observed the same issues.
> I'm confused. Does this mean that you can _reproduce_ the issue from a clean
> working UBI image also with 4.1.1?
> Or does it mean that the already broken image does also not work with 4.1.1?

Reproduced the issue with a clean UBI image.

>
> Thanks,
> //richard
>
Best regards,
Bhuvan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-07-14  6:30       ` Bhuvanchandra DV
@ 2015-07-14  6:32         ` Richard Weinberger
  2015-07-14  8:29           ` Bhuvanchandra DV
  0 siblings, 1 reply; 34+ messages in thread
From: Richard Weinberger @ 2015-07-14  6:32 UTC (permalink / raw)
  To: Bhuvanchandra DV; +Cc: linux-mtd@lists.infradead.org

Am 14.07.2015 um 08:30 schrieb Bhuvanchandra DV:
> Reproduced the issue with a clean UBI image.

On 4.1?
How can you reproduce?

Thanks,
//richard

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-07-14  6:32         ` Richard Weinberger
@ 2015-07-14  8:29           ` Bhuvanchandra DV
  2015-07-14  8:42             ` Richard Weinberger
  0 siblings, 1 reply; 34+ messages in thread
From: Bhuvanchandra DV @ 2015-07-14  8:29 UTC (permalink / raw)
  To: Richard Weinberger; +Cc: linux-mtd@lists.infradead.org

On 07/14/2015 12:02 PM, Richard Weinberger wrote:

> Am 14.07.2015 um 08:30 schrieb Bhuvanchandra DV:
>> Reproduced the issue with a clean UBI image.
> On 4.1?
> How can you reproduce?

Flashed a clean UBI image with 4.1.
I can reproduce it by amost filling up the flash and doing a power resets for around ~200 cycles.
During some point U-Boot cannot mount the ubifs partition and fails with:
"Error reading superblock on volume 'ubi0:rootfs' errno=-22!"

Tried to mount the same ubifs partition via tftp, got stack trace when trying to mount the ubifs.

Complete debug log when booting with tftp:

Colibri VFxx # setenv bootargs ${defargs} ${ubiargs} ${mtdparts} ${setupargs} ${vidargs}
Colibri VFxx # dhcp ${kernel_addr_r} && tftp ${fdt_addr_r} ${soc}-colibri-${fdt_board}.dtb && bootz ${kernel_addr_r} - ${fdt_addr_r}
BOOTP broadcast 1
DHCP client bound to address 10.18.0.144 (3 ms)
Using FEC device
TFTP from server 10.18.0.132; our IP address is 10.18.0.144
Filename 'zImage'.
Load address: 0x82000000
Loading: #################################################################
          #################################################################
          #################################################################
          #################################################################
          ##########################################
          760.7 KiB/s
done
Bytes transferred = 4431512 (439e98 hex)
Using FEC device
TFTP from server 10.18.0.132; our IP address is 10.18.0.144
Filename 'vf500-colibri-eval-v3.dtb'.
Load address: 0x84000000
Loading: ##
          256.8 KiB/s
done
Bytes transferred = 20846 (516e hex)
Kernel image @ 0x82000000 [ 0x000000 - 0x439e98 ]
## Flattened Device Tree blob at 84000000
    Booting using the fdt blob at 0x84000000
    Loading Device Tree to 876ff000, end 8770716d ... OK

Starting kernel ...

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.1.1-00245-g4a73219 (dvb@dev) (gcc version 4.9.3 20141031 (prerelease) (Linaro GCC 2014.11) ) #2 Tue Jul 14 13:01:16 I5
[    0.000000] CPU: ARMv7 Processor [410fc051] revision 1 (ARMv7), cr=10c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] Machine model: Toradex Colibri VF50 on Colibri Evaluation Board
[    0.000000] cma: Reserved 16 MiB at 0x86400000
[    0.000000] Memory policy: Data cache writeback
[    0.000000] CPU: All CPU(s) started in SVC mode.
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 32004
[    0.000000] Kernel command line: ubi.mtd=ubi root=ubi0:rootfs rootfstype=ubifs ubi.fm_autoconvert=1 mtdparts=vf610_nfc:128k(vf-bcb)ro,1408k(u-boo0
[    0.000000] PID hash table entries: 512 (order: -1, 2048 bytes)
[    0.000000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
[    0.000000] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
[    0.000000] Memory: 103176K/129024K available (5715K kernel code, 201K rwdata, 1840K rodata, 216K init, 171K bss, 9464K reserved, 16384K cma-rese)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
[    0.000000]     vmalloc : 0x88000000 - 0xff000000   (1904 MB)
[    0.000000]     lowmem  : 0x80000000 - 0x87e00000   ( 126 MB)
[    0.000000]     modules : 0x7f000000 - 0x80000000   (  16 MB)
[    0.000000]       .text : 0x80008000 - 0x8076904c   (7557 kB)
[    0.000000]       .init : 0x8076a000 - 0x807a0000   ( 216 kB)
[    0.000000]       .data : 0x807a0000 - 0x807d24a0   ( 202 kB)
[    0.000000]        .bss : 0x807d24a0 - 0x807fd0d0   ( 172 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] NR_IRQS:16 nr_irqs:16 16
[    0.000000] L2C: failed to init: -19
[    0.000054] sched_clock: 64 bits at 132MHz, resolution 7ns, wraps every 2199023255551ns
[    0.000125] clocksource arm_global_timer: mask: 0xffffffffffffffff max_cycles: 0x1e7178659b, max_idle_ns: 440795204301 ns
[    0.000849] Console: colour dummy device 80x30
[    0.002020] console [tty1] enabled
[    0.002121] Calibrating delay loop... 262.96 BogoMIPS (lpj=1314816)
[    0.070303] pid_max: default: 32768 minimum: 301
[    0.070668] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.070779] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.072749] CPU: Testing write buffer coherency: ok
[    0.073687] Setting up static identity map for 0x80008200 - 0x80008258
[    0.077538] devtmpfs: initialized
[    0.090865] VFP support v0.3: implementor 41 architecture 2 part 30 variant 5 rev 1
[    0.091928] clocksource jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.095527] pinctrl core: initialized pinctrl subsystem
[    0.098746] NET: Registered protocol family 16
[    0.102859] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.105728] cpuidle: using governor menu
[    0.134103] hw-breakpoint: found 2 (+1 reserved) breakpoint and 1 watchpoint registers.
[    0.134261] hw-breakpoint: maximum watchpoint size is 4 bytes.
[    0.135299] vf610-pinctrl 40048000.iomuxc: initialized IMX pinctrl driver
[    0.171433] SCSI subsystem initialized
[    0.172626] usbcore: registered new interface driver usbfs
[    0.172993] usbcore: registered new interface driver hub
[    0.173374] usbcore: registered new device driver usb
[    0.175965] i2c i2c-0: IMX I2C adapter registered
[    0.176207] i2c i2c-0: using dma0chan0 (tx) and dma0chan1 (rx) for DMA transfers
[    0.176666] Linux video capture interface: v2.00
[    0.177092] pps_core: LinuxPPS API ver. 1 registered
[    0.177173] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.177397] PTP clock support registered
[    0.178934] Advanced Linux Sound Architecture Driver Initialized.
[    0.182091] Switched to clocksource arm_global_timer
[    0.220933] NET: Registered protocol family 2
[    0.223441] TCP established hash table entries: 1024 (order: 0, 4096 bytes)
[    0.223620] TCP bind hash table entries: 1024 (order: 0, 4096 bytes)
[    0.223734] TCP: Hash tables configured (established 1024 bind 1024)
[    0.224144] UDP hash table entries: 256 (order: 0, 4096 bytes)
[    0.224276] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[    0.224870] NET: Registered protocol family 1
[    0.225936] RPC: Registered named UNIX socket transport module.
[    0.226064] RPC: Registered udp transport module.
[    0.226135] RPC: Registered tcp transport module.
[    0.226199] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.230980] futex hash table entries: 256 (order: -1, 3072 bytes)
[    0.255535] NFS: Registering the id_resolver key type
[    0.255804] Key type id_resolver registered
[    0.255890] Key type id_legacy registered
[    0.256040] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.257822] ntfs: driver 2.1.32 [Flags: R/W].
[    0.259474] fuse init (API version 7.23)
[    0.268197] io scheduler noop registered
[    0.268343] io scheduler deadline registered
[    0.268620] io scheduler cfq registered (default)
[    0.280233] backlight supply power not found, using dummy regulator
[    0.301896] Console: switching to colour frame buffer device 80x30
[    0.313909] fb0: fb device registered successfully.
[    0.319322] fb1: fb device registered successfully.
[    0.324671] fb2: fb device registered successfully.
[    0.329643] fb3: fb device registered successfully.
[    0.334724] fb4: fb device registered successfully.
[    0.339378] fb5: fb device registered successfully.
[    0.344996] 40027000.serial: ttyLP0 at MMIO 0x40027000 (irq = 19, base_baud = 4125000) is a FSL_LPUART
[    0.888645] console [ttyLP0] enabled
[    0.897621] 40028000.serial: ttyLP1 at MMIO 0x40028000 (irq = 20, base_baud = 4125000) is a FSL_LPUART
[    0.916706] 40029000.serial: ttyLP2 at MMIO 0x40029000 (irq = 21, base_baud = 4125000) is a FSL_LPUART
[    0.955586] loop: module loaded
[    0.966803] nand: device found, Manufacturer ID: 0xc2, Chip ID: 0xf1
[    0.977644] nand: Macronix NAND 128MiB 3,3V 8-bit
[    0.986782] nand: 128 MiB, SLC, erase size: 128 KiB, page size: 2048, OOB size: 64
[    1.003429] Bad block table found at page 65472, version 0x01
[    1.014062] Bad block table found at page 65408, version 0x01
[    1.024768] 4 cmdlinepart partitions found on MTD device vf610_nfc
[    1.035640] Creating 4 MTD partitions on "vf610_nfc":
[    1.045408] 0x000000000000-0x000000020000 : "vf-bcb"
[    1.056418] 0x000000020000-0x000000180000 : "u-boot"
[    1.067310] 0x000000180000-0x000000200000 : "u-boot-env"
[    1.078436] 0x000000200000-0x000008000000 : "ubi"
[    1.095947] 400d1000.ethernet supply phy not found, using dummy regulator
[    1.117728] libphy: fec_enet_mii_bus: probed
[    1.128873] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.141625] usbcore: registered new interface driver usb-storage
[    1.153688] usbcore: registered new interface driver usbserial
[    1.164859] usbcore: registered new interface driver usbserial_generic
[    1.176470] usbserial: USB Serial support registered for generic
[    1.187664] usbcore: registered new interface driver ftdi_sio
[    1.198481] usbserial: USB Serial support registered for FTDI USB Serial Device
[    1.215340] usbcore: registered new interface driver pl2303
[    1.225866] usbserial: USB Serial support registered for pl2303
[    1.246498] imx_usb 400b4000.usb: Can't register ci_hdrc platform device, err=-517
[    1.265515] mousedev: PS/2 mouse device common for all mice
[    1.277903] rtc-ds1307: probe of 0-0068 failed with error -5
[    1.290355] snvs_rtc 400a7034.snvs-rtc-lp: rtc core: registered 400a7034.snvs-rtc-l as rtc0
[    1.308688] i2c /dev entries driver
[    1.321359] imx2-wdt 4003e000.wdog: timeout 60 sec (nowayout=0)
[    1.333032] sdhci: Secure Digital Host Controller Interface driver
[    1.344317] sdhci: Copyright(c) Pierre Ossman
[    1.353809] sdhci-pltfm: SDHCI platform and OF driver helper
[    1.366082] /soc/aips-bus@40080000/esdhc@400b2000: voltage-ranges unspecified
[    1.378925] sdhci-esdhc-imx 400b2000.esdhc: Got CD GPIO
[    1.389963] sdhci-esdhc-imx 400b2000.esdhc: No vmmc regulator found
[    1.401634] sdhci-esdhc-imx 400b2000.esdhc: No vqmmc regulator found
[    1.452220] mmc0: SDHCI controller on 400b2000.esdhc [400b2000.esdhc] using ADMA
[    1.475559] usbcore: registered new interface driver usbhid
[    1.486806] usbhid: USB HID core driver
[    1.497384] 4003b000.adc supply vref not found, using dummy regulator
[    1.514460] 400bb000.adc supply vref not found, using dummy regulator
[    1.531429] Netfilter messages via NETLINK v0.30.
[    1.542908] nfnl_acct: registering with nfnetlink.
[    1.553034] nf_conntrack version 0.5.0 (1868 buckets, 7472 max)
[    1.569452] nf_tables: (c) 2007-2009 Patrick McHardy <kaber@trash.net>
[    1.583336] ip_tables: (C) 2000-2006 Netfilter Core Team
[    1.596707] NET: Registered protocol family 10
[    1.610419] ip6_tables: (C) 2000-2006 Netfilter Core Team
[    1.621187] sit: IPv6 over IPv4 tunneling driver
[    1.634053] NET: Registered protocol family 17
[    1.643852] bridge: automatic filtering via arp/ip/ip6tables has been deprecated. Update your scripts to load br_netfilter if you need this.
[    1.666816] Bridge firewalling registered
[    1.677391] 8021q: 802.1Q VLAN Support v1.8
[    1.689062] Key type dns_resolver registered
[    1.698929] Registering SWP/SWPB emulation handler
[    1.712281] registered taskstats version 1
[    1.728415] usbh_vbus: supplied by 5v0
[    1.741823] ci_hdrc ci_hdrc.1: EHCI Host Controller
[    1.752957] ci_hdrc ci_hdrc.1: new USB bus registered, assigned bus number 1
[    1.782224] ci_hdrc ci_hdrc.1: USB 2.0 started, EHCI 1.00
[    1.795354] hub 1-0:1.0: USB hub found
[    1.804157] hub 1-0:1.0: 1 port detected
[    1.816698] input: colibri-vf50-ts as /devices/platform/vf50_touchctrl/input/input0
[    1.836924] toradex,vf50_touchctrl vf50_touchctrl: Attached colibri-vf50-ts driver successfully
[    1.856553] ubi0: default fastmap pool size: 50
[    1.866179] ubi0: default fastmap WL pool size: 25
[    1.875836] ubi0: attaching mtd3
[    1.975937] ubi0: attached by fastmap
[    1.984411] ubi0: fastmap pool size: 50
[    1.992859] ubi0: fastmap WL pool size: 25
[    2.012913] ubi0: attached mtd3 (name "ubi", size 126 MiB)
[    2.023140] ubi0: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
[    2.034658] ubi0: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
[    2.046015] ubi0: VID header offset: 2048 (aligned 2048), data offset: 4096
[    2.057546] ubi0: good PEBs: 1004, bad PEBs: 4, corrupted PEBs: 0
[    2.068348] ubi0: user volume: 1, internal volumes: 1, max. volumes count: 128
[    2.084771] ubi0: max/mean erase counter: 29/6, WL threshold: 4096, image sequence number: 0
[    2.102911] ubi0: available PEBs: 0, total reserved PEBs: 1004, PEBs reserved for bad PEB handling: 16
[    2.122563] ubi0: background thread "ubi_bgt0d" started, PID 50
[    2.135081] snvs_rtc 400a7034.snvs-rtc-lp: setting system clock to 2015-07-14 08:17:11 UTC (1436861831)
[    2.170929] ALSA device list:
[    2.179354]   No soundcards found.
[    2.192343] usb 1-1: new high-speed USB device number 2 using ci_hdrc
[    2.227211] UBIFS (ubi0:0): recovery needed
[    2.355517] hub 1-1:1.0: USB hub found
[    2.365430] hub 1-1:1.0: 4 ports detected
[    2.410558] UBIFS error (ubi0:0 pid 1): ubifs_read_node: bad node type (10 but expected 3)
[    2.429359] UBIFS error (ubi0:0 pid 1): ubifs_read_node: bad node at LEB 908:29408, LEB mapping status 1
[    2.450012] Not a node, first 24 bytes:
[    2.453975] 00000000: dc 06 05 48 11 b3 9a 28 d9 b4 f1 90 1a 70 00 de 05 98 d2 bc 0a 68 02 6c                          ...H...(.....p.......h.l
[    2.483992] CPU: 0 PID: 1 Comm: swapper Not tainted 4.1.1-00245-g4a73219 #2
[    2.496932] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
[    2.509317] Backtrace:
[    2.517656] [<80012ab8>] (dump_backtrace) from [<80012cd8>] (show_stack+0x18/0x1c)
[    2.536748]  r7:00000000 r6:00000000 r5:0000038c r4:000072e0
[    2.548497] [<80012cc0>] (show_stack) from [<80597828>] (dump_stack+0x24/0x28)
[    2.567075] [<80597804>] (dump_stack) from [<8022dbe8>] (ubifs_read_node+0x294/0x310)
[    2.586390] [<8022d954>] (ubifs_read_node) from [<8022dd0c>] (ubifs_read_node_wbuf+0xa8/0x2fc)
[    2.606659]  r10:0000038c r9:00000049 r8:87be6380 r7:00000003 r6:87b53000 r5:87b4db20
[    2.626990]  r4:000072e0
[    2.635632] [<8022dc64>] (ubifs_read_node_wbuf) from [<8024b39c>] (ubifs_tnc_read_node+0x50/0x140)
[    2.657072]  r10:87bd7a00 r9:87be6380 r8:87bd7a00 r7:00000003 r6:87be6380 r5:87b53000
[    2.677875]  r4:87bd7a30
[    2.686669] [<8024b34c>] (ubifs_tnc_read_node) from [<8022ec3c>] (tnc_read_node_nm+0xcc/0x1e4)
[    2.707690]  r8:87bd7a00 r7:87b531c0 r6:87b53000 r5:87be6380 r4:87bd7a30
[    2.721103] [<8022eb70>] (tnc_read_node_nm) from [<80232784>] (ubifs_tnc_next_ent+0x140/0x1a4)
[    2.742233]  r7:87b531c0 r6:87b53000 r5:87849c38 r4:00000030
[    2.754489] [<80232644>] (ubifs_tnc_next_ent) from [<8023289c>] (ubifs_tnc_remove_ino+0xb4/0x144)
[    2.775956]  r10:87b53000 r9:00003ee1 r8:ffffffff r7:00000000 r6:000003b3 r5:87b53000
[    2.796730]  r4:87bddde0
[    2.805546] [<802327e8>] (ubifs_tnc_remove_ino) from [<80235468>] (ubifs_replay_journal+0xe9c/0x1490)
[    2.827195]  r10:87b53000 r9:87849d08 r8:87bdddc0 r7:87b53930 r6:000003b3 r5:00000000
[    2.847754]  r4:87bddde0
[    2.856397] [<802345cc>] (ubifs_replay_journal) from [<8022a01c>] (ubifs_mount+0x10f8/0x1740)
[    2.876909]  r10:87b53190 r9:00000000 r8:0001e5a0 r7:87b47c00 r6:87b53000 r5:00000000
[    2.897398]  r4:00000000
[    2.906044] [<80228f24>] (ubifs_mount) from [<800c47c0>] (mount_fs+0x1c/0xac)
[    2.919382]  r10:00008001 r9:00000060 r8:807b13e8 r7:807b13e8 r6:00008001 r5:87b58a00
[    2.939597]  r4:87b0a600
[    2.948224] [<800c47a4>] (mount_fs) from [<800dba54>] (vfs_kern_mount+0x50/0xfc)
[    2.967514]  r8:00000000 r7:807b13e8 r6:00008001 r5:87b58a00 r4:87b0a600
[    2.980635] [<800dba04>] (vfs_kern_mount) from [<800de720>] (do_mount+0x19c/0x9b4)
[    3.000129]  r9:00000060 r8:87b589c0 r7:87b58a00 r6:807a9658 r5:00000000 r4:807b13e8
[    3.020237] [<800de584>] (do_mount) from [<800df274>] (SyS_mount+0x7c/0xa8)
[    3.033423]  r10:87ba7000 r9:807962b8 r8:00008001 r7:806c83f0 r6:00000000 r5:87b58a00
[    3.053626]  r4:87b589c0
[    3.062280] [<800df1f8>] (SyS_mount) from [<8076b1f4>] (mount_block_root+0x144/0x270)
[    3.082062]  r8:87de94e0 r7:87ba7000 r6:807962a8 r5:87ba7000 r4:00008001
[    3.095233] [<8076b0b0>] (mount_block_root) from [<8076b4e8>] (prepare_namespace+0xb0/0x1a4)
[    3.115944]  r10:80796284 r9:8076a5ec r8:00000097 r7:807d24c0 r6:807d24c0 r5:807962b8
[    3.136353]  r4:807962a8
[    3.144950] [<8076b438>] (prepare_namespace) from [<8076ae9c>] (kernel_init_freeable+0x1bc/0x1d0)
[    3.166110]  r5:00000008 r4:8079ec3c
[    3.175907] [<8076ace0>] (kernel_init_freeable) from [<80594f30>] (kernel_init+0x18/0xf0)
[    3.196270]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80594f18
[    3.216825]  r4:807d24c0
[    3.225507] [<80594f18>] (kernel_init) from [<8000f668>] (ret_from_fork+0x14/0x2c)
[    3.245180]  r5:80594f18 r4:00000000
[    3.258206] List of all partitions:
[    3.267753] No filesystem could mount root, tried:  ubifs
[    3.279225] Kernel panic - not syncing: VFS: Unable to mount root fs on unknown-block(0,0)
[    3.298764] ---[ end Kernel panic - not syncing: VFS: Unable to mount root fs on unknown-block(0,0)

>
> Thanks,
> //richard
>
Best regards,

Bhuvan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-07-14  8:29           ` Bhuvanchandra DV
@ 2015-07-14  8:42             ` Richard Weinberger
  2015-07-14 10:08               ` Bhuvanchandra DV
  0 siblings, 1 reply; 34+ messages in thread
From: Richard Weinberger @ 2015-07-14  8:42 UTC (permalink / raw)
  To: Bhuvanchandra DV; +Cc: linux-mtd@lists.infradead.org

Am 14.07.2015 um 10:29 schrieb Bhuvanchandra DV:
> On 07/14/2015 12:02 PM, Richard Weinberger wrote:
> 
>> Am 14.07.2015 um 08:30 schrieb Bhuvanchandra DV:
>>> Reproduced the issue with a clean UBI image.
>> On 4.1?
>> How can you reproduce?
> 
> Flashed a clean UBI image with 4.1.
> I can reproduce it by amost filling up the flash and doing a power resets for around ~200 cycles.

And it really happens only if you're filling up the UBIFS?
If you set the UBI module parameter "fm_debug", does the EBA selfcheck trigger?

> During some point U-Boot cannot mount the ubifs partition and fails with:
> "Error reading superblock on volume 'ubi0:rootfs' errno=-22!"

How exactly is U-Boot involved? Does U-Boot touch UBI in any way?

Thanks,
//richard

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-07-14  8:42             ` Richard Weinberger
@ 2015-07-14 10:08               ` Bhuvanchandra DV
  2015-07-14 11:06                 ` Richard Weinberger
  0 siblings, 1 reply; 34+ messages in thread
From: Bhuvanchandra DV @ 2015-07-14 10:08 UTC (permalink / raw)
  To: Richard Weinberger; +Cc: linux-mtd@lists.infradead.org

On 07/14/2015 02:12 PM, Richard Weinberger wrote:

> Am 14.07.2015 um 10:29 schrieb Bhuvanchandra DV:
>> On 07/14/2015 12:02 PM, Richard Weinberger wrote:
>>
>>> Am 14.07.2015 um 08:30 schrieb Bhuvanchandra DV:
>>>> Reproduced the issue with a clean UBI image.
>>> On 4.1?
>>> How can you reproduce?
>> Flashed a clean UBI image with 4.1.
>> I can reproduce it by amost filling up the flash and doing a power resets for around ~200 cycles.
> And it really happens only if you're filling up the UBIFS?

The only thing observed so far during this tests is when the journactl log starts filling up the flash
memory and at some point of time fails to mount the ubifs.

Flashed an Image which occupies less flash ~40-50%. Run the same tests for around 1200 power cycles
no issues observed during mounting but still there are few error messages:
..
[    6.879643] ubi0 error: __wl_get_peb: no free eraseblocks
..
So came to an assumption that filling the flash to max lead to this issue.

Could there be any other possibility for this issue apart from filling up the flash ?

> If you set the UBI module parameter "fm_debug", does the EBA selfcheck trigger?

Yes, EBA selfcheck got triggered. Atleast i could see the debug printks added
in 'self_check_eba' method after setting the fm_debug parameter.

>
>> During some point U-Boot cannot mount the ubifs partition and fails with:
>> "Error reading superblock on volume 'ubi0:rootfs' errno=-22!"
> How exactly is U-Boot involved? Does U-Boot touch UBI in any way?

kernel, device tree blobs are available in rootfs /boot. U-Boot mounts the ubi partition
and loads the kernel and device tree blob.

Also U-Boot is involved during flashing the UBI image to flash.

>
> Thanks,
> //richard
>
Best regards,
Bhuvan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-07-14 10:08               ` Bhuvanchandra DV
@ 2015-07-14 11:06                 ` Richard Weinberger
       [not found]                   ` <55A74812.2020906@gmail.com>
  0 siblings, 1 reply; 34+ messages in thread
From: Richard Weinberger @ 2015-07-14 11:06 UTC (permalink / raw)
  To: Bhuvanchandra DV; +Cc: linux-mtd@lists.infradead.org

Am 14.07.2015 um 12:08 schrieb Bhuvanchandra DV:
> On 07/14/2015 02:12 PM, Richard Weinberger wrote:
> 
>> Am 14.07.2015 um 10:29 schrieb Bhuvanchandra DV:
>>> On 07/14/2015 12:02 PM, Richard Weinberger wrote:
>>>
>>>> Am 14.07.2015 um 08:30 schrieb Bhuvanchandra DV:
>>>>> Reproduced the issue with a clean UBI image.
>>>> On 4.1?
>>>> How can you reproduce?
>>> Flashed a clean UBI image with 4.1.
>>> I can reproduce it by amost filling up the flash and doing a power resets for around ~200 cycles.
>> And it really happens only if you're filling up the UBIFS?
> 
> The only thing observed so far during this tests is when the journactl log starts filling up the flash
> memory and at some point of time fails to mount the ubifs.

You mean filling up the filesystem? How and when does the power cut happen?

> Flashed an Image which occupies less flash ~40-50%. Run the same tests for around 1200 power cycles
> no issues observed during mounting but still there are few error messages:
> ..
> [    6.879643] ubi0 error: __wl_get_peb: no free eraseblocks

This message cannot come from a recent kernel.

> So came to an assumption that filling the flash to max lead to this issue.
> 
> Could there be any other possibility for this issue apart from filling up the flash ?
> 
>> If you set the UBI module parameter "fm_debug", does the EBA selfcheck trigger?
> 
> Yes, EBA selfcheck got triggered. Atleast i could see the debug printks added
> in 'self_check_eba' method after setting the fm_debug parameter.
> 
>>
>>> During some point U-Boot cannot mount the ubifs partition and fails with:
>>> "Error reading superblock on volume 'ubi0:rootfs' errno=-22!"
>> How exactly is U-Boot involved? Does U-Boot touch UBI in any way?
> 
> kernel, device tree blobs are available in rootfs /boot. U-Boot mounts the ubi partition
> and loads the kernel and device tree blob.
> 
> Also U-Boot is involved during flashing the UBI image to flash.

In you last mail you wrote
"During some point U-Boot cannot mount the ubifs partition and fails with"..

So, please reproduce from scratch(!) with a recent kernel (4.1 or newer) and provide all needed infos.
Otherwise I see no way howto help you.

Thanks,
//richard

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
       [not found]                           ` <55A75A05.7040603@nod.at>
@ 2015-07-16  7:33                             ` Bhuvanchandra DV
  2015-07-21  6:04                             ` Bhuvanchandra DV
  1 sibling, 0 replies; 34+ messages in thread
From: Bhuvanchandra DV @ 2015-07-16  7:33 UTC (permalink / raw)
  To: Richard Weinberger; +Cc: linux-mtd

On 07/16/2015 12:45 PM, Richard Weinberger wrote:

> Am 16.07.2015 um 09:11 schrieb Bhuvanchandra DV:
>> On 07/16/2015 12:19 PM, Richard Weinberger wrote:
>>
>>> Am 16.07.2015 um 08:09 schrieb Richard Weinberger:
>>>> Am 16.07.2015 um 07:58 schrieb Bhuvanchandra DV:
>>>>> Power cut test with 4.1.2 kernel:
>>>>>
>>>>> Preparing UBI image using mkfs.ubifs utility:
>>>>>
>>>>> $ mkfs.ubifs -c 8112 -e 124KiB -m 2KiB -o ubifs.img -r rootfs/ -v
>>>>>
>>>>>
>>>>> Flashing UBI image from U-Boot:
>>>>>
>>>>> # fatload ${interface} 0:1 ${loadaddr} ubifs.img
>>>>> reading ubifs.img
>>>>> 108691456 bytes read in 7139 ms (14.5 MiB/s)
>>>>> # ubi part ubi && ubi check rootfs || ubi create rootfs
>>>>> UBI: default fastmap pool size: 50
>>>>> UBI: default fastmap WL pool size: 25
>>>>> UBI: attaching mtd1 to ubi0
>>>>> UBI: attached by fastmap
>>>>> UBI: fastmap pool size: 50
>>>>> UBI: fastmap WL pool size: 25
>>>>> UBI: attached mtd1 (name "mtd=3", size 126 MiB) to ubi0
>>>>> UBI: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
>>>>> UBI: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
>>>>> UBI: VID header offset: 2048 (aligned 2048), data offset: 4096
>>>>> UBI: good PEBs: 1003, bad PEBs: 5, corrupted PEBs: 0
>>>>> UBI: user volume: 1, internal volumes: 1, max. volumes count: 128
>>>>> UBI: max/mean erase counter: 14/4, WL threshold: 4096, image sequence number: 0
>>>>> UBI: available PEBs: 0, total reserved PEBs: 1003, PEBs reserved for bad PEB handling: 15
>>>>> # ubi write ${loadaddr} rootfs ${filesize}
>>>>> 108691456 bytes written to volume rootfs
>>>>>
>>>>> With 4.1.2 kernel after ~600 power cut cycles, no issues with mounting the ubifs,
>>>>> but observed few stack traces.
>>>> But your kernel log shows an issue. It is not clear whether it comes from fastmap.
>>> BTW: I forgot to ask one thing, did you test using fm_debug?
>> No, if needed i can do the test again with fm_debug enabled.
>> Enabled fm_debug now with the corrupted ubifs, no addiditional debug logs observed.
> Okay. So far it does not really sound like a fastmap issue.
> But please double check using fm_debug.

Ok

>
> P.s: Why are you writing me privately?

My bad! some how in one my reply to previous mail i missed reply-all.
Will forward previous conversations to ML.

>
> Thanks,
> //richard
>
Best regards,
Bhuvan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Fwd: Re: UBIFS errors when file-system is full
       [not found]                   ` <55A74812.2020906@gmail.com>
@ 2015-07-16  7:35                     ` Bhuvanchandra DV
       [not found]                     ` <55A74AA1.2000000@nod.at>
  1 sibling, 0 replies; 34+ messages in thread
From: Bhuvanchandra DV @ 2015-07-16  7:35 UTC (permalink / raw)
  To: linux-mtd@lists.infradead.org; +Cc: richard

-------- Forwarded Message --------

Subject: 	

Re: UBIFS errors when file-system is full

Date: 	

Thu, 16 Jul 2015 11:28:42 +0530

From: 	

Bhuvanchandra DV <bhuvanchandra.dv@gmail.com>

To: 	

Richard Weinberger <richard@nod.at>

On 07/14/2015 04:36 PM, Richard Weinberger wrote:

> Am 14.07.2015 um 12:08 schrieb Bhuvanchandra DV:
>> On 07/14/2015 02:12 PM, Richard Weinberger wrote:
>>
>>> Am 14.07.2015 um 10:29 schrieb Bhuvanchandra DV:
>>>> On 07/14/2015 12:02 PM, Richard Weinberger wrote:
>>>>
>>>>> Am 14.07.2015 um 08:30 schrieb Bhuvanchandra DV:
>>>>>> Reproduced the issue with a clean UBI image.
>>>>> On 4.1?
>>>>> How can you reproduce?
>>>> Flashed a clean UBI image with 4.1.
>>>> I can reproduce it by amost filling up the flash and doing a power resets for around ~200 cycles.
>>> And it really happens only if you're filling up the UBIFS?
>> The only thing observed so far during this tests is when the journactl log starts filling up the flash
>> memory and at some point of time fails to mount the ubifs.
> You mean filling up the filesystem? How and when does the power cut happen?
>
>> Flashed an Image which occupies less flash ~40-50%. Run the same tests for around 1200 power cycles
>> no issues observed during mounting but still there are few error messages:
>> ..
>> [    6.879643] ubi0 error: __wl_get_peb: no free eraseblocks
> This message cannot come from a recent kernel.
>
>> So came to an assumption that filling the flash to max lead to this issue.
>>
>> Could there be any other possibility for this issue apart from filling up the flash ?
>>
>>> If you set the UBI module parameter "fm_debug", does the EBA selfcheck trigger?
>> Yes, EBA selfcheck got triggered. Atleast i could see the debug printks added
>> in 'self_check_eba' method after setting the fm_debug parameter.
>>
>>>> During some point U-Boot cannot mount the ubifs partition and fails with:
>>>> "Error reading superblock on volume 'ubi0:rootfs' errno=-22!"
>>> How exactly is U-Boot involved? Does U-Boot touch UBI in any way?
>> kernel, device tree blobs are available in rootfs /boot. U-Boot mounts the ubi partition
>> and loads the kernel and device tree blob.
>>
>> Also U-Boot is involved during flashing the UBI image to flash.
> In you last mail you wrote
> "During some point U-Boot cannot mount the ubifs partition and fails with"..
>
> So, please reproduce from scratch(!) with a recent kernel (4.1 or newer) and provide all needed infos.
> Otherwise I see no way howto help you.
>
> Thanks,
> //richard
>
Power cut test with 4.1.2 kernel:

Preparing UBI image using mkfs.ubifs utility:

$ mkfs.ubifs -c 8112 -e 124KiB -m 2KiB -o ubifs.img -r rootfs/ -v


Flashing UBI image from U-Boot:

# fatload ${interface} 0:1 ${loadaddr} ubifs.img
reading ubifs.img
108691456 bytes read in 7139 ms (14.5 MiB/s)
# ubi part ubi && ubi check rootfs || ubi create rootfs
UBI: default fastmap pool size: 50
UBI: default fastmap WL pool size: 25
UBI: attaching mtd1 to ubi0
UBI: attached by fastmap
UBI: fastmap pool size: 50
UBI: fastmap WL pool size: 25
UBI: attached mtd1 (name "mtd=3", size 126 MiB) to ubi0
UBI: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
UBI: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
UBI: VID header offset: 2048 (aligned 2048), data offset: 4096
UBI: good PEBs: 1003, bad PEBs: 5, corrupted PEBs: 0
UBI: user volume: 1, internal volumes: 1, max. volumes count: 128
UBI: max/mean erase counter: 14/4, WL threshold: 4096, image sequence number: 0
UBI: available PEBs: 0, total reserved PEBs: 1003, PEBs reserved for bad PEB handling: 15
# ubi write ${loadaddr} rootfs ${filesize}
108691456 bytes written to volume rootfs

With 4.1.2 kernel after ~600 power cut cycles, no issues with mounting the ubifs,
but observed few stack traces.

Debug logs:

U-Boot 2015.04 (May 18 2015 - 15:37:34)

CPU: Freescale Vybrid VF500 at 396 MHz
Reset cause: POWER ON RESET
DRAM:  128 MiB
NAND:  128 MiB
MMC:   FSL_SDHC: 0
*** Warning - bad CRC, using default environment

In:    serial
Out:   serial
Err:   serial
Model: Toradex Colibri VF50 128MB V38.655341, Serial# 04833251
Net:   FEC
Hit any key to stop autoboot:  1 \b\b\b 0
Booting from NAND...
UBI: default fastmap pool size: 50
UBI: default fastmap WL pool size: 25
UBI: attaching mtd1 to ubi0
UBI: attached by fastmap
UBI: fastmap pool size: 50
UBI: fastmap WL pool size: 25
UBI: attached mtd1 (name "mtd=3", size 126 MiB) to ubi0
UBI: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
UBI: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
UBI: VID header offset: 2048 (aligned 2048), data offset: 4096
UBI: good PEBs: 1004, bad PEBs: 4, corrupted PEBs: 0
UBI: user volume: 1, internal volumes: 1, max. volumes count: 128
UBI: max/mean erase counter: 115/17, WL threshold: 4096, image sequence number: 0
UBI: available PEBs: 0, total reserved PEBs: 1004, PEBs reserved for bad PEB handling: 16
Loading file '/boot/zImage' to addr 0x82000000 with size 4433808 (0x0043a790)...
Done
Loading file '/boot/vf500-colibri-eval-v3.dtb' to addr 0x84000000 with size 21126 (0x00005286)...
Done
Kernel image @ 0x82000000 [ 0x000000 - 0x43a790 ]
## Flattened Device Tree blob at 84000000
    Booting using the fdt blob at 0x84000000
    Loading Device Tree to 876ff000, end 87707285 ... OK

Starting kernel ...

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.1.2-00312-g796aee8 (dvb@dev) (gcc version 4.9.3 20141031 (prerelease) (Linaro GCC 2014.11) ) #4 Tue Jul 14 18:02:37 IST 2015
[    0.000000] CPU: ARMv7 Processor [410fc051] revision 1 (ARMv7), cr=10c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] Machine model: Toradex Colibri VF50 on Colibri Evaluation Board
[    0.000000] cma: Reserved 16 MiB at 0x86400000
[    0.000000] Memory policy: Data cache writeback
[    0.000000] CPU: All CPU(s) started in SVC mode.
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 32004
[    0.000000] Kernel command line: ubi.mtd=ubi root=ubi0:rootfs rootfstype=ubifs ubi.fm_autoconvert=1 mtdparts=vf610_nfc:128k(vf-bcb)ro,1408k(u-boot)ro,512k(u-boot-env),-(ubi) console=tty1 console=ttyLP0,115200n8 consoleblank=0
[    0.000000] PID hash table entries: 512 (order: -1, 2048 bytes)
[    0.000000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
[    0.000000] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
[    0.000000] Memory: 103168K/129024K available (5719K kernel code, 201K rwdata, 1844K rodata, 216K init, 171K bss, 9472K reserved, 16384K cma-reserved)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
[    0.000000]     vmalloc : 0x88000000 - 0xff000000   (1904 MB)
[    0.000000]     lowmem  : 0x80000000 - 0x87e00000   ( 126 MB)
[    0.000000]     modules : 0x7f000000 - 0x80000000   (  16 MB)
[    0.000000]       .text : 0x80008000 - 0x8076b04c   (7565 kB)
[    0.000000]       .init : 0x8076c000 - 0x807a2000   ( 216 kB)
[    0.000000]       .data : 0x807a2000 - 0x807d44e0   ( 202 kB)
[    0.000000]        .bss : 0x807d44e0 - 0x807ff1d0   ( 172 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] NR_IRQS:16 nr_irqs:16 16
[    0.000000] L2C: failed to init: -19
[    0.000054] sched_clock: 64 bits at 132MHz, resolution 7ns, wraps every 2199023255551ns
[    0.000121] clocksource arm_global_timer: mask: 0xffffffffffffffff max_cycles: 0x1e7178659b, max_idle_ns: 440795204301 ns
[    0.000839] Console: colour dummy device 80x30
[    0.002013] console [tty1] enabled
[    0.002110] Calibrating delay loop... 262.96 BogoMIPS (lpj=1314816)
[    0.070301] pid_max: default: 32768 minimum: 301
[    0.070658] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.070770] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.072712] CPU: Testing write buffer coherency: ok
[    0.073658] Setting up static identity map for 0x80008200 - 0x80008258
[    0.077525] devtmpfs: initialized
[    0.093135] VFP support v0.3: implementor 41 architecture 2 part 30 variant 5 rev 1
[    0.094188] clocksource jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.097801] pinctrl core: initialized pinctrl subsystem
[    0.101219] NET: Registered protocol family 16
[    0.105104] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.108068] cpuidle: using governor menu
[    0.137632] hw-breakpoint: found 2 (+1 reserved) breakpoint and 1 watchpoint registers.
[    0.137788] hw-breakpoint: maximum watchpoint size is 4 bytes.
[    0.138850] vf610-pinctrl 40048000.iomuxc: initialized IMX pinctrl driver
[    0.174198] SCSI subsystem initialized
[    0.175455] usbcore: registered new interface driver usbfs
[    0.175794] usbcore: registered new interface driver hub
[    0.176170] usbcore: registered new device driver usb
[    0.178816] i2c i2c-0: IMX I2C adapter registered
[    0.179100] i2c i2c-0: using dma0chan0 (tx) and dma0chan1 (rx) for DMA transfers
[    0.179575] Linux video capture interface: v2.00
[    0.180005] pps_core: LinuxPPS API ver. 1 registered
[    0.180089] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.180439] PTP clock support registered
[    0.181919] Advanced Linux Sound Architecture Driver Initialized.
[    0.184905] Switched to clocksource arm_global_timer
[    0.223577] NET: Registered protocol family 2
[    0.226136] TCP established hash table entries: 1024 (order: 0, 4096 bytes)
[    0.226299] TCP bind hash table entries: 1024 (order: 0, 4096 bytes)
[    0.226412] TCP: Hash tables configured (established 1024 bind 1024)
[    0.226809] UDP hash table entries: 256 (order: 0, 4096 bytes)
[    0.226943] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[    0.227550] NET: Registered protocol family 1
[    0.228636] RPC: Registered named UNIX socket transport module.
[    0.228762] RPC: Registered udp transport module.
[    0.228832] RPC: Registered tcp transport module.
[    0.228895] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.234529] futex hash table entries: 256 (order: -1, 3072 bytes)
[    0.259291] NFS: Registering the id_resolver key type
[    0.259517] Key type id_resolver registered
[    0.259604] Key type id_legacy registered
[    0.259755] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.261592] ntfs: driver 2.1.32 [Flags: R/W].
[    0.263267] fuse init (API version 7.23)
[    0.272288] io scheduler noop registered
[    0.272427] io scheduler deadline registered
[    0.272651] io scheduler cfq registered (default)
[    0.284169] backlight supply power not found, using dummy regulator
[    0.306254] Console: switching to colour frame buffer device 80x30
[    0.318141] fb0: fb device registered successfully.
[    0.323589] fb1: fb device registered successfully.
[    0.328902] fb2: fb device registered successfully.
[    0.333947] fb3: fb device registered successfully.
[    0.338955] fb4: fb device registered successfully.
[    0.343640] fb5: fb device registered successfully.
[    0.349178] 40027000.serial: ttyLP0 at MMIO 0x40027000 (irq = 20, base_baud = 4125000) is a FSL_LPUART
[    0.892838] console [ttyLP0] enabled
[    0.901914] 40028000.serial: ttyLP1 at MMIO 0x40028000 (irq = 21, base_baud = 4125000) is a FSL_LPUART
[    0.921023] 40029000.serial: ttyLP2 at MMIO 0x40029000 (irq = 22, base_baud = 4125000) is a FSL_LPUART
[    0.959833] loop: module loaded
[    0.971087] nand: device found, Manufacturer ID: 0xc2, Chip ID: 0xf1
[    0.981940] nand: Macronix NAND 128MiB 3,3V 8-bit
[    0.991078] nand: 128 MiB, SLC, erase size: 128 KiB, page size: 2048, OOB size: 64
[    1.007717] Bad block table found at page 65472, version 0x01
[    1.018356] Bad block table found at page 65408, version 0x01
[    1.029057] 4 cmdlinepart partitions found on MTD device vf610_nfc
[    1.039930] Creating 4 MTD partitions on "vf610_nfc":
[    1.049703] 0x000000000000-0x000000020000 : "vf-bcb"
[    1.060727] 0x000000020000-0x000000180000 : "u-boot"
[    1.071572] 0x000000180000-0x000000200000 : "u-boot-env"
[    1.082758] 0x000000200000-0x000008000000 : "ubi"
[    1.100289] 400d1000.ethernet supply phy not found, using dummy regulator
[    1.122026] libphy: fec_enet_mii_bus: probed
[    1.133190] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.146042] usbcore: registered new interface driver usb-storage
[    1.158133] usbcore: registered new interface driver usbserial
[    1.169262] usbcore: registered new interface driver usbserial_generic
[    1.180859] usbserial: USB Serial support registered for generic
[    1.192041] usbcore: registered new interface driver ftdi_sio
[    1.202848] usbserial: USB Serial support registered for FTDI USB Serial Device
[    1.219659] usbcore: registered new interface driver pl2303
[    1.230175] usbserial: USB Serial support registered for pl2303
[    1.250842] imx_usb 400b4000.usb: Can't register ci_hdrc platform device, err=-517
[    1.269902] mousedev: PS/2 mouse device common for all mice
[    1.282256] rtc-ds1307: probe of 0-0068 failed with error -5
[    1.294713] snvs_rtc 400a7034.snvs-rtc-lp: rtc core: registered 400a7034.snvs-rtc-l as rtc0
[    1.313066] i2c /dev entries driver
[    1.325910] imx2-wdt 4003e000.wdog: timeout 60 sec (nowayout=0)
[    1.337470] sdhci: Secure Digital Host Controller Interface driver
[    1.348776] sdhci: Copyright(c) Pierre Ossman
[    1.358357] sdhci-pltfm: SDHCI platform and OF driver helper
[    1.370640] /soc/aips-bus@40080000/esdhc@400b2000: voltage-ranges unspecified
[    1.383491] sdhci-esdhc-imx 400b2000.esdhc: Got CD GPIO
[    1.394551] sdhci-esdhc-imx 400b2000.esdhc: No vmmc regulator found
[    1.406232] sdhci-esdhc-imx 400b2000.esdhc: No vqmmc regulator found
[    1.455030] mmc0: SDHCI controller on 400b2000.esdhc [400b2000.esdhc] using ADMA
[    1.478433] usbcore: registered new interface driver usbhid
[    1.489668] usbhid: USB HID core driver
[    1.500167] 4003b000.adc supply vref not found, using dummy regulator
[    1.517255] 400bb000.adc supply vref not found, using dummy regulator
[    1.534193] Netfilter messages via NETLINK v0.30.
[    1.545659] nfnl_acct: registering with nfnetlink.
[    1.555779] nf_conntrack version 0.5.0 (1868 buckets, 7472 max)
[    1.572189] nf_tables: (c) 2007-2009 Patrick McHardy <kaber@trash.net>
[    1.586113] ip_tables: (C) 2000-2006 Netfilter Core Team
[    1.599463] NET: Registered protocol family 10
[    1.613218] ip6_tables: (C) 2000-2006 Netfilter Core Team
[    1.623982] sit: IPv6 over IPv4 tunneling driver
[    1.636845] NET: Registered protocol family 17
[    1.646637] bridge: automatic filtering via arp/ip/ip6tables has been deprecated. Update your scripts to load br_netfilter if you need this.
[    1.669574] Bridge firewalling registered
[    1.680245] 8021q: 802.1Q VLAN Support v1.8
[    1.691818] Key type dns_resolver registered
[    1.701660] Registering SWP/SWPB emulation handler
[    1.714822] registered taskstats version 1
[    1.731301] usbh_vbus: supplied by 5v0
[    1.744627] ci_hdrc ci_hdrc.1: EHCI Host Controller
[    1.755851] ci_hdrc ci_hdrc.1: new USB bus registered, assigned bus number 1
[    1.785043] ci_hdrc ci_hdrc.1: USB 2.0 started, EHCI 1.00
[    1.798152] hub 1-0:1.0: USB hub found
[    1.806943] hub 1-0:1.0: 1 port detected
[    1.819450] input: colibri-vf50-ts as /devices/platform/vf50_touchctrl/input/input0
[    1.839751] toradex,vf50_touchctrl vf50_touchctrl: Attached colibri-vf50-ts driver successfully
[    1.859364] ubi0: default fastmap pool size: 50
[    1.868992] ubi0: default fastmap WL pool size: 25
[    1.878648] ubi0: attaching mtd3
[    1.944886] ubi0: attached by fastmap
[    1.953386] ubi0: fastmap pool size: 50
[    1.961818] ubi0: fastmap WL pool size: 25
[    1.981616] ubi0: attached mtd3 (name "ubi", size 126 MiB)
[    1.991835] ubi0: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
[    2.003327] ubi0: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
[    2.014674] ubi0: VID header offset: 2048 (aligned 2048), data offset: 4096
[    2.026229] ubi0: good PEBs: 1004, bad PEBs: 4, corrupted PEBs: 0
[    2.036951] ubi0: user volume: 1, internal volumes: 1, max. volumes count: 128
[    2.053305] ubi0: max/mean erase counter: 115/11, WL threshold: 4096, image sequence number: 0
[    2.071614] ubi0: available PEBs: 0, total reserved PEBs: 1004, PEBs reserved for bad PEB handling: 16
[    2.091286] ubi0: background thread "ubi_bgt0d" started, PID 50
[    2.103973] snvs_rtc 400a7034.snvs-rtc-lp: setting system clock to 1970-01-01 00:12:04 UTC (724)
[    2.139189] ALSA device list:
[    2.147659]   No soundcards found.
[    2.186556] UBIFS (ubi0:0): recovery needed
[    2.215265] usb 1-1: new high-speed USB device number 2 using ci_hdrc
[    2.378103] hub 1-1:1.0: USB hub found
[    2.387452] hub 1-1:1.0: 4 ports detected
[    2.552203] UBIFS (ubi0:0): recovery deferred
[    2.561990] UBIFS (ubi0:0): UBIFS: mounted UBI device 0, volume 0, name "rootfs", R/O mode
[    2.580664] UBIFS (ubi0:0): LEB size: 126976 bytes (124 KiB), min./max. I/O unit sizes: 2048 bytes/2048 bytes
[    2.601698] UBIFS (ubi0:0): FS size: 123293696 bytes (117 MiB, 971 LEBs), journal size 9023488 bytes (8 MiB, 72 LEBs)
[    2.623697] UBIFS (ubi0:0): reserved for root: 0 bytes (0 KiB)
[    2.635373] UBIFS (ubi0:0): media format: w4/r0 (latest is w4/r0), UUID 8CD1C68E-FE03-420D-A522-9D1348A77201, small LPT model
[    2.659795] VFS: Mounted root (ubifs filesystem) readonly on device 0:14.
[    2.673917] devtmpfs: mounted
[    2.684499] Freeing unused kernel memory: 216K (8076c000 - 807a2000)
[    2.735477] usb 1-1.1: new high-speed USB device number 3 using ci_hdrc
[    2.860342] usb-storage 1-1.1:1.0: USB Mass Storage device detected
[    2.881163] scsi host0: usb-storage 1-1.1:1.0
[    3.047468] random: systemd urandom read with 35 bits of entropy available
[    3.091951] systemd[1]: systemd 218 running in system mode. (+PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT +GNUTLS +ACL +XZ -LZ4 -SECCOMP +BLKID -ELFUTILS +KMOD +IDN)
[    3.130741] systemd[1]: Detected architecture 'arm'.

Welcome to The Ångström Distribution v2014.12!

[    3.167766] systemd[1]: Set hostname to <colibri-vf>.
[    3.689001] systemd[1]: Unit type .busname is not supported on this system.
[    3.897008] scsi 0:0:0:0: Direct-Access     Generic  Flash-Disk       1.05 PQ: 0 ANSI: 2
[    4.306965] systemd[1]: Cannot add dependency job for unit bootmisc.service, ignoring: Unit bootmisc.service is masked.
[    4.330580] systemd[1]: Cannot add dependency job for unit banner.service, ignoring: Unit banner.service is masked.
[    4.353712] systemd[1]: Cannot add dependency job for unit mountall.service, ignoring: Unit mountall.service is masked.
[    4.378435] systemd[1]: Cannot add dependency job for unit populate-volatile.service, ignoring: Unit populate-volatile.service is masked.
[    4.404195] systemd[1]: Cannot add dependency job for unit read-only-rootfs-hook.service, ignoring: Unit read-only-rootfs-hook.service is masked.
[    4.430216] systemd[1]: Cannot add dependency job for unit sysfs.service, ignoring: Unit sysfs.service is masked.
[    4.453515] systemd[1]: Cannot add dependency job for unit devpts.service, ignoring: Unit devpts.service is masked.
[    4.477877] systemd[1]: Cannot add dependency job for unit checkroot.service, ignoring: Unit checkroot.service is masked.
[    4.502421] systemd[1]: Cannot add dependency job for unit dmesg.service, ignoring: Unit dmesg.service is masked.
[    4.526224] systemd[1]: Cannot add dependency job for unit hostname.service, ignoring: Unit hostname.service is masked.
[    4.550765] systemd[1]: Cannot add dependency job for unit urandom.service, ignoring: Unit urandom.service is masked.
[    4.576608] systemd[1]: Cannot add dependency job for unit rmnologin.service, ignoring: Unit rmnologin.service is masked.
[    4.602803] systemd[1]: Cannot add dependency job for unit mountnfs.service, ignoring: Unit mountnfs.service is masked.
[    4.628138] systemd[1]: Cannot add dependency job for unit mountnfs.service, ignoring: Unit mountnfs.service is masked.
[    4.653227] systemd[1]: Cannot add dependency job for unit rmnologin.service, ignoring: Unit rmnologin.service is masked.
[    4.694217] systemd[1]: Starting Forward Password Requests to Wall Directory Watch.
[    4.718176] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    4.740225] systemd[1]: Expecting device dev-ttyLP0.device...
          Expecting device dev-ttyLP0.device...
[    4.775606] systemd[1]: Starting Root Slice.
[  OK  ] Created slice Root Slice.
[    4.805520] systemd[1]: Created slice Root Slice.
[    4.817591] systemd[1]: Starting System Slice.
[  OK  ] Created slice System Slice.
[    4.845485] systemd[1]: Created slice System Slice.
[    4.857452] systemd[1]: Starting system-getty.slice.
[  OK  ] Created slice system-getty.slice.
[    4.885514] systemd[1]: Created slice system-getty.slice.
[    4.897628] systemd[1]: Starting User and Session Slice.
[  OK  ] Created slice User and Session Slice.
[    4.925523] systemd[1]: Created slice User and Session Slice.
[    4.937782] systemd[1]: Starting /dev/initctl Compatibility Named Pipe.
[  OK  ] Listening on /dev/initctl Compatibility Named Pipe.
[    4.975502] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
[    4.988870] systemd[1]: Starting Delayed Shutdown Socket.
[  OK  ] Listening on Delayed Shutdown Socket.
[    5.025521] systemd[1]: Listening on Delayed Shutdown Socket.
[    5.037429] systemd[1]: Starting system-serial\x2dgetty.slice.
[  OK  ] Created slice system-serial\x2dgetty.slice.
[    5.065506] systemd[1]: Created slice system-serial\x2dgetty.slice.
[    5.077871] systemd[1]: Starting Dispatch Password Requests to Console Directory Watch.
[    5.097329] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[    5.117637] systemd[1]: Starting Journal Socket (/dev/log).
[    5.129572] sd 0:0:0:0: [sda] 7761920 512-byte logical blocks: (3.97 GB/3.70 GiB)
[  OK  ] Listening on J[    5.150472] sd 0:0:0:0: [sda] Write Protect is off
ournal Socket (/dev/log).
[    5.163099] sd 0:0:0:0: [sda] No Caching mode page found
[    5.173454] sd 0:0:0:0: [sda] Assuming drive cache: write through
[    5.185085] systemd[1]: Listening on Journal Socket (/dev/log).
[    5.198892] systemd[1]: Expecting device dev-ttyGS0.device...
          Expecting device dev-ttyGS0.device...
[    5.217790]  sda: sda1
[    5.232267] sd 0:0:0:0: [sda] Attached SCSI removable disk
[    5.243642] systemd[1]: Starting Journal Socket.
[  OK  ] Listening on Journal Socket.
[    5.275646] systemd[1]: Listening on Journal Socket.
[    5.286378] systemd[1]: Starting (null)...
          Starting        ..
[    5.343585] systemd[1]: Started Load Kernel Modules.
[    5.358896] systemd[1]: Starting Apply Kernel Variab         Startingriables.ernel Variables...
[    5.396219] systemd[1]: Mounting FUSE Control File Sys         Mounting FUSE Control File System...
[    5.454009] systemd[1]: Mounting Configuration File System...
          Mounting Configuration File System...
[    5.546855] systemd[1]: Started Create list of required static device nodes for the current kernel.
[    5.590853] systemd[1]: Starting udev Control Socket.
[  OK  ] Listening on udev Control Socket.
[    5.621530] systemd[1]: Listening on udev Control Socket.
[    5.646880] systemd[1]: Mounted POSIX Message Queue File System.
[    5.674078] systemd[1]: Mounted Huge Pages File System.
[    5.847231] systemd[1]: Listening on Journal Audit Socket.
[    5.860268] systemd[1]: Starting Journal Service...
          Starting Journal Service...
[    5.901190] systemd[1]: Starting udev Kernel Socket.
[  OK  ] Listening on udev Kernel Socket.
[    5.945608] systemd[1]: Listening on udev Kernel Socket.
[    5.960923] systemd[1]: Starting udev Coldplug all Devices...
          Starting udev Coldplug all Devices...
[    6.000942] systemd[1]: Starting Paths.
[  OK  ] Reached target Paths.
[    6.065500] systemd[1]: Reached target Paths.
[    6.086043] systemd[1]: Mounting Temporary Directory...
          Mounting Temporary Directory...
[    6.120796] systemd[1]: Starting Slices.
[  OK  ] Reached target Slices.
[    6.168419] systemd[1]: Reached target Slices.
[    6.184476] systemd[1]: Starting File System Check on Root Device...
          Starting File System Check on Root Device...
[    6.231118] systemd[1]: Starting Swap.
[  OK  ] Reached target Swap.
[    6.278976] systemd[1]: Reached target Swap.
[  OK  ] Mounted FUSE Control File System.
[    6.338579] systemd[1]: Mounted FUSE Control File System.
[  OK  ] Mounted Configuration File System.
[    6.385515] systemd[1]: Mounted Configuration File System.
[  OK  ] Mounted Temporary Directory.
[    6.435501] systemd[1]: Mounted Temporary Directory.
[  OK  ] Started (null).
[    6.515669] systemd[1]: Started (null).
[  OK  ] Started Apply Kernel Variables.
[    6.555838] systemd[1]: Started Apply Kernel Variables.
[  OK  ] Started File System Check on Root Device.
[    6.665743] systemd[1]: Started File System Check on Root Device.
[  OK  ] Started Journal Service.
[    7.085522] systemd[1]: Started Journal Service.
[  OK  ] Started udev Coldplug all Devices.
          Starting Remount Root and Kernel File Systems...
[    7.669256] UBIFS (ubi0:0): completing deferred recovery
[    7.989718] UBIFS (ubi0:0): background thread "ubifs_bgt0_0" started, PID 93
[    8.201567] random: nonblocking pool is initialized
[    8.440773] UBIFS error (ubi0:0 pid 89): ubifs_check_node: bad CRC: calculated 0x3e594a6c, read 0xfd9c1779
[    8.458517] UBIFS error (ubi0:0 pid 89): ubifs_check_node: bad node at LEB 957:1920
[    8.474556] 	magic          0x6101831
[    8.482579] 	crc            0xfd9c1779
[    8.490614] 	node_type      9 (indexing node)
[    8.499268] 	group_type     0 (no node group)
[    8.507927] 	sqnum          427384
[    8.515589] 	len            188
[    8.522902] 	child_cnt      8
[    8.530025] 	level          0
[    8.537043] 	Branches:
[    8.543287] 	0: LEB 902:4800 len 92 key (23325, data, 882)
[    8.552944] 	1: LEB 902:4896 len 92 key (23325, data, 883)
[    8.562534] 	2: LEB 902:4992 len 92 key (23325, data, 884)
[    8.572039] 	3: LEB 902:5088 len 92 key (23325, data, 885)
[    8.581477] 	4: LEB 902:5184 len 92 key (23325, data, 886)
[    8.590856] 	5: LEB 101718065:817737798 len 427374 key (0, inode)
[    8.600949] 	6: LEB 9:8 len 891 key (124792, inode)
[    8.609820] CPU: 0 PID: 89 Comm: mount Not tainted 4.1.2-00312-g796aee8 #4
[    8.620843] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
[    8.631473] Backtrace:
[    8.638159] [<80012ab8>] (dump_backtrace) from [<80012cd8>] (show_stack+0x18/0x1c)
[    8.653694]  r7:881d4780 r6:87b53000 r5:00000780 r4:ffffff8b
[    8.664070] [<80012cc0>] (show_stack) from [<805982a8>] (dump_stack+0x24/0x28)
[    8.679119] [<80598284>] (dump_stack) from [<8022cddc>] (ubifs_check_node+0x1b8/0x2e4)
[    8.695402] [<8022cc24>] (ubifs_check_node) from [<80234340>] (ubifs_scan_a_node+0xcc/0x1e4)
[    8.712845]  r9:000003bd r8:00000000 r7:87b53000 r6:000003bd r5:87b53000 r4:881d4780
[    8.730997] [<80234274>] (ubifs_scan_a_node) from [<80234838>] (ubifs_scan+0x60/0x39c)
[    8.749411]  r6:881d4780 r5:00000780 r4:0001e880
[    8.760074] [<802347d8>] (ubifs_scan) from [<8023e0d0>] (ubifs_tnc_start_commit+0x6b8/0xab8)
[    8.779783]  r10:ffffffe4 r9:000000f5 r8:00000000 r7:87b53000 r6:0001f000 r5:00000001
[    8.800496]  r4:000003bd
[    8.809485] [<8023da18>] (ubifs_tnc_start_commit) from [<80237ac4>] (do_commit+0x140/0x4dc)
[    8.830491]  r10:00008020 r9:00000020 r8:87b4ed44 r7:00000003 r6:87b53130 r5:00000000
[    8.851929]  r4:87b53000
[    8.861020] [<80237984>] (do_commit) from [<80238060>] (ubifs_run_commit+0x74/0xb4)
[    8.881320]  r8:00000000 r7:87b537a8 r6:87b4ec00 r5:87b531a4 r4:87b53000
[    8.895426] [<80237fec>] (ubifs_run_commit) from [<80246d88>] (ubifs_rcvry_gc_commit+0x7c/0x1ec)
[    8.916989]  r5:87b537ec r4:87b53000
[    8.927248] [<80246d0c>] (ubifs_rcvry_gc_commit) from [<80228e28>] (ubifs_remount_fs+0x440/0x744)
[    8.948618]  r7:87b537a8 r6:00000000 r5:87b537ec r4:87b53000
[    8.961318] [<802289e8>] (ubifs_remount_fs) from [<800c4cbc>] (do_remount_sb+0x6c/0x1c4)
[    8.981687]  r9:00000020 r8:00000000 r7:00000000 r6:00000000 r5:00000000 r4:87b47c00
[    9.002500] [<800c4c50>] (do_remount_sb) from [<800df390>] (do_mount+0x5a8/0x9b4)
[    9.022463]  r8:87b47c00 r7:87b47c40 r6:00000000 r5:00000000 r4:87b086d0
[    9.036416] [<800dede8>] (do_mount) from [<800dfad8>] (SyS_mount+0x7c/0xa8)
[    9.049829]  r10:00000000 r9:85cce000 r8:c0ed8020 r7:008ed1e8 r6:00000000 r5:85c5ee40
[    9.070954]  r4:85c5ef00
[    9.079921] [<800dfa5c>] (SyS_mount) from [<8000f5c0>] (ret_fast_syscall+0x0/0x3c)
[    9.099814]  r8:8000f764 r7:00000015 r6:00000000 r5:008ed158 r4:00000000
[    9.113569] UBIFS error (ubi0:0 pid 89): ubifs_scan: bad node
[    9.125801] UBIFS error (ubi0:0 pid 89): ubifs_scanned_corruption: corruption at LEB 957:1920
[    9.146679] UBIFS error (ubi0:0 pid 89): ubifs_scanned_corruption: first 8192 bytes from LEB 957:1920
[    9.179238] UBIFS error (ubi0:0 pid 89): ubifs_scan: LEB 957 scanning failed
[    9.192828] UBIFS error (ubi0:0 pid 89): do_commit: commit failed, error -117
[    9.206460] UBIFS warning (ubi0:0 pid 89): ubifs_ro_mode: switched to read-only mode, error -117
[    9.227664] CPU: 0 PID: 89 Comm: mount Not tainted 4.1.2-00312-g796aee8 #4
[    9.241015] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
[    9.253900] Backtrace:
[    9.262769] [<80012ab8>] (dump_backtrace) from [<80012cd8>] (show_stack+0x18/0x1c)
[    9.282622]  r7:00000003 r6:87b53130 r5:00000010 r4:85d18980
[    9.295256] [<80012cc0>] (show_stack) from [<805982a8>] (dump_stack+0x24/0x28)
[    9.314631] [<80598284>] (dump_stack) from [<8022c50c>] (ubifs_ro_mode.part.9+0x7c/0x84)
[    9.335027] [<8022c490>] (ubifs_ro_mode.part.9) from [<8022c624>] (ubifs_ro_mode+0x1c/0x20)
[    9.355855]  r5:ffffff8b r4:87b53000
[    9.366062] [<8022c608>] (ubifs_ro_mode) from [<80237e50>] (do_commit+0x4cc/0x4dc)
[    9.386052] [<80237984>] (do_commit) from [<80238060>] (ubifs_run_commit+0x74/0xb4)
[    9.406342]  r8:00000000 r7:87b537a8 r6:87b4ec00 r5:87b531a4 r4:87b53000
[    9.420346] [<80237fec>] (ubifs_run_commit) from [<80246d88>] (ubifs_rcvry_gc_commit+0x7c/0x1ec)
[    9.441865]  r5:87b537ec r4:87b53000
[    9.452097] [<80246d0c>] (ubifs_rcvry_gc_commit) from [<80228e28>] (ubifs_remount_fs+0x440/0x744)
[    9.473678]  r7:87b537a8 r6:00000000 r5:87b537ec r4:87b53000
[    9.486526] [<802289e8>] (ubifs_remount_fs) from [<800c4cbc>] (do_remount_sb+0x6c/0x1c4)
[    9.507262]  r9:00000020 r8:00000000 r7:00000000 r6:00000000 r5:00000000 r4:87b47c00
[    9.528476] [<800c4c50>] (do_remount_sb) from [<800df390>] (do_mount+0x5a8/0x9b4)
[    9.548833]  r8:87b47c00 r7:87b47c40 r6:00000000 r5:00000000 r4:87b086d0
[    9.562946] [<800dede8>] (do_mount) from [<800dfad8>] (SyS_mount+0x7c/0xa8)
[    9.576599]  r10:00000000 r9:85cce000 r8:c0ed8020 r7:008ed1e8 r6:00000000 r5:85c5ee40
[    9.597950]  r4:85c5ef00
[    9.606978] [<800dfa5c>] (SyS_mount) from [<8000f5c0>] (ret_fast_syscall+0x0/0x3c)
[    9.627131]  r8:8000f764 r7:00000015 r6:00000000 r5:008ed158 r4:00000000
[    9.645229] UBIFS (ubi0:0): background thread "ubifs_bgt0_0" stops
[FAILED] Failed to start Remount Root and Kernel File Systems.
...


Best regards,
Bhuvan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
       [not found]                           ` <55A75A05.7040603@nod.at>
  2015-07-16  7:33                             ` Bhuvanchandra DV
@ 2015-07-21  6:04                             ` Bhuvanchandra DV
  2015-07-21  6:14                               ` Richard Weinberger
  1 sibling, 1 reply; 34+ messages in thread
From: Bhuvanchandra DV @ 2015-07-21  6:04 UTC (permalink / raw)
  To: Richard Weinberger; +Cc: linux-mtd

On 07/16/2015 12:45 PM, Richard Weinberger wrote:

> Am 16.07.2015 um 09:11 schrieb Bhuvanchandra DV:
>> On 07/16/2015 12:19 PM, Richard Weinberger wrote:
>>
>>> Am 16.07.2015 um 08:09 schrieb Richard Weinberger:
>>>> Am 16.07.2015 um 07:58 schrieb Bhuvanchandra DV:
>>>>> Power cut test with 4.1.2 kernel:
>>>>>
>>>>> Preparing UBI image using mkfs.ubifs utility:
>>>>>
>>>>> $ mkfs.ubifs -c 8112 -e 124KiB -m 2KiB -o ubifs.img -r rootfs/ -v
>>>>>
>>>>>
>>>>> Flashing UBI image from U-Boot:
>>>>>
>>>>> # fatload ${interface} 0:1 ${loadaddr} ubifs.img
>>>>> reading ubifs.img
>>>>> 108691456 bytes read in 7139 ms (14.5 MiB/s)
>>>>> # ubi part ubi && ubi check rootfs || ubi create rootfs
>>>>> UBI: default fastmap pool size: 50
>>>>> UBI: default fastmap WL pool size: 25
>>>>> UBI: attaching mtd1 to ubi0
>>>>> UBI: attached by fastmap
>>>>> UBI: fastmap pool size: 50
>>>>> UBI: fastmap WL pool size: 25
>>>>> UBI: attached mtd1 (name "mtd=3", size 126 MiB) to ubi0
>>>>> UBI: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
>>>>> UBI: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
>>>>> UBI: VID header offset: 2048 (aligned 2048), data offset: 4096
>>>>> UBI: good PEBs: 1003, bad PEBs: 5, corrupted PEBs: 0
>>>>> UBI: user volume: 1, internal volumes: 1, max. volumes count: 128
>>>>> UBI: max/mean erase counter: 14/4, WL threshold: 4096, image sequence number: 0
>>>>> UBI: available PEBs: 0, total reserved PEBs: 1003, PEBs reserved for bad PEB handling: 15
>>>>> # ubi write ${loadaddr} rootfs ${filesize}
>>>>> 108691456 bytes written to volume rootfs
>>>>>
>>>>> With 4.1.2 kernel after ~600 power cut cycles, no issues with mounting the ubifs,
>>>>> but observed few stack traces.
>>>> But your kernel log shows an issue. It is not clear whether it comes from fastmap.
>>> BTW: I forgot to ask one thing, did you test using fm_debug?
>> No, if needed i can do the test again with fm_debug enabled.
>> Enabled fm_debug now with the corrupted ubifs, no addiditional debug logs observed.
> Okay. So far it does not really sound like a fastmap issue.
> But please double check using fm_debug.

Ran the power cut tests with fm_debug enabled, no additional logs are observed.
After few hundred power cuts U-Boot fails to mount with -22 and kernel fails
mounting with stack trace when reading the node.

Log:
  
U-Boot 2015.04 (May 18 2015 - 15:37:34)

CPU: Freescale Vybrid VF500 at 396 MHz
Reset cause: WDOG A5
DRAM:  128 MiB
NAND:  128 MiB
MMC:   FSL_SDHC: 0
In:    serial
Out:   serial
Err:   serial
Model: Toradex Colibri VF50 128MB V38.655341, Serial# 04833251
Net:   FEC
Hit any key to stop autoboot:  0
Colibri VFxx #
Colibri VFxx #
Colibri VFxx # boot
Booting from NAND...
UBI: default fastmap pool size: 50
UBI: default fastmap WL pool size: 25
UBI: attaching mtd1 to ubi0
UBI: attached by fastmap
UBI: fastmap pool size: 50
UBI: fastmap WL pool size: 25
UBI: attached mtd1 (name "mtd=3", size 126 MiB) to ubi0
UBI: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
UBI: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
UBI: VID header offset: 2048 (aligned 2048), data offset: 4096
UBI: good PEBs: 1004, bad PEBs: 4, corrupted PEBs: 0
UBI: user volume: 1, internal volumes: 1, max. volumes count: 128
UBI: max/mean erase counter: 185/29, WL threshold: 4096, image sequence number: 0
UBI: available PEBs: 0, total reserved PEBs: 1004, PEBs reserved for bad PEB handling: 16
Error reading superblock on volume 'ubi0:rootfs' errno=-22!
ubifsmount - mount UBIFS volume

Usage:
ubifsmount <volume-name>
     - mount 'volume-name' volume
Colibri VFxx # setenv bootargs ${defargs} ${ubiargs} ${mtdparts} ${setupargs} ${vidargs}
Colibri VFxx # dhcp ${kernel_addr_r} && tftp ${fdt_addr_r} ${soc}-colibri-${fdt_board}.dtb && bootz ${kernel_addr_r} - ${fdt_addr_r}
BOOTP broadcast 1
DHCP client bound to address 10.18.0.139 (5 ms)
Using FEC device
TFTP from server 10.18.0.132; our IP address is 10.18.0.139
Filename 'zImage'.
Load address: 0x82000000
Loading: #################################################################
          #################################################################
          #################################################################
          #################################################################
          ###########################################
          1.2 MiB/s
done
Bytes transferred = 4433808 (43a790 hex)
Using FEC device
TFTP from server 10.18.0.132; our IP address is 10.18.0.139
Filename 'vf500-colibri-eval-v3.dtb'.
Load address: 0x84000000
Loading: ##
          588.9 KiB/s
done
Bytes transferred = 21126 (5286 hex)
Kernel image @ 0x82000000 [ 0x000000 - 0x43a790 ]
## Flattened Device Tree blob at 84000000
    Booting using the fdt blob at 0x84000000
    Loading Device Tree to 876ff000, end 87707285 ... OK

Starting kernel ...

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.1.2-00312-g796aee8 (dvb@dev) (gcc version 4.9.3 20141031 (prerelease) (Linaro GCC 2014.11) ) #4 Tue Jul 14 18:02:37 I5
[    0.000000] CPU: ARMv7 Processor [410fc051] revision 1 (ARMv7), cr=10c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] Machine model: Toradex Colibri VF50 on Colibri Evaluation Board
[    0.000000] cma: Reserved 16 MiB at 0x86400000
[    0.000000] Memory policy: Data cache writeback
[    0.000000] CPU: All CPU(s) started in SVC mode.
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 32004
[    0.000000] Kernel command line: ubi.mtd=ubi root=ubi0:rootfs rootfstype=ubifs ubi.fm_autoconvert=1 ubi.fm_debug=1 mtdparts=vf610_nfc:128k(vf-bcb0
[    0.000000] PID hash table entries: 512 (order: -1, 2048 bytes)
[    0.000000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
[    0.000000] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
[    0.000000] Memory: 103168K/129024K available (5719K kernel code, 201K rwdata, 1844K rodata, 216K init, 171K bss, 9472K reserved, 16384K cma-rese)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
[    0.000000]     vmalloc : 0x88000000 - 0xff000000   (1904 MB)
[    0.000000]     lowmem  : 0x80000000 - 0x87e00000   ( 126 MB)
[    0.000000]     modules : 0x7f000000 - 0x80000000   (  16 MB)
[    0.000000]       .text : 0x80008000 - 0x8076b04c   (7565 kB)
[    0.000000]       .init : 0x8076c000 - 0x807a2000   ( 216 kB)
[    0.000000]       .data : 0x807a2000 - 0x807d44e0   ( 202 kB)
[    0.000000]        .bss : 0x807d44e0 - 0x807ff1d0   ( 172 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] NR_IRQS:16 nr_irqs:16 16
[    0.000000] L2C: failed to init: -19
[    0.000054] sched_clock: 64 bits at 132MHz, resolution 7ns, wraps every 2199023255551ns
[    0.000124] clocksource arm_global_timer: mask: 0xffffffffffffffff max_cycles: 0x1e7178659b, max_idle_ns: 440795204301 ns
[    0.000841] Console: colour dummy device 80x30
[    0.002050] console [tty1] enabled
[    0.002147] Calibrating delay loop... 262.96 BogoMIPS (lpj=1314816)
[    0.070305] pid_max: default: 32768 minimum: 301
[    0.070664] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.070779] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.072721] CPU: Testing write buffer coherency: ok
[    0.073666] Setting up static identity map for 0x80008200 - 0x80008258
[    0.077519] devtmpfs: initialized
[    0.093174] VFP support v0.3: implementor 41 architecture 2 part 30 variant 5 rev 1
[    0.094210] clocksource jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.097837] pinctrl core: initialized pinctrl subsystem
[    0.101264] NET: Registered protocol family 16
[    0.105157] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.108118] cpuidle: using governor menu
[    0.137763] hw-breakpoint: found 2 (+1 reserved) breakpoint and 1 watchpoint registers.
[    0.137919] hw-breakpoint: maximum watchpoint size is 4 bytes.
[    0.138989] vf610-pinctrl 40048000.iomuxc: initialized IMX pinctrl driver
[    0.174491] SCSI subsystem initialized
[    0.175762] usbcore: registered new interface driver usbfs
[    0.176105] usbcore: registered new interface driver hub
[    0.176478] usbcore: registered new device driver usb
[    0.179128] i2c i2c-0: IMX I2C adapter registered
[    0.179415] i2c i2c-0: using dma0chan0 (tx) and dma0chan1 (rx) for DMA transfers
[    0.179894] Linux video capture interface: v2.00
[    0.180453] pps_core: LinuxPPS API ver. 1 registered
[    0.180544] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.180774] PTP clock support registered
[    0.182240] Advanced Linux Sound Architecture Driver Initialized.
[    0.185232] Switched to clocksource arm_global_timer
[    0.223890] NET: Registered protocol family 2
[    0.226465] TCP established hash table entries: 1024 (order: 0, 4096 bytes)
[    0.226631] TCP bind hash table entries: 1024 (order: 0, 4096 bytes)
[    0.226744] TCP: Hash tables configured (established 1024 bind 1024)
[    0.227141] UDP hash table entries: 256 (order: 0, 4096 bytes)
[    0.227273] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[    0.227890] NET: Registered protocol family 1
[    0.228993] RPC: Registered named UNIX socket transport module.
[    0.229121] RPC: Registered udp transport module.
[    0.229190] RPC: Registered tcp transport module.
[    0.229252] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.234875] futex hash table entries: 256 (order: -1, 3072 bytes)
[    0.259703] NFS: Registering the id_resolver key type
[    0.259925] Key type id_resolver registered
[    0.260013] Key type id_legacy registered
[    0.260168] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.262003] ntfs: driver 2.1.32 [Flags: R/W].
[    0.263686] fuse init (API version 7.23)
[    0.272665] io scheduler noop registered
[    0.272800] io scheduler deadline registered
[    0.273025] io scheduler cfq registered (default)
[    0.284568] backlight supply power not found, using dummy regulator
[    0.306663] Console: switching to colour frame buffer device 80x30
[    0.318568] fb0: fb device registered successfully.
[    0.324027] fb1: fb device registered successfully.
[    0.329358] fb2: fb device registered successfully.
[    0.334407] fb3: fb device registered successfully.
[    0.339438] fb4: fb device registered successfully.
[    0.344143] fb5: fb device registered successfully.
[    0.349692] 40027000.serial: ttyLP0 at MMIO 0x40027000 (irq = 20, base_baud = 4125000) is a FSL_LPUART
[    0.894689] console [ttyLP0] enabled
[    0.903762] 40028000.serial: ttyLP1 at MMIO 0x40028000 (irq = 21, base_baud = 4125000) is a FSL_LPUART
[    0.922873] 40029000.serial: ttyLP2 at MMIO 0x40029000 (irq = 22, base_baud = 4125000) is a FSL_LPUART
[    0.961752] loop: module loaded
[    0.973019] nand: device found, Manufacturer ID: 0xc2, Chip ID: 0xf1
[    0.983874] nand: Macronix NAND 128MiB 3,3V 8-bit
[    0.993009] nand: 128 MiB, SLC, erase size: 128 KiB, page size: 2048, OOB size: 64
[    1.009656] Bad block table found at page 65472, version 0x01
[    1.020289] Bad block table found at page 65408, version 0x01
[    1.030998] 4 cmdlinepart partitions found on MTD device vf610_nfc
[    1.041879] Creating 4 MTD partitions on "vf610_nfc":
[    1.051654] 0x000000000000-0x000000020000 : "vf-bcb"
[    1.062715] 0x000000020000-0x000000180000 : "u-boot"
[    1.073559] 0x000000180000-0x000000200000 : "u-boot-env"
[    1.084735] 0x000000200000-0x000008000000 : "ubi"
[    1.102282] 400d1000.ethernet supply phy not found, using dummy regulator
[    1.123935] libphy: fec_enet_mii_bus: probed
[    1.135101] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.147887] usbcore: registered new interface driver usb-storage
[    1.159979] usbcore: registered new interface driver usbserial
[    1.171122] usbcore: registered new interface driver usbserial_generic
[    1.182724] usbserial: USB Serial support registered for generic
[    1.193912] usbcore: registered new interface driver ftdi_sio
[    1.204717] usbserial: USB Serial support registered for FTDI USB Serial Device
[    1.221540] usbcore: registered new interface driver pl2303
[    1.232067] usbserial: USB Serial support registered for pl2303
[    1.252895] imx_usb 400b4000.usb: Can't register ci_hdrc platform device, err=-517
[    1.271955] mousedev: PS/2 mouse device common for all mice
[    1.284327] rtc-ds1307: probe of 0-0068 failed with error -5
[    1.296958] snvs_rtc 400a7034.snvs-rtc-lp: rtc core: registered 400a7034.snvs-rtc-l as rtc0
[    1.315370] i2c /dev entries driver
[    1.328192] imx2-wdt 4003e000.wdog: timeout 60 sec (nowayout=0)
[    1.339765] sdhci: Secure Digital Host Controller Interface driver
[    1.351087] sdhci: Copyright(c) Pierre Ossman
[    1.360675] sdhci-pltfm: SDHCI platform and OF driver helper
[    1.372955] /soc/aips-bus@40080000/esdhc@400b2000: voltage-ranges unspecified
[    1.385812] sdhci-esdhc-imx 400b2000.esdhc: Got CD GPIO
[    1.396871] sdhci-esdhc-imx 400b2000.esdhc: No vmmc regulator found
[    1.408545] sdhci-esdhc-imx 400b2000.esdhc: No vqmmc regulator found
[    1.455367] mmc0: SDHCI controller on 400b2000.esdhc [400b2000.esdhc] using ADMA
[    1.478770] usbcore: registered new interface driver usbhid
[    1.490006] usbhid: USB HID core driver
[    1.500507] 4003b000.adc supply vref not found, using dummy regulator
[    1.517613] 400bb000.adc supply vref not found, using dummy regulator
[    1.534556] Netfilter messages via NETLINK v0.30.
[    1.546012] nfnl_acct: registering with nfnetlink.
[    1.556142] nf_conntrack version 0.5.0 (1868 buckets, 7472 max)
[    1.572515] nf_tables: (c) 2007-2009 Patrick McHardy <kaber@trash.net>
[    1.586430] ip_tables: (C) 2000-2006 Netfilter Core Team
[    1.599772] NET: Registered protocol family 10
[    1.613556] ip6_tables: (C) 2000-2006 Netfilter Core Team
[    1.624325] sit: IPv6 over IPv4 tunneling driver
[    1.637185] NET: Registered protocol family 17
[    1.646985] bridge: automatic filtering via arp/ip/ip6tables has been deprecated. Update your scripts to load br_netfilter if you need this.
[    1.669933] Bridge firewalling registered
[    1.680590] 8021q: 802.1Q VLAN Support v1.8
[    1.692142] Key type dns_resolver registered
[    1.702005] Registering SWP/SWPB emulation handler
[    1.715193] registered taskstats version 1
[    1.730262] usbh_vbus: supplied by 5v0
[    1.744936] ci_hdrc ci_hdrc.1: EHCI Host Controller
[    1.754998] ci_hdrc ci_hdrc.1: new USB bus registered, assigned bus number 1
[    1.785483] ci_hdrc ci_hdrc.1: USB 2.0 started, EHCI 1.00
[    1.801830] hub 1-0:1.0: USB hub found
[    1.810607] hub 1-0:1.0: 1 port detected
[    1.823065] input: colibri-vf50-ts as /devices/platform/vf50_touchctrl/input/input0
[    1.842329] toradex,vf50_touchctrl vf50_touchctrl: Attached colibri-vf50-ts driver successfully
[    1.862105] ubi0: default fastmap pool size: 50
[    1.871770] ubi0: default fastmap WL pool size: 25
[    1.881478] ubi0: attaching mtd3
[    1.962475] ubi0: attached by fastmap
[    1.970933] ubi0: fastmap pool size: 50
[    1.979367] ubi0: fastmap WL pool size: 25
[    2.135517] usb 1-1: new high-speed USB device number 2 using ci_hdrc
[    2.298663] hub 1-1:1.0: USB hub found
[    2.307624] hub 1-1:1.0: 4 ports detected
[    2.433347] ubi0: scanning is finished
[    2.446548] ubi0: attached mtd3 (name "ubi", size 126 MiB)
[    2.456528] ubi0: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
[    2.467905] ubi0: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
[    2.479213] ubi0: VID header offset: 2048 (aligned 2048), data offset: 4096
[    2.490787] ubi0: good PEBs: 1004, bad PEBs: 4, corrupted PEBs: 0
[    2.501544] ubi0: user volume: 1, internal volumes: 1, max. volumes count: 128
[    2.518002] ubi0: max/mean erase counter: 185/19, WL threshold: 4096, image sequence number: 0
[    2.536247] ubi0: available PEBs: 0, total reserved PEBs: 1004, PEBs reserved for bad PEB handling: 16
[    2.556011] ubi0: background thread "ubi_bgt0d" started, PID 51
[    2.568689] snvs_rtc 400a7034.snvs-rtc-lp: setting system clock to 1970-01-01 00:00:01 UTC (1)
[    2.604265] ALSA device list:
[    2.612344]   No soundcards found.
[    2.645776] usb 1-1.3: new high-speed USB device number 3 using ci_hdrc
[    2.657942] UBIFS (ubi0:0): recovery needed
[    2.779547] usb-storage 1-1.3:1.0: USB Mass Storage device detected
[    2.799038] scsi host0: usb-storage 1-1.3:1.0
[    2.847326] UBIFS error (ubi0:0 pid 1): ubifs_read_node: bad node type (255 but expected 3)
[    2.866839] UBIFS error (ubi0:0 pid 1): ubifs_read_node: bad node at LEB 981:70368, LEB mapping status 1
[    2.887961] Not a node, first 24 bytes:
[    2.891864] 00000000: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff                          ........................
[    2.922636] CPU: 0 PID: 1 Comm: swapper Not tainted 4.1.2-00312-g796aee8 #4
[    2.935771] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
[    2.948373] Backtrace:
[    2.956951] [<80012ab8>] (dump_backtrace) from [<80012cd8>] (show_stack+0x18/0x1c)
[    2.976494]  r7:00000000 r6:00000000 r5:000003d5 r4:000112e0
[    2.988441] [<80012cc0>] (show_stack) from [<805982a8>] (dump_stack+0x24/0x28)
[    3.007490] [<80598284>] (dump_stack) from [<8022e45c>] (ubifs_read_node+0x294/0x310)
[    3.027250] [<8022e1c8>] (ubifs_read_node) from [<8022e580>] (ubifs_read_node_wbuf+0xa8/0x2fc)
[    3.047959]  r10:000003d5 r9:00000049 r8:87bfbc00 r7:00000003 r6:87b54000 r5:87bc3f20
[    3.068618]  r4:000112e0
[    3.077490] [<8022e4d8>] (ubifs_read_node_wbuf) from [<8024bc10>] (ubifs_tnc_read_node+0x50/0x140)
[    3.099047]  r10:85c05700 r9:87bfbc00 r8:85c05700 r7:00000003 r6:87bfbc00 r5:87b54000
[    3.119822]  r4:85c05730
[    3.128608] [<8024bbc0>] (ubifs_tnc_read_node) from [<8022f4b0>] (tnc_read_node_nm+0xcc/0x1e4)
[    3.149628]  r8:85c05700 r7:87b541c0 r6:87b54000 r5:87bfbc00 r4:85c05730
[    3.163055] [<8022f3e4>] (tnc_read_node_nm) from [<80232ff8>] (ubifs_tnc_next_ent+0x140/0x1a4)
[    3.184179]  r7:87b541c0 r6:87b54000 r5:87849c38 r4:00000030
[    3.196516] [<80232eb8>] (ubifs_tnc_next_ent) from [<80233110>] (ubifs_tnc_remove_ino+0xb4/0x144)
[    3.217959]  r10:87b54000 r9:00006961 r8:ffffffff r7:00000000 r6:000003d5 r5:87b54000
[    3.238613]  r4:87bddf60
[    3.247434] [<8023305c>] (ubifs_tnc_remove_ino) from [<80235cdc>] (ubifs_replay_journal+0xe9c/0x1490)
[    3.269059]  r10:87b54000 r9:87849d08 r8:87bddf40 r7:87b54930 r6:000003d5 r5:00000000
[    3.289546]  r4:87bddf60
[    3.298171] [<80234e40>] (ubifs_replay_journal) from [<8022a890>] (ubifs_mount+0x10f8/0x1740)
[    3.318665]  r10:87b54190 r9:00000000 r8:0001e5a0 r7:87bd0400 r6:87b54000 r5:00000000
[    3.339106]  r4:00000000
[    3.347742] [<80229798>] (ubifs_mount) from [<800c5064>] (mount_fs+0x1c/0xac)
[    3.361078]  r10:00008001 r9:00000060 r8:807b3428 r7:807b3428 r6:00008001 r5:87bc2d00
[    3.381290]  r4:87b086c0
[    3.389932] [<800c5048>] (mount_fs) from [<800dc2b8>] (vfs_kern_mount+0x50/0xfc)
[    3.409213]  r8:00000000 r7:807b3428 r6:00008001 r5:87bc2d00 r4:87b086c0
[    3.422307] [<800dc268>] (vfs_kern_mount) from [<800def84>] (do_mount+0x19c/0x9b4)
[    3.441758]  r9:00000060 r8:87bc2cc0 r7:87bc2d00 r6:807ab698 r5:00000000 r4:807b3428
[    3.461842] [<800dede8>] (do_mount) from [<800dfad8>] (SyS_mount+0x7c/0xa8)
[    3.475003]  r10:87b9b000 r9:807982e8 r8:00008001 r7:806c98b0 r6:00000000 r5:87bc2d00
[    3.495279]  r4:87bc2cc0
[    3.503823] [<800dfa5c>] (SyS_mount) from [<8076d1f4>] (mount_block_root+0x144/0x270)
[    3.523579]  r8:87de9360 r7:87b9b000 r6:807982d8 r5:87b9b000 r4:00008001
[    3.536745] [<8076d0b0>] (mount_block_root) from [<8076d4e8>] (prepare_namespace+0xb0/0x1a4)
[    3.557450]  r10:807982b4 r9:8076c5ec r8:00000097 r7:807d4500 r6:807d4500 r5:807982e8
[    3.577758]  r4:807982d8
[    3.586342] [<8076d438>] (prepare_namespace) from [<8076ce9c>] (kernel_init_freeable+0x1bc/0x1d0)
[    3.607503]  r5:00000008 r4:807a0c60
[    3.617295] [<8076cce0>] (kernel_init_freeable) from [<805959b0>] (kernel_init+0x18/0xf0)
[    3.637662]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80595998
[    3.658098]  r4:807d4500
[    3.666783] [<80595998>] (kernel_init) from [<8000f668>] (ret_from_fork+0x14/0x2c)
[    3.686456]  r5:80595998 r4:00000000
[    3.698481] List of all partitions:
[    3.707956] No filesystem could mount root, tried:  ubifs
[    3.719340] Kernel panic - not syncing: VFS: Unable to mount root fs on unknown-block(0,0)
[    3.738887] ---[ end Kernel panic - not syncing: VFS: Unable to mount root fs on unknown-block(0,0)

>
> P.s: Why are you writing me privately?
>
> Thanks,
> //richard

Best regards,
Bhuvan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-07-21  6:04                             ` Bhuvanchandra DV
@ 2015-07-21  6:14                               ` Richard Weinberger
  2015-07-22  7:10                                 ` Bhuvanchandra DV
  0 siblings, 1 reply; 34+ messages in thread
From: Richard Weinberger @ 2015-07-21  6:14 UTC (permalink / raw)
  To: Bhuvanchandra DV; +Cc: linux-mtd

Hi!

Am 21.07.2015 um 08:04 schrieb Bhuvanchandra DV:
> Ran the power cut tests with fm_debug enabled, no additional logs are observed.
> After few hundred power cuts U-Boot fails to mount with -22 and kernel fails
> mounting with stack trace when reading the node.

Why U-Boot? Has U-Boot fastmap enabled?

Anyway, we need to sort out what is going on.
As fm_debug does not trigger it could also be a non-fastmap issue.
Did you try your test without fastmap being enabled?

Does your target pass UBI tests too?

> Log:
[...]
> [    2.847326] UBIFS error (ubi0:0 pid 1): ubifs_read_node: bad node type (255 but expected 3)
> [    2.866839] UBIFS error (ubi0:0 pid 1): ubifs_read_node: bad node at LEB 981:70368, LEB mapping status 1
> [    2.887961] Not a node, first 24 bytes:
> [    2.891864] 00000000: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff                          ........................

Hmm, LEB1 is unmapped.
If you disable fastmap, does this target boot as expected?
Or is this a persistent corruption?

Thanks,
//richard

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-07-21  6:14                               ` Richard Weinberger
@ 2015-07-22  7:10                                 ` Bhuvanchandra DV
  2015-07-22  7:20                                   ` Richard Weinberger
  0 siblings, 1 reply; 34+ messages in thread
From: Bhuvanchandra DV @ 2015-07-22  7:10 UTC (permalink / raw)
  To: Richard Weinberger; +Cc: linux-mtd

On 07/21/2015 11:44 AM, Richard Weinberger wrote:

> Hi!
>
> Am 21.07.2015 um 08:04 schrieb Bhuvanchandra DV:
>> Ran the power cut tests with fm_debug enabled, no additional logs are observed.
>> After few hundred power cuts U-Boot fails to mount with -22 and kernel fails
>> mounting with stack trace when reading the node.
> Why U-Boot? Has U-Boot fastmap enabled?

Yes, fastmap is enabled in U-Boot.

The same power cut tests are done by skipping the U-Boot to mount the UBIFS. Loaded
the kernel via tftp and mount the rootfs with kernel. The power cut test passed.
I think U-Boot might have some issues, but not very sure.

>
> Anyway, we need to sort out what is going on.
> As fm_debug does not trigger it could also be a non-fastmap issue.
> Did you try your test without fastmap being enabled?
>
> Does your target pass UBI tests too?

I'm not aware of UBI tests so far the driver passed all MTD tests.
Can you please provide some pointers for UBI tests. Will run the UBI tests with
driver.

>
>> Log:
> [...]
>> [    2.847326] UBIFS error (ubi0:0 pid 1): ubifs_read_node: bad node type (255 but expected 3)
>> [    2.866839] UBIFS error (ubi0:0 pid 1): ubifs_read_node: bad node at LEB 981:70368, LEB mapping status 1
>> [    2.887961] Not a node, first 24 bytes:
>> [    2.891864] 00000000: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff                          ........................
> Hmm, LEB1 is unmapped.
> If you disable fastmap, does this target boot as expected?
> Or is this a persistent corruption?

No, the corruption is persistent.
- removed|fm_autoconvert from kernel args - removed the fastmap support from 
kernel Tested with above both cases, the corruption is persistent. |

> Thanks,
> //richard

Best regards,
Bhuvan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-07-22  7:10                                 ` Bhuvanchandra DV
@ 2015-07-22  7:20                                   ` Richard Weinberger
  2015-07-24 14:43                                     ` Bhuvanchandra DV
  0 siblings, 1 reply; 34+ messages in thread
From: Richard Weinberger @ 2015-07-22  7:20 UTC (permalink / raw)
  To: Bhuvanchandra DV; +Cc: linux-mtd

Am 22.07.2015 um 09:10 schrieb Bhuvanchandra DV:
> On 07/21/2015 11:44 AM, Richard Weinberger wrote:
> 
>> Hi!
>>
>> Am 21.07.2015 um 08:04 schrieb Bhuvanchandra DV:
>>> Ran the power cut tests with fm_debug enabled, no additional logs are observed.
>>> After few hundred power cuts U-Boot fails to mount with -22 and kernel fails
>>> mounting with stack trace when reading the node.
>> Why U-Boot? Has U-Boot fastmap enabled?
> 
> Yes, fastmap is enabled in U-Boot.

Please disable it.

> The same power cut tests are done by skipping the U-Boot to mount the UBIFS. Loaded
> the kernel via tftp and mount the rootfs with kernel. The power cut test passed.
> I think U-Boot might have some issues, but not very sure.

To my knowledge U-Boot's fastmap support is incomplete.
If you *really* need fastmap in U-Boot make sure that they have backported
all recent fastmap changes. Fastmap is still experimental and faced a lot of fixes
recently.

>>
>> Anyway, we need to sort out what is going on.
>> As fm_debug does not trigger it could also be a non-fastmap issue.
>> Did you try your test without fastmap being enabled?
>>
>> Does your target pass UBI tests too?
> 
> I'm not aware of UBI tests so far the driver passed all MTD tests.
> Can you please provide some pointers for UBI tests. Will run the UBI tests with
> driver.

They are in the mtd-utils source.

>>
>>> Log:
>> [...]
>>> [    2.847326] UBIFS error (ubi0:0 pid 1): ubifs_read_node: bad node type (255 but expected 3)
>>> [    2.866839] UBIFS error (ubi0:0 pid 1): ubifs_read_node: bad node at LEB 981:70368, LEB mapping status 1
>>> [    2.887961] Not a node, first 24 bytes:
>>> [    2.891864] 00000000: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff                          ........................
>> Hmm, LEB1 is unmapped.
>> If you disable fastmap, does this target boot as expected?
>> Or is this a persistent corruption?
> 
> No, the corruption is persistent.
> - removed|fm_autoconvert from kernel args - removed the fastmap support from kernel Tested with above both cases, the corruption is persistent. |

Okay that is a clear hint that Linux's fastmap is only the messenger and not the evil doer.

Thanks,
//richard

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-07-22  7:20                                   ` Richard Weinberger
@ 2015-07-24 14:43                                     ` Bhuvanchandra DV
  2015-07-24 16:51                                       ` Richard Weinberger
  0 siblings, 1 reply; 34+ messages in thread
From: Bhuvanchandra DV @ 2015-07-24 14:43 UTC (permalink / raw)
  To: Richard Weinberger; +Cc: linux-mtd

On 07/22/2015 12:50 PM, Richard Weinberger wrote:

> Am 22.07.2015 um 09:10 schrieb Bhuvanchandra DV:
>> On 07/21/2015 11:44 AM, Richard Weinberger wrote:
>>
>>> Hi!
>>>
>>> Am 21.07.2015 um 08:04 schrieb Bhuvanchandra DV:
>>>> Ran the power cut tests with fm_debug enabled, no additional logs are observed.
>>>> After few hundred power cuts U-Boot fails to mount with -22 and kernel fails
>>>> mounting with stack trace when reading the node.
>>> Why U-Boot? Has U-Boot fastmap enabled?
>> Yes, fastmap is enabled in U-Boot.
> Please disable it.

Disabled fastmap in U-Boot, still the corruption is persistent when using
U-Boot to mount rootfs and load kernel.

>> The same power cut tests are done by skipping the U-Boot to mount the UBIFS. Loaded
>> the kernel via tftp and mount the rootfs with kernel. The power cut test passed.
>> I think U-Boot might have some issues, but not very sure.
> To my knowledge U-Boot's fastmap support is incomplete.
> If you *really* need fastmap in U-Boot make sure that they have backported
> all recent fastmap changes. Fastmap is still experimental and faced a lot of fixes
> recently.

Tested with mainline U-Boot along with few downstream patches for boot config block
support applied, the ubifs corruption is persistant.

>
>>> Anyway, we need to sort out what is going on.
>>> As fm_debug does not trigger it could also be a non-fastmap issue.
>>> Did you try your test without fastmap being enabled?
>>>
>>> Does your target pass UBI tests too?
>> I'm not aware of UBI tests so far the driver passed all MTD tests.
>> Can you please provide some pointers for UBI tests. Will run the UBI tests with
>> driver.
> They are in the mtd-utils source.

Not yet ran the ubi-tests. Will run the tests and share the results.

>
>>>> Log:
>>> [...]
>>>> [    2.847326] UBIFS error (ubi0:0 pid 1): ubifs_read_node: bad node type (255 but expected 3)
>>>> [    2.866839] UBIFS error (ubi0:0 pid 1): ubifs_read_node: bad node at LEB 981:70368, LEB mapping status 1
>>>> [    2.887961] Not a node, first 24 bytes:
>>>> [    2.891864] 00000000: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff                          ........................
>>> Hmm, LEB1 is unmapped.
>>> If you disable fastmap, does this target boot as expected?
>>> Or is this a persistent corruption?
>> No, the corruption is persistent.
>> - removed|fm_autoconvert from kernel args - removed the fastmap support from kernel Tested with above both cases, the corruption is persistent. |
> Okay that is a clear hint that Linux's fastmap is only the messenger and not the evil doer.
>
> Thanks,
> //richard

Best regards,

Bhuvan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-07-24 14:43                                     ` Bhuvanchandra DV
@ 2015-07-24 16:51                                       ` Richard Weinberger
  2015-07-31 16:47                                         ` Bhuvanchandra DV
  0 siblings, 1 reply; 34+ messages in thread
From: Richard Weinberger @ 2015-07-24 16:51 UTC (permalink / raw)
  To: Bhuvanchandra DV; +Cc: linux-mtd

Hi!

Am 24.07.2015 um 16:43 schrieb Bhuvanchandra DV:
> Disabled fastmap in U-Boot, still the corruption is persistent when using
> U-Boot to mount rootfs and load kernel.

Can you please describe your boot setup in detail?
Why does U-Boot _mount_ an UBIFS? Install the kernel on an UBI static volume.

If U-Boot mounts UBIFS it has to use UBI in RW mode and therefore it has to process
fastmap or _delete_ it.

>>> The same power cut tests are done by skipping the U-Boot to mount the UBIFS. Loaded
>>> the kernel via tftp and mount the rootfs with kernel. The power cut test passed.
>>> I think U-Boot might have some issues, but not very sure.
>> To my knowledge U-Boot's fastmap support is incomplete.
>> If you *really* need fastmap in U-Boot make sure that they have backported
>> all recent fastmap changes. Fastmap is still experimental and faced a lot of fixes
>> recently.
> 
> Tested with mainline U-Boot along with few downstream patches for boot config block
> support applied, the ubifs corruption is persistant.
> 
>>
>>>> Anyway, we need to sort out what is going on.
>>>> As fm_debug does not trigger it could also be a non-fastmap issue.
>>>> Did you try your test without fastmap being enabled?
>>>>
>>>> Does your target pass UBI tests too?
>>> I'm not aware of UBI tests so far the driver passed all MTD tests.
>>> Can you please provide some pointers for UBI tests. Will run the UBI tests with
>>> driver.
>> They are in the mtd-utils source.
> 
> Not yet ran the ubi-tests. Will run the tests and share the results.

Please do so. :-)

Thanks,
//richard

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-07-24 16:51                                       ` Richard Weinberger
@ 2015-07-31 16:47                                         ` Bhuvanchandra DV
  2015-08-01  6:36                                           ` Richard Weinberger
  2015-09-11  4:03                                           ` Bhuvanchandra
  0 siblings, 2 replies; 34+ messages in thread
From: Bhuvanchandra DV @ 2015-07-31 16:47 UTC (permalink / raw)
  To: Richard Weinberger; +Cc: linux-mtd

On 07/24/2015 06:51 PM, Richard Weinberger wrote:

> Hi!
>
> Am 24.07.2015 um 16:43 schrieb Bhuvanchandra DV:
>> Disabled fastmap in U-Boot, still the corruption is persistent when using
>> U-Boot to mount rootfs and load kernel.
> Can you please describe your boot setup in detail?
> Why does U-Boot _mount_ an UBIFS? Install the kernel on an UBI static volume.

U-Boot mounts UBIFS for loading the kernel and device tree blobs availabel in rootfs.
Since approximately around ~3-5 % of spare blocks are reserverd for wear leveling
(according to the NAND manufacturer). Initially we had a separate UBI partition of 8MB
for Kenrel, but after few times of re-writing the kernel to that volume kernel fails
with no available free space. Due to that reason we made a single big ubi volume and
moved the kernel and device tree blobs to rootfs.

> If U-Boot mounts UBIFS it has to use UBI in RW mode and therefore it has to process
> fastmap or _delete_ it.
>
>>>> The same power cut tests are done by skipping the U-Boot to mount the UBIFS. Loaded
>>>> the kernel via tftp and mount the rootfs with kernel. The power cut test passed.
>>>> I think U-Boot might have some issues, but not very sure.
>>> To my knowledge U-Boot's fastmap support is incomplete.
>>> If you *really* need fastmap in U-Boot make sure that they have backported
>>> all recent fastmap changes. Fastmap is still experimental and faced a lot of fixes
>>> recently.
>> Tested with mainline U-Boot along with few downstream patches for boot config block
>> support applied, the ubifs corruption is persistant.
>>
>>>>> Anyway, we need to sort out what is going on.
>>>>> As fm_debug does not trigger it could also be a non-fastmap issue.
>>>>> Did you try your test without fastmap being enabled?
>>>>>
>>>>> Does your target pass UBI tests too?
>>>> I'm not aware of UBI tests so far the driver passed all MTD tests.
>>>> Can you please provide some pointers for UBI tests. Will run the UBI tests with
>>>> driver.
>>> They are in the mtd-utils source.
>> Not yet ran the ubi-tests. Will run the tests and share the results.
> Please do so. :-)

Seems the mtd-utils are not really cross-compile friendly, some how managed to build the ubi-tests
tweeking the Makefiles.

The tests ran on ubi partition after isolating it from U-Boot completly.
Formatted the ubi partition and then boot with SD card (4.1.2 kernel fastmap enabled/disabled, fm_debug enabled).
Please find the below log of ubi-tests:

root@colibri-vf:~# ubiattach -m 3
[   44.663944] ubi0: default fastmap pool size: 50
[   44.668930] ubi0: default fastmap WL pool size: 25
[   44.674045] ubi0: attaching mtd3
[   44.995279] ubi0: scanning is finished
[   44.999364] ubi0: empty MTD device detected
[   45.033211] ubi0: attached mtd3 (name "ubi", size 126 MiB)
[   45.039205] ubi0: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
[   45.046572] ubi0: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
[   45.053715] ubi0: VID header offset: 2048 (aligned 2048), data offset: 4096
[   45.061141] ubi0: good PEBs: 1003, bad PEBs: 5, corrupted PEBs: 0
[   45.067951] ubi0: user volume: 0, internal volumes: 1, max. volumes count: 128
[   45.075701] ubi0: max/mean erase counter: 0/0, WL threshold: 4096, image sequence number: 595808446
[   45.085278] ubi0: available PEBs: 982, total reserved PEBs: 21, PEBs reserved for bad PEB handling: 15
[   45.101889] ubi0: background thread "ubi_bgt0d" started, PID 337
UBI device number 0, total 1003 LEBs (127356928 bytes, 121.5 MiB), available 982 LEBs (124690432 bytes, 118.9 MiB), LEB size 126976 bytes (124.0 KiB)
root@colibri-vf:~# cd ubi-tests-bin/
root@colibri-vf:~/ubi-tests-bin# ./runtests.sh /dev/ubi0 - test /dev/ubi0
Running mkvol_basic /dev/ubi0
Running mkvol_bad /dev/ubi0
[   99.630756] ubi0 error: verify_mkvol_req: bad volume creation request
[   99.637579] Volume creation request dump:
[   99.641987]  vol_id    -2
[   99.644784]  alignment 1
[   99.647466]  bytes     124690432
[   99.650994]  vol_type  3
[   99.653696]  name_len  22
[   99.656464]  1st 16 characters of name: mkvol_bad:test_m
[   99.669464] ubi0 error: verify_mkvol_req: bad volume creation request
[   99.676292] Volume creation request dump:
[   99.680674]  vol_id    128
[   99.683558]  alignment 1
[   99.686240]  bytes     124690432
[   99.694911]  vol_type  3
[   99.702852]  name_len  22
[   99.710786]  1st 16 characters of name: mkvol_bad:test_m
[   99.728668] ubi0 error: verify_mkvol_req: bad volume creation request
[   99.740962] Volume creation request dump:
[   99.750630]  vol_id    0
[   99.758537]  alignment 0
[   99.766352]  bytes     124690432
[   99.774804]  vol_type  3
[   99.782409]  name_len  22
[   99.789923]  1st 16 characters of name: mkvol_bad:test_m
[   99.808480] ubi0 error: verify_mkvol_req: bad volume creation request
[   99.820028] Volume creation request dump:
[   99.828796]  vol_id    0
[   99.835879]  alignment -1
[   99.842859]  bytes     124690432
[   99.850335]  vol_type  3
[   99.856849]  name_len  22
[   99.863395]  1st 16 characters of name: mkvol_bad:test_m
[   99.880157] ubi0 error: verify_mkvol_req: bad volume creation request
[   99.891064] Volume creation request dump:
[   99.899440]  vol_id    0
[   99.906182]  alignment 126977
[   99.913456]  bytes     124690432
[   99.920926]  vol_type  3
[   99.927467]  name_len  22
[   99.934058]  1st 16 characters of name: mkvol_bad:test_m
[   99.950732] ubi0 error: verify_mkvol_req: bad volume creation request
[   99.961655] Volume creation request dump:
[   99.970057]  vol_id    0
[   99.976826]  alignment 2049
[   99.983931]  bytes     124690432
[   99.991412]  vol_type  3
[   99.997959]  name_len  22
[  100.004551]  1st 16 characters of name: mkvol_bad:test_m
[  100.021254] ubi0 error: verify_mkvol_req: bad volume creation request
[  100.032201] Volume creation request dump:
[  100.040649]  vol_id    0
[  100.047441]  alignment 1
[  100.054334]  bytes     -1
[  100.061191]  vol_type  3
[  100.067708]  name_len  22
[  100.074250]  1st 16 characters of name: mkvol_bad:test_m
[  100.090929] ubi0 error: verify_mkvol_req: bad volume creation request
[  100.101834] Volume creation request dump:
[  100.110223]  vol_id    0
[  100.116969]  alignment 1
[  100.123783]  bytes     0
[  100.130505]  vol_type  3
[  100.136980]  name_len  22
[  100.143502]  1st 16 characters of name: mkvol_bad:test_m
[  100.160274] ubi0 error: ubi_create_volume: not enough PEBs, only 982 available
[  100.175970] ubi0 error: ubi_create_volume: cannot create volume 0, error -28
[  100.189501] ubi0 error: ubi_create_volume: not enough PEBs, only 982 available
[  100.205998] ubi0 error: ubi_create_volume: cannot create volume 0, error -28
[  100.222091] ubi0 error: verify_mkvol_req: bad volume creation request
[  100.233529] Volume creation request dump:
[  100.242409]  vol_id    0
[  100.249771]  alignment 1
[  100.256993]  bytes     126976
[  100.264716]  vol_type  7
[  100.272035]  name_len  22
[  100.279316]  1st 16 characters of name: mkvol_bad:test_m
[  100.416661] ubi0 error: ubi_create_volume: volume 0 already exists
[  100.427776] ubi0 error: ubi_create_volume: cannot create volume 0, error -17
[  100.441410] ubi0 error: ubi_create_volume: volume "mkvol_bad:test_mkvol()" exists (ID 0)
[  100.459295] ubi0 error: ubi_create_volume: cannot create volume 1, error -17
[  100.711027] ubi0 error: ubi_create_volume: volume "mkvol_bad:test_mkvol()" exists (ID 0)
[  100.729733] ubi0 error: ubi_create_volume: cannot create volume 1, error -17
[  131.225291] ubi0 error: ubi_open_volume: cannot open device 0, volume 128, error -22
[  131.244295] ubi0 error: ubi_open_volume: cannot open device 0, volume -1, error -22
[  131.269510] ubi0 error: ubi_open_volume: cannot open device 0, volume 128, error -22
[  131.290092] ubi0 error: ubi_open_volume: cannot open device 0, volume 0, error -19
[  131.551660] ubi0 error: ubi_open_volume: cannot open device 0, volume 0, error -19
Running mkvol_paral /dev/ubi0
Running rsvol /dev/ubi0
Running io_basic /dev/ubi0
Running io_read /dev/ubi0
Running io_update /dev/ubi0
Running io_paral /dev/ubi0
[io_paral] write_thread():222: written and read data are different
Running volrefcnt /dev/ubi0
SUCCESS
root@colibri-vf:~/ubi-tests-bin#

>
> Thanks,
> //richard

Best regards,
Bhuvan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-07-31 16:47                                         ` Bhuvanchandra DV
@ 2015-08-01  6:36                                           ` Richard Weinberger
  2015-08-06 10:31                                             ` Bhuvanchandra DV
  2015-09-11  4:03                                           ` Bhuvanchandra
  1 sibling, 1 reply; 34+ messages in thread
From: Richard Weinberger @ 2015-08-01  6:36 UTC (permalink / raw)
  To: Bhuvanchandra DV; +Cc: linux-mtd

Am 31.07.2015 um 18:47 schrieb Bhuvanchandra DV:
> On 07/24/2015 06:51 PM, Richard Weinberger wrote:
> 
>> Hi!
>>
>> Am 24.07.2015 um 16:43 schrieb Bhuvanchandra DV:
>>> Disabled fastmap in U-Boot, still the corruption is persistent when using
>>> U-Boot to mount rootfs and load kernel.
>> Can you please describe your boot setup in detail?
>> Why does U-Boot _mount_ an UBIFS? Install the kernel on an UBI static volume.
> 
> U-Boot mounts UBIFS for loading the kernel and device tree blobs availabel in rootfs.
> Since approximately around ~3-5 % of spare blocks are reserverd for wear leveling
> (according to the NAND manufacturer). Initially we had a separate UBI partition of 8MB
> for Kenrel, but after few times of re-writing the kernel to that volume kernel fails
> with no available free space. Due to that reason we made a single big ubi volume and
> moved the kernel and device tree blobs to rootfs.

UBI partition? You mean UBI volume?
Just install kernel, initrd and dtb on UBI static volumes.

If U-Boot has to mount UBIFS it has to do that in RW mode.
So, no fastmap for you.

> Seems the mtd-utils are not really cross-compile friendly, some how managed to build the ubi-tests
> tweeking the Makefiles.

Seeing forward to receive patches or at least a bug report.

> The tests ran on ubi partition after isolating it from U-Boot completly.
> Formatted the ubi partition and then boot with SD card (4.1.2 kernel fastmap enabled/disabled, fm_debug enabled).
> Please find the below log of ubi-tests:
> 

> [io_paral] write_thread():222: written and read data are different

*blink*

Thanks,
//richard

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-08-01  6:36                                           ` Richard Weinberger
@ 2015-08-06 10:31                                             ` Bhuvanchandra DV
  2015-08-07 12:37                                               ` Richard Weinberger
  0 siblings, 1 reply; 34+ messages in thread
From: Bhuvanchandra DV @ 2015-08-06 10:31 UTC (permalink / raw)
  To: Richard Weinberger; +Cc: linux-mtd

Hi Richard,

On 08/01/2015 08:36 AM, Richard Weinberger wrote:

> Am 31.07.2015 um 18:47 schrieb Bhuvanchandra DV:
>> On 07/24/2015 06:51 PM, Richard Weinberger wrote:
>>
>>> Hi!
>>>
>>> Am 24.07.2015 um 16:43 schrieb Bhuvanchandra DV:
>>>> Disabled fastmap in U-Boot, still the corruption is persistent when using
>>>> U-Boot to mount rootfs and load kernel.
>>> Can you please describe your boot setup in detail?
>>> Why does U-Boot _mount_ an UBIFS? Install the kernel on an UBI static volume.
>> U-Boot mounts UBIFS for loading the kernel and device tree blobs availabel in rootfs.
>> Since approximately around ~3-5 % of spare blocks are reserverd for wear leveling
>> (according to the NAND manufacturer). Initially we had a separate UBI partition of 8MB
>> for Kenrel, but after few times of re-writing the kernel to that volume kernel fails
>> with no available free space. Due to that reason we made a single big ubi volume and
>> moved the kernel and device tree blobs to rootfs.
> UBI partition? You mean UBI volume?

Sorry, UBI volume.

> Just install kernel, initrd and dtb on UBI static volumes.
>
> If U-Boot has to mount UBIFS it has to do that in RW mode.
> So, no fastmap for you.

Okay

>> Seems the mtd-utils are not really cross-compile friendly, some how managed to build the ubi-tests
>> tweeking the Makefiles.
> Seeing forward to receive patches or at least a bug report.

Sure will do it.

>
>> The tests ran on ubi partition after isolating it from U-Boot completly.
>> Formatted the ubi partition and then boot with SD card (4.1.2 kernel fastmap enabled/disabled, fm_debug enabled).
>> Please find the below log of ubi-tests:
>>
>> [io_paral] write_thread():222: written and read data are different
> *blink*

Tried to run the io_paral test multiple times seperately with few debug prints added to see what exact
differences with read and write buffers, so far we could see one complete page is read twice even though
it is written once. I'm now confused is the issue happen while reading or while writing. Can you give us
some pointers so that we can narrow down the cause for this failure.

>
> Thanks,
> //richard

Best regards,
Bhuvan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-08-06 10:31                                             ` Bhuvanchandra DV
@ 2015-08-07 12:37                                               ` Richard Weinberger
  2015-08-12  7:01                                                 ` Stefan Agner
  0 siblings, 1 reply; 34+ messages in thread
From: Richard Weinberger @ 2015-08-07 12:37 UTC (permalink / raw)
  To: Bhuvanchandra DV; +Cc: linux-mtd

Hi!

Am 06.08.2015 um 12:31 schrieb Bhuvanchandra DV:
>>> The tests ran on ubi partition after isolating it from U-Boot completly.
>>> Formatted the ubi partition and then boot with SD card (4.1.2 kernel fastmap enabled/disabled, fm_debug enabled).
>>> Please find the below log of ubi-tests:
>>>
>>> [io_paral] write_thread():222: written and read data are different
>> *blink*
> 
> Tried to run the io_paral test multiple times seperately with few debug prints added to see what exact
> differences with read and write buffers, so far we could see one complete page is read twice even though
> it is written once. I'm now confused is the issue happen while reading or while writing. Can you give us
> some pointers so that we can narrow down the cause for this failure.

The test verifies that the data has been written correctly to the block.
(Maybe a buffer problem in your MTD driver?)

You can also enable UBI's IO checks.
i.e. echo 1 > /sys/kernel/debug/ubi/ubi0/chk_io

It will also verify it's writes. Maybe it can give you a clue.

Thanks,
//richard

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-08-07 12:37                                               ` Richard Weinberger
@ 2015-08-12  7:01                                                 ` Stefan Agner
  2015-08-12  7:27                                                   ` Richard Weinberger
  0 siblings, 1 reply; 34+ messages in thread
From: Stefan Agner @ 2015-08-12  7:01 UTC (permalink / raw)
  To: Richard Weinberger, computersforpeace; +Cc: Bhuvanchandra DV, linux-mtd

Hi Richard,

[also added Brian to the discussion, since he had a look into that
driver before]

On 2015-08-07 14:37, Richard Weinberger wrote:
> Hi!
> 
> Am 06.08.2015 um 12:31 schrieb Bhuvanchandra DV:
>>>> The tests ran on ubi partition after isolating it from U-Boot completly.
>>>> Formatted the ubi partition and then boot with SD card (4.1.2 kernel fastmap enabled/disabled, fm_debug enabled).
>>>> Please find the below log of ubi-tests:
>>>>
>>>> [io_paral] write_thread():222: written and read data are different
>>> *blink*
>>
>> Tried to run the io_paral test multiple times seperately with few debug prints added to see what exact
>> differences with read and write buffers, so far we could see one complete page is read twice even though
>> it is written once. I'm now confused is the issue happen while reading or while writing. Can you give us
>> some pointers so that we can narrow down the cause for this failure.
> 
> The test verifies that the data has been written correctly to the block.
> (Maybe a buffer problem in your MTD driver?)
> 
> You can also enable UBI's IO checks.
> i.e. echo 1 > /sys/kernel/debug/ubi/ubi0/chk_io
> 
> It will also verify it's writes. Maybe it can give you a clue.

According to Bhuvan's test, it really seems that we have an issue on
write path (this error is reproduceable):
root@colibri-vf:~/ubi-tests-bin# ./io_paral /dev/ubi0 2>&1 | tee
~/io-parl4.log
[ 6451.223087] ubi0 error: self_check_write: self-check failed for PEB
843:4096, len 126976
[ 6451.231650] ubi0: data differ at position 61440
[ 6451.236325] ubi0: hex dump of the original buffer from 61440 to
126976
[ 6451.331045] ubi0: hex dump of the read buffer from 61440 to 126976
[ 6451.426703] CPU: 0 PID: 1182 Comm: io_paral Not tainted
4.1.4-00704-g2631972 #21
[ 6451.434506] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)

This 4.1.4 with v10 of the driver applied:
http://thread.gmane.org/gmane.linux.drivers.devicetree/130300


I worked on the driver since quite some time, currently v10 is in
review. With this issue in mind, I went through the driver however I
currently can't see an issue.

The error position is always page aligned, but at different pages. We
printed the reread buffers once: It seems that one page lands on flash
twice. My guess is that the second page doesn't get transmitted
properly, while the new column/row gets transmitted and
NAND_CMD_PAGEPROG executed... Hence the same buffer would be written to
the device again.

The NFC IP in Vybrid (vf610) has a higher level programming model which
takes care of the command sequencing. Therefore some callbacks are not
actually sending a command to the device (e.g. NAND_CMD_SEQIN) since
this will be done one command later, on in NAND_CMD_PAGEPROG. Now, of
course, the driver relies heavily on not being interrupted by other
requests in between, (also not read!) but I thought that this is taken
care of by the MTD subsystem? So for me it is a bit hard to spot the
error since I'm always unsure whether the assumptions regarding
locking/exclusiveness between the calls is really guaranteed...

--
Stefan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-08-12  7:01                                                 ` Stefan Agner
@ 2015-08-12  7:27                                                   ` Richard Weinberger
  2015-09-01  0:45                                                     ` Stefan Agner
  0 siblings, 1 reply; 34+ messages in thread
From: Richard Weinberger @ 2015-08-12  7:27 UTC (permalink / raw)
  To: Stefan Agner, computersforpeace; +Cc: Bhuvanchandra DV, linux-mtd

Stefan,

Am 12.08.2015 um 09:01 schrieb Stefan Agner:
> Hi Richard,
> 
> [also added Brian to the discussion, since he had a look into that
> driver before]

Good idea, maybe Brian has an idea.

> On 2015-08-07 14:37, Richard Weinberger wrote:
>> Hi!
>>
>> Am 06.08.2015 um 12:31 schrieb Bhuvanchandra DV:
>>>>> The tests ran on ubi partition after isolating it from U-Boot completly.
>>>>> Formatted the ubi partition and then boot with SD card (4.1.2 kernel fastmap enabled/disabled, fm_debug enabled).
>>>>> Please find the below log of ubi-tests:
>>>>>
>>>>> [io_paral] write_thread():222: written and read data are different
>>>> *blink*
>>>
>>> Tried to run the io_paral test multiple times seperately with few debug prints added to see what exact
>>> differences with read and write buffers, so far we could see one complete page is read twice even though
>>> it is written once. I'm now confused is the issue happen while reading or while writing. Can you give us
>>> some pointers so that we can narrow down the cause for this failure.
>>
>> The test verifies that the data has been written correctly to the block.
>> (Maybe a buffer problem in your MTD driver?)
>>
>> You can also enable UBI's IO checks.
>> i.e. echo 1 > /sys/kernel/debug/ubi/ubi0/chk_io
>>
>> It will also verify it's writes. Maybe it can give you a clue.
> 
> According to Bhuvan's test, it really seems that we have an issue on
> write path (this error is reproduceable):
> root@colibri-vf:~/ubi-tests-bin# ./io_paral /dev/ubi0 2>&1 | tee
> ~/io-parl4.log
> [ 6451.223087] ubi0 error: self_check_write: self-check failed for PEB
> 843:4096, len 126976
> [ 6451.231650] ubi0: data differ at position 61440
> [ 6451.236325] ubi0: hex dump of the original buffer from 61440 to
> 126976
> [ 6451.331045] ubi0: hex dump of the read buffer from 61440 to 126976
> [ 6451.426703] CPU: 0 PID: 1182 Comm: io_paral Not tainted
> 4.1.4-00704-g2631972 #21
> [ 6451.434506] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)

Thanks for letting me know. :)

> This 4.1.4 with v10 of the driver applied:
> http://thread.gmane.org/gmane.linux.drivers.devicetree/130300
> 
> 
> I worked on the driver since quite some time, currently v10 is in
> review. With this issue in mind, I went through the driver however I
> currently can't see an issue.
> 
> The error position is always page aligned, but at different pages. We
> printed the reread buffers once: It seems that one page lands on flash
> twice. My guess is that the second page doesn't get transmitted
> properly, while the new column/row gets transmitted and
> NAND_CMD_PAGEPROG executed... Hence the same buffer would be written to
> the device again.
> 
> The NFC IP in Vybrid (vf610) has a higher level programming model which
> takes care of the command sequencing. Therefore some callbacks are not
> actually sending a command to the device (e.g. NAND_CMD_SEQIN) since
> this will be done one command later, on in NAND_CMD_PAGEPROG. Now, of
> course, the driver relies heavily on not being interrupted by other
> requests in between, (also not read!) but I thought that this is taken
> care of by the MTD subsystem? So for me it is a bit hard to spot the
> error since I'm always unsure whether the assumptions regarding
> locking/exclusiveness between the calls is really guaranteed...

NAND access is serialized using nand_get_device() and nand_release_device()
in nand_base.c, so serialization should be fine.

HTH,
//richard

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-08-12  7:27                                                   ` Richard Weinberger
@ 2015-09-01  0:45                                                     ` Stefan Agner
  2015-09-01  1:43                                                       ` Brian Norris
  0 siblings, 1 reply; 34+ messages in thread
From: Stefan Agner @ 2015-09-01  0:45 UTC (permalink / raw)
  To: Richard Weinberger, computersforpeace; +Cc: Bhuvanchandra DV, linux-mtd

Hi Brian, Hi Richard,

On 2015-08-12 00:27, Richard Weinberger wrote:
> Stefan,
> 
> Am 12.08.2015 um 09:01 schrieb Stefan Agner:
>> Hi Richard,
>>
>> [also added Brian to the discussion, since he had a look into that
>> driver before]
> 
> Good idea, maybe Brian has an idea.
> 
<snip>
>> I worked on the driver since quite some time, currently v10 is in
>> review. With this issue in mind, I went through the driver however I
>> currently can't see an issue.
>>
>> The error position is always page aligned, but at different pages. We
>> printed the reread buffers once: It seems that one page lands on flash
>> twice. My guess is that the second page doesn't get transmitted
>> properly, while the new column/row gets transmitted and
>> NAND_CMD_PAGEPROG executed... Hence the same buffer would be written to
>> the device again.
>>
>> The NFC IP in Vybrid (vf610) has a higher level programming model which
>> takes care of the command sequencing. Therefore some callbacks are not
>> actually sending a command to the device (e.g. NAND_CMD_SEQIN) since
>> this will be done one command later, on in NAND_CMD_PAGEPROG. Now, of
>> course, the driver relies heavily on not being interrupted by other
>> requests in between, (also not read!) but I thought that this is taken
>> care of by the MTD subsystem? So for me it is a bit hard to spot the
>> error since I'm always unsure whether the assumptions regarding
>> locking/exclusiveness between the calls is really guaranteed...
> 
> NAND access is serialized using nand_get_device() and nand_release_device()
> in nand_base.c, so serialization should be fine.

I did some more testing with v11 of this driver, and it seems when I
continuously reset the system, I get read errors from time to time. The
read errors end up in various errors, I have seen ubifs_read_node: bad
node type or ubifs_tnc_read_node: bad key in node. However, particularly
often and interesting are ubifs_decompress: cannot decompress errors,
such as this one. It seems that same page is read twice (or has been
written twice, see data pattern at offset 0x00000000 and 0x00000800).

[   13.929731] using random host ethernet address
[   13.945658] UBIFS error (ubi0:0 pid 139): ubifs_decompress: cannot
decompress 3347 bytes, compressor lzo, error -22
[   13.966268] UBIFS error (ubi0:0 pid 139): read_block: bad data node
(block 35, inode 3485)
[   13.984795]  magic          0x6101831
[   13.993549]  crc            0xecfdbd78
[   14.002194]  node_type      1 (data node)
[   14.011041]  group_type     0 (no node group)
[   14.020268]  sqnum          19753
[   14.028382]  len            3395
[   14.036360]  key            (3485, data, 35)
[   14.045398]  size           4096
[   14.053239]  compr_typ      1
[   14.060847]  data size      3347
[   14.068649]  data:
[   14.075012]  00000000: 4e 4a 20 38 46 22 49 c2 f3 07 23 43 ea 02 22
79 44 92 b2 fc f7 c9 ff 00 28 cd d0 41 46 38 46 04
[   14.094736]  00000020: f0 61 fb 00 28 c7 d0 01 20 d7 e7 0d f1 4a 01
20 46 fc f7 42 fe 17 49 38 46 79 44 fc f7 3b 5f 04
[   14.114594]  00000040: b9 d0 21 9d 04 4d 5c 04 00 0b b3 d0 ea e7 06
ac 28 46 2e 23 13 a9 22 46 de f7 c8 ef 00 28 a9 d0
[   14.134439]  00000060: bd f8 4a 50 22 46 0b 4d 06 c5 96 0c 05 23 0d
0e 9b 55 0c 96 54 07 00 01 9a d0 d1 e7 00 bf ea 18
[   14.154374]  00000080: 01 00 ec 05 01 00 aa 11 01 00 3e 4d 01 70 4e
01 b8 17 0c 00 00 13 10 b5 18 20 fc f7 02 fc 04 46
[   14.174888]  000000a0: 48 b1 00 21 de f7 b8 ef 0b 38 01 28 20 46 00
d9 10 bd fc f7 00 fc 00 20 10 bd 70 4e 04 82 b0 06
[   14.195415]  000000c0: 03 ef fb 04 09 02 b8 b1 01 ad 28 5c 0e 01 aa
ef 01 21 7c 00 02 ac ef 29 46 20 5c 00 00 03 9c ef
[   14.216087]  000000e0: 06 46 28 46 0b 3e de f7 a8 ef 01 2e 20 46 01
d9 02 b0 70 45 08 df 0e 2c 20 f9 5f 0f 10 b5 04 56
[   14.237440]  00000100: 04 a0 ef 04 06 05 bd e8 10 40 fc f7 d3 bb ed
02 96 27 4d 00 c9 4c 02 05 0a f0 b2 bb 0a f0 b0 bb
[   14.259392]  00000120: ff 00 70 b5 30 8d 0f b1 4d 0f e0 cc 0f 07 84
ef 0d 4b 7b 44 1b 68 6b b9 ad 0f 82 27 ed 01 82 8d
[   14.282059]  00000140: 0f 06 8c 0f bc 13 04 80 ef ec e7 fc f7 9c 54
10 01 f4 e7 8c 5a 7c 1d 6d 0e 7a 27 cd 01 8f 8c 0e
[   14.305453]  00000160: 00 0b 80 bb 28 4b 2d e9 f0 43 7b 44 0d 46 85
b0 19 68 04 46 17 46 00 29 3f d0 02 ae 01 20 31 5c
[   14.329611]  00000180: 05 00 0c e8 ed 03 9b 44 f6 d3 50 02 9a c1 f2
62 00 83 fb 00 01 db 17 00 92 c3 eb a1 1c cd f8 04
[   14.354038]  000001a0: c0 47 03 58 f9 17 44 03 00 0f 08 4f f4 7a 70
87 fb 08 89 4f f4 4a 4e c3 f6 9a 3e c1 eb a9 13 99
[   14.378463]  000001c0: 18 02 91 00 fb 13 73 00 fb 03 c3 4c 00 00 07
f3 73 45 03 93 07 dd 4f f4 4e 50 30 bd 0e 02 42 e9
[   14.402888]  000001e0: 6c bf 03 d8 fc 05 4a 06 49 74 b3 01 79 44 00
90 77 12 89 fe 00 85 04 46 5d 0a b8 4c 6f 06 30 b5
[   14.427312]  00000200: a3 b0 02 ac 80 23 1a 6d bc 21 05 11 01 56 a1
5a e9 0d 8e 28 05 02 aa 5d 39 ea 04 73 07 a9 bf bd
[   14.451740]  00000220: f8 08 00 00 20 01 38 6e 0e a8 bf 05 1d 23 5e
07 2d 48 77 fb 78 44 c7 0f 70 f7 da ea 0c 69 09 00
[   14.476159]  00000240: 28 3e d0 02 af 01 ae 0d f1 0c 0a 4d f5 09 0d
36 51 55 64 c7 0d 99 90 4d 44 ea 0c 16 00 07 48 bb
[   14.500578]  00000260: 34 68 3c b3 e3 7a 2e 2b f1 d0 df f7 f2 e8 0a
22 39 46 83 46 05 60 04 4c 19 4e ff ea db 05 0a 30
[   14.524997]  00000280: 6c a6 00 09 e2 d1 3b 68 00 2b df d0 1b 78 00
33 18 bf 01 23 02 28 d8 bf 43 f0 01 03 00 2b d5 5c
[   14.549417]  000002a0: c6 66 78 84 42 05 29 cf 4c 08 01 e2 e8 cc e7
66 02 b2 ea b5 c8 04 45 7f 0a 04 1a 06 1e 09 db 03
[   14.573840]  000002c0: 2d f5 dd 03 24 4d 19 34 4c 0f 04 e8 ac 42 f9
db ed e7 5e 66 65 f4 5e 29 12 1d ef 4f 02 ac 88 46
[   14.598270]  000002e0: 61 07 46 0d 9f 23 94 87 7e 3a 45 4d 56 1f ea
7d 0f 4a 28 10 db 04 02 06 8c ea 04 1e 3a db 54 d0
[   14.622702]  00000300: 03 47 fe ac e8 31 04 e6 44 78 04 87 f8 58 b3
02 98 05 de 89 8e e8 28 3d 11 10 5f 89 8c fd 04 6d
[   14.647120]  00000320: c2 00 04 5e 02 1b fc 33 4a 21 84 ce 7e 51 ce
fd 76 70 e3 e7 0d 1b 23 c5 83 28 46 2b 4f db 04 12
[   14.671542]  00000340: 02 fe f7 a6 fe 03 54 00 02 a3 fe c6 e7 02 5e
0c 78 e8 65 05 ce 4e b3 60 e8 5c 21 4e 8e 62 fd 4c
[   14.695969]  00000360: 7f 4f 39 f2 fb 1f 45 ee 3b 4e 0a 00 90 6e 0a
a4 fd 7e 05 60 e8 75 13 5c 95 06 b3 86 08 56 e8 0c
[   14.720402]  00000380: 1d 6e 02 32 ea 04 1b 7e 00 2e ea 04 01 0b 01
28 01 d9 df f7 4a e8 ff f7 23 ff 41 46 7c c9 09 2a
[   14.744829]  000003a0: ea 0d 4b eb 58 1c 68 df f7 2c e8 64 45 02 c3
fb 0a 49 3a 4d 54 03 86 49 b2 e8 7e a8 aa e8 6c 19
[   14.769250]  000003c0: 09 93 e7 74 5a 01 00 02 1c 01 00 d2 1b bd af
96 5d 00 1e 44 7c 03 5a 68 0a b1 98 68 46 53 b5 87
[   14.793675]  000003e0: 07 53 aa 01 a9 0c ad 02 df f7 04 ea d8 4d ff
06 06 37 90 02 45 3f 08 0d 1e 90 22 d7 2a 38 e9 01
[   14.818112]  00000400: 94 01 03 04 90 11 4b 01 20 5d b2 99 04 0f 04
8a 42 58 60 0d d0 0e 5f 08 98 60 07 23 c4 28 07 05
[   14.842540]  00000420: aa 04 a9 03 a8 df f7 fa e9 46 8a d0 db 04 33
05 9b 9a 42 ee d1 03 9a 04 5c 00 03 ea d1 05 9b d0
[   14.866968]  00000440: 1a 44 42 02 20 e5 e7 8a 60 4c 88 4e 00 42 60
8e 39 4f dd 5d c0 16 21 cc 2a 08 b5 ff c2 4d 7d 44
[   14.891389]  00000460: 04 46 60 bb c1 54 91 0d 01 f0 27 fb 08 b1 03
78 53 b9 be 4a 30 46 be 49 6c 60 04 f0 f7 85 fc 20
[   14.915812]  00000480: 46 5d 9c 45 01 0d f1 38 08 22 25 22 3c 07 1e
46 f8 b1 04 02 00 06 fb f7 bd ff 04 46 18 bb b5 4b
[   14.940236]  000004a0: 30 46 b5 49 eb 58 79 44 1a 68 f0 f7 6d fc 6e
04 4e f8 f5 06 af 4c 09 01 af 49 00 24 b5 09 5e 27
[   14.964667]  000004c0: 35 01 a7 55 06 aa 27 d4 00 00 01 52 fc cb e7
a8 4c 0c ab 04 93 0d f1 28 09 03 93 7c 44 d8 5c 5b
[   14.989089]  000004e0: 0b 0d f1 70 0b 94 e8 03 00 0d f1 58 0a a1 4a
05 a9 93 07 36 7a 44 89 44 02 02 df f8 7c e2 83 5c
[   15.013520]  00000500: 00 00 05 58 46 06 9b fe 44 df f8 70 c2 9c 49
fc 44 ca f8 04 e0 ca f8 08 30 79 44 01 0c 0c c0 07
[   15.037952]  00000520: 92 ca f8 00 20 3c aa ca f8 10 10 05 4e 01 14
40 04 4a 02 6a e9 11 21 58 57 2e 6c e9 59 0d d2 9a
[   15.062376]  00000540: 64 37 05 6e e9 7b 68 48 46 04 93 67 01 a0 42
74 0d c2 98 74 04 54 73 5c 59 0d 24 e9 b0 f1 00 0b
[   15.086789]  00000560: c0 f2 cb 80 7b d1 85 48 02 21 64 b6 05 06 e8
41 1c 04 46 2c d0 65 3d de 0c 69 07 ef 03 9d 28 68
[   15.111200]  00000580: de f7 34 ef 20 54 81 44 8a 01 e9 01 30 1e 4f
03 04 00 01 55 01 0a 54 01 02 17 d0 68 68 02 4d 01
[   15.135616]  000005a0: 04 4c 01 02 11 d0 75 4c ff 5e b1 05 99 07 b4
7c 44 02 47 46 2e e9 51 9d 47 36 5f 00 04 f1 09 45
[   15.160036]  000005c0: 7b f6 44 49 06 de f7 84 ef de f7 f8 ee 05 9e
59 fa fb 0d dc 28 44 4e 05 8a fa 66 4a 39 46 07 9b
[   15.184456]  000005e0: fe 59 3c fc 7c 08 76 08 0c e9 75 11 45 05 9c
d0 06 0d f0 ee 75 0f 41 8c 01 04 ea ee 03 9b 18 68
[   15.208856]  00000600: 42 8d 01 e4 4c 01 0e 58 68 43 1c 3f f4 2f af
de f7 dc ee 2b e7 de f7 c8 c5 0c c9 c7 0c 59 fa 4f
[   15.233260]  00000620: 2b 87 01 0b fc cd 55 ef 04 5d 1c c4 06 0f 9c
60 5e 1c c0 ee 5e 66 33 c9 0f 04 30 63 60 46 84 62
[   15.257677]  00000640: 39 d4 77 21 44 36 00 03 28 f6 dc 09 ac 04 e0
de f7 9c ee 03 68 04 2b 06 d1 00 22 21 46 6d 2d ce
[   15.282095]  00000660: 04 34 00 04 30 f3 d0 23 68 5a 06 04 d1 c3 f3
07 23 01 24 00 2b a1 d0 12 ac 20 5c c8 03 16 ff 78
[   15.306514]  00000680: b3 03 9d 65 09 21 85 10 ac 5c 08 01 f7 dc 04
99 77 f4 00 f8 63 44 9b 0c 28 dd 21 68 30 46 2a 4b
[   15.330933]  000006a0: 2a 4a 00 91 7b 44 2a d6 52 be fb 05 83 7f 45
18 66 c5 18 68 c7 18 f8 f9 22 2b 04 03 02 aa fb 6c
[   15.355353]  000006c0: e7 0d 45 4d 1e 27 a4 09 02 1d fb e1 e7 1b 44
02 03 1b 4a 1c 49 7b 44 b4 09 06 97 fb d7 e7 b8 58
[   15.379770]  000006e0: 01 00 14 5d 74 0a 4e 00 3c cc 0d 34 c0 5e 76
66 ad 0e 01 90 1a 21 4d 26 cb 5c be 4e 01 92 49 0d
[   15.404184]  00000700: 02 b4 5d 01 ba 4d 00 c2 4d 00 c8 4d 00 a8 4e
00 ec 19 0d 00 fa 4d 00 98 4e 00 b8 18 0d 00 30 5d
[   15.428592]  00000720: 00 22 5e 05 de 17 0e 01 c6 aa 0d 01 68 4d 02
1a 4f 02 d4 ac 00 7e 6f 41 b2 9c 6f 00 15 12 a9 01
[   15.453004]  00000740: aa 80 23 01 93 de f7 ae ef 04 46 28 bb bd f8
48 50 02 2d 6e d0 0a 2d 34 d0 01 2d 0c d0 16 20 01
[   15.477423]  00000760: f0 fc fa 40 23 fc 24 6d 19 44 21 85 2e 32 6f
67 81 9d f8 01 d5 02 0f 12 2b 45 d1 04 c6 58 83 5c
[   15.501854]  00000780: 28 02 88 fe 37 49 38 54 91 09 fc f7 81 ff 00
28 45 d1 de f7 da ed b6 a1 db fa b7 a1 6b f9 30 54
[   15.526284]  000007a0: a1 fd ab 1e 0d 4f 20 ad 09 06 21 1f 25 08 08
21 4c cf 02 fc f7 65 fe 22 5c d8 0b 2e 23 14 a9 de
[   15.550708]  000007c0: f7 fa ef 00 28 db d0 bd f8 11 00 00 ff ff ff
ff 31 18 10 06 78 bd fd ec 29 4d 00 00 00 00 00 00
[   15.575161]  000007e0: 43 0d 00 00 01 00 00 00 9d 0d 00 00 23 00 00
20 00 00 00 00 00 00 00 00 00 10 00 00 01 00 00 00
[   15.599574]  00000800: 4e 4a 20 38 46 22 49 c2 f3 07 23 43 ea 02 22
79 44 92 b2 fc f7 c9 ff 00 28 cd d0 41 46 38 46 04
[   15.623982]  00000820: f0 61 fb 00 28 c7 d0 01 20 d7 e7 0d f1 4a 01
20 46 fc f7 42 fe 17 49 38 46 79 44 fc f7 3b 5f 04
[   15.648391]  00000840: b9 d0 21 9d 04 4d 5c 04 00 0b b3 d0 ea e7 06
ac 28 46 2e 23 13 a9 22 46 de f7 c8 ef 00 28 a9 d0
[   15.672803]  00000860: bd f8 4a 50 22 46 0b 4d 06 c5 96 0c 05 23 0d
0e 9b 55 0c 96 54 07 00 01 9a d0 d1 e7 00 bf ea 18
[   15.697224]  00000880: 01 00 ec 05 01 00 aa 11 01 00 3e 4d 01 70 4e
01 b8 17 0c 00 00 13 10 b5 18 20 fc f7 02 fc 04 46
[   15.721638]  000008a0: 48 b1 00 21 de f7 b8 ef 0b 38 01 28 20 46 00
d9 10 bd fc f7 00 fc 00 20 10 bd 70 4e 04 82 b0 06
[   15.746057]  000008c0: 03 ef fb 04 09 02 b8 b1 01 ad 28 5c 0e 01 aa
ef 01 21 7c 00 02 ac ef 29 46 20 5c 00 00 03 9c ef
[   15.770460]  000008e0: 06 46 28 46 0b 3e de f7 a8 ef 01 2e 20 46 01
d9 02 b0 70 45 08 df 0e 2c 20 f9 5f 0f 10 b5 04 56
[   15.794871]  00000900: 04 a0 ef 04 06 05 bd e8 10 40 fc f7 d3 bb ed
02 96 27 4d 00 c9 4c 02 05 0a f0 b2 bb 0a f0 b0 bb
[   15.819271]  00000920: ff 00 70 b5 30 8d 0f b1 4d 0f e0 cc 0f 07 84
ef 0d 4b 7b 44 1b 68 6b b9 ad 0f 82 27 ed 01 82 8d
[   15.843677]  00000940: 0f 06 8c 0f bc 13 04 80 ef ec e7 fc f7 9c 54
10 01 f4 e7 8c 5a 7c 1d 6d 0e 7a 27 cd 01 8f 8c 0e
[   15.868091]  00000960: 00 0b 80 bb 28 4b 2d e9 f0 43 7b 44 0d 46 85
b0 19 68 04 46 17 46 00 29 3f d0 02 ae 01 20 31 5c
[   15.892508]  00000980: 05 00 0c e8 ed 03 9b 44 f6 d3 50 02 9a c1 f2
62 00 83 fb 00 01 db 17 00 92 c3 eb a1 1c cd f8 04
[   15.916944]  000009a0: c0 47 03 58 f9 17 44 03 00 0f 08 4f f4 7a 70
87 fb 08 89 4f f4 4a 4e c3 f6 9a 3e c1 eb a9 13 99
[   15.941369]  000009c0: 18 02 91 00 fb 13 73 00 fb 03 c3 4c 00 00 07
f3 73 45 03 93 07 dd 4f f4 58 52 01 31 cc f2 65 42
[   15.965789]  000009e0: 02 91 1a 44 03 92 32 46 ac 19 00 0b 34 ef 6e
38 18 bf 01 20 05 b0 bd e8 f0 83 68 46 02 ae de f7
[   15.990200]  00000a00: b0 ed 9d e8 04 10 cb e7 36 5f 17 0a f0 2e 07
2c b5 83 b0 05 08 69 54 05 00 15 22 ef 18 b9 05 4b
[   16.014615]  00000a20: 01 22 7b 44 1a 60 ff f7 6f fc 01 20 03 b0 5d
f8 04 fb 00 bf 7e 59 01 00 02 48 78 44 04 30 0a f0
[   16.039016]  00000a40: 09 4d 1c 66 29 3d 00 05 5d 01 56 5c 01 44 1e
07 41 84 b0 07 46 0e 46 68 46 90 57 4e f1 fc 6d 04
[   16.063418]  00000a60: 99 05 46 98 b3 f6 b9 23 49 68 94 4f 02 fc fd
f8 b1 39 4c 2b 04 fc f7 f7 fd d0 b1 31 54 50 00 04
[   16.087846]  00000a80: 42 46 fe f7 83 fc 06 1e 19 db 2a 46 00 21 fa
f7 eb f9 04 46 10 b3 66 04 f6 fc 0d 2f 04 76 16 81
[   16.112265]  00000aa0: 14 d6 07 dd fd 04 9f 04 df d1 12 49 40 46 00
54 5e 01 f0 f7 85 f9 7d 04 e2 4c 4a bd 04 0c 46 03
[   16.136680]  00000ac0: 22 46 66 03 78 f9 0f 0e e0 e7 09 27 3e 00 70
f9 05 bc 30 47 0d b6 fb e5 4e 47 f2 02 0d 2a a4 4c
[   16.161078]  00000ae0: 00 02 8c a6 00 00 72 4d 00 62 4c 00 4c 17 05
4f 8b b0 8b 46 92 46 06 44 63 06 12 fa aa 4d 7d 44
[   16.185476]  00000b00: 29 46 07 4e 22 da eb 04 24 02 00 28 5b d0 a7
84 68 06 de f7 d2 eb 18 b1 00 20 0b 67 0e 8f a3 49
[   16.209879]  00000b20: 05 15 79 0c 40 01 f0 fc f9 81 4c 04 00 03 00
f0 ed 80 df f8 7c 82 03 ad 01 27 f8 44 00 e0 01 37
[   16.234264]  00000b40: 19 21 3b 44 1c 7f 46 94 ee 29 44 10 00 02 04
f0 e7 f9 00 28 f2 d1 04 46 78 1c 80 00 fc f7 72 fa
[   16.258658]  00000b60: 00 90 7d 06 da 00 03 00 02 9b 1f 1f 05 e0 fb
f7 33 fa 01 34 47 f8 04 0f a8 b1 19 21 23 cd 07 76
[   16.283053]  00000b80: cd 07 c9 4c 07 0b ed d1 00 2c 5c d1 48 46 01
34 fb f7 1d fa 64 05 0f 00 28 e9 d1 01 90 00 98 fc
[   16.307455]  00000ba0: f7 5f fa 81 49 50 46 01 9a 67 1e f7 f8 03 cd
14 7d cc 14 04 aa f9 7b 49 79 44 80 87 09 a4 f9 79
[   16.331868]  00000bc0: 4d 01 07 8c 01 04 9e f9 57 b1 77 4b 50 47 25
21 46 7b 5f 04 26 f9 02 c4 07 00 02 00 28 08 bf b8
[   16.356280]  00000be0: f1 00 0f 0c bf 01 22 00 22 18 d0 18 f1 00 04
4d 49 24 0e 05 0c bf 0f 6a 04 f0 01 0a 50 29 40 02
[   16.380695]  00000c00: 95 80 52 0d 3e 2c 0e 30 ab 80 05 5b ff 0b 75
fe cb f8 07 53 00 28 65 5c 8f 04 6c e7 62 4a 50 46
[   16.405110]  00000c20: 3b 45 51 7a 5e 0a fa f8 0e 15 63 e7 04 2a 6c
36 02 e4 fb 01 9b 04 86 26 89 80 4d 19 93 05 07 59
[   16.429589]  00000c40: c4 02 02 36 d0 56 49 28 44 02 7d 3d e5 0d 9f
9b 05 04 5a 54 95 64 02 5d 3f fc 06 03 53 d0 7d 99
[   16.453997]  00000c60: dc 07 42 9b 18 68 74 03 07 57 d0 4b 4a 1c 46
00 9f 7a 44 45 67 90 06 9d 0d e0 7f 0b 42 fd 81 4c
[   16.478408]  00000c80: 1b 02 fc f7 c8 f9 b9 7e 17 d0 57 9e 24 3f d0
0e 19 25 fb 0d 39 41 57 27 06 46 03 57 0d e8 d1 3c
[   16.502812]  00000ca0: 44 26 b6 49 5e f8 06 0e 00 24 0e 0c ba fb 45
18 40 7f 29 b7 f9 db 04 02 07 30 00 2b 99 d1 03 20
[   16.527231]  00000cc0: 06 e7 33 4f 24 4a 46 49 8d 24 94 4c 19 04 fd
e6 2f 49 02 46 50 9c 4b 02 40 f8 ed e7 2d 5d 03 11
[   16.551655]  00000ce0: 95 03 85 57 03 ee e6 2a 27 66 01 31 f8 6c 16
02 82 f9 ce e7 dd 4e 14 48 46 5d 25 99 06 4a 1e fa
[   16.576084]  00000d00: 05 bd c5 d5 5e 70 0f 05 46 80 b1 64 17 04 7b
fb bf e7 1c
[   16.596997] UBIFS error (ubi0:0 pid 139): do_readpage: cannot read
page 35 of inode 3485, error -22

I checked the code regarding glitches on read/write side which could
lead to page number not getting updated or something along this line, so
far I could not nail the issue.

Brian, with the pattern above in mind, do you see possible issues in the
driver?

--
Stefan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-09-01  0:45                                                     ` Stefan Agner
@ 2015-09-01  1:43                                                       ` Brian Norris
  2015-09-01  2:20                                                         ` Stefan Agner
  2015-09-02 19:58                                                         ` Stefan Agner
  0 siblings, 2 replies; 34+ messages in thread
From: Brian Norris @ 2015-09-01  1:43 UTC (permalink / raw)
  To: Stefan Agner; +Cc: Richard Weinberger, Bhuvanchandra DV, linux-mtd

Hi Stefan,

On Mon, Aug 31, 2015 at 05:45:47PM -0700, Stefan Agner wrote:
> On 2015-08-12 00:27, Richard Weinberger wrote:
> > Am 12.08.2015 um 09:01 schrieb Stefan Agner:
> >> [also added Brian to the discussion, since he had a look into that
> >> driver before]
> > 
> > Good idea, maybe Brian has an idea.

Sorry, didn't look until now.

> >> I worked on the driver since quite some time, currently v10 is in
> >> review. With this issue in mind, I went through the driver however I
> >> currently can't see an issue.
> >>
> >> The error position is always page aligned, but at different pages. We
> >> printed the reread buffers once: It seems that one page lands on flash
> >> twice. My guess is that the second page doesn't get transmitted
> >> properly, while the new column/row gets transmitted and
> >> NAND_CMD_PAGEPROG executed... Hence the same buffer would be written to
> >> the device again.
> >>
> >> The NFC IP in Vybrid (vf610) has a higher level programming model which
> >> takes care of the command sequencing. Therefore some callbacks are not
> >> actually sending a command to the device (e.g. NAND_CMD_SEQIN) since
> >> this will be done one command later, on in NAND_CMD_PAGEPROG. Now, of
> >> course, the driver relies heavily on not being interrupted by other
> >> requests in between, (also not read!) but I thought that this is taken
> >> care of by the MTD subsystem? So for me it is a bit hard to spot the
> >> error since I'm always unsure whether the assumptions regarding
> >> locking/exclusiveness between the calls is really guaranteed...
> > 
> > NAND access is serialized using nand_get_device() and nand_release_device()
> > in nand_base.c, so serialization should be fine.

Right, on a macro level. But I suspect you may have serialization
problems within your driver routines themselves. See below.

> I did some more testing with v11 of this driver, and it seems when I
> continuously reset the system, I get read errors from time to time. The
> read errors end up in various errors, I have seen ubifs_read_node: bad
> node type or ubifs_tnc_read_node: bad key in node. However, particularly
> often and interesting are ubifs_decompress: cannot decompress errors,
> such as this one. It seems that same page is read twice (or has been
> written twice, see data pattern at offset 0x00000000 and 0x00000800).
> 
[...]
> 
> I checked the code regarding glitches on read/write side which could
> lead to page number not getting updated or something along this line, so
> far I could not nail the issue.
> 
> Brian, with the pattern above in mind, do you see possible issues in the
> driver?

I don't have any particular knowledge about that pattern. Regarding
patterns, I've mostly been worried about incomplete "check for 0xff"
algorithms. Doesn't seem to be relevant here.

I don't know too much of this IP other than what I glean from general
NAND code review. With that in mind, this snippet does look a bit
suspect:

+static void vf610_nfc_done(struct vf610_nfc *nfc)
+{
+	unsigned long timeout = msecs_to_jiffies(100);
+
+	/*
+	 * Barrier is needed after this write. This write need
+	 * to be done before reading the next register the first
+	 * time.
+	 * vf610_nfc_set implicates such a barrier by using writel
+	 * to write to the register.
+	 */
+	vf610_nfc_set(nfc, NFC_IRQ_STATUS, IDLE_EN_BIT);
+	vf610_nfc_set(nfc, NFC_FLASH_CMD2, START_BIT);
+
+	if (!(vf610_nfc_read(nfc, NFC_IRQ_STATUS) & IDLE_IRQ_BIT)) {

^^^ this line

+		if (!wait_for_completion_timeout(&nfc->cmd_done, timeout))
+			dev_warn(nfc->dev, "Timeout while waiting for BUSY.\n");
+	}
+	vf610_nfc_clear_status(nfc);
+}

Why do you actually need to check the idle bit? If you need to read it
to clear out some FIFO, then that's fine -- just read it, but don't use
it as a second condition. The complete()/wait_for_completion()
synchronization should be sufficient on its own. (If not, then I think
you have other problems.)

The NFC_IRQ_STATUS-based condition looks like it could lead to races
because your interrupt may fire between setting and checking
the idle bit. So the IRQ handler will increment the completion struct
(cmd_done), but you *won't* be doing the corresponding decrement via
wait_for_completion(). If you don't do that... then the subsequent
wait_for_completion() will immediately succeed.

Anyway, that's a quick and possibly disorganized explanation of my
initial thoughts. Let me know if you
(1) don't understand me;
(2) disagree; or
(3) have tested my suggested fix and still see the behavior.

I can take another look if we're on to option (2) or (3) :)

Regards,
Brian

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-09-01  1:43                                                       ` Brian Norris
@ 2015-09-01  2:20                                                         ` Stefan Agner
  2015-09-02 19:58                                                         ` Stefan Agner
  1 sibling, 0 replies; 34+ messages in thread
From: Stefan Agner @ 2015-09-01  2:20 UTC (permalink / raw)
  To: Brian Norris; +Cc: Richard Weinberger, Bhuvanchandra DV, linux-mtd

Hi Brian,

On 2015-08-31 18:43, Brian Norris wrote:
> Hi Stefan,
> 
> On Mon, Aug 31, 2015 at 05:45:47PM -0700, Stefan Agner wrote:
>> On 2015-08-12 00:27, Richard Weinberger wrote:
>> > Am 12.08.2015 um 09:01 schrieb Stefan Agner:
>> >> [also added Brian to the discussion, since he had a look into that
>> >> driver before]
>> >
>> > Good idea, maybe Brian has an idea.
> 
> Sorry, didn't look until now.
> 
>> >> I worked on the driver since quite some time, currently v10 is in
>> >> review. With this issue in mind, I went through the driver however I
>> >> currently can't see an issue.
>> >>
>> >> The error position is always page aligned, but at different pages. We
>> >> printed the reread buffers once: It seems that one page lands on flash
>> >> twice. My guess is that the second page doesn't get transmitted
>> >> properly, while the new column/row gets transmitted and
>> >> NAND_CMD_PAGEPROG executed... Hence the same buffer would be written to
>> >> the device again.
>> >>
>> >> The NFC IP in Vybrid (vf610) has a higher level programming model which
>> >> takes care of the command sequencing. Therefore some callbacks are not
>> >> actually sending a command to the device (e.g. NAND_CMD_SEQIN) since
>> >> this will be done one command later, on in NAND_CMD_PAGEPROG. Now, of
>> >> course, the driver relies heavily on not being interrupted by other
>> >> requests in between, (also not read!) but I thought that this is taken
>> >> care of by the MTD subsystem? So for me it is a bit hard to spot the
>> >> error since I'm always unsure whether the assumptions regarding
>> >> locking/exclusiveness between the calls is really guaranteed...
>> >
>> > NAND access is serialized using nand_get_device() and nand_release_device()
>> > in nand_base.c, so serialization should be fine.
> 
> Right, on a macro level. But I suspect you may have serialization
> problems within your driver routines themselves. See below.
> 
>> I did some more testing with v11 of this driver, and it seems when I
>> continuously reset the system, I get read errors from time to time. The
>> read errors end up in various errors, I have seen ubifs_read_node: bad
>> node type or ubifs_tnc_read_node: bad key in node. However, particularly
>> often and interesting are ubifs_decompress: cannot decompress errors,
>> such as this one. It seems that same page is read twice (or has been
>> written twice, see data pattern at offset 0x00000000 and 0x00000800).
>>
> [...]
>>
>> I checked the code regarding glitches on read/write side which could
>> lead to page number not getting updated or something along this line, so
>> far I could not nail the issue.
>>
>> Brian, with the pattern above in mind, do you see possible issues in the
>> driver?
> 
> I don't have any particular knowledge about that pattern. Regarding
> patterns, I've mostly been worried about incomplete "check for 0xff"
> algorithms. Doesn't seem to be relevant here.

By  pattern I meant mainly the fact that the same data appear twice.

> 
> I don't know too much of this IP other than what I glean from general
> NAND code review. With that in mind, this snippet does look a bit
> suspect:
> 
> +static void vf610_nfc_done(struct vf610_nfc *nfc)
> +{
> +	unsigned long timeout = msecs_to_jiffies(100);
> +
> +	/*
> +	 * Barrier is needed after this write. This write need
> +	 * to be done before reading the next register the first
> +	 * time.
> +	 * vf610_nfc_set implicates such a barrier by using writel
> +	 * to write to the register.
> +	 */
> +	vf610_nfc_set(nfc, NFC_IRQ_STATUS, IDLE_EN_BIT);
> +	vf610_nfc_set(nfc, NFC_FLASH_CMD2, START_BIT);
> +
> +	if (!(vf610_nfc_read(nfc, NFC_IRQ_STATUS) & IDLE_IRQ_BIT)) {
> 
> ^^^ this line
> 
> +		if (!wait_for_completion_timeout(&nfc->cmd_done, timeout))
> +			dev_warn(nfc->dev, "Timeout while waiting for BUSY.\n");
> +	}
> +	vf610_nfc_clear_status(nfc);
> +}
> 
> Why do you actually need to check the idle bit? If you need to read it
> to clear out some FIFO, then that's fine -- just read it, but don't use
> it as a second condition. The complete()/wait_for_completion()
> synchronization should be sufficient on its own. (If not, then I think
> you have other problems.)
> 
> The NFC_IRQ_STATUS-based condition looks like it could lead to races
> because your interrupt may fire between setting and checking
> the idle bit. So the IRQ handler will increment the completion struct
> (cmd_done), but you *won't* be doing the corresponding decrement via
> wait_for_completion(). If you don't do that... then the subsequent
> wait_for_completion() will immediately succeed.

I totally see your point. And it would even explain the pattern above:
Since the subsequent wait_for_completion() succeeds immediately, the
data read using vf610_nfc_read_buf would just return the same data
(given the controller is not fast enough to transfer the data...)

 
> Anyway, that's a quick and possibly disorganized explanation of my
> initial thoughts. Let me know if you
> (1) don't understand me;
> (2) disagree; or
> (3) have tested my suggested fix and still see the behavior.
> 
> I can take another look if we're on to option (2) or (3) :)

Cool, thanks, will test the above and let you know...

--
Stefan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-09-01  1:43                                                       ` Brian Norris
  2015-09-01  2:20                                                         ` Stefan Agner
@ 2015-09-02 19:58                                                         ` Stefan Agner
  2015-09-02 20:13                                                           ` Brian Norris
  2015-09-07 13:47                                                           ` Bhuvanchandra
  1 sibling, 2 replies; 34+ messages in thread
From: Stefan Agner @ 2015-09-02 19:58 UTC (permalink / raw)
  To: Brian Norris; +Cc: Richard Weinberger, Bhuvanchandra DV, linux-mtd

On 2015-08-31 18:43, Brian Norris wrote:
> Why do you actually need to check the idle bit? If you need to read it
> to clear out some FIFO, then that's fine -- just read it, but don't use
> it as a second condition. The complete()/wait_for_completion()
> synchronization should be sufficient on its own. (If not, then I think
> you have other problems.)
> 
> The NFC_IRQ_STATUS-based condition looks like it could lead to races
> because your interrupt may fire between setting and checking
> the idle bit. So the IRQ handler will increment the completion struct
> (cmd_done), but you *won't* be doing the corresponding decrement via
> wait_for_completion(). If you don't do that... then the subsequent
> wait_for_completion() will immediately succeed.

Tested over night and did some additional tests today, I did not see any
issues for more than 2000 boots, so this really seems to fix the issue!
Thanks Brian, will send out v12 soon.

--
Stefan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-09-02 19:58                                                         ` Stefan Agner
@ 2015-09-02 20:13                                                           ` Brian Norris
  2015-09-02 20:41                                                             ` Stefan Agner
  2015-09-07 13:47                                                           ` Bhuvanchandra
  1 sibling, 1 reply; 34+ messages in thread
From: Brian Norris @ 2015-09-02 20:13 UTC (permalink / raw)
  To: Stefan Agner
  Cc: Richard Weinberger, Bhuvanchandra DV, linux-mtd, Boris Brezillon

On Wed, Sep 02, 2015 at 12:58:08PM -0700, Stefan Agner wrote:
> On 2015-08-31 18:43, Brian Norris wrote:
> > Why do you actually need to check the idle bit? If you need to read it
> > to clear out some FIFO, then that's fine -- just read it, but don't use
> > it as a second condition. The complete()/wait_for_completion()
> > synchronization should be sufficient on its own. (If not, then I think
> > you have other problems.)
> > 
> > The NFC_IRQ_STATUS-based condition looks like it could lead to races
> > because your interrupt may fire between setting and checking
> > the idle bit. So the IRQ handler will increment the completion struct
> > (cmd_done), but you *won't* be doing the corresponding decrement via
> > wait_for_completion(). If you don't do that... then the subsequent
> > wait_for_completion() will immediately succeed.
> 
> Tested over night and did some additional tests today, I did not see any
> issues for more than 2000 boots, so this really seems to fix the issue!

Awesome!

> Thanks Brian, will send out v12 soon.

Glad to help.

In case I didn't mention it already, I'm taking a closer look at Boris'
approach for this series:

http://lists.infradead.org/pipermail/linux-mtd/2015-August/061361.html

but your driver looks like a good candidate for using
nand_check_erased_ecc_chunk(), once we've agreed. Depenending on the
order of acceptance, I might like to get your driver converted either
before or after merging it. Shouldn't be too hard, though, as your
implementation looks very similar right now.

Brian

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-09-02 20:13                                                           ` Brian Norris
@ 2015-09-02 20:41                                                             ` Stefan Agner
  0 siblings, 0 replies; 34+ messages in thread
From: Stefan Agner @ 2015-09-02 20:41 UTC (permalink / raw)
  To: Brian Norris
  Cc: Richard Weinberger, Bhuvanchandra DV, linux-mtd, Boris Brezillon

On 2015-09-02 13:13, Brian Norris wrote:
> On Wed, Sep 02, 2015 at 12:58:08PM -0700, Stefan Agner wrote:
> In case I didn't mention it already, I'm taking a closer look at Boris'
> approach for this series:
> 
> http://lists.infradead.org/pipermail/linux-mtd/2015-August/061361.html
> 
> but your driver looks like a good candidate for using
> nand_check_erased_ecc_chunk(), once we've agreed. Depenending on the
> order of acceptance, I might like to get your driver converted either
> before or after merging it. Shouldn't be too hard, though, as your
> implementation looks very similar right now.

Sure, can update my driver if the common implementations lands in the
MTD tree before the driver.

Otherwise, I just will send a follow up patch afterwards.

--
Stefan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-09-02 19:58                                                         ` Stefan Agner
  2015-09-02 20:13                                                           ` Brian Norris
@ 2015-09-07 13:47                                                           ` Bhuvanchandra
  1 sibling, 0 replies; 34+ messages in thread
From: Bhuvanchandra @ 2015-09-07 13:47 UTC (permalink / raw)
  To: Stefan Agner, Brian Norris
  Cc: Richard Weinberger, Bhuvanchandra DV, linux-mtd, bhuvanchandra.dv

On 09/03/2015 01:28 AM, Stefan Agner wrote:

> On 2015-08-31 18:43, Brian Norris wrote:
>> Why do you actually need to check the idle bit? If you need to read it
>> to clear out some FIFO, then that's fine -- just read it, but don't use
>> it as a second condition. The complete()/wait_for_completion()
>> synchronization should be sufficient on its own. (If not, then I think
>> you have other problems.)
>>
>> The NFC_IRQ_STATUS-based condition looks like it could lead to races
>> because your interrupt may fire between setting and checking
>> the idle bit. So the IRQ handler will increment the completion struct
>> (cmd_done), but you *won't* be doing the corresponding decrement via
>> wait_for_completion(). If you don't do that... then the subsequent
>> wait_for_completion() will immediately succeed.
> Tested over night and did some additional tests today, I did not see any
> issues for more than 2000 boots, so this really seems to fix the issue!
> Thanks Brian, will send out v12 soon.

The io_paral ubi-test also now passed with these fixes.
Thanks!

Best regards,
Bhuvan

>
> --
> Stefan

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-07-31 16:47                                         ` Bhuvanchandra DV
  2015-08-01  6:36                                           ` Richard Weinberger
@ 2015-09-11  4:03                                           ` Bhuvanchandra
  2015-09-12  9:39                                             ` Richard Weinberger
  1 sibling, 1 reply; 34+ messages in thread
From: Bhuvanchandra @ 2015-09-11  4:03 UTC (permalink / raw)
  To: Richard Weinberger; +Cc: linux-mtd, Stefan Agner, richard

Hi Richard,

On 07/31/2015 10:17 PM, Bhuvanchandra DV wrote:

> On 07/24/2015 06:51 PM, Richard Weinberger wrote:
>
>> Hi!
>>
>> Am 24.07.2015 um 16:43 schrieb Bhuvanchandra DV:
>>> Disabled fastmap in U-Boot, still the corruption is persistent when 
>>> using
>>> U-Boot to mount rootfs and load kernel.
>> Can you please describe your boot setup in detail?
>> Why does U-Boot _mount_ an UBIFS? Install the kernel on an UBI static 
>> volume.
>
> U-Boot mounts UBIFS for loading the kernel and device tree blobs 
> availabel in rootfs.
> Since approximately around ~3-5 % of spare blocks are reserverd for 
> wear leveling
> (according to the NAND manufacturer). Initially we had a separate UBI 
> partition of 8MB
> for Kenrel, but after few times of re-writing the kernel to that 
> volume kernel fails
> with no available free space. Due to that reason we made a single big 
> ubi volume and
> moved the kernel and device tree blobs to rootfs.
>
>> If U-Boot mounts UBIFS it has to use UBI in RW mode and therefore it 
>> has to process
>> fastmap or _delete_ it.
>>
>>>>> The same power cut tests are done by skipping the U-Boot to mount 
>>>>> the UBIFS. Loaded
>>>>> the kernel via tftp and mount the rootfs with kernel. The power 
>>>>> cut test passed.
>>>>> I think U-Boot might have some issues, but not very sure.
>>>> To my knowledge U-Boot's fastmap support is incomplete.
>>>> If you *really* need fastmap in U-Boot make sure that they have 
>>>> backported
>>>> all recent fastmap changes. Fastmap is still experimental and faced 
>>>> a lot of fixes
>>>> recently.
>>> Tested with mainline U-Boot along with few downstream patches for 
>>> boot config block
>>> support applied, the ubifs corruption is persistant.
>>>
>>>>>> Anyway, we need to sort out what is going on.
>>>>>> As fm_debug does not trigger it could also be a non-fastmap issue.
>>>>>> Did you try your test without fastmap being enabled?
>>>>>>
>>>>>> Does your target pass UBI tests too?
>>>>> I'm not aware of UBI tests so far the driver passed all MTD tests.
>>>>> Can you please provide some pointers for UBI tests. Will run the 
>>>>> UBI tests with
>>>>> driver.
>>>> They are in the mtd-utils source.
>>> Not yet ran the ubi-tests. Will run the tests and share the results.
>> Please do so. :-)
>
> Seems the mtd-utils are not really cross-compile friendly, some how 
> managed to build the ubi-tests
> tweeking the Makefiles.
>
> The tests ran on ubi partition after isolating it from U-Boot completly.
> Formatted the ubi partition and then boot with SD card (4.1.2 kernel 
> fastmap enabled/disabled, fm_debug enabled).
> Please find the below log of ubi-tests:
>
> root@colibri-vf:~# ubiattach -m 3
> [   44.663944] ubi0: default fastmap pool size: 50
> [   44.668930] ubi0: default fastmap WL pool size: 25
> [   44.674045] ubi0: attaching mtd3
> [   44.995279] ubi0: scanning is finished
> [   44.999364] ubi0: empty MTD device detected
> [   45.033211] ubi0: attached mtd3 (name "ubi", size 126 MiB)
> [   45.039205] ubi0: PEB size: 131072 bytes (128 KiB), LEB size: 
> 126976 bytes
> [   45.046572] ubi0: min./max. I/O unit sizes: 2048/2048, sub-page 
> size 2048
> [   45.053715] ubi0: VID header offset: 2048 (aligned 2048), data 
> offset: 4096
> [   45.061141] ubi0: good PEBs: 1003, bad PEBs: 5, corrupted PEBs: 0
> [   45.067951] ubi0: user volume: 0, internal volumes: 1, max. volumes 
> count: 128
> [   45.075701] ubi0: max/mean erase counter: 0/0, WL threshold: 4096, 
> image sequence number: 595808446
> [   45.085278] ubi0: available PEBs: 982, total reserved PEBs: 21, 
> PEBs reserved for bad PEB handling: 15
> [   45.101889] ubi0: background thread "ubi_bgt0d" started, PID 337
> UBI device number 0, total 1003 LEBs (127356928 bytes, 121.5 MiB), 
> available 982 LEBs (124690432 bytes, 118.9 MiB), LEB size 126976 bytes 
> (124.0 KiB)
> root@colibri-vf:~# cd ubi-tests-bin/
> root@colibri-vf:~/ubi-tests-bin# ./runtests.sh /dev/ubi0 - test /dev/ubi0
> Running mkvol_basic /dev/ubi0
> Running mkvol_bad /dev/ubi0
> [   99.630756] ubi0 error: verify_mkvol_req: bad volume creation request
> [   99.637579] Volume creation request dump:
> [   99.641987]  vol_id    -2
> [   99.644784]  alignment 1
> [   99.647466]  bytes     124690432
> [   99.650994]  vol_type  3
> [   99.653696]  name_len  22
> [   99.656464]  1st 16 characters of name: mkvol_bad:test_m
> [   99.669464] ubi0 error: verify_mkvol_req: bad volume creation request
> [   99.676292] Volume creation request dump:
> [   99.680674]  vol_id    128
> [   99.683558]  alignment 1
> [   99.686240]  bytes     124690432
> [   99.694911]  vol_type  3
> [   99.702852]  name_len  22
> [   99.710786]  1st 16 characters of name: mkvol_bad:test_m
> [   99.728668] ubi0 error: verify_mkvol_req: bad volume creation request
> [   99.740962] Volume creation request dump:
> [   99.750630]  vol_id    0
> [   99.758537]  alignment 0
> [   99.766352]  bytes     124690432
> [   99.774804]  vol_type  3
> [   99.782409]  name_len  22
> [   99.789923]  1st 16 characters of name: mkvol_bad:test_m
> [   99.808480] ubi0 error: verify_mkvol_req: bad volume creation request
> [   99.820028] Volume creation request dump:
> [   99.828796]  vol_id    0
> [   99.835879]  alignment -1
> [   99.842859]  bytes     124690432
> [   99.850335]  vol_type  3
> [   99.856849]  name_len  22
> [   99.863395]  1st 16 characters of name: mkvol_bad:test_m
> [   99.880157] ubi0 error: verify_mkvol_req: bad volume creation request
> [   99.891064] Volume creation request dump:
> [   99.899440]  vol_id    0
> [   99.906182]  alignment 126977
> [   99.913456]  bytes     124690432
> [   99.920926]  vol_type  3
> [   99.927467]  name_len  22
> [   99.934058]  1st 16 characters of name: mkvol_bad:test_m
> [   99.950732] ubi0 error: verify_mkvol_req: bad volume creation request
> [   99.961655] Volume creation request dump:
> [   99.970057]  vol_id    0
> [   99.976826]  alignment 2049
> [   99.983931]  bytes     124690432
> [   99.991412]  vol_type  3
> [   99.997959]  name_len  22
> [  100.004551]  1st 16 characters of name: mkvol_bad:test_m
> [  100.021254] ubi0 error: verify_mkvol_req: bad volume creation request
> [  100.032201] Volume creation request dump:
> [  100.040649]  vol_id    0
> [  100.047441]  alignment 1
> [  100.054334]  bytes     -1
> [  100.061191]  vol_type  3
> [  100.067708]  name_len  22
> [  100.074250]  1st 16 characters of name: mkvol_bad:test_m
> [  100.090929] ubi0 error: verify_mkvol_req: bad volume creation request
> [  100.101834] Volume creation request dump:
> [  100.110223]  vol_id    0
> [  100.116969]  alignment 1
> [  100.123783]  bytes     0
> [  100.130505]  vol_type  3
> [  100.136980]  name_len  22
> [  100.143502]  1st 16 characters of name: mkvol_bad:test_m
> [  100.160274] ubi0 error: ubi_create_volume: not enough PEBs, only 
> 982 available
> [  100.175970] ubi0 error: ubi_create_volume: cannot create volume 0, 
> error -28
> [  100.189501] ubi0 error: ubi_create_volume: not enough PEBs, only 
> 982 available
> [  100.205998] ubi0 error: ubi_create_volume: cannot create volume 0, 
> error -28
> [  100.222091] ubi0 error: verify_mkvol_req: bad volume creation request
> [  100.233529] Volume creation request dump:
> [  100.242409]  vol_id    0
> [  100.249771]  alignment 1
> [  100.256993]  bytes     126976
> [  100.264716]  vol_type  7
> [  100.272035]  name_len  22
> [  100.279316]  1st 16 characters of name: mkvol_bad:test_m
> [  100.416661] ubi0 error: ubi_create_volume: volume 0 already exists
> [  100.427776] ubi0 error: ubi_create_volume: cannot create volume 0, 
> error -17
> [  100.441410] ubi0 error: ubi_create_volume: volume 
> "mkvol_bad:test_mkvol()" exists (ID 0)
> [  100.459295] ubi0 error: ubi_create_volume: cannot create volume 1, 
> error -17
> [  100.711027] ubi0 error: ubi_create_volume: volume 
> "mkvol_bad:test_mkvol()" exists (ID 0)
> [  100.729733] ubi0 error: ubi_create_volume: cannot create volume 1, 
> error -17
> [  131.225291] ubi0 error: ubi_open_volume: cannot open device 0, 
> volume 128, error -22
> [  131.244295] ubi0 error: ubi_open_volume: cannot open device 0, 
> volume -1, error -22
> [  131.269510] ubi0 error: ubi_open_volume: cannot open device 0, 
> volume 128, error -22
> [  131.290092] ubi0 error: ubi_open_volume: cannot open device 0, 
> volume 0, error -19
> [  131.551660] ubi0 error: ubi_open_volume: cannot open device 0, 
> volume 0, error -19

With the recent fixes by Stefan to vf610_nfc driver the io_paral test 
passed, but the
above error's with the volume creation are still reproducible. Are these 
erros need to
be taken into consideration ?

Best regards,
Bhuvan
> Running mkvol_paral /dev/ubi0
> Running rsvol /dev/ubi0
> Running io_basic /dev/ubi0
> Running io_read /dev/ubi0
> Running io_update /dev/ubi0
> Running io_paral /dev/ubi0
> [io_paral] write_thread():222: written and read data are different
> Running volrefcnt /dev/ubi0
> SUCCESS
> root@colibri-vf:~/ubi-tests-bin#
>
>>
>> Thanks,
>> //richard
>
> Best regards,
> Bhuvan
>

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-09-11  4:03                                           ` Bhuvanchandra
@ 2015-09-12  9:39                                             ` Richard Weinberger
  2015-09-13  4:45                                               ` Bhuvanchandra
  0 siblings, 1 reply; 34+ messages in thread
From: Richard Weinberger @ 2015-09-12  9:39 UTC (permalink / raw)
  To: Bhuvanchandra; +Cc: linux-mtd, Stefan Agner

Hi!

Am 11.09.2015 um 06:03 schrieb Bhuvanchandra:
>> Running mkvol_bad /dev/ubi0
>> [   99.630756] ubi0 error: verify_mkvol_req: bad volume creation request
>> [   99.637579] Volume creation request dump:
>> [   99.641987]  vol_id    -2
>> [   99.644784]  alignment 1
>> [   99.647466]  bytes     124690432
>> [   99.650994]  vol_type  3
>> [   99.653696]  name_len  22
>> [   99.656464]  1st 16 characters of name: mkvol_bad:test_m
>> [   99.669464] ubi0 error: verify_mkvol_req: bad volume creation request
>> [   99.676292] Volume creation request dump:
>> [   99.680674]  vol_id    128
>> [   99.683558]  alignment 1
>> [   99.686240]  bytes     124690432
>> [   99.694911]  vol_type  3
>> [   99.702852]  name_len  22
>> [   99.710786]  1st 16 characters of name: mkvol_bad:test_m
>> [   99.728668] ubi0 error: verify_mkvol_req: bad volume creation request
>> [   99.740962] Volume creation request dump:
>> [   99.750630]  vol_id    0
>> [   99.758537]  alignment 0
>> [   99.766352]  bytes     124690432
>> [   99.774804]  vol_type  3
>> [   99.782409]  name_len  22
>> [   99.789923]  1st 16 characters of name: mkvol_bad:test_m
>> [   99.808480] ubi0 error: verify_mkvol_req: bad volume creation request
>> [   99.820028] Volume creation request dump:
>> [   99.828796]  vol_id    0
>> [   99.835879]  alignment -1
>> [   99.842859]  bytes     124690432
>> [   99.850335]  vol_type  3
>> [   99.856849]  name_len  22
>> [   99.863395]  1st 16 characters of name: mkvol_bad:test_m
>> [   99.880157] ubi0 error: verify_mkvol_req: bad volume creation request
>> [   99.891064] Volume creation request dump:
>> [   99.899440]  vol_id    0
>> [   99.906182]  alignment 126977
>> [   99.913456]  bytes     124690432
>> [   99.920926]  vol_type  3
>> [   99.927467]  name_len  22
>> [   99.934058]  1st 16 characters of name: mkvol_bad:test_m
>> [   99.950732] ubi0 error: verify_mkvol_req: bad volume creation request
>> [   99.961655] Volume creation request dump:
>> [   99.970057]  vol_id    0
>> [   99.976826]  alignment 2049
>> [   99.983931]  bytes     124690432
>> [   99.991412]  vol_type  3
>> [   99.997959]  name_len  22
>> [  100.004551]  1st 16 characters of name: mkvol_bad:test_m
>> [  100.021254] ubi0 error: verify_mkvol_req: bad volume creation request
>> [  100.032201] Volume creation request dump:
>> [  100.040649]  vol_id    0
>> [  100.047441]  alignment 1
>> [  100.054334]  bytes     -1
>> [  100.061191]  vol_type  3
>> [  100.067708]  name_len  22
>> [  100.074250]  1st 16 characters of name: mkvol_bad:test_m
>> [  100.090929] ubi0 error: verify_mkvol_req: bad volume creation request
>> [  100.101834] Volume creation request dump:
>> [  100.110223]  vol_id    0
>> [  100.116969]  alignment 1
>> [  100.123783]  bytes     0
>> [  100.130505]  vol_type  3
>> [  100.136980]  name_len  22
>> [  100.143502]  1st 16 characters of name: mkvol_bad:test_m
>> [  100.160274] ubi0 error: ubi_create_volume: not enough PEBs, only 982 available
>> [  100.175970] ubi0 error: ubi_create_volume: cannot create volume 0, error -28
>> [  100.189501] ubi0 error: ubi_create_volume: not enough PEBs, only 982 available
>> [  100.205998] ubi0 error: ubi_create_volume: cannot create volume 0, error -28
>> [  100.222091] ubi0 error: verify_mkvol_req: bad volume creation request
>> [  100.233529] Volume creation request dump:
>> [  100.242409]  vol_id    0
>> [  100.249771]  alignment 1
>> [  100.256993]  bytes     126976
>> [  100.264716]  vol_type  7
>> [  100.272035]  name_len  22
>> [  100.279316]  1st 16 characters of name: mkvol_bad:test_m
>> [  100.416661] ubi0 error: ubi_create_volume: volume 0 already exists
>> [  100.427776] ubi0 error: ubi_create_volume: cannot create volume 0, error -17
>> [  100.441410] ubi0 error: ubi_create_volume: volume "mkvol_bad:test_mkvol()" exists (ID 0)
>> [  100.459295] ubi0 error: ubi_create_volume: cannot create volume 1, error -17
>> [  100.711027] ubi0 error: ubi_create_volume: volume "mkvol_bad:test_mkvol()" exists (ID 0)
>> [  100.729733] ubi0 error: ubi_create_volume: cannot create volume 1, error -17
>> [  131.225291] ubi0 error: ubi_open_volume: cannot open device 0, volume 128, error -22
>> [  131.244295] ubi0 error: ubi_open_volume: cannot open device 0, volume -1, error -22
>> [  131.269510] ubi0 error: ubi_open_volume: cannot open device 0, volume 128, error -22
>> [  131.290092] ubi0 error: ubi_open_volume: cannot open device 0, volume 0, error -19
>> [  131.551660] ubi0 error: ubi_open_volume: cannot open device 0, volume 0, error -19
> 
> With the recent fixes by Stefan to vf610_nfc driver the io_paral test passed, but the
> above error's with the volume creation are still reproducible. Are these erros need to
> be taken into consideration ?

No. These logs are fine. mkvol_bad does negative testing.

Thanks,
//richard

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: UBIFS errors when file-system is full
  2015-09-12  9:39                                             ` Richard Weinberger
@ 2015-09-13  4:45                                               ` Bhuvanchandra
  0 siblings, 0 replies; 34+ messages in thread
From: Bhuvanchandra @ 2015-09-13  4:45 UTC (permalink / raw)
  To: Richard Weinberger, Bhuvanchandra; +Cc: linux-mtd, Stefan Agner

On 09/12/2015 03:09 PM, Richard Weinberger wrote:

> Hi!
>
> Am 11.09.2015 um 06:03 schrieb Bhuvanchandra:
>>> Running mkvol_bad /dev/ubi0
>>> [   99.630756] ubi0 error: verify_mkvol_req: bad volume creation request
>>> [   99.637579] Volume creation request dump:
>>> [   99.641987]  vol_id    -2
>>> [   99.644784]  alignment 1
>>> [   99.647466]  bytes     124690432
>>> [   99.650994]  vol_type  3
>>> [   99.653696]  name_len  22
>>> [   99.656464]  1st 16 characters of name: mkvol_bad:test_m
>>> [   99.669464] ubi0 error: verify_mkvol_req: bad volume creation request
>>> [   99.676292] Volume creation request dump:
>>> [   99.680674]  vol_id    128
>>> [   99.683558]  alignment 1
>>> [   99.686240]  bytes     124690432
>>> [   99.694911]  vol_type  3
>>> [   99.702852]  name_len  22
>>> [   99.710786]  1st 16 characters of name: mkvol_bad:test_m
>>> [   99.728668] ubi0 error: verify_mkvol_req: bad volume creation request
>>> [   99.740962] Volume creation request dump:
>>> [   99.750630]  vol_id    0
>>> [   99.758537]  alignment 0
>>> [   99.766352]  bytes     124690432
>>> [   99.774804]  vol_type  3
>>> [   99.782409]  name_len  22
>>> [   99.789923]  1st 16 characters of name: mkvol_bad:test_m
>>> [   99.808480] ubi0 error: verify_mkvol_req: bad volume creation request
>>> [   99.820028] Volume creation request dump:
>>> [   99.828796]  vol_id    0
>>> [   99.835879]  alignment -1
>>> [   99.842859]  bytes     124690432
>>> [   99.850335]  vol_type  3
>>> [   99.856849]  name_len  22
>>> [   99.863395]  1st 16 characters of name: mkvol_bad:test_m
>>> [   99.880157] ubi0 error: verify_mkvol_req: bad volume creation request
>>> [   99.891064] Volume creation request dump:
>>> [   99.899440]  vol_id    0
>>> [   99.906182]  alignment 126977
>>> [   99.913456]  bytes     124690432
>>> [   99.920926]  vol_type  3
>>> [   99.927467]  name_len  22
>>> [   99.934058]  1st 16 characters of name: mkvol_bad:test_m
>>> [   99.950732] ubi0 error: verify_mkvol_req: bad volume creation request
>>> [   99.961655] Volume creation request dump:
>>> [   99.970057]  vol_id    0
>>> [   99.976826]  alignment 2049
>>> [   99.983931]  bytes     124690432
>>> [   99.991412]  vol_type  3
>>> [   99.997959]  name_len  22
>>> [  100.004551]  1st 16 characters of name: mkvol_bad:test_m
>>> [  100.021254] ubi0 error: verify_mkvol_req: bad volume creation request
>>> [  100.032201] Volume creation request dump:
>>> [  100.040649]  vol_id    0
>>> [  100.047441]  alignment 1
>>> [  100.054334]  bytes     -1
>>> [  100.061191]  vol_type  3
>>> [  100.067708]  name_len  22
>>> [  100.074250]  1st 16 characters of name: mkvol_bad:test_m
>>> [  100.090929] ubi0 error: verify_mkvol_req: bad volume creation request
>>> [  100.101834] Volume creation request dump:
>>> [  100.110223]  vol_id    0
>>> [  100.116969]  alignment 1
>>> [  100.123783]  bytes     0
>>> [  100.130505]  vol_type  3
>>> [  100.136980]  name_len  22
>>> [  100.143502]  1st 16 characters of name: mkvol_bad:test_m
>>> [  100.160274] ubi0 error: ubi_create_volume: not enough PEBs, only 982 available
>>> [  100.175970] ubi0 error: ubi_create_volume: cannot create volume 0, error -28
>>> [  100.189501] ubi0 error: ubi_create_volume: not enough PEBs, only 982 available
>>> [  100.205998] ubi0 error: ubi_create_volume: cannot create volume 0, error -28
>>> [  100.222091] ubi0 error: verify_mkvol_req: bad volume creation request
>>> [  100.233529] Volume creation request dump:
>>> [  100.242409]  vol_id    0
>>> [  100.249771]  alignment 1
>>> [  100.256993]  bytes     126976
>>> [  100.264716]  vol_type  7
>>> [  100.272035]  name_len  22
>>> [  100.279316]  1st 16 characters of name: mkvol_bad:test_m
>>> [  100.416661] ubi0 error: ubi_create_volume: volume 0 already exists
>>> [  100.427776] ubi0 error: ubi_create_volume: cannot create volume 0, error -17
>>> [  100.441410] ubi0 error: ubi_create_volume: volume "mkvol_bad:test_mkvol()" exists (ID 0)
>>> [  100.459295] ubi0 error: ubi_create_volume: cannot create volume 1, error -17
>>> [  100.711027] ubi0 error: ubi_create_volume: volume "mkvol_bad:test_mkvol()" exists (ID 0)
>>> [  100.729733] ubi0 error: ubi_create_volume: cannot create volume 1, error -17
>>> [  131.225291] ubi0 error: ubi_open_volume: cannot open device 0, volume 128, error -22
>>> [  131.244295] ubi0 error: ubi_open_volume: cannot open device 0, volume -1, error -22
>>> [  131.269510] ubi0 error: ubi_open_volume: cannot open device 0, volume 128, error -22
>>> [  131.290092] ubi0 error: ubi_open_volume: cannot open device 0, volume 0, error -19
>>> [  131.551660] ubi0 error: ubi_open_volume: cannot open device 0, volume 0, error -19
>> With the recent fixes by Stefan to vf610_nfc driver the io_paral test passed, but the
>> above error's with the volume creation are still reproducible. Are these erros need to
>> be taken into consideration ?
> No. These logs are fine. mkvol_bad does negative testing.

Thanks! for the confirmation.

Best regards,
Bhuvan

>
> Thanks,
> //richard

^ permalink raw reply	[flat|nested] 34+ messages in thread

end of thread, other threads:[~2015-09-13  4:45 UTC | newest]

Thread overview: 34+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2015-07-13 13:55 UBIFS errors when file-system is full Bhuvanchandra DV
2015-07-13 14:09 ` Richard Weinberger
2015-07-14  4:23   ` Bhuvanchandra DV
2015-07-14  6:13     ` Richard Weinberger
2015-07-14  6:30       ` Bhuvanchandra DV
2015-07-14  6:32         ` Richard Weinberger
2015-07-14  8:29           ` Bhuvanchandra DV
2015-07-14  8:42             ` Richard Weinberger
2015-07-14 10:08               ` Bhuvanchandra DV
2015-07-14 11:06                 ` Richard Weinberger
     [not found]                   ` <55A74812.2020906@gmail.com>
2015-07-16  7:35                     ` Fwd: " Bhuvanchandra DV
     [not found]                     ` <55A74AA1.2000000@nod.at>
     [not found]                       ` <55A7540C.3050900@nod.at>
     [not found]                         ` <55A7592D.6010906@gmail.com>
     [not found]                           ` <55A75A05.7040603@nod.at>
2015-07-16  7:33                             ` Bhuvanchandra DV
2015-07-21  6:04                             ` Bhuvanchandra DV
2015-07-21  6:14                               ` Richard Weinberger
2015-07-22  7:10                                 ` Bhuvanchandra DV
2015-07-22  7:20                                   ` Richard Weinberger
2015-07-24 14:43                                     ` Bhuvanchandra DV
2015-07-24 16:51                                       ` Richard Weinberger
2015-07-31 16:47                                         ` Bhuvanchandra DV
2015-08-01  6:36                                           ` Richard Weinberger
2015-08-06 10:31                                             ` Bhuvanchandra DV
2015-08-07 12:37                                               ` Richard Weinberger
2015-08-12  7:01                                                 ` Stefan Agner
2015-08-12  7:27                                                   ` Richard Weinberger
2015-09-01  0:45                                                     ` Stefan Agner
2015-09-01  1:43                                                       ` Brian Norris
2015-09-01  2:20                                                         ` Stefan Agner
2015-09-02 19:58                                                         ` Stefan Agner
2015-09-02 20:13                                                           ` Brian Norris
2015-09-02 20:41                                                             ` Stefan Agner
2015-09-07 13:47                                                           ` Bhuvanchandra
2015-09-11  4:03                                           ` Bhuvanchandra
2015-09-12  9:39                                             ` Richard Weinberger
2015-09-13  4:45                                               ` Bhuvanchandra

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.