UBIFS errors are randomly seen after reboots

Wed Jan 18 03:35:23 PST 2017

Hi Richard,
io_basic test failed  whereas the rest of the tests i.e io_read
,io_update,  io_paral,  volrefcnt passed.  I also ran mtd-tests and
all of them passed.

To sum it up , we've rsvol and io_basic which failed and the rest all
passed. Does this give any lead to the root cause of UBIFS errors or
are there any pending tests which we need to perform ?

Below is the output of io_basic test

root at router6654A1:~/arm-openwrt-linux# ./io_basic /dev/ubi1
[137176.494161] INFO: rcu_sched detected stall on CPU 0 (t=6000 jiffies)
[137176.500628] Backtrace:
[137176.503212] [<c40113a0>] (dump_backtrace+0x0/0x110) from
[<c43fff28>] (dump_stack+0x18/0x1c)
[137176.511765]  r6:c458e080
[137176.514150] INFO: rcu_sched detected stalls on CPUs/tasks: { 0}
(detected by 1, t=6002 jiffies)
[137176.514166] Backtrace:
[137176.514186] [<c40113a0>] (dump_backtrace+0x0/0x110) from
[<c43fff28>] (dump_stack+0x18/0x1c)
[137176.514196]  r6:c45a6680 r5:c45a6620 r4:c4e31674 r3:00000000
[137176.514228] [<c43fff10>] (dump_stack+0x0/0x1c) from [<c4080368>]
(__rcu_pending+0x210/0x38c)
[137176.514248] [<c4080158>] (__rcu_pending+0x0/0x38c) from
[<c4081270>] (rcu_check_callbacks+0xe8/0x17c)
[137176.514269] [<c4081188>] (rcu_check_callbacks+0x0/0x17c) from
[<c4041f70>] (update_process_times+0x40/0x64)
[137176.514279]  r8:e5267595 r7:00000001 r6:e6049780 r5:00000000 r4:e6066000
[137176.514294] r3:00010000
[137176.514315] [<c4041f30>] (update_process_times+0x0/0x64) from
[<c4063174>] (tick_sched_timer+0x9c/0xdc)
[137176.514325]  r7:c4e314a0 r6:e6067f68 r5:e6066000 r4:c4e31598
[137176.514351] [<c40630d8>] (tick_sched_timer+0x0/0xdc) from
[<c40564f0>] (__run_hrtimer+0xf4/0x1c8)
[137176.514360]  r9:e6067eb0 r8:e5266b80 r6:c4e314d8 r5:c4e314a0 r4:c4e31598
[137176.514385] [<c40563fc>] (__run_hrtimer+0x0/0x1c8) from
[<c4057248>] (hrtimer_interrupt+0x124/0x288)
[137176.514404] [<c4057124>] (hrtimer_interrupt+0x0/0x288) from
[<c4013640>] (twd_handler+0x28/0x30)
[137176.514422] [<c4013618>] (twd_handler+0x0/0x30) from [<c407d8d8>]
(handle_percpu_devid_irq+0xd0/0x150)
[137176.514431]  r4:0000001d r3:c4013618
[137176.514448] [<c407d808>] (handle_percpu_devid_irq+0x0/0x150) from
[<c4079e88>] (generic_handle_irq+0x34/0x48)
[137176.514466] [<c4079e54>] (generic_handle_irq+0x0/0x48) from
[<c400e494>] (handle_IRQ+0x80/0xc0)
[137176.514483] [<c400e414>] (handle_IRQ+0x0/0xc0) from [<c40081d0>]
(asm_do_IRQ+0x10/0x14)
[137176.514492]  r5:60000013 r4:c400e72c
[137176.514507] [<c40081c0>] (asm_do_IRQ+0x0/0x14) from [<c400d738>]
(__irq_svc+0x38/0x90)
[137176.514518] Exception stack(0xe6067f68 to 0xe6067fb0)
[137176.514529] 7f60:                   00000001 00000000 e6067fb0
00000000 e6066000 c44058a8
[137176.514544] 7f80: c45c6984 c45c6ab4 0400406a 412fc091 00000000
e6067fbc e6067fc0 e6067fb0
[137176.514555] 7fa0: c400e728 c400e72c 60000013 ffffffff
[137176.514571] [<c400e700>] (default_idle+0x0/0x30) from [<c400e90c>]
(cpu_idle+0x84/0xc8)
[137176.514596] [<c400e888>] (cpu_idle+0x0/0xc8) from [<c43fcc0c>]
(secondary_start_kernel+0x140/0x158)
[137176.514606]  r6:10c03c7d r5:c45a8b14 r4:00000002 r3:c45988ac
[137176.514693] [<c43fcacc>] (secondary_start_kernel+0x0/0x158) from
[<043fc4b4>] (0x43fc4b4)
[137176.514703]  r5:00000015 r4:2606806a
[137176.739774]  r5:c45a6620 r4:c4e29674 r3:c45a2dbc
[137176.744558] [<c43fff10>] (dump_stack+0x0/0x1c) from [<c40801e0>]
(__rcu_pending+0x88/0x38c)
[137176.753035] [<c4080158>] (__rcu_pending+0x0/0x38c) from
[<c4081270>] (rcu_check_callbacks+0xe8/0x17c)
[137176.762382] [<c4081188>] (rcu_check_callbacks+0x0/0x17c) from
[<c4041f70>] (update_process_times+0x40/0x64)
[137176.772240]  r8:e3f551f5 r7:00000000 r6:e4a71540 r5:00000000 r4:e2012000
[137176.778925] r3:00010000
[137176.781677] [<c4041f30>] (update_process_times+0x0/0x64) from
[<c4063174>] (tick_sched_timer+0x9c/0xdc)
[137176.791186]  r7:c4e294a0 r6:e2013c70 r5:e2012000 r4:c4e29598
[137176.797011] [<c40630d8>] (tick_sched_timer+0x0/0xdc) from
[<c40564f0>] (__run_hrtimer+0xf4/0x1c8)
[137176.805998]  r9:e2013bb8 r8:e3f53e80 r6:c4e294d8 r5:c4e294a0 r4:c4e29598
[137176.812875] [<c40563fc>] (__run_hrtimer+0x0/0x1c8) from
[<c4057248>] (hrtimer_interrupt+0x124/0x288)
[137176.822134] [<c4057124>] (hrtimer_interrupt+0x0/0x288) from
[<c4013640>] (twd_handler+0x28/0x30)
[137176.831042] [<c4013618>] (twd_handler+0x0/0x30) from [<c407d8d8>]
(handle_percpu_devid_irq+0xd0/0x150)
[137176.840465]  r4:0000001d r3:c4013618
[137176.844170] [<c407d808>] (handle_percpu_devid_irq+0x0/0x150) from
[<c4079e88>] (generic_handle_irq+0x34/0x48)
[137176.854213] [<c4079e54>] (generic_handle_irq+0x0/0x48) from
[<c400e494>] (handle_IRQ+0x80/0xc0)
[137176.863032] [<c400e414>] (handle_IRQ+0x0/0xc0) from [<c40081d0>]
(asm_do_IRQ+0x10/0x14)
[137176.871148]  r5:20000013 r4:c41c330c
[137176.874852] [<c40081c0>] (asm_do_IRQ+0x0/0x14) from [<c400d738>]
(__irq_svc+0x38/0x90)
[137176.882883] Exception stack(0xe2013c70 to 0xe2013cb8)
[137176.888041] 3c60:                                     e8800000
ec3cf580 00000270 a5a5a5a5
[137176.896335] 3c80: a5a5a5a5 0000a5a5 000000a5 ec3cf400 00000001
c4619aa8 00000400 e2013cd4
[137176.904629] 3ca0: 000000a5 e2013cb8 000000a5 c41c330c 20000013 ffffffff
[137176.911371] [<c42594c8>] (nand_read_buf+0x0/0x1c) from
[<c425d8a4>] (comcerto_nand_read_page_hwecc+0x70/0x140)
[137176.921498] [<c425d834>] (comcerto_nand_read_page_hwecc+0x0/0x140)
from [<c4258e68>] (nand_do_read_ops+0x200/0x438)
[137176.932062] [<c4258c68>] (nand_do_read_ops+0x0/0x438) from
[<c425a950>] (nand_read+0x80/0xa4)
[137176.940708] [<c425a8d0>] (nand_read+0x0/0xa4) from [<c42442ac>]
(part_read+0x78/0xcc)
[137176.948649]  r9:00000000 r8:04140000 r7:00000000 r6:06d40000 r5:00000003
[137176.955334] r4:e6295c00
[137176.958081] [<c4244234>] (part_read+0x0/0xcc) from [<c42675b0>]
(ubi_io_read+0x120/0x2b0)
[137176.966379] [<c4267490>] (ubi_io_read+0x0/0x2b0) from [<c426522c>]
(ubi_eba_read_leb+0x2b8/0x3b0)
[137176.975375] [<c4264f74>] (ubi_eba_read_leb+0x0/0x3b0) from
[<c426ddd4>] (ubi_check_volume+0x78/0xbc)
[137176.984630] [<c426dd5c>] (ubi_check_volume+0x0/0xbc) from
[<c42639ec>] (vol_cdev_write+0x2d4/0x354)
[137176.993806] [<c4263718>] (vol_cdev_write+0x0/0x354) from
[<c40d7c00>] (vfs_write+0xbc/0x148)
[137177.002364] [<c40d7b44>] (vfs_write+0x0/0x148) from [<c40d7e8c>]
(sys_write+0x48/0x74)
[137177.010392]  r8:c400dd44 r7:00000004 r6:00000200 r5:bebc3a18 r4:e4996e40
[137177.017270] [<c40d7e44>] (sys_write+0x0/0x74) from [<c400dbc0>]
(ret_fast_syscall+0x0/0x30)
[137177.025734]  r6:00010ba0 r5:00000000 r4:bebc3ca8

Thanks
Chaitanya

On Tue, Jan 17, 2017 at 8:09 PM, Richard Weinberger <richard at nod.at> wrote:
> Chaitanya,
>
> Am 17.01.2017 um 15:32 schrieb chaitanya vinnakota:
>> Now , I'm seeing altogether different form of errors.
>>
>> ./runtests.sh /dev/ubi1
>> Running mkvol_basic /dev/ubi1
>> Running mkvol_bad /dev/ubi1
>
> _bad is supposed to return errors.
>
>> [77361.468670] UBI error: verify_mkvol_req: bad volume creation request
>> [77361.475116] Volume creation request dump:
>> [77361.479139]  vol_id    -2
>> [77361.481768]  alignment 1
>> [77361.484322]  bytes     86343680
>> [77361.487473]  vol_type  3
>> [77361.490013]  name_len  22
>> [77361.492641]  1st 16 characters of name: mkvol_bad:test_m
>> [77361.498235] UBI error: verify_mkvol_req: bad volume creation request
>> [77361.504652] Volume creation request dump:
>> [77361.508676]  vol_id    128
>> [77361.511390]  alignment 1
>> [77361.513930]  bytes     86343680
>> [77361.517095]  vol_type  3
>> [77361.519636]  name_len  22
>> [77361.522265]  1st 16 characters of name: mkvol_bad:test_m
>> [77361.527634] UBI error: verify_mkvol_req: bad volume creation request
>> [77361.534009] Volume creation request dump:
>> [77361.538064]  vol_id    0
>> [77361.540606]  alignment 0
>> [77361.543145]  bytes     86343680
>> [77361.546316]  vol_type  3
>> [77361.548857]  name_len  22
>> [77361.551485]  1st 16 characters of name: mkvol_bad:test_m
>> [77361.558437] UBI error: verify_mkvol_req: bad volume creation request
>> [77361.564862] Volume creation request dump:
>> [77361.568902]  vol_id    0
>> [77361.571457]  alignment -1
>> [77361.574101]  bytes     86343680
>> [77361.577313]  vol_type  3
>> [77361.579866]  name_len  22
>> [77361.582504]  1st 16 characters of name: mkvol_bad:test_m
>> [77361.587943] UBI error: verify_mkvol_req: bad volume creation request
>> [77361.594355] Volume creation request dump:
>> [77361.598394]  vol_id    0
>> [77361.600945]  alignment 126977
>> [77361.603936]  bytes     86343680
>> [77361.607132]  vol_type  3
>> [77361.609688]  name_len  22
>> [77361.612329]  1st 16 characters of name: mkvol_bad:test_m
>> [77361.617765] UBI error: verify_mkvol_req: bad volume creation request
>> [77361.624199] Volume creation request dump:
>> [77361.628241]  vol_id    0
>> [77361.630800]  alignment 2049
>> [77361.633617]  bytes     86343680
>> [77361.636814]  vol_type  3
>> [77361.639368]  name_len  22
>> [77361.642010]  1st 16 characters of name: mkvol_bad:test_m
>> [77361.647478] UBI error: verify_mkvol_req: bad volume creation request
>> [77361.653868] Volume creation request dump:
>> [77361.657940]  vol_id    0
>> [77361.660510]  alignment 1
>> [77361.663065]  bytes     -1
>> [77361.665739]  vol_type  3
>> [77361.668290]  name_len  22
>> [77361.670930]  1st 16 characters of name: mkvol_bad:test_m
>> [77361.676360] UBI error: verify_mkvol_req: bad volume creation request
>> [77361.682748] Volume creation request dump:
>> [77361.686826]  vol_id    0
>> [77361.689383]  alignment 1
>> [77361.691936]  bytes     0
>> [77361.694513]  vol_type  3
>> [77361.697068]  name_len  22
>> [77361.699708]  1st 16 characters of name: mkvol_bad:test_m
>> [77361.705119] UBI error: ubi_create_volume: not enough PEBs, only 680 available
>> [77361.712293] UBI error: ubi_create_volume: cannot create volume 0, error -28
>> [77361.719415] UBI error: ubi_create_volume: not enough PEBs, only 680 available
>> [77361.726655] UBI error: ubi_create_volume: cannot create volume 0, error -28
>> [77361.733804] UBI error: verify_mkvol_req: bad volume creation request
>
> These are fine.
>
>> [77361.740243] Volume creation request dump:
>> [77361.744301]  vol_id    0
>> [77361.746854]  alignment 1
>> [77361.749407]  bytes     126976
>> [77361.752397]  vol_type  7
>> [77361.754981]  name_len  22
>> [77361.757622]  1st 16 characters of name: mkvol_bad:test_m
>> [77361.926468] UBI error: ubi_create_volume: volume 0 already exists
>> [77361.932606] UBI error: ubi_create_volume: cannot create volume 0, error -17
>> [77361.939839] UBI error: ubi_create_volume: volume "mkvol_bad:test_mkvol()" exists (ID 0)
>> [77361.947946] UBI error: ubi_create_volume: cannot create volume 1, error -17
>> [77362.290898] UBI error: ubi_create_volume: volume "mkvol_bad:test_mkvol()" exists (ID 0)
>> [77362.299021] UBI error: ubi_create_volume: cannot create volume 1, error -17
>> [77405.406937] UBI error: ubi_open_volume: cannot open device 1, volume 128, error -22
>> [77405.420226] UBI error: ubi_open_volume: cannot open device 1, volume -1, error -22
>> [77405.427910] UBI error: ubi_open_volume: cannot open device 1, volume 128, error -22
>> [77405.435657] UBI error: ubi_open_volume: cannot open device 1, volume 0, error -19
>> [77405.774800] UBI error: ubi_open_volume: cannot open device 1, volume 0, error -19
>
> These are fine too.
>
>> Running mkvol_paral /dev/ubi1
>> Running rsvol /dev/ubi1
>> [rsvol] test_rsvol1():178: function open() failed with error 2 (No such file or directory)
>> [rsvol] test_rsvol1():179: cannot open "/dev/ubi1_0"
>
> That's one is odd.
> Do all other tests fail too?
> io_basic and io_parallel are interesting. You can also start them by hand.
>
> Thanks,
> //richard