[BUG] reproducable ubifs reboot assert and corruption

[BUG] reproducable ubifs reboot assert and corruption

[Andrew Ruder]

Just expanding distribution a little bit to see if anyone has any ideas.

On Tue, Jan 21, 2014 at 11:15:10PM -0600, Andrew Ruder wrote:
> Problem:
> ubifs corruption to the point where uboot can no longer deal with it and
> it takes multiple mounts to recover filesystem from Linux.
> 
> My hardware:
> NOR flash
> [    3.244397] 0.flash: Found 1 x16 devices at 0x0 in 16-bit bank. Manufacturer ID 0x000001 Chip ID 0x002301
> PXA270
> 
> My software:
> 3.12.0 with some patches (not mtd or ubi or flash related) to support my
> board.
> 
> I'm able to reproduce this fairly readily by the following sequence of
> commands.  I'm not able to trigger it with full debug messages enabled
> but possibly I could enable them for certain files within the ubifs
> driver if something specific would be helpful.  But basically it seems
> like if I reboot (or mount -o remount,ro) while ubifs is writing, it
> sometimes crashes and leaves the partition in a bad state.  Sorry about
> some of the strangeness of the commands, I am scripting this with expect
> and this is my lame attempt to give me something to pattern recognize
> off of.
> 
> I should also point out, I have not had any problems at all when I do an
> abrupt shutdown (either via pulling power or letting a hardware watchdog
> take care of the reset).
> 
> ==============================================================
> ==============================================================
> ==============================================================
> 
> Here's the log of ubifs driver crashing.
> 
> [    0.000000] Booting Linux on physical CPU 0x0
> [    0.000000] Linux version 3.12.0-00041-g7f12d39-dirty (andy at andrewruder-hplin) (gcc version 4.8.2 (Buildroot 2013.11-rc1-00028-gf388663) ) #210 PREEMPT Tue Jan 21 21:36:54 CST 2014
> [    0.000000] CPU: XScale-PXA270 [69054118] revision 8 (ARMv5TE), cr=0000397f
> ...
> [    3.211589] 0.flash: Found 1 x16 devices at 0x0 in 16-bit bank. Manufacturer ID 0x000001 Chip ID 0x002301
> [    3.322188] Amd/Fujitsu Extended Query Table at 0x0040
> [    3.327405]   Amd/Fujitsu Extended Query version 1.5.
> [    3.370661] number of CFI chips: 1
> [    3.378822] 5 cmdlinepart partitions found on MTD device 0.flash
> [    3.385273] Creating 5 MTD partitions on "0.flash":
> [    3.390212] 0x000000000000-0x000000080000 : "uboot"
> [    3.423423] 0x000000080000-0x0000000a0000 : "env"
> [    3.503423] 0x0000000a0000-0x0000000c0000 : "env_redund"
> [    3.603453] 0x0000000c0000-0x0000000e0000 : "env_default"
> [    3.674772] 0x0000000e0000-0x000004000000 : "data"
> ...
> Welcome to Buildroot
> buildroot login: root
> Password: 
> [root at buildroot ~]# echo 7 > /proc/sys/kernel/printk; a=$?; sleep 2 ; [ x$a = x0 ] || echo "@@FAIL@@"
> [root at buildroot ~]# ubiattach -m 4 -d 0; a=$?; sleep 2 ; [ x$a = x0 ] || echo "@@FAIL@@"
> [   10.055595] UBI: attaching mtd4 to ubi0
> [   10.107901] UBI: scanning is finished
> [   10.172362] UBI: attached mtd4 (name "data", size 63 MiB) to ubi0
> [   10.178509] UBI: PEB size: 131072 bytes (128 KiB), LEB size: 130944 bytes
> [   10.220887] UBI: min./max. I/O unit sizes: 1/512, sub-page size 1
> [   10.228545] UBI: VID header offset: 64 (aligned 64), data offset: 128
> [   10.240011] UBI: good PEBs: 505, bad PEBs: 0, corrupted PEBs: 0
> [   10.247227] UBI: user volume: 1, internal volumes: 1, max. volumes count: 128
> [   10.255658] UBI: max/mean erase counter: 42/22, WL threshold: 4096, image sequence number: 2104545903
> [   10.266343] UBI: available PEBs: 4, total reserved PEBs: 501, PEBs reserved for bad PEB handling: 0
> [   10.276740] UBI: background thread "ubi_bgt0d" started, PID 510
> UBI device number 0, total 505 LEBs (66126720 bytes, 63.1 MiB), available 4 LEBs (523776 bytes, 511.5 KiB), LEB size 130944 bytes (127.9 KiB)
> [root at buildroot ~]# mkdir -p /mnt; a=$?; sleep 2 ; [ x$a = x0 ] || echo "@@FAIL@@"
> [root at buildroot ~]# mount -t ubifs ubi0:rootfs /mnt; a=$?; sleep 2 ; [ x$a = x0 ] || echo "@@FAIL@@"
> [   14.463104] UBIFS: background thread "ubifs_bgt0_0" started, PID 516
> [   14.985636] UBIFS: mounted UBI device 0, volume 0, name "rootfs"
> [   14.991670] UBIFS: LEB size: 130944 bytes (127 KiB), min./max. I/O unit sizes: 8 bytes/512 bytes
> [   15.008984] UBIFS: FS size: 63769728 bytes (60 MiB, 487 LEBs), journal size 3142656 bytes (2 MiB, 24 LEBs)
> [   15.020052] UBIFS: reserved for root: 3012001 bytes (2941 KiB)
> [   15.027374] UBIFS: media format: w4/r0 (latest is w4/r0), UUID 567F5BCB-663D-4F84-BF34-3282E100D2D9, small LPT model
> [root at buildroot ~]# rm -fr /mnt/fsstress; a=$?; sleep 2 ; [ x$a = x0 ] || echo "@@FAIL@@"
> [root at buildroot ~]# mkdir -p /mnt/fsstress; a=$?; sleep 2 ; [ x$a = x0 ] || echo "@@FAIL@@"
> [root at buildroot ~]# (sleep 41 ; reboot) &
> [1] 522
> [root at buildroot ~]# fsstress -p 10 -n 10 -X -d /mnt/fsstress -l 0
> seed = 653587
> [   64.672770] UBIFS: background thread "ubifs_bgt0_0" stops
> The system is going down NOW!
> Sent SIGTERM to[   64.753793] UBIFS assert failed in reserve_space at 125 (pid 14)
>  all processes
> [   64.760886] CPU: 0 PID: 14 Comm: kworker/u2:1 Not tainted 3.12.0-00041-g7f12d39-dirty #210
> [1]+  Done                    ( [   64.773747] Workqueue: writeback bdi_writeback_workfnsleep 41; reboot (flush-ubifs_0_0) )
> Terminated
> 
> [   64.783579] [<c0013390>] (unwind_backtrace+0x0/0xe0) from [<c00110c8>] (show_stack+0x10/0x14)
> [   64.792304] [<c00110c8>] (show_stack+0x10/0x14) from [<c00f2500>] (make_reservation+0x80/0x46c)
> [   64.801054] [<c00f2500>] (make_reservation+0x80/0x46c) from [<c00f3630>] (ubifs_jnl_write_inode+0x90/0x1dc)
> [root at buildroot [   64.811456] [<c00f3630>] (ubifs_jnl_write_inode+0x90/0x1dc) from [<c00f9f60>] (ubifs_write_inode+0xc0/0x140)
> ~]# [   64.822628] [<c00f9f60>] (ubifs_write_inode+0xc0/0x140) from [<c00b99a0>] (__writeback_single_inode+0xe8/0xfc)
> [   64.832988] [<c00b99a0>] (__writeback_single_inode+0xe8/0xfc) from [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c)
> [   64.843435] [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c) from [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4)
> [   64.853547] [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4) from [<c00ba8ec>] (wb_writeback+0x10c/0x1a4)
> [   64.863020] [<c00ba8ec>] (wb_writeback+0x10c/0x1a4) from [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304)
> [   64.872487] [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304) from [<c0030db0>] (process_one_work+0x208/0x344)
> [   64.882286] [<c0030db0>] (process_one_work+0x208/0x344) from [<c00313a8>] (worker_thread+0x22c/0x36c)
> [   64.891555] [<c00313a8>] (worker_thread+0x22c/0x36c) from [<c0035d40>] (kthread+0xa0/0xac)
> [   64.899904] [<c0035d40>] (kthread+0xa0/0xac) from [<c000e0f0>] (ret_from_fork+0x14/0x24)
> [   64.908159] UBIFS assert failed in ubifs_wbuf_write_nolock at 691 (pid 14)
> [   64.915120] CPU: 0 PID: 14 Comm: kworker/u2:1 Not tainted 3.12.0-00041-g7f12d39-dirty #210
> [   64.923452] Workqueue: writeback bdi_writeback_workfn (flush-ubifs_0_0)
> [   64.930177] [<c0013390>] (unwind_backtrace+0x0/0xe0) from [<c00110c8>] (show_stack+0x10/0x14)
> [   64.938823] [<c00110c8>] (show_stack+0x10/0x14) from [<c00ffe10>] (ubifs_wbuf_write_nolock+0x244/0x7dc)
> [   64.948291] [<c00ffe10>] (ubifs_wbuf_write_nolock+0x244/0x7dc) from [<c00f2cfc>] (write_head.constprop.14+0x84/0xb0)
> [   64.958876] [<c00f2cfc>] (write_head.constprop.14+0x84/0xb0) from [<c00f3668>] (ubifs_jnl_write_inode+0xc8/0x1dc)
> [   64.969196] [<c00f3668>] (ubifs_jnl_write_inode+0xc8/0x1dc) from [<c00f9f60>] (ubifs_write_inode+0xc0/0x140)
> [   64.979089] [<c00f9f60>] (ubifs_write_inode+0xc0/0x140) from [<c00b99a0>] (__writeback_single_inode+0xe8/0xfc)
> [   64.989160] [<c00b99a0>] (__writeback_single_inode+0xe8/0xfc) from [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c)
> [   64.999487] [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c) from [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4)
> [   65.009545] [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4) from [<c00ba8ec>] (wb_writeback+0x10c/0x1a4)
> [   65.019000] [<c00ba8ec>] (wb_writeback+0x10c/0x1a4) from [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304)
> [   65.028475] [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304) from [<c0030db0>] (process_one_work+0x208/0x344)
> [   65.038284] [<c0030db0>] (process_one_work+0x208/0x344) from [<c00313a8>] (worker_thread+0x22c/0x36c)
> [   65.047577] [<c00313a8>] (worker_thread+0x22c/0x36c) from [<c0035d40>] (kthread+0xa0/0xac)
> [   65.055909] [<c0035d40>] (kthread+0xa0/0xac) from [<c000e0f0>] (ret_from_fork+0x14/0x24)
> [   65.064740] UBIFS assert failed in reserve_space at 125 (pid 14)
> [   65.070780] CPU: 0 PID: 14 Comm: kworker/u2:1 Not tainted 3.12.0-00041-g7f12d39-dirty #210
> [   65.079212] Workqueue: writeback bdi_writeback_workfn (flush-ubifs_0_0)
> [   65.085974] [<c0013390>] (unwind_backtrace+0x0/0xe0) from [<c00110c8>] (show_stack+0x10/0x14)
> [   65.094584] [<c00110c8>] (show_stack+0x10/0x14) from [<c00f2500>] (make_reservation+0x80/0x46c)
> [   65.103362] [<c00f2500>] (make_reservation+0x80/0x46c) from [<c00f345c>] (ubifs_jnl_write_data+0x198/0x2dc)
> [   65.113174] [<c00f345c>] (ubifs_jnl_write_data+0x198/0x2dc) from [<c00f5048>] (do_writepage+0xc0/0x1fc)
> [   65.122630] [<c00f5048>] (do_writepage+0xc0/0x1fc) from [<c006d4ec>] (__writepage+0x14/0x5c)
> [   65.131099] [<c006d4ec>] (__writepage+0x14/0x5c) from [<c006db84>] (write_cache_pages+0x23c/0x330)
> [   65.140122] [<c006db84>] (write_cache_pages+0x23c/0x330) from [<c006dcb4>] (generic_writepages+0x3c/0x58)
> [   65.149751] [<c006dcb4>] (generic_writepages+0x3c/0x58) from [<c00b98ec>] (__writeback_single_inode+0x34/0xfc)
> [   65.159814] [<c00b98ec>] (__writeback_single_inode+0x34/0xfc) from [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c)
> [   65.170141] [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c) from [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4)
> [   65.180205] [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4) from [<c00ba8ec>] (wb_writeback+0x10c/0x1a4)
> [   65.189663] [<c00ba8ec>] (wb_writeback+0x10c/0x1a4) from [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304)
> [   65.199127] [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304) from [<c0030db0>] (process_one_work+0x208/0x344)
> [   65.208930] [<c0030db0>] (process_one_work+0x208/0x344) from [<c00313a8>] (worker_thread+0x22c/0x36c)
> [   65.218227] [<c00313a8>] (worker_thread+0x22c/0x36c) from [<c0035d40>] (kthread+0xa0/0xac)
> [   65.226564] [<c0035d40>] (kthread+0xa0/0xac) from [<c000e0f0>] (ret_from_fork+0x14/0x24)
> [   65.234798] UBIFS assert failed in ubifs_wbuf_write_nolock at 691 (pid 14)
> [   65.241702] CPU: 0 PID: 14 Comm: kworker/u2:1 Not tainted 3.12.0-00041-g7f12d39-dirty #210
> [   65.250053] Workqueue: writeback bdi_writeback_workfn (flush-ubifs_0_0)
> [   65.256797] [<c0013390>] (unwind_backtrace+0x0/0xe0) from [<c00110c8>] (show_stack+0x10/0x14)
> [   65.265404] [<c00110c8>] (show_stack+0x10/0x14) from [<c00ffe10>] (ubifs_wbuf_write_nolock+0x244/0x7dc)
> [   65.274857] [<c00ffe10>] (ubifs_wbuf_write_nolock+0x244/0x7dc) from [<c00f34d8>] (ubifs_jnl_write_data+0x214/0x2dc)
> [   65.285346] [<c00f34d8>] (ubifs_jnl_write_data+0x214/0x2dc) from [<c00f5048>] (do_writepage+0xc0/0x1fc)
> [   65.294798] [<c00f5048>] (do_writepage+0xc0/0x1fc) from [<c006d4ec>] (__writepage+0x14/0x5c)
> [   65.303295] [<c006d4ec>] (__writepage+0x14/0x5c) from [<c006db84>] (write_cache_pages+0x23c/0x330)
> [   65.312310] [<c006db84>] (write_cache_pages+0x23c/0x330) from [<c006dcb4>] (generic_writepages+0x3c/0x58)
> [   65.321940] [<c006dcb4>] (generic_writepages+0x3c/0x58) from [<c00b98ec>] (__writeback_single_inode+0x34/0xfc)
> [   65.332008] [<c00b98ec>] (__writeback_single_inode+0x34/0xfc) from [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c)
> [   65.342330] [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c) from [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4)
> [   65.352393] [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4) from [<c00ba8ec>] (wb_writeback+0x10c/0x1a4)
> [   65.361818] [<c00ba8ec>] (wb_writeback+0x10c/0x1a4) from [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304)
> [   65.371272] [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304) from [<c0030db0>] (process_one_work+0x208/0x344)
> [   65.381070] [<c0030db0>] (process_one_work+0x208/0x344) from [<c00313a8>] (worker_thread+0x22c/0x36c)
> [   65.390351] [<c00313a8>] (worker_thread+0x22c/0x36c) from [<c0035d40>] (kthread+0xa0/0xac)
> [   65.398679] [<c0035d40>] (kthread+0xa0/0xac) from [<c000e0f0>] (ret_from_fork+0x14/0x24)
> [   65.407416] UBIFS assert failed in reserve_space at 125 (pid 14)
> [   65.413585] CPU: 0 PID: 14 Comm: kworker/u2:1 Not tainted 3.12.0-00041-g7f12d39-dirty #210
> [   65.421910] Workqueue: writeback bdi_writeback_workfn (flush-ubifs_0_0)
> [   65.428674] [<c0013390>] (unwind_backtrace+0x0/0xe0) from [<c00110c8>] (show_stack+0x10/0x14)
> [   65.437276] [<c00110c8>] (show_stack+0x10/0x14) from [<c00f2500>] (make_reservation+0x80/0x46c)
> [   65.446041] [<c00f2500>] (make_reservation+0x80/0x46c) from [<c00f345c>] (ubifs_jnl_write_data+0x198/0x2dc)
> [   65.455839] [<c00f345c>] (ubifs_jnl_write_data+0x198/0x2dc) from [<c00f5048>] (do_writepage+0xc0/0x1fc)
> [   65.465290] [<c00f5048>] (do_writepage+0xc0/0x1fc) from [<c006d4ec>] (__writepage+0x14/0x5c)
> [   65.473786] [<c006d4ec>] (__writepage+0x14/0x5c) from [<c006db84>] (write_cache_pages+0x23c/0x330)
> [   65.482807] [<c006db84>] (write_cache_pages+0x23c/0x330) from [<c006dcb4>] (generic_writepages+0x3c/0x58)
> [   65.492439] [<c006dcb4>] (generic_writepages+0x3c/0x58) from [<c00b98ec>] (__writeback_single_inode+0x34/0xfc)
> [   65.502501] [<c00b98ec>] (__writeback_single_inode+0x34/0xfc) from [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c)
> [   65.512820] [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c) from [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4)
> [   65.522883] [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4) from [<c00ba8ec>] (wb_writeback+0x10c/0x1a4)
> [   65.532342] [<c00ba8ec>] (wb_writeback+0x10c/0x1a4) from [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304)
> [   65.541781] [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304) from [<c0030db0>] (process_one_work+0x208/0x344)
> [   65.551589] [<c0030db0>] (process_one_work+0x208/0x344) from [<c00313a8>] (worker_thread+0x22c/0x36c)
> [   65.560880] [<c00313a8>] (worker_thread+0x22c/0x36c) from [<c0035d40>] (kthread+0xa0/0xac)
> [   65.569215] [<c0035d40>] (kthread+0xa0/0xac) from [<c000e0f0>] (ret_from_fork+0x14/0x24)
> [   65.577442] UBIFS assert failed in ubifs_wbuf_write_nolock at 691 (pid 14)
> [   65.584389] CPU: 0 PID: 14 Comm: kworker/u2:1 Not tainted 3.12.0-00041-g7f12d39-dirty #210
> [   65.592715] Workqueue: writeback bdi_writeback_workfn (flush-ubifs_0_0)
> [   65.599412] [<c0013390>] (unwind_backtrace+0x0/0xe0) from [<c00110c8>] (show_stack+0x10/0x14)
> [   65.608038] [<c00110c8>] (show_stack+0x10/0x14) from [<c00ffe10>] (ubifs_wbuf_write_nolock+0x244/0x7dc)
> [   65.617493] [<c00ffe10>] (ubifs_wbuf_write_nolock+0x244/0x7dc) from [<c00f34d8>] (ubifs_jnl_write_data+0x214/0x2dc)
> [   65.627984] [<c00f34d8>] (ubifs_jnl_write_data+0x214/0x2dc) from [<c00f5048>] (do_writepage+0xc0/0x1fc)
> [   65.637436] [<c00f5048>] (do_writepage+0xc0/0x1fc) from [<c006d4ec>] (__writepage+0x14/0x5c)
> [   65.645932] [<c006d4ec>] (__writepage+0x14/0x5c) from [<c006db84>] (write_cache_pages+0x23c/0x330)
> [   65.654964] [<c006db84>] (write_cache_pages+0x23c/0x330) from [<c006dcb4>] (generic_writepages+0x3c/0x58)
> [   65.664605] [<c006dcb4>] (generic_writepages+0x3c/0x58) from [<c00b98ec>] (__writeback_single_inode+0x34/0xfc)
> [   65.674680] [<c00b98ec>] (__writeback_single_inode+0x34/0xfc) from [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c)
> [   65.685002] [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c) from [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4)
> [   65.695061] [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4) from [<c00ba8ec>] (wb_writeback+0x10c/0x1a4)
> [   65.704514] [<c00ba8ec>] (wb_writeback+0x10c/0x1a4) from [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304)
> [   65.713968] [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304) from [<c0030db0>] (process_one_work+0x208/0x344)
> [   65.723770] [<c0030db0>] (process_one_work+0x208/0x344) from [<c00313a8>] (worker_thread+0x22c/0x36c)
> [   65.733050] [<c00313a8>] (worker_thread+0x22c/0x36c) from [<c0035d40>] (kthread+0xa0/0xac)
> [   65.741349] [<c0035d40>] (kthread+0xa0/0xac) from [<c000e0f0>] (ret_from_fork+0x14/0x24)
> [   65.749527] UBIFS assert failed in ubifs_leb_write at 122 (pid 14)
> [   65.755767] CPU: 0 PID: 14 Comm: kworker/u2:1 Not tainted 3.12.0-00041-g7f12d39-dirty #210
> [   65.764086] Workqueue: writeback bdi_writeback_workfn (flush-ubifs_0_0)
> [   65.770778] [<c0013390>] (unwind_backtrace+0x0/0xe0) from [<c00110c8>] (show_stack+0x10/0x14)
> [   65.779391] [<c00110c8>] (show_stack+0x10/0x14) from [<c00feacc>] (ubifs_leb_write+0x4c/0x11c)
> Sent SIGKILL to[   65.790297] [<c00feacc>] (ubifs_leb_write+0x4c/0x11c) from [<c010002c>] (ubifs_wbuf_write_nolock+0x460/0x7dc)
> [   65.800424] [<c010002c>] (ubifs_wbuf_write_nolock+0x460/0x7dc) from [<c00f34d8>] (ubifs_jnl_write_data+0x214/0x2dc)
> [   65.811038] [<c00f34d8>] (ubifs_jnl_write_data+0x214/0x2dc) from [<c00f5048>] (do_writepage+0xc0/0x1fc)
> [   65.820627] [<c00f5048>] (do_writepage+0xc0/0x1fc) from [<c006d4ec>] (__writepage+0x14/0x5c)
> [   65.829195] [<c006d4ec>] (__writepage+0x14/0x5c) from [<c006db84>] (write_cache_pages+0x23c/0x330)
> [   65.838236] [<c006db84>] (write_cache_pages+0x23c/0x330) from [<c006dcb4>] (generic_writepages+0x3c/0x58)
> [   65.847988] [<c006dcb4>] (generic_writepages+0x3c/0x58) from [<c00b98ec>] (__writeback_single_inode+0x34/0xfc)
> [   65.858194] [<c00b98ec>] (__writeback_single_inode+0x34/0xfc) from [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c)
> [   65.868593] [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c) from [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4)
> [   65.878679] [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4) from [<c00ba8ec>] (wb_writeback+0x10c/0x1a4)
> [   65.888133] [<c00ba8ec>] (wb_writeback+0x10c/0x1a4) from [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304)
> [   65.897596] [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304) from [<c0030db0>] (process_one_work+0x208/0x344)
> [   65.907392] [<c0030db0>] (process_one_work+0x208/0x344) from [<c00313a8>] (worker_thread+0x22c/0x36c)
> [   65.916685] [<c00313a8>] (worker_thread+0x22c/0x36c) from [<c0035d40>] (kthread+0xa0/0xac)
> [   65.925018] [<c0035d40>] (kthread+0xa0/0xac) from [<c000e0f0>] (ret_from_fork+0x14/0x24)
> [   65.934393] UBIFS assert failed in reserve_space at 125 (pid 14)
> [   65.940435] CPU: 0 PID: 14 Comm: kworker/u2:1 Not tainted 3.12.0-00041-g7f12d39-dirty #210
> [   65.948879] Workqueue: writeback bdi_writeback_workfn (flush-ubifs_0_0)
> [   65.955654] [<c0013390>] (unwind_backtrace+0x0/0xe0) from [<c00110c8>] (show_stack+0x10/0x14)
> [   65.964264] [<c00110c8>] (show_stack+0x10/0x14) from [<c00f2500>] (make_reservation+0x80/0x46c)
> [   65.973019] [<c00f2500>] (make_reservation+0x80/0x46c) from [<c00f345c>] (ubifs_jnl_write_data+0x198/0x2dc)
> [   65.982820] [<c00f345c>] (ubifs_jnl_write_data+0x198/0x2dc) from [<c00f5048>] (do_writepage+0xc0/0x1fc)
> [   65.992271] [<c00f5048>] (do_writepage+0xc0/0x1fc) from [<c006d4ec>] (__writepage+0x14/0x5c)
> [   66.000743] [<c006d4ec>] (__writepage+0x14/0x5c) from [<c006db84>] (write_cache_pages+0x23c/0x330)
> [   66.009760] [<c006db84>] (write_cache_pages+0x23c/0x330) from [<c006dcb4>] (generic_writepages+0x3c/0x58)
> [   66.019387] [<c006dcb4>] (generic_writepages+0x3c/0x58) from [<c00b98ec>] (__writeback_single_inode+0x34/0xfc)
> [   66.029460] [<c00b98ec>] (__writeback_single_inode+0x34/0xfc) from [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c)
> [   66.039783] [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c) from [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4)
> [   66.049843] [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4) from [<c00ba8ec>] (wb_writeback+0x10c/0x1a4)
> [   66.059303] [<c00ba8ec>] (wb_writeback+0x10c/0x1a4) from [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304)
> [   66.068770] [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304) from [<c0030db0>] (process_one_work+0x208/0x344)
> [   66.078568] [<c0030db0>] (process_one_work+0x208/0x344) from [<c00313a8>] (worker_thread+0x22c/0x36c)
> [   66.087861] [<c00313a8>] (worker_thread+0x22c/0x36c) from [<c0035d40>] (kthread+0xa0/0xac)
> [   66.096199] [<c0035d40>] (kthread+0xa0/0xac) from [<c000e0f0>] (ret_from_fork+0x14/0x24)
> [   66.104420] UBIFS assert failed in ubifs_wbuf_write_nolock at 691 (pid 14)
> [   66.111315] CPU: 0 PID: 14 Comm: kworker/u2:1 Not tainted 3.12.0-00041-g7f12d39-dirty #210
> [   66.119654] Workqueue: writeback bdi_writeback_workfn (flush-ubifs_0_0)
> [   66.126379] [<c0013390>] (unwind_backtrace+0x0/0xe0) from [<c00110c8>] (show_stack+0x10/0x14)
> [   66.134988] [<c00110c8>] (show_stack+0x10/0x14) from [<c00ffe10>] (ubifs_wbuf_write_nolock+0x244/0x7dc)
> [   66.144452] [<c00ffe10>] (ubifs_wbuf_write_nolock+0x244/0x7dc) from [<c00f34d8>] (ubifs_jnl_write_data+0x214/0x2dc)
> [   66.154956] [<c00f34d8>] (ubifs_jnl_write_data+0x214/0x2dc) from [<c00f5048>] (do_writepage+0xc0/0x1fc)
> [   66.164415] [<c00f5048>] (do_writepage+0xc0/0x1fc) from [<c006d4ec>] (__writepage+0x14/0x5c)
> [   66.172904] [<c006d4ec>] (__writepage+0x14/0x5c) from [<c006db84>] (write_cache_pages+0x23c/0x330)
> [   66.181892] [<c006db84>] (write_cache_pages+0x23c/0x330) from [<c006dcb4>] (generic_writepages+0x3c/0x58)
> [   66.191527] [<c006dcb4>] (generic_writepages+0x3c/0x58) from [<c00b98ec>] (__writeback_single_inode+0x34/0xfc)
> [   66.201593] [<c00b98ec>] (__writeback_single_inode+0x34/0xfc) from [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c)
> [   66.211919] [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c) from [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4)
> [   66.222000] [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4) from [<c00ba8ec>] (wb_writeback+0x10c/0x1a4)
> [   66.231430] [<c00ba8ec>] (wb_writeback+0x10c/0x1a4) from [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304)
> [   66.240898] [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304) from [<c0030db0>] (process_one_work+0x208/0x344)
> [   66.250705] [<c0030db0>] (process_one_work+0x208/0x344) from [<c00313a8>] (worker_thread+0x22c/0x36c)
> [   66.259989] [<c00313a8>] (worker_thread+0x22c/0x36c) from [<c0035d40>] (kthread+0xa0/0xac)
> [   66.268314] [<c0035d40>] (kthread+0xa0/0xac) from [<c000e0f0>] (ret_from_fork+0x14/0x24)
> [   66.277052] UBIFS assert failed in reserve_space at 125 (pid 14)
> [   66.283220] CPU: 0 PID: 14 Comm: kworker/u2:1 Not tainted 3.12.0-00041-g7f12d39-dirty #210
> [   66.291545] Workqueue: writeback bdi_writeback_workfn (flush-ubifs_0_0)
> [   66.298329] [<c0013390>] (unwind_backtrace+0x0/0xe0) from [<c00110c8>] (show_stack+0x10/0x14)
> [   66.306939] [<c00110c8>] (show_stack+0x10/0x14) from [<c00f2500>] (make_reservation+0x80/0x46c)
> [   66.315700] [<c00f2500>] (make_reservation+0x80/0x46c) from [<c00f345c>] (ubifs_jnl_write_data+0x198/0x2dc)
> [   66.325498] [<c00f345c>] (ubifs_jnl_write_data+0x198/0x2dc) from [<c00f5048>] (do_writepage+0xc0/0x1fc)
> [   66.334950] [<c00f5048>] (do_writepage+0xc0/0x1fc) from [<c006d4ec>] (__writepage+0x14/0x5c)
> [   66.343447] [<c006d4ec>] (__writepage+0x14/0x5c) from [<c006db84>] (write_cache_pages+0x23c/0x330)
> [   66.352458] [<c006db84>] (write_cache_pages+0x23c/0x330) from [<c006dcb4>] (generic_writepages+0x3c/0x58)
> [   66.362096] [<c006dcb4>] (generic_writepages+0x3c/0x58) from [<c00b98ec>] (__writeback_single_inode+0x34/0xfc)
> [   66.372167] [<c00b98ec>] (__writeback_single_inode+0x34/0xfc) from [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c)
> [   66.382495] [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c) from [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4)
> [   66.392556] [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4) from [<c00ba8ec>] (wb_writeback+0x10c/0x1a4)
> [   66.402011] [<c00ba8ec>] (wb_writeback+0x10c/0x1a4) from [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304)
> [   66.411450] [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304) from [<c0030db0>] (process_one_work+0x208/0x344)
> [   66.421264] [<c0030db0>] (process_one_work+0x208/0x344) from [<c00313a8>] (worker_thread+0x22c/0x36c)
> [   66.430556] [<c00313a8>] (worker_thread+0x22c/0x36c) from [<c0035d40>] (kthread+0xa0/0xac)
> [   66.438895] [<c0035d40>] (kthread+0xa0/0xac) from [<c000e0f0>] (ret_from_fork+0x14/0x24)
> [   66.447126] UBIFS assert failed in ubifs_wbuf_write_nolock at 691 (pid 14)
> [   66.454079] CPU: 0 PID: 14 Comm: kworker/u2:1 Not tainted 3.12.0-00041-g7f12d39-dirty #210
> [   66.462399] Workqueue: writeback bdi_writeback_workfn (flush-ubifs_0_0)
> [   66.469093] [<c0013390>] (unwind_backtrace+0x0/0xe0) from [<c00110c8>] (show_stack+0x10/0x14)
> [   66.477706] [<c00110c8>] (show_stack+0x10/0x14) from [<c00ffe10>] (ubifs_wbuf_write_nolock+0x244/0x7dc)
> [   66.487162] [<c00ffe10>] (ubifs_wbuf_write_nolock+0x244/0x7dc) from [<c00f34d8>] (ubifs_jnl_write_data+0x214/0x2dc)
> [   66.497653] [<c00f34d8>] (ubifs_jnl_write_data+0x214/0x2dc) from [<c00f5048>] (do_writepage+0xc0/0x1fc)
> [   66.507103] [<c00f5048>] (do_writepage+0xc0/0x1fc) from [<c006d4ec>] (__writepage+0x14/0x5c)
> [   66.515593] [<c006d4ec>] (__writepage+0x14/0x5c) from [<c006db84>] (write_cache_pages+0x23c/0x330)
> [   66.524603] [<c006db84>] (write_cache_pages+0x23c/0x330) from [<c006dcb4>] (generic_writepages+0x3c/0x58)
> [   66.534228] [<c006dcb4>] (generic_writepages+0x3c/0x58) from [<c00b98ec>] (__writeback_single_inode+0x34/0xfc)
> [   66.544289] [<c00b98ec>] (__writeback_single_inode+0x34/0xfc) from [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c)
> [   66.554609] [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c) from [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4)
> [   66.564671] [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4) from [<c00ba8ec>] (wb_writeback+0x10c/0x1a4)
> [   66.574124] [<c00ba8ec>] (wb_writeback+0x10c/0x1a4) from [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304)
> [   66.583579] [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304) from [<c0030db0>] (process_one_work+0x208/0x344)
> [   66.593378] [<c0030db0>] (process_one_work+0x208/0x344) from [<c00313a8>] (worker_thread+0x22c/0x36c)
> [   66.602658] [<c00313a8>] (worker_thread+0x22c/0x36c) from [<c0035d40>] (kthread+0xa0/0xac)
> [   66.610959] [<c0035d40>] (kthread+0xa0/0xac) from [<c000e0f0>] (ret_from_fork+0x14/0x24)
> [   66.619785] UBIFS assert failed in reserve_space at 125 (pid 14)
> [   66.625961] CPU: 0 PID: 14 Comm: kworker/u2:1 Not tainted 3.12.0-00041-g7f12d39-dirty #210
> [   66.634324] Workqueue: writeback bdi_writeback_workfn (flush-ubifs_0_0)
> [   66.641055] [<c0013390>] (unwind_backtrace+0x0/0xe0) from [<c00110c8>] (show_stack+0x10/0x14)
> [   66.649675] [<c00110c8>] (show_stack+0x10/0x14) from [<c00f2500>] (make_reservation+0x80/0x46c)
> [   66.658435] [<c00f2500>] (make_reservation+0x80/0x46c) from [<c00f345c>] (ubifs_jnl_write_data+0x198/0x2dc)
> [   66.668239] [<c00f345c>] (ubifs_jnl_write_data+0x198/0x2dc) from [<c00f5048>] (do_writepage+0xc0/0x1fc)
> [   66.677692] [<c00f5048>] (do_writepage+0xc0/0x1fc) from [<c006d4ec>] (__writepage+0x14/0x5c)
> [   66.686189] [<c006d4ec>] (__writepage+0x14/0x5c) from [<c006db84>] (write_cache_pages+0x23c/0x330)
> [   66.695206] [<c006db84>] (write_cache_pages+0x23c/0x330) from [<c006dcb4>] (generic_writepages+0x3c/0x58)
> [   66.704830] [<c006dcb4>] (generic_writepages+0x3c/0x58) from [<c00b98ec>] (__writeback_single_inode+0x34/0xfc)
> [   66.714893] [<c00b98ec>] (__writeback_single_inode+0x34/0xfc) from [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c)
> [   66.725213] [<c00ba5c0>] (writeback_sb_inodes+0x200/0x37c) from [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4)
> [   66.735272] [<c00ba7a4>] (__writeback_inodes_wb+0x68/0xa4) from [<c00ba8ec>] (wb_writeback+0x10c/0x1a4)
> [   66.744727] [<c00ba8ec>] (wb_writeback+0x10c/0x1a4) from [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304)
> [   66.754190] [<c00baaa4>] (bdi_writeback_workfn+0x78/0x304) from [<c0030db0>] (process_one_work+0x208/0x344)
> [   66.763988] [<c0030db0>] (process_one_work+0x208/0x344) from [<c00313a8>] (worker_thread+0x22c/0x36c)
> [   66.773279] [<c00313a8>] (worker_thread+0x22c/0x36c) from [<c0035d40>] (kthread+0xa0/0xac)
> [   66.781580] [<c0035d40>] (kthread+0xa0/0xac) from [<c000e0f0>] (ret_from_fork+0x14/0x24)
> [   66.789798] UBIFS assert failed in ubifs_wbuf_write_nolock at 691 (pid 14)
> [   66.797145] CPU: 0 PID: 14 Comm: kworker/u2:1 Not tainted 3.12.0-00041-g7f12d39-dirty #210
> [   66.808684] reboot: Restarting system
> 
> ==============================================================
> ==============================================================
> ==============================================================
> 
> Here's what happens if I then try to mount/load a file from u-boot.
> 
> U-Boot 2013.10-00014-gce4b76b (Nov 25 2013 - 17:12:39)
> 
> CPU: Marvell PXA27x rev. Unknown
> Checking SDRAM U16/U20 data
> pass
> Checking SDRAM U44/U45 data
> pass
> Checking SDRAM U16/U20 address
> pass
> Checking SDRAM U44/U45 address
> pass
> DRAM:  256 MiB
> WARNING: Caches not enabled
> Flash: 64 MiB
> MMC:   PXA MMC: 0
> In:    serial
> Out:   serial
> Err:   serial
> KSZ8895MQ REV0 found, configuring...done
> Net:   dm9000
> Warning: dm9000 using MAC address from net device
> 
> Hit any key to stop autoboot:  0 
> $ <INTERRUPT>
> $ <INTERRUPT>
> $ <INTERRUPT>
> $ ubi part data || echo FAIL ; ubifsmount ubi0:rootfs || echo FAIL ; ubifsload ${scratch} ${kernel.ubi.path} || echo FAIL
> UBI: attaching mtd1 to ubi0
> UBI: physical eraseblock size:   131072 bytes (128 KiB)
> UBI: logical eraseblock size:    130944 bytes
> UBI: smallest flash I/O unit:    1
> UBI: VID header offset:          64 (aligned 64)
> UBI: data offset:                128
> UBI: attached mtd1 to ubi0
> UBI: MTD device name:            "mtd=4"
> UBI: MTD device size:            63 MiB
> UBI: number of good PEBs:        505
> UBI: number of bad PEBs:         0
> UBI: max. allowed volumes:       128
> UBI: wear-leveling threshold:    4096
> UBI: number of internal volumes: 1
> UBI: number of user volumes:     1
> UBI: available PEBs:             4
> UBI: total number of reserved PEBs: 501
> UBI: number of PEBs reserved for bad PEB handling: 0
> UBI: max/mean erase counter: 42/22
> UBIFS error (pid 0): ubifs_check_node: bad CRC: calculated 0x5bfc9168, read 0x653f8e7
> UBIFS error (pid 0): ubifs_check_node: bad node at LEB 46:61392
> UBIFS error (pid 0): ubifs_scanned_corruption: corrupted data at LEB 46:61392
> UBIFS error (pid 0): ubifs_scan: LEB 46 scanning failed
> UBIFS error (pid 0): ubifs_mount: Error reading superblock on volume 'ubi0:rootfs' errno=-117!
> 
> ubifsmount - mount UBIFS volume
> 
> Usage:
> ubifsmount <volume-name>
>     - mount 'volume-name' volume
> FAIL
> UBIFS not mounted, use ubifs mount to mount volume first!
> ubifsload - load file from an UBIFS filesystem
> 
> Usage:
> ubifsload <addr> <filename> [bytes]
>     - load file 'filename' to address 'addr'
> FAIL
> $ We have corrupted our ubifs partition (Run #1)
>     while executing
> "return -level 1 -code error $errorMsg"
> 
> ==============================================================
> ==============================================================
> ==============================================================
> 
> Here's the recovery process from Linux.  Note that I mount twice to get
> a successful mount.
> 
> [root at buildroot ~]# echo 7 > /proc/sys/kernel/printk
> [root at buildroot ~]# ubiattach -m4 -d0
> [   45.556102] UBI: attaching mtd4 to ubi0
> [   45.608396] UBI: scanning is finished
> [   45.672433] UBI: attached mtd4 (name "data", size 63 MiB) to ubi0
> [   45.678581] UBI: PEB size: 131072 bytes (128 KiB), LEB size: 130944 bytes
> [   45.720983] UBI: min./max. I/O unit sizes: 1/512, sub-page size 1
> [   45.728883] UBI: VID header offset: 64 (aligned 64), data offset: 128
> [   45.740496] UBI: good PEBs: 505, bad PEBs: 0, corrupted PEBs: 0
> [   45.747679] UBI: user volume: 1, internal volumes: 1, max. volumes count: 128
> [   45.756101] UBI: max/mean erase counter: 42/22, WL threshold: 4096, image sequence number: 2104545903
> [   45.766843] UBI: available PEBs: 4, total reserved PEBs: 501, PEBs reserved for bad PEB handling: 0
> [   45.777256] UBI: background thread "ubi_bgt0d" started, PID 509
> UBI device number 0, total 505 LEBs (66126720 bytes, 63.1 MiB), available 4 LEBs (523776 bytes, 511.5 KiB), LEB size 130944 bytes (127.9 KiB)
> [root at buildroot ~]# mount -t ubifs ubi0:rootfs /mnt
> [   59.813152] UBIFS: background thread "ubifs_bgt0_0" started, PID 512
> [   60.436819] UBIFS error (pid 510): ubifs_check_node: bad CRC: calculated 0x5bfc9168, read 0x653f8e7
> [   60.470007] UBIFS error (pid 510): ubifs_check_node: bad node at LEB 46:61392
> [   60.491545]  magic          0x6101831
> [   60.495442]  crc            0x653f8e7
> [   60.499127]  node_type      1 (data node)
> [   60.503205]  group_type     0 (no node group)
> [   60.507577]  sqnum          32292
> [   60.510910]  len            92
> [   60.514016]  key            (3682, data, 174)
> [   60.518383]  size           4096
> [   60.521620]  compr_typ      1
> [   60.524648]  data size      44
> [   60.527712]  data:
> [   60.529753]  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 ff ff ff ff ff ff ff ff
> [   60.540515]  00000020: ff ff ff ff ff ff ff ff ff ff ff ff
> [   60.553316] CPU: 0 PID: 510 Comm: mount Not tainted 3.12.0-00041-g7f12d39-dirty #210
> [   60.561188] [<c0013390>] (unwind_backtrace+0x0/0xe0) from [<c00110c8>] (show_stack+0x10/0x14)
> [   60.601841] [<c00110c8>] (show_stack+0x10/0x14) from [<c00ff15c>] (ubifs_check_node+0x27c/0x2b8)
> [   60.613301] [<c00ff15c>] (ubifs_check_node+0x27c/0x2b8) from [<c0105dd8>] (ubifs_scan_a_node+0x14c/0x290)
> [   60.624261] [<c0105dd8>] (ubifs_scan_a_node+0x14c/0x290) from [<c0106334>] (ubifs_scan+0x98/0x31c)
> [   60.634852] [<c0106334>] (ubifs_scan+0x98/0x31c) from [<c0107184>] (ubifs_replay_journal+0x8c0/0x1550)
> [   60.645449] [<c0107184>] (ubifs_replay_journal+0x8c0/0x1550) from [<c00fc10c>] (ubifs_mount+0xd30/0x1960)
> [   60.656319] [<c00fc10c>] (ubifs_mount+0xd30/0x1960) from [<c009d0d8>] (mount_fs+0x10/0xc0)
> [   60.665944] [<c009d0d8>] (mount_fs+0x10/0xc0) from [<c00b2d78>] (vfs_kern_mount+0x48/0xc4)
> [   60.675557] [<c00b2d78>] (vfs_kern_mount+0x48/0xc4) from [<c00b502c>] (do_mount+0x6fc/0x800)
> [   60.685354] [<c00b502c>] (do_mount+0x6fc/0x800) from [<c00b51b4>] (SyS_mount+0x84/0xb8)
> [   60.694719] [<c00b51b4>] (SyS_mount+0x84/0xb8) from [<c000e060>] (ret_fast_syscall+0x0/0x2c)
> [   60.704467] UBIFS error (pid 510): ubifs_scan: bad node
> [   60.709747] UBIFS error (pid 510): ubifs_scanned_corruption: corruption at LEB 46:61392
> [   60.719347] UBIFS error (pid 510): ubifs_scanned_corruption: first 8192 bytes from LEB 46:61392
> [   60.756438] UBIFS error (pid 510): ubifs_scan: LEB 46 scanning failed
> [   60.776467] UBIFS: background thread "ubifs_bgt0_0" stops
> mount: mounting ubi0:rootfs on /mnt failed: Structure needs cleaning
> [root at buildroot ~]# echo $?
> 255
> [root at buildroot ~]# mount -t ubifs ubi0:rootfs /mnt
> [   70.023360] UBIFS: background thread "ubifs_bgt0_0" started, PID 516
> [   70.305482] UBIFS: recovery needed
> [   71.169289] UBIFS: recovery completed
> [   71.180961] UBIFS: mounted UBI device 0, volume 0, name "rootfs"
> [   71.199497] UBIFS: LEB size: 130944 bytes (127 KiB), min./max. I/O unit sizes: 8 bytes/512 bytes
> [   71.226483] UBIFS: FS size: 63769728 bytes (60 MiB, 487 LEBs), journal size 3142656 bytes (2 MiB, 24 LEBs)
> [   71.254470] UBIFS: reserved for root: 3012001 bytes (2941 KiB)
> [   71.260366] UBIFS: media format: w4/r0 (latest is w4/r0), UUID 567F5BCB-663D-4F84-BF34-3282E100D2D9, small LPT model
> [root at buildroot ~]# echo $?
> 0
> ==============================================================
> ==============================================================
> ==============================================================

[BUG] reproducable ubifs reboot assert and corruption

[Andrew Ruder]

On Sat, Jan 25, 2014 at 04:02:15PM +0100, Richard Weinberger wrote:
> So ubifs_bgt0_0 stops and the fun begins.
> Can you trigger the issue also by unmounting /mnt?
> I.e umount -l /mnt
> The background thread should only stop after all io is done...

Did some experiments last week to see if I could trigger the bug with
full debug messages enabled.  Biggest problem is that I don't have
non-volatile memory available, serial logging slows it down too much to
trigger the bug, and the reboot tends to shut down any attempt to
offload the log to capture the relevant messages.

That being said, I was able to trigger the bug with the following:

[root at buildroot ~]# (sleep 5 ; while ! mount -o remount,ro /mnt ; do true ; done ; echo remount > /dev/kmsg ; sleep 5 ; echo reboot > /dev/kmsg ; reboot ) &
[2] 564
[root at buildroot ~]# fsstress -p 10 -n 10 -X -d /mnt/fsstress -l 0

In my log I can see the "remount" message and 100ms later I can see the
first ubifs assert.  I've attached the relevant portion of the logs
below from the first time I see LEB 44 mentioned through the asserts.
I've put the logs on the web due to concerns of flooding the mailing
list with 100's of kB in attachments.

https://gist.github.com/aeruder/8651928

ubi_corruption.txt is the kernel log
afterwards.txt is the console log with the ensuing issue with ubifs

I also have logs of the recovery process in the Linux kernel later on,
(still takes 2 mounts), an image of the MTD device, and would be happy
to try anything or enable any additional debug messages.

> Can you also please find out whether fssstress is still running when
> reboot takes action?

Thanks for taking a look.  I'm reading everything I can find about ubifs
to see if I can make some headway into understanding what is going on
but filesytems are definitely not my forte :).

Cheers,
Andrew Ruder

[BUG] reproducable ubifs reboot assert and corruption

[Andrew Ruder]

Ok, I've got some more useful information.  I have been adding
a multitude of WARN_ON's and prink's all over the remount code and have
come up with the attached log.

A little bit of explanation:

Line 1: sync_filesystem (from do_remount_sb)
Line 188: sync_filesystem ends
Line 43, 64, 81, 98, 114, 135, 156, 173: write operations that occur
during sync_filesystem.  Before each warning I print the inode pointer.
Line 197: read-only remount has completely finished (this message is
from userspace post remount)
Line 199: a sync is called, there are apparently dirty inodes in our
now-readonly ubifs filesystem
Line 215: failed assert that occurs because the writeback triggers for
inode 0xd75b9450 (see line 41, it got in with a sys_write while we were
running our sync_filesystem in do_remount_sb)

Does this help?  It looks like there is a race condition between the
writeback code and the remount read-only.  Nothing is done to lock out
writes during the first half of the do_remount_sb and some stuff makes
it into the writeback worker queue while we are busy syncing the
filesystem only to trigger later when ubifs has decided it is
read-only...

Note: I only barely know what I am talking about - filesystems still not
my forte :)

Thanks,
Andy


  1: pre sync_filesystem
  2: ------------[ cut here ]------------
  3: WARNING: CPU: 0 PID: 645 at fs/fs-writeback.c:98 bdi_queue_work+0xc8/0x130()
  4: Modules linked in:
  5: CPU: 0 PID: 645 Comm: mount Tainted: G        W    3.12.0-00041-g7f12d39-dirty #236
  6: [<c0014fb4>] (unwind_backtrace+0x0/0x128) from [<c0012394>] (show_stack+0x20/0x24)
  7: [<c0012394>] (show_stack+0x20/0x24) from [<c0348590>] (dump_stack+0x20/0x28)
  8: [<c0348590>] (dump_stack+0x20/0x28) from [<c0020874>] (warn_slowpath_common+0x78/0x98)
  9: [<c0020874>] (warn_slowpath_common+0x78/0x98) from [<c0020950>] (warn_slowpath_null+0x2c/0x34)
 10: [<c0020950>] (warn_slowpath_null+0x2c/0x34) from [<c00f4f00>] (bdi_queue_work+0xc8/0x130)
 11: [<c00f4f00>] (bdi_queue_work+0xc8/0x130) from [<c00f58cc>] (writeback_inodes_sb_nr+0xb4/0xd4)
 12: [<c00f58cc>] (writeback_inodes_sb_nr+0xb4/0xd4) from [<c00f591c>] (writeback_inodes_sb+0x30/0x34)
 13: [<c00f591c>] (writeback_inodes_sb+0x30/0x34) from [<c00fa3fc>] (sync_filesystem+0x50/0xbc)
 14: [<c00fa3fc>] (sync_filesystem+0x50/0xbc) from [<c00d3bf4>] (do_remount_sb+0xb8/0x1fc)
 15: [<c00d3bf4>] (do_remount_sb+0xb8/0x1fc) from [<c00ee3d0>] (do_mount+0x2e8/0x81c)
 16: [<c00ee3d0>] (do_mount+0x2e8/0x81c) from [<c00ee998>] (SyS_mount+0x94/0xc8)
 17: [<c00ee998>] (SyS_mount+0x94/0xc8) from [<c000e820>] (ret_fast_syscall+0x0/0x2c)
 18: ---[ end trace c6e04f3813781dc3 ]---
 19: Adding tail
 20: writeback_workfn d781c110 d700fe8c
 21: inode: d75a2c30
 22: inode: d75b8c30
 23: ------------[ cut here ]------------
 24: WARNING: CPU: 0 PID: 645 at fs/fs-writeback.c:98 bdi_queue_work+0xc8/0x130()
 25: Modules linked in:
 26: CPU: 0 PID: 645 Comm: mount Tainted: G        W    3.12.0-00041-g7f12d39-dirty #236
 27: [<c0014fb4>] (unwind_backtrace+0x0/0x128) from [<c0012394>] (show_stack+0x20/0x24)
 28: [<c0012394>] (show_stack+0x20/0x24) from [<c0348590>] (dump_stack+0x20/0x28)
 29: [<c0348590>] (dump_stack+0x20/0x28) from [<c0020874>] (warn_slowpath_common+0x78/0x98)
 30: [<c0020874>] (warn_slowpath_common+0x78/0x98) from [<c0020950>] (warn_slowpath_null+0x2c/0x34)
 31: [<c0020950>] (warn_slowpath_null+0x2c/0x34) from [<c00f4f00>] (bdi_queue_work+0xc8/0x130)
 32: [<c00f4f00>] (bdi_queue_work+0xc8/0x130) from [<c00f59dc>] (sync_inodes_sb+0xbc/0x1bc)
 33: [<c00f59dc>] (sync_inodes_sb+0xbc/0x1bc) from [<c00fa434>] (sync_filesystem+0x88/0xbc)
 34: [<c00fa434>] (sync_filesystem+0x88/0xbc) from [<c00d3bf4>] (do_remount_sb+0xb8/0x1fc)
 35: [<c00d3bf4>] (do_remount_sb+0xb8/0x1fc) from [<c00ee3d0>] (do_mount+0x2e8/0x81c)
 36: [<c00ee3d0>] (do_mount+0x2e8/0x81c) from [<c00ee998>] (SyS_mount+0x94/0xc8)
 37: [<c00ee998>] (SyS_mount+0x94/0xc8) from [<c000e820>] (ret_fast_syscall+0x0/0x2c)
 38: ---[ end trace c6e04f3813781dc4 ]---
 39: Adding tail
 40: writeback_workfn d781c110 d700fe9c
 41: inode: d75b9450
 42: ------------[ cut here ]------------
 43: WARNING: CPU: 0 PID: 651 at fs/fs-writeback.c:1215 __mark_inode_dirty+0x2dc/0x32c()
 44: Modules linked in:
 45: CPU: 0 PID: 651 Comm: fsstress Tainted: G        W    3.12.0-00041-g7f12d39-dirty #236
 46: [<c0014fb4>] (unwind_backtrace+0x0/0x128) from [<c0012394>] (show_stack+0x20/0x24)
 47: [<c0012394>] (show_stack+0x20/0x24) from [<c0348590>] (dump_stack+0x20/0x28)
 48: [<c0348590>] (dump_stack+0x20/0x28) from [<c0020874>] (warn_slowpath_common+0x78/0x98)
 49: [<c0020874>] (warn_slowpath_common+0x78/0x98) from [<c0020950>] (warn_slowpath_null+0x2c/0x34)
 50: [<c0020950>] (warn_slowpath_null+0x2c/0x34) from [<c00f57c8>] (__mark_inode_dirty+0x2dc/0x32c)
 51: [<c00f57c8>] (__mark_inode_dirty+0x2dc/0x32c) from [<c009dc70>] (__set_page_dirty_nobuffers+0xf4/0x110)
 52: [<c009dc70>] (__set_page_dirty_nobuffers+0xf4/0x110) from [<c0138a48>] (ubifs_write_end+0x1c8/0x294)
 53: [<c0138a48>] (ubifs_write_end+0x1c8/0x294) from [<c009504c>] (generic_file_buffered_write+0x17c/0x260)
 54: [<c009504c>] (generic_file_buffered_write+0x17c/0x260) from [<c0096ce8>] (__generic_file_aio_write+0x420/0x448)
 55: [<c0096ce8>] (__generic_file_aio_write+0x420/0x448) from [<c0096d78>] (generic_file_aio_write+0x68/0xac)
 56: [<c0096d78>] (generic_file_aio_write+0x68/0xac) from [<c0139880>] (ubifs_aio_write+0x17c/0x18c)
 57: [<c0139880>] (ubifs_aio_write+0x17c/0x18c) from [<c00d0290>] (do_sync_write+0x7c/0xa0)
 58: [<c00d0290>] (do_sync_write+0x7c/0xa0) from [<c00d09e4>] (vfs_write+0xe4/0x194)
 59: [<c00d09e4>] (vfs_write+0xe4/0x194) from [<c00d0f94>] (SyS_write+0x4c/0x7c)
 60: [<c00d0f94>] (SyS_write+0x4c/0x7c) from [<c000e820>] (ret_fast_syscall+0x0/0x2c)
 61: ---[ end trace c6e04f3813781dc5 ]---
 62: inode: d75a3248
 63: ------------[ cut here ]------------
 64: WARNING: CPU: 0 PID: 656 at fs/fs-writeback.c:1215 __mark_inode_dirty+0x2dc/0x32c()
 65: Modules linked in:
 66: CPU: 0 PID: 656 Comm: fsstress Tainted: G        W    3.12.0-00041-g7f12d39-dirty #236
 67: [<c0014fb4>] (unwind_backtrace+0x0/0x128) from [<c0012394>] (show_stack+0x20/0x24)
 68: [<c0012394>] (show_stack+0x20/0x24) from [<c0348590>] (dump_stack+0x20/0x28)
 69: [<c0348590>] (dump_stack+0x20/0x28) from [<c0020874>] (warn_slowpath_common+0x78/0x98)
 70: [<c0020874>] (warn_slowpath_common+0x78/0x98) from [<c0020950>] (warn_slowpath_null+0x2c/0x34)
 71: [<c0020950>] (warn_slowpath_null+0x2c/0x34) from [<c00f57c8>] (__mark_inode_dirty+0x2dc/0x32c)
 72: [<c00f57c8>] (__mark_inode_dirty+0x2dc/0x32c) from [<c0138184>] (ubifs_setattr+0x40c/0x49c)
 73: [<c0138184>] (ubifs_setattr+0x40c/0x49c) from [<c00e9634>] (notify_change+0x204/0x2e8)
 74: [<c00e9634>] (notify_change+0x204/0x2e8) from [<c00ce888>] (chown_common.isra.14+0x80/0x98)
 75: [<c00ce888>] (chown_common.isra.14+0x80/0x98) from [<c00cf820>] (SyS_fchownat+0x8c/0xd4)
 76: [<c00cf820>] (SyS_fchownat+0x8c/0xd4) from [<c00cf8e8>] (SyS_lchown+0x3c/0x44)
 77: [<c00cf8e8>] (SyS_lchown+0x3c/0x44) from [<c000e820>] (ret_fast_syscall+0x0/0x2c)
 78: ---[ end trace c6e04f3813781dc6 ]---
 79: inode: d75a7040
 80: ------------[ cut here ]------------
 81: WARNING: CPU: 0 PID: 652 at fs/fs-writeback.c:1215 __mark_inode_dirty+0x2dc/0x32c()
 82: Modules linked in:
 83: CPU: 0 PID: 652 Comm: fsstress Tainted: G        W    3.12.0-00041-g7f12d39-dirty #236
 84: [<c0014fb4>] (unwind_backtrace+0x0/0x128) from [<c0012394>] (show_stack+0x20/0x24)
 85: [<c0012394>] (show_stack+0x20/0x24) from [<c0348590>] (dump_stack+0x20/0x28)
 86: [<c0348590>] (dump_stack+0x20/0x28) from [<c0020874>] (warn_slowpath_common+0x78/0x98)
 87: [<c0020874>] (warn_slowpath_common+0x78/0x98) from [<c0020950>] (warn_slowpath_null+0x2c/0x34)
 88: [<c0020950>] (warn_slowpath_null+0x2c/0x34) from [<c00f57c8>] (__mark_inode_dirty+0x2dc/0x32c)
 89: [<c00f57c8>] (__mark_inode_dirty+0x2dc/0x32c) from [<c0138184>] (ubifs_setattr+0x40c/0x49c)
 90: [<c0138184>] (ubifs_setattr+0x40c/0x49c) from [<c00e9634>] (notify_change+0x204/0x2e8)
 91: [<c00e9634>] (notify_change+0x204/0x2e8) from [<c00ce888>] (chown_common.isra.14+0x80/0x98)
 92: [<c00ce888>] (chown_common.isra.14+0x80/0x98) from [<c00cf820>] (SyS_fchownat+0x8c/0xd4)
 93: [<c00cf820>] (SyS_fchownat+0x8c/0xd4) from [<c00cf8e8>] (SyS_lchown+0x3c/0x44)
 94: [<c00cf8e8>] (SyS_lchown+0x3c/0x44) from [<c000e820>] (ret_fast_syscall+0x0/0x2c)
 95: ---[ end trace c6e04f3813781dc7 ]---
 96: inode: d75b9c70
 97: ------------[ cut here ]------------
 98: WARNING: CPU: 0 PID: 647 at fs/fs-writeback.c:1215 __mark_inode_dirty+0x2dc/0x32c()
 99: Modules linked in:
100: CPU: 0 PID: 647 Comm: fsstress Tainted: G        W    3.12.0-00041-g7f12d39-dirty #236
101: [<c0014fb4>] (unwind_backtrace+0x0/0x128) from [<c0012394>] (show_stack+0x20/0x24)
102: [<c0012394>] (show_stack+0x20/0x24) from [<c0348590>] (dump_stack+0x20/0x28)
103: [<c0348590>] (dump_stack+0x20/0x28) from [<c0020874>] (warn_slowpath_common+0x78/0x98)
104: [<c0020874>] (warn_slowpath_common+0x78/0x98) from [<c0020950>] (warn_slowpath_null+0x2c/0x34)
105: [<c0020950>] (warn_slowpath_null+0x2c/0x34) from [<c00f57c8>] (__mark_inode_dirty+0x2dc/0x32c)
106: [<c00f57c8>] (__mark_inode_dirty+0x2dc/0x32c) from [<c013b8ac>] (ubifs_rename+0x4a4/0x600)
107: [<c013b8ac>] (ubifs_rename+0x4a4/0x600) from [<c00de80c>] (vfs_rename+0x280/0x3f4)
108: [<c00de80c>] (vfs_rename+0x280/0x3f4) from [<c00df4ac>] (SyS_renameat+0x18c/0x218)
109: [<c00df4ac>] (SyS_renameat+0x18c/0x218) from [<c00df564>] (SyS_rename+0x2c/0x30)
110: [<c00df564>] (SyS_rename+0x2c/0x30) from [<c000e820>] (ret_fast_syscall+0x0/0x2c)
111: ---[ end trace c6e04f3813781dc8 ]---
112: inode: d75a6e38
113: ------------[ cut here ]------------
114: WARNING: CPU: 0 PID: 650 at fs/fs-writeback.c:1215 __mark_inode_dirty+0x2dc/0x32c()
115: Modules linked in:
116: CPU: 0 PID: 650 Comm: fsstress Tainted: G        W    3.12.0-00041-g7f12d39-dirty #236
117: [<c0014fb4>] (unwind_backtrace+0x0/0x128) from [<c0012394>] (show_stack+0x20/0x24)
118: [<c0012394>] (show_stack+0x20/0x24) from [<c0348590>] (dump_stack+0x20/0x28)
119: [<c0348590>] (dump_stack+0x20/0x28) from [<c0020874>] (warn_slowpath_common+0x78/0x98)
120: [<c0020874>] (warn_slowpath_common+0x78/0x98) from [<c0020950>] (warn_slowpath_null+0x2c/0x34)
121: [<c0020950>] (warn_slowpath_null+0x2c/0x34) from [<c00f57c8>] (__mark_inode_dirty+0x2dc/0x32c)
122: [<c00f57c8>] (__mark_inode_dirty+0x2dc/0x32c) from [<c009dc70>] (__set_page_dirty_nobuffers+0xf4/0x110)
123: [<c009dc70>] (__set_page_dirty_nobuffers+0xf4/0x110) from [<c0138a48>] (ubifs_write_end+0x1c8/0x294)
124: [<c0138a48>] (ubifs_write_end+0x1c8/0x294) from [<c009504c>] (generic_file_buffered_write+0x17c/0x260)
125: [<c009504c>] (generic_file_buffered_write+0x17c/0x260) from [<c0096ce8>] (__generic_file_aio_write+0x420/0x448)
126: [<c0096ce8>] (__generic_file_aio_write+0x420/0x448) from [<c0096d78>] (generic_file_aio_write+0x68/0xac)
127: [<c0096d78>] (generic_file_aio_write+0x68/0xac) from [<c0139880>] (ubifs_aio_write+0x17c/0x18c)
128: [<c0139880>] (ubifs_aio_write+0x17c/0x18c) from [<c00d0290>] (do_sync_write+0x7c/0xa0)
129: [<c00d0290>] (do_sync_write+0x7c/0xa0) from [<c00d09e4>] (vfs_write+0xe4/0x194)
130: [<c00d09e4>] (vfs_write+0xe4/0x194) from [<c00d0f94>] (SyS_write+0x4c/0x7c)
131: [<c00d0f94>] (SyS_write+0x4c/0x7c) from [<c000e820>] (ret_fast_syscall+0x0/0x2c)
132: ---[ end trace c6e04f3813781dc9 ]---
133: inode: d75a2e38
134: ------------[ cut here ]------------
135: WARNING: CPU: 0 PID: 651 at fs/fs-writeback.c:1215 __mark_inode_dirty+0x2dc/0x32c()
136: Modules linked in:
137: CPU: 0 PID: 651 Comm: fsstress Tainted: G        W    3.12.0-00041-g7f12d39-dirty #236
138: [<c0014fb4>] (unwind_backtrace+0x0/0x128) from [<c0012394>] (show_stack+0x20/0x24)
139: [<c0012394>] (show_stack+0x20/0x24) from [<c0348590>] (dump_stack+0x20/0x28)
140: [<c0348590>] (dump_stack+0x20/0x28) from [<c0020874>] (warn_slowpath_common+0x78/0x98)
141: [<c0020874>] (warn_slowpath_common+0x78/0x98) from [<c0020950>] (warn_slowpath_null+0x2c/0x34)
142: [<c0020950>] (warn_slowpath_null+0x2c/0x34) from [<c00f57c8>] (__mark_inode_dirty+0x2dc/0x32c)
143: [<c00f57c8>] (__mark_inode_dirty+0x2dc/0x32c) from [<c009dc70>] (__set_page_dirty_nobuffers+0xf4/0x110)
144: [<c009dc70>] (__set_page_dirty_nobuffers+0xf4/0x110) from [<c0138a48>] (ubifs_write_end+0x1c8/0x294)
145: [<c0138a48>] (ubifs_write_end+0x1c8/0x294) from [<c009504c>] (generic_file_buffered_write+0x17c/0x260)
146: [<c009504c>] (generic_file_buffered_write+0x17c/0x260) from [<c0096ce8>] (__generic_file_aio_write+0x420/0x448)
147: [<c0096ce8>] (__generic_file_aio_write+0x420/0x448) from [<c0096d78>] (generic_file_aio_write+0x68/0xac)
148: [<c0096d78>] (generic_file_aio_write+0x68/0xac) from [<c0139880>] (ubifs_aio_write+0x17c/0x18c)
149: [<c0139880>] (ubifs_aio_write+0x17c/0x18c) from [<c00d0290>] (do_sync_write+0x7c/0xa0)
150: [<c00d0290>] (do_sync_write+0x7c/0xa0) from [<c00d09e4>] (vfs_write+0xe4/0x194)
151: [<c00d09e4>] (vfs_write+0xe4/0x194) from [<c00d0f94>] (SyS_write+0x4c/0x7c)
152: [<c00d0f94>] (SyS_write+0x4c/0x7c) from [<c000e820>] (ret_fast_syscall+0x0/0x2c)
153: ---[ end trace c6e04f3813781dca ]---
154: inode: d75a2410
155: ------------[ cut here ]------------
156: WARNING: CPU: 0 PID: 653 at fs/fs-writeback.c:1215 __mark_inode_dirty+0x2dc/0x32c()
157: Modules linked in:
158: CPU: 0 PID: 653 Comm: fsstress Tainted: G        W    3.12.0-00041-g7f12d39-dirty #236
159: [<c0014fb4>] (unwind_backtrace+0x0/0x128) from [<c0012394>] (show_stack+0x20/0x24)
160: [<c0012394>] (show_stack+0x20/0x24) from [<c0348590>] (dump_stack+0x20/0x28)
161: [<c0348590>] (dump_stack+0x20/0x28) from [<c0020874>] (warn_slowpath_common+0x78/0x98)
162: [<c0020874>] (warn_slowpath_common+0x78/0x98) from [<c0020950>] (warn_slowpath_null+0x2c/0x34)
163: [<c0020950>] (warn_slowpath_null+0x2c/0x34) from [<c00f57c8>] (__mark_inode_dirty+0x2dc/0x32c)
164: [<c00f57c8>] (__mark_inode_dirty+0x2dc/0x32c) from [<c0138184>] (ubifs_setattr+0x40c/0x49c)
165: [<c0138184>] (ubifs_setattr+0x40c/0x49c) from [<c00e9634>] (notify_change+0x204/0x2e8)
166: [<c00e9634>] (notify_change+0x204/0x2e8) from [<c00ce888>] (chown_common.isra.14+0x80/0x98)
167: [<c00ce888>] (chown_common.isra.14+0x80/0x98) from [<c00cf820>] (SyS_fchownat+0x8c/0xd4)
168: [<c00cf820>] (SyS_fchownat+0x8c/0xd4) from [<c00cf8e8>] (SyS_lchown+0x3c/0x44)
169: [<c00cf8e8>] (SyS_lchown+0x3c/0x44) from [<c000e820>] (ret_fast_syscall+0x0/0x2c)
170: ---[ end trace c6e04f3813781dcb ]---
171: inode: d75a6410
172: ------------[ cut here ]------------
173: WARNING: CPU: 0 PID: 653 at fs/fs-writeback.c:1215 __mark_inode_dirty+0x2dc/0x32c()
174: Modules linked in:
175: CPU: 0 PID: 653 Comm: fsstress Tainted: G        W    3.12.0-00041-g7f12d39-dirty #236
176: [<c0014fb4>] (unwind_backtrace+0x0/0x128) from [<c0012394>] (show_stack+0x20/0x24)
177: [<c0012394>] (show_stack+0x20/0x24) from [<c0348590>] (dump_stack+0x20/0x28)
178: [<c0348590>] (dump_stack+0x20/0x28) from [<c0020874>] (warn_slowpath_common+0x78/0x98)
179: [<c0020874>] (warn_slowpath_common+0x78/0x98) from [<c0020950>] (warn_slowpath_null+0x2c/0x34)
180: [<c0020950>] (warn_slowpath_null+0x2c/0x34) from [<c00f57c8>] (__mark_inode_dirty+0x2dc/0x32c)
181: [<c00f57c8>] (__mark_inode_dirty+0x2dc/0x32c) from [<c0138184>] (ubifs_setattr+0x40c/0x49c)
182: [<c0138184>] (ubifs_setattr+0x40c/0x49c) from [<c00e9634>] (notify_change+0x204/0x2e8)
183: [<c00e9634>] (notify_change+0x204/0x2e8) from [<c00ce888>] (chown_common.isra.14+0x80/0x98)
184: [<c00ce888>] (chown_common.isra.14+0x80/0x98) from [<c00cf820>] (SyS_fchownat+0x8c/0xd4)
185: [<c00cf820>] (SyS_fchownat+0x8c/0xd4) from [<c00cf8e8>] (SyS_lchown+0x3c/0x44)
186: [<c00cf8e8>] (SyS_lchown+0x3c/0x44) from [<c000e820>] (ret_fast_syscall+0x0/0x2c)
187: ---[ end trace c6e04f3813781dcc ]---
188: post sync_filesystem
189: preparing
190: done preparing
191: success
192: In remount_ro
193: UBIFS: background thread "ubifs_bgt0_0" stops
194: thread stopped
195: ending 1 d781c110 d781c110
196: remount done 1
197:  remount
198: ------------[ cut here ]------------
199: WARNING: CPU: 0 PID: 661 at fs/fs-writeback.c:98 bdi_queue_work+0xc8/0x130()
200: Modules linked in:
201: CPU: 0 PID: 661 Comm: fsstress Tainted: G        W    3.12.0-00041-g7f12d39-dirty #236
202: [<c0014fb4>] (unwind_backtrace+0x0/0x128) from [<c0012394>] (show_stack+0x20/0x24)
203: [<c0012394>] (show_stack+0x20/0x24) from [<c0348590>] (dump_stack+0x20/0x28)
204: [<c0348590>] (dump_stack+0x20/0x28) from [<c0020874>] (warn_slowpath_common+0x78/0x98)
205: [<c0020874>] (warn_slowpath_common+0x78/0x98) from [<c0020950>] (warn_slowpath_null+0x2c/0x34)
206: [<c0020950>] (warn_slowpath_null+0x2c/0x34) from [<c00f4f00>] (bdi_queue_work+0xc8/0x130)
207: [<c00f4f00>] (bdi_queue_work+0xc8/0x130) from [<c00f5e48>] (__bdi_start_writeback+0x114/0x128)
208: [<c00f5e48>] (__bdi_start_writeback+0x114/0x128) from [<c00f70fc>] (wakeup_flusher_threads+0x70/0x90)
209: [<c00f70fc>] (wakeup_flusher_threads+0x70/0x90) from [<c00fa49c>] (sys_sync+0x34/0xa4)
210: [<c00fa49c>] (sys_sync+0x34/0xa4) from [<c000e820>] (ret_fast_syscall+0x0/0x2c)
211: ---[ end trace c6e04f3813781dcd ]---
212: Adding tail
213: writeback_workfn d781c110 d7b970d8
214: inode: d75b9450
215: UBIFS assert failed in reserve_space at 125 (pid 6)
216: CPU: 0 PID: 6 Comm: kworker/u2:0 Tainted: G        W    3.12.0-00041-g7f12d39-dirty #236
217: Workqueue: writeback bdi_writeback_workfn (flush-ubifs_0_0)
218: [<c0014fb4>] (unwind_backtrace+0x0/0x128) from [<c0012394>] (show_stack+0x20/0x24)
219: [<c0012394>] (show_stack+0x20/0x24) from [<c0348590>] (dump_stack+0x20/0x28)
220: [<c0348590>] (dump_stack+0x20/0x28) from [<c0134b84>] (make_reservation+0x8c/0x560)
221: [<c0134b84>] (make_reservation+0x8c/0x560) from [<c0135ed8>] (ubifs_jnl_write_inode+0xbc/0x214)
222: [<c0135ed8>] (ubifs_jnl_write_inode+0xbc/0x214) from [<c013d168>] (ubifs_write_inode+0xec/0x17c)
223: [<c013d168>] (ubifs_write_inode+0xec/0x17c) from [<c01391d8>] (ubifs_writepage+0x180/0x288)
224: [<c01391d8>] (ubifs_writepage+0x180/0x288) from [<c009d2dc>] (__writepage+0x24/0x6c)
225: [<c009d2dc>] (__writepage+0x24/0x6c) from [<c009d89c>] (write_cache_pages+0x2e8/0x3e8)
226: [<c009d89c>] (write_cache_pages+0x2e8/0x3e8) from [<c009d9e8>] (generic_writepages+0x4c/0x68)
227: [<c009d9e8>] (generic_writepages+0x4c/0x68) from [<c009f040>] (do_writepages+0x3c/0x48)
228: [<c009f040>] (do_writepages+0x3c/0x48) from [<c00f518c>] (__writeback_single_inode+0xf8/0x37c)
229: [<c00f518c>] (__writeback_single_inode+0xf8/0x37c) from [<c00f60f0>] (writeback_sb_inodes+0x1f8/0x3dc)
230: [<c00f60f0>] (writeback_sb_inodes+0x1f8/0x3dc) from [<c00f6354>] (__writeback_inodes_wb+0x80/0xc0)
231: [<c00f6354>] (__writeback_inodes_wb+0x80/0xc0) from [<c00f6548>] (wb_writeback+0x1b4/0x364)
232: [<c00f6548>] (wb_writeback+0x1b4/0x364) from [<c00f6c74>] (bdi_writeback_workfn+0xbc/0x4d4)
233: [<c00f6c74>] (bdi_writeback_workfn+0xbc/0x4d4) from [<c0038454>] (process_one_work+0x298/0x44c)
234: [<c0038454>] (process_one_work+0x298/0x44c) from [<c0038b04>] (worker_thread+0x240/0x380)
235: [<c0038b04>] (worker_thread+0x240/0x380) from [<c003e1a8>] (kthread+0xbc/0xc8)
236: [<c003e1a8>] (kthread+0xbc/0xc8) from [<c000e8b0>] (ret_from_fork+0x14/0x20)

[BUG] reproducable ubifs reboot assert and corruption

[Richard Weinberger]

Am 29.01.2014 06:32, schrieb Andrew Ruder:
> Ok, I've got some more useful information.  I have been adding
> a multitude of WARN_ON's and prink's all over the remount code and have
> come up with the attached log.
> 
> A little bit of explanation:
> 
> Line 1: sync_filesystem (from do_remount_sb)
> Line 188: sync_filesystem ends
> Line 43, 64, 81, 98, 114, 135, 156, 173: write operations that occur
> during sync_filesystem.  Before each warning I print the inode pointer.
> Line 197: read-only remount has completely finished (this message is
> from userspace post remount)
> Line 199: a sync is called, there are apparently dirty inodes in our
> now-readonly ubifs filesystem
> Line 215: failed assert that occurs because the writeback triggers for
> inode 0xd75b9450 (see line 41, it got in with a sys_write while we were
> running our sync_filesystem in do_remount_sb)
> 
> Does this help?  It looks like there is a race condition between the
> writeback code and the remount read-only.  Nothing is done to lock out
> writes during the first half of the do_remount_sb and some stuff makes
> it into the writeback worker queue while we are busy syncing the
> filesystem only to trigger later when ubifs has decided it is
> read-only...

So you can trigger this by running fsstress on /mnt and then call
mount -o remount,ro /mnt?

Can you also trigger it on nandsim or mtdram?

I did a quick test on my testbed using mtdram and was unable to trigger it.
But I fear my box is too fast.

Thanks,
//richard

[BUG] reproducable ubifs reboot assert and corruption

[Andrew Ruder]

On Wed, Jan 29, 2014 at 08:17:35AM +0100, Richard Weinberger wrote:
> So you can trigger this by running fsstress on /mnt and then call
> mount -o remount,ro /mnt?

That's all it takes.  I actually run the remount until it succeeds,
obviously with fsstress going in the background there is a pretty narrow
window where it needs to sneak in with a write between the start of the
sync_filesystem and before the remount check for writers (-EBUSY).

> Can you also trigger it on nandsim or mtdram?

Haven't tried, but I can.  I just don't really have that great of
a development environment for doing this on a desktop machine.

> I did a quick test on my testbed using mtdram and was unable to trigger it.
> But I fear my box is too fast.

I think there is definitely a speed component of my 416 MHz PXA 270 that
makes this pretty easy to hit.  What if you did something like (changing
the ubiattach and mount lines obviously)?

I'll see if I can do this in a qemu, but it might take me a while to get
that setup.

- Andy

[BUG] reproducable ubifs reboot assert and corruption

[Richard Weinberger]

Am 29.01.2014 06:32, schrieb Andrew Ruder:
> Ok, I've got some more useful information.  I have been adding
> a multitude of WARN_ON's and prink's all over the remount code and have
> come up with the attached log.
> 
> A little bit of explanation:
> 
> Line 1: sync_filesystem (from do_remount_sb)
> Line 188: sync_filesystem ends
> Line 43, 64, 81, 98, 114, 135, 156, 173: write operations that occur
> during sync_filesystem.  Before each warning I print the inode pointer.
> Line 197: read-only remount has completely finished (this message is
> from userspace post remount)
> Line 199: a sync is called, there are apparently dirty inodes in our
> now-readonly ubifs filesystem
> Line 215: failed assert that occurs because the writeback triggers for
> inode 0xd75b9450 (see line 41, it got in with a sys_write while we were
> running our sync_filesystem in do_remount_sb)
> 
> Does this help?  It looks like there is a race condition between the
> writeback code and the remount read-only.  Nothing is done to lock out
> writes during the first half of the do_remount_sb and some stuff makes
> it into the writeback worker queue while we are busy syncing the
> filesystem only to trigger later when ubifs has decided it is
> read-only...
> 
> Note: I only barely know what I am talking about - filesystems still not
> my forte :)

BTW: Can you please share your .config?

Thanks,
//richard

[BUG] reproducable ubifs reboot assert and corruption

[Andrew Ruder]

On Wed, Jan 29, 2014 at 08:30:45AM +0100, Richard Weinberger wrote:
> BTW: Can you please share your .config?

No problem.  FYI, this is for a board that is still in development so
not all my changes have been submitted for inclusion yet.  I would be
happy to share the changes now if necessary but I've attached the --stat
to show that as far as mtd/ubifs goes, i'm basically running a stock
v3.12:

% git diff --stat v3.12..HEAD
 Documentation/devicetree/bindings/usb/pxa-usb.txt |    5 +-
 arch/arm/boot/dts/Makefile                        |    2 +
 arch/arm/boot/dts/pxa270-elecsys_z2.dts           |  330 ++++++
 arch/arm/boot/dts/pxa270-elecsys_z4.dts           |  434 +++++++
 arch/arm/boot/dts/pxa27x.dtsi                     |   13 +-
 arch/arm/boot/dts/pxa2xx.dtsi                     |   14 +-
 arch/arm/boot/dts/pxa3xx.dtsi                     |    4 +
 arch/arm/configs/elecsys_z2_defconfig             | 3089 +++++++++++++++
 arch/arm/mach-pxa/Kconfig                         |   18 +
 arch/arm/mach-pxa/Makefile                        |    3 +-
 arch/arm/mach-pxa/generic.c                       |    3 +-
 arch/arm/mach-pxa/include/mach/hardware.h         |    2 +-
 arch/arm/mach-pxa/irq.c                           |    8 +-
 arch/arm/mach-pxa/{pxa-dt.c => pxa27x-dt.c}       |   44 +-
 arch/arm/mach-pxa/pxa27x.c                        |   25 +-
 arch/arm/mach-pxa/{pxa-dt.c => pxa3xx-dt.c}       |   11 +-
 arch/arm/mach-pxa/sleep.S                         |    2 +-
 drivers/irqchip/Kconfig                           |    8 +
 drivers/irqchip/Makefile                          |    1 +
 drivers/irqchip/irq-zeus.c                        |  192 +++
 drivers/mmc/host/pxamci.c                         |   33 +-
 drivers/net/ethernet/8390/ne.c                    |    4 +-
 drivers/net/ethernet/davicom/dm9000.c             |   68 +-
 drivers/tty/serial/pxa.c                          |    6 +-
 24 files changed, 4222 insertions(+), 97 deletions(-)

And the .config I'm using is attached.

Thanks,
Andy



-------------- next part --------------
A non-text attachment was scrubbed...
Name: config.gz
Type: application/x-gunzip
Size: 14745 bytes
Desc: not available
URL: <http://lists.infradead.org/pipermail/linux-arm-kernel/attachments/20140129/c86abdca/attachment.bin>

[BUG] reproducable ubifs reboot assert and corruption

[Richard Weinberger]

Am 29.01.2014 16:46, schrieb Andrew Ruder:
> On Wed, Jan 29, 2014 at 08:30:45AM +0100, Richard Weinberger wrote:
>> BTW: Can you please share your .config?
> 
> No problem.  FYI, this is for a board that is still in development so
> not all my changes have been submitted for inclusion yet.  I would be
> happy to share the changes now if necessary but I've attached the --stat
> to show that as far as mtd/ubifs goes, i'm basically running a stock
> v3.12:

Does the issue also happen if you disable preemption?
i.e. CONFIG_PREEMPT_NONE=y

Maybe it is really a race...

Thanks,
//richard

[BUG] reproducable ubifs reboot assert and corruption

[Andrew Ruder]

On Wed, Jan 29, 2014 at 04:56:04PM +0100, Richard Weinberger wrote:
> Does the issue also happen if you disable preemption?
> i.e. CONFIG_PREEMPT_NONE=y

CONFIG_PREEMPT_NONE=y still breaks.  I suspect that sync_filesystem
has some blocking behavior that allows other processes to schedule.

Another log is attached and the patch I used to create this log is
below.  I think the most interesting part of this patch is the last hunk
that modifies ubifs_remount_ro.  This clearly shows that after the mount
has been marked as read-only we have dirty inodes waiting for the
writeback to come in and hit all the asserts.

Here's some of the important parts of the log:

  170 pre sync_filesystem
# Notice that while we were running sync_filesystem
# a inode (0xd75ab658) snuck in with a sys_rename
  204 inode: d75ab658
  205 ------------[ cut here ]------------
  206 WARNING: CPU: 0 PID: 625 at fs/fs-writeback.c:1213 __mark_inode_dirty+0x2a4/0x2f4()
  207 Modules linked in:
  208 CPU: 0 PID: 625 Comm: fsstress Tainted: G        W    3.12.0-00041-g7f12d39-dirty #250
  209 [<c0014f54>] (unwind_backtrace+0x0/0x128) from [<c001235c>] (show_stack+0x20/0x24)
  210 [<c001235c>] (show_stack+0x20/0x24) from [<c0344574>] (dump_stack+0x20/0x28)
  211 [<c0344574>] (dump_stack+0x20/0x28) from [<c00206d4>] (warn_slowpath_common+0x78/0x98)
  212 [<c00206d4>] (warn_slowpath_common+0x78/0x98) from [<c00207b0>] (warn_slowpath_null+0x2c/0x34)
  213 [<c00207b0>] (warn_slowpath_null+0x2c/0x34) from [<c00f0e8c>] (__mark_inode_dirty+0x2a4/0x2f4)
  214 [<c00f0e8c>] (__mark_inode_dirty+0x2a4/0x2f4) from [<c0136428>] (ubifs_rename+0x4a4/0x600)
  215 [<c0136428>] (ubifs_rename+0x4a4/0x600) from [<c00d9f44>] (vfs_rename+0x280/0x3f4)
  216 [<c00d9f44>] (vfs_rename+0x280/0x3f4) from [<c00dabe4>] (SyS_renameat+0x18c/0x218)
  217 [<c00dabe4>] (SyS_renameat+0x18c/0x218) from [<c00dac9c>] (SyS_rename+0x2c/0x30)
  218 [<c00dac9c>] (SyS_rename+0x2c/0x30) from [<c000e820>] (ret_fast_syscall+0x0/0x2c)
  219 ---[ end trace 35ebec8569a53526 ]---
  754 post sync_filesystem
  755 pre prepare_remount
  756 post prepare_remount
  757 prepare_remount success
  758 UBIFS: background thread "ubifs_bgt0_0" stops
  759 we are now a read-only mount
  760 bdi.work_list = d7ac4110, .next = d7ac4110
# WE HAVE DIRTY I/O (notice the .next != &b_dirty)
  761 bdi.wb.b_dirty = d7ac40d8, .next = d75accd0
  762 bdi.wb.b_io = d7ac40e0, .next = d7ac40e0
  763 bdi.wb.b_more_io = d7ac40e8, .next = d7ac40e8
  764 do_remount_sb success
# And now our friend (inode 0xd75ab658) comes in with a writeback after
# we are read-only triggering the assert
  779 inode: d75ab658
  780 UBIFS assert failed in reserve_space at 125 (pid 11)
  781 CPU: 0 PID: 11 Comm: kworker/u2:1 Tainted: G        W    3.12.0-00041-g7f12d39-dirty #250
  782 Workqueue: writeback bdi_writeback_workfn (flush-ubifs_0_0)
  783 [<c0014f54>] (unwind_backtrace+0x0/0x128) from [<c001235c>] (show_stack+0x20/0x24)
  784 [<c001235c>] (show_stack+0x20/0x24) from [<c0344574>] (dump_stack+0x20/0x28)
  785 [<c0344574>] (dump_stack+0x20/0x28) from [<c012f90c>] (make_reservation+0x8c/0x560)
  786 [<c012f90c>] (make_reservation+0x8c/0x560) from [<c0130c60>] (ubifs_jnl_write_inode+0xbc/0x214)
  787 [<c0130c60>] (ubifs_jnl_write_inode+0xbc/0x214) from [<c0137ce0>] (ubifs_write_inode+0xec/0x17c)
  788 [<c0137ce0>] (ubifs_write_inode+0xec/0x17c) from [<c00f0a00>] (__writeback_single_inode+0x1fc/0x308)
  789 [<c00f0a00>] (__writeback_single_inode+0x1fc/0x308) from [<c00f1780>] (writeback_sb_inodes+0x1f8/0x3c4)
  790 [<c00f1780>] (writeback_sb_inodes+0x1f8/0x3c4) from [<c00f19cc>] (__writeback_inodes_wb+0x80/0xc0)
  791 [<c00f19cc>] (__writeback_inodes_wb+0x80/0xc0) from [<c00f1ba4>] (wb_writeback+0x198/0x310)
  792 [<c00f1ba4>] (wb_writeback+0x198/0x310) from [<c00f2328>] (bdi_writeback_workfn+0x15c/0x454)
  793 [<c00f2328>] (bdi_writeback_workfn+0x15c/0x454) from [<c0038348>] (process_one_work+0x280/0x420)
  794 [<c0038348>] (process_one_work+0x280/0x420) from [<c00389e4>] (worker_thread+0x240/0x380)
  795 [<c00389e4>] (worker_thread+0x240/0x380) from [<c003dff8>] (kthread+0xbc/0xc8)
  796 [<c003dff8>] (kthread+0xbc/0xc8) from [<c000e8b0>] (ret_from_fork+0x14/0x20)

- Andy




--- patch ---
diff --git a/fs/fs-writeback.c b/fs/fs-writeback.c
index 9f4935b..48e4272 100644
--- a/fs/fs-writeback.c
+++ b/fs/fs-writeback.c
@@ -93,6 +93,10 @@ static void bdi_queue_work(struct backing_dev_info *bdi,
 {
 	trace_writeback_queue(bdi, work);
 
+	do {
+		extern bool ubifs_enable_debug;
+		WARN_ON(ubifs_enable_debug);
+	} while (0);
 	spin_lock_bh(&bdi->wb_lock);
 	list_add_tail(&work->list, &bdi->work_list);
 	spin_unlock_bh(&bdi->wb_lock);
@@ -194,6 +198,11 @@ static void redirty_tail(struct inode *inode, struct bdi_writeback *wb)
 		if (time_before(inode->dirtied_when, tail->dirtied_when))
 			inode->dirtied_when = jiffies;
 	}
+	do {
+		extern bool ubifs_enable_debug;
+		if (ubifs_enable_debug) pr_info("inode: %p\n", inode);
+		WARN_ON(ubifs_enable_debug);
+	} while (0);
 	list_move(&inode->i_wb_list, &wb->b_dirty);
 }
 
@@ -204,6 +213,11 @@ static void requeue_io(struct inode *inode, struct bdi_writeback *wb)
 {
 	assert_spin_locked(&wb->list_lock);
 	list_move(&inode->i_wb_list, &wb->b_more_io);
+	do {
+		extern bool ubifs_enable_debug;
+		if (ubifs_enable_debug) pr_info("inode: %p\n", inode);
+		WARN_ON(ubifs_enable_debug);
+	} while (0);
 }
 
 static void inode_sync_complete(struct inode *inode)
@@ -437,6 +451,8 @@ __writeback_single_inode(struct inode *inode, struct writeback_control *wbc)
 	unsigned dirty;
 	int ret;
 
+	extern bool ubifs_enable_debug;
+	if (ubifs_enable_debug) pr_info("inode: %p\n", inode);
 	WARN_ON(!(inode->i_state & I_SYNC));
 
 	trace_writeback_single_inode_start(inode, wbc, nr_to_write);
@@ -1191,6 +1207,11 @@ void __mark_inode_dirty(struct inode *inode, int flags)
 
 			inode->dirtied_when = jiffies;
 			list_move(&inode->i_wb_list, &bdi->wb.b_dirty);
+	do {
+		extern bool ubifs_enable_debug;
+		if (ubifs_enable_debug) pr_info("inode: %p\n", inode);
+		WARN_ON(ubifs_enable_debug);
+	} while (0);
 			spin_unlock(&bdi->wb.list_lock);
 
 			if (wakeup_bdi)
diff --git a/fs/super.c b/fs/super.c
index 0225c20..29afc68 100644
--- a/fs/super.c
+++ b/fs/super.c
@@ -737,6 +737,12 @@ int do_remount_sb(struct super_block *sb, int flags, void *data, int force)
 	int retval;
 	int remount_ro;
 
+	extern bool ubifs_enable_debug;
+	if (flags & MS_RDONLY) {
+		ubifs_enable_debug = true;
+	}
+	WARN_ON(ubifs_enable_debug);
+
 	if (sb->s_writers.frozen != SB_UNFROZEN)
 		return -EBUSY;
 
@@ -747,8 +753,11 @@ int do_remount_sb(struct super_block *sb, int flags, void *data, int force)
 
 	if (flags & MS_RDONLY)
 		acct_auto_close(sb);
+	pr_info("pre shrink_dcache_sb\n");
 	shrink_dcache_sb(sb);
+	pr_info("pre sync_filesystem\n");
 	sync_filesystem(sb);
+	pr_info("post sync_filesystem\n");
 
 	remount_ro = (flags & MS_RDONLY) && !(sb->s_flags & MS_RDONLY);
 
@@ -758,9 +767,12 @@ int do_remount_sb(struct super_block *sb, int flags, void *data, int force)
 		if (force) {
 			mark_files_ro(sb);
 		} else {
+			pr_info("pre prepare_remount\n");
 			retval = sb_prepare_remount_readonly(sb);
+			pr_info("post prepare_remount\n");
 			if (retval)
 				return retval;
+			pr_info("prepare_remount success\n");
 		}
 	}
 
@@ -789,6 +801,7 @@ int do_remount_sb(struct super_block *sb, int flags, void *data, int force)
 	 */
 	if (remount_ro && sb->s_bdev)
 		invalidate_bdev(sb->s_bdev);
+	pr_info("do_remount_sb success\n");
 	return 0;
 
 cancel_readonly:
diff --git a/fs/ubifs/file.c b/fs/ubifs/file.c
index 123c79b..c9f2d5d 100644
--- a/fs/ubifs/file.c
+++ b/fs/ubifs/file.c
@@ -902,6 +902,8 @@ static int do_writepage(struct page *page, int len)
 	struct inode *inode = page->mapping->host;
 	struct ubifs_info *c = inode->i_sb->s_fs_info;
 
+	WARN_ON(c->ro_mount);
+
 #ifdef UBIFS_DEBUG
 	spin_lock(&ui->ui_lock);
 	ubifs_assert(page->index <= ui->synced_i_size << PAGE_CACHE_SIZE);
diff --git a/fs/ubifs/super.c b/fs/ubifs/super.c
index 3e4aa72..8cbb731 100644
--- a/fs/ubifs/super.c
+++ b/fs/ubifs/super.c
@@ -38,6 +38,8 @@
 #include <linux/writeback.h>
 #include "ubifs.h"
 
+bool ubifs_enable_debug;
+
 /*
  * Maximum amount of memory we may 'kmalloc()' without worrying that we are
  * allocating too much.
@@ -1756,6 +1758,11 @@ static void ubifs_remount_ro(struct ubifs_info *c)
 	err = dbg_check_space_info(c);
 	if (err)
 		ubifs_ro_mode(c, err);
+	pr_info("we are now a read-only mount\n");
+	pr_info("bdi.work_list = %p, .next = %p\n", &c->bdi.work_list, c->bdi.work_list.next);
+	pr_info("bdi.wb.b_dirty = %p, .next = %p\n", &c->bdi.wb.b_dirty, c->bdi.wb.b_dirty.next);
+	pr_info("bdi.wb.b_io = %p, .next = %p\n", &c->bdi.wb.b_io, c->bdi.wb.b_io.next);
+	pr_info("bdi.wb.b_more_io = %p, .next = %p\n", &c->bdi.wb.b_more_io, c->bdi.wb.b_more_io.next);
 	mutex_unlock(&c->umount_mutex);
 }
 
-------------- next part --------------
A non-text attachment was scrubbed...
Name: experiments11.small.txt.gz
Type: application/x-gunzip
Size: 5974 bytes
Desc: not available
URL: <http://lists.infradead.org/pipermail/linux-arm-kernel/attachments/20140129/fc352ff5/attachment-0001.bin>

[BUG] reproducable ubifs reboot assert and corruption

[Richard Weinberger]

On Wed, Jan 29, 2014 at 8:13 PM, Andrew Ruder <andy@aeruder.net> wrote:
> On Wed, Jan 29, 2014 at 04:56:04PM +0100, Richard Weinberger wrote:
>> Does the issue also happen if you disable preemption?
>> i.e. CONFIG_PREEMPT_NONE=y
>
> CONFIG_PREEMPT_NONE=y still breaks.  I suspect that sync_filesystem
> has some blocking behavior that allows other processes to schedule.

Okay, I have to test this on real hardware.
May take a few days.

BTW: s/not.at/nod.at/g ;)

> Another log is attached and the patch I used to create this log is
> below.  I think the most interesting part of this patch is the last hunk
> that modifies ubifs_remount_ro.  This clearly shows that after the mount
> has been marked as read-only we have dirty inodes waiting for the
> writeback to come in and hit all the asserts.
>
> Here's some of the important parts of the log:
>
>   170 pre sync_filesystem
> # Notice that while we were running sync_filesystem
> # a inode (0xd75ab658) snuck in with a sys_rename
>   204 inode: d75ab658
>   205 ------------[ cut here ]------------
>   206 WARNING: CPU: 0 PID: 625 at fs/fs-writeback.c:1213 __mark_inode_dirty+0x2a4/0x2f4()
>   207 Modules linked in:
>   208 CPU: 0 PID: 625 Comm: fsstress Tainted: G        W    3.12.0-00041-g7f12d39-dirty #250
>   209 [<c0014f54>] (unwind_backtrace+0x0/0x128) from [<c001235c>] (show_stack+0x20/0x24)
>   210 [<c001235c>] (show_stack+0x20/0x24) from [<c0344574>] (dump_stack+0x20/0x28)
>   211 [<c0344574>] (dump_stack+0x20/0x28) from [<c00206d4>] (warn_slowpath_common+0x78/0x98)
>   212 [<c00206d4>] (warn_slowpath_common+0x78/0x98) from [<c00207b0>] (warn_slowpath_null+0x2c/0x34)
>   213 [<c00207b0>] (warn_slowpath_null+0x2c/0x34) from [<c00f0e8c>] (__mark_inode_dirty+0x2a4/0x2f4)
>   214 [<c00f0e8c>] (__mark_inode_dirty+0x2a4/0x2f4) from [<c0136428>] (ubifs_rename+0x4a4/0x600)
>   215 [<c0136428>] (ubifs_rename+0x4a4/0x600) from [<c00d9f44>] (vfs_rename+0x280/0x3f4)
>   216 [<c00d9f44>] (vfs_rename+0x280/0x3f4) from [<c00dabe4>] (SyS_renameat+0x18c/0x218)
>   217 [<c00dabe4>] (SyS_renameat+0x18c/0x218) from [<c00dac9c>] (SyS_rename+0x2c/0x30)
>   218 [<c00dac9c>] (SyS_rename+0x2c/0x30) from [<c000e820>] (ret_fast_syscall+0x0/0x2c)
>   219 ---[ end trace 35ebec8569a53526 ]---
>   754 post sync_filesystem
>   755 pre prepare_remount
>   756 post prepare_remount
>   757 prepare_remount success
>   758 UBIFS: background thread "ubifs_bgt0_0" stops
>   759 we are now a read-only mount
>   760 bdi.work_list = d7ac4110, .next = d7ac4110
> # WE HAVE DIRTY I/O (notice the .next != &b_dirty)
>   761 bdi.wb.b_dirty = d7ac40d8, .next = d75accd0
>   762 bdi.wb.b_io = d7ac40e0, .next = d7ac40e0
>   763 bdi.wb.b_more_io = d7ac40e8, .next = d7ac40e8
>   764 do_remount_sb success
> # And now our friend (inode 0xd75ab658) comes in with a writeback after
> # we are read-only triggering the assert
>   779 inode: d75ab658
>   780 UBIFS assert failed in reserve_space at 125 (pid 11)
>   781 CPU: 0 PID: 11 Comm: kworker/u2:1 Tainted: G        W    3.12.0-00041-g7f12d39-dirty #250
>   782 Workqueue: writeback bdi_writeback_workfn (flush-ubifs_0_0)
>   783 [<c0014f54>] (unwind_backtrace+0x0/0x128) from [<c001235c>] (show_stack+0x20/0x24)
>   784 [<c001235c>] (show_stack+0x20/0x24) from [<c0344574>] (dump_stack+0x20/0x28)
>   785 [<c0344574>] (dump_stack+0x20/0x28) from [<c012f90c>] (make_reservation+0x8c/0x560)
>   786 [<c012f90c>] (make_reservation+0x8c/0x560) from [<c0130c60>] (ubifs_jnl_write_inode+0xbc/0x214)
>   787 [<c0130c60>] (ubifs_jnl_write_inode+0xbc/0x214) from [<c0137ce0>] (ubifs_write_inode+0xec/0x17c)
>   788 [<c0137ce0>] (ubifs_write_inode+0xec/0x17c) from [<c00f0a00>] (__writeback_single_inode+0x1fc/0x308)
>   789 [<c00f0a00>] (__writeback_single_inode+0x1fc/0x308) from [<c00f1780>] (writeback_sb_inodes+0x1f8/0x3c4)
>   790 [<c00f1780>] (writeback_sb_inodes+0x1f8/0x3c4) from [<c00f19cc>] (__writeback_inodes_wb+0x80/0xc0)
>   791 [<c00f19cc>] (__writeback_inodes_wb+0x80/0xc0) from [<c00f1ba4>] (wb_writeback+0x198/0x310)
>   792 [<c00f1ba4>] (wb_writeback+0x198/0x310) from [<c00f2328>] (bdi_writeback_workfn+0x15c/0x454)
>   793 [<c00f2328>] (bdi_writeback_workfn+0x15c/0x454) from [<c0038348>] (process_one_work+0x280/0x420)
>   794 [<c0038348>] (process_one_work+0x280/0x420) from [<c00389e4>] (worker_thread+0x240/0x380)
>   795 [<c00389e4>] (worker_thread+0x240/0x380) from [<c003dff8>] (kthread+0xbc/0xc8)
>   796 [<c003dff8>] (kthread+0xbc/0xc8) from [<c000e8b0>] (ret_from_fork+0x14/0x20)
>
> - Andy
>
>
>
>
> --- patch ---
> diff --git a/fs/fs-writeback.c b/fs/fs-writeback.c
> index 9f4935b..48e4272 100644
> --- a/fs/fs-writeback.c
> +++ b/fs/fs-writeback.c
> @@ -93,6 +93,10 @@ static void bdi_queue_work(struct backing_dev_info *bdi,
>  {
>         trace_writeback_queue(bdi, work);
>
> +       do {
> +               extern bool ubifs_enable_debug;
> +               WARN_ON(ubifs_enable_debug);
> +       } while (0);
>         spin_lock_bh(&bdi->wb_lock);
>         list_add_tail(&work->list, &bdi->work_list);
>         spin_unlock_bh(&bdi->wb_lock);
> @@ -194,6 +198,11 @@ static void redirty_tail(struct inode *inode, struct bdi_writeback *wb)
>                 if (time_before(inode->dirtied_when, tail->dirtied_when))
>                         inode->dirtied_when = jiffies;
>         }
> +       do {
> +               extern bool ubifs_enable_debug;
> +               if (ubifs_enable_debug) pr_info("inode: %p\n", inode);
> +               WARN_ON(ubifs_enable_debug);
> +       } while (0);
>         list_move(&inode->i_wb_list, &wb->b_dirty);
>  }
>
> @@ -204,6 +213,11 @@ static void requeue_io(struct inode *inode, struct bdi_writeback *wb)
>  {
>         assert_spin_locked(&wb->list_lock);
>         list_move(&inode->i_wb_list, &wb->b_more_io);
> +       do {
> +               extern bool ubifs_enable_debug;
> +               if (ubifs_enable_debug) pr_info("inode: %p\n", inode);
> +               WARN_ON(ubifs_enable_debug);
> +       } while (0);
>  }
>
>  static void inode_sync_complete(struct inode *inode)
> @@ -437,6 +451,8 @@ __writeback_single_inode(struct inode *inode, struct writeback_control *wbc)
>         unsigned dirty;
>         int ret;
>
> +       extern bool ubifs_enable_debug;
> +       if (ubifs_enable_debug) pr_info("inode: %p\n", inode);
>         WARN_ON(!(inode->i_state & I_SYNC));
>
>         trace_writeback_single_inode_start(inode, wbc, nr_to_write);
> @@ -1191,6 +1207,11 @@ void __mark_inode_dirty(struct inode *inode, int flags)
>
>                         inode->dirtied_when = jiffies;
>                         list_move(&inode->i_wb_list, &bdi->wb.b_dirty);
> +       do {
> +               extern bool ubifs_enable_debug;
> +               if (ubifs_enable_debug) pr_info("inode: %p\n", inode);
> +               WARN_ON(ubifs_enable_debug);
> +       } while (0);
>                         spin_unlock(&bdi->wb.list_lock);
>
>                         if (wakeup_bdi)
> diff --git a/fs/super.c b/fs/super.c
> index 0225c20..29afc68 100644
> --- a/fs/super.c
> +++ b/fs/super.c
> @@ -737,6 +737,12 @@ int do_remount_sb(struct super_block *sb, int flags, void *data, int force)
>         int retval;
>         int remount_ro;
>
> +       extern bool ubifs_enable_debug;
> +       if (flags & MS_RDONLY) {
> +               ubifs_enable_debug = true;
> +       }
> +       WARN_ON(ubifs_enable_debug);
> +
>         if (sb->s_writers.frozen != SB_UNFROZEN)
>                 return -EBUSY;
>
> @@ -747,8 +753,11 @@ int do_remount_sb(struct super_block *sb, int flags, void *data, int force)
>
>         if (flags & MS_RDONLY)
>                 acct_auto_close(sb);
> +       pr_info("pre shrink_dcache_sb\n");
>         shrink_dcache_sb(sb);
> +       pr_info("pre sync_filesystem\n");
>         sync_filesystem(sb);
> +       pr_info("post sync_filesystem\n");
>
>         remount_ro = (flags & MS_RDONLY) && !(sb->s_flags & MS_RDONLY);
>
> @@ -758,9 +767,12 @@ int do_remount_sb(struct super_block *sb, int flags, void *data, int force)
>                 if (force) {
>                         mark_files_ro(sb);
>                 } else {
> +                       pr_info("pre prepare_remount\n");
>                         retval = sb_prepare_remount_readonly(sb);
> +                       pr_info("post prepare_remount\n");
>                         if (retval)
>                                 return retval;
> +                       pr_info("prepare_remount success\n");
>                 }
>         }
>
> @@ -789,6 +801,7 @@ int do_remount_sb(struct super_block *sb, int flags, void *data, int force)
>          */
>         if (remount_ro && sb->s_bdev)
>                 invalidate_bdev(sb->s_bdev);
> +       pr_info("do_remount_sb success\n");
>         return 0;
>
>  cancel_readonly:
> diff --git a/fs/ubifs/file.c b/fs/ubifs/file.c
> index 123c79b..c9f2d5d 100644
> --- a/fs/ubifs/file.c
> +++ b/fs/ubifs/file.c
> @@ -902,6 +902,8 @@ static int do_writepage(struct page *page, int len)
>         struct inode *inode = page->mapping->host;
>         struct ubifs_info *c = inode->i_sb->s_fs_info;
>
> +       WARN_ON(c->ro_mount);
> +
>  #ifdef UBIFS_DEBUG
>         spin_lock(&ui->ui_lock);
>         ubifs_assert(page->index <= ui->synced_i_size << PAGE_CACHE_SIZE);
> diff --git a/fs/ubifs/super.c b/fs/ubifs/super.c
> index 3e4aa72..8cbb731 100644
> --- a/fs/ubifs/super.c
> +++ b/fs/ubifs/super.c
> @@ -38,6 +38,8 @@
>  #include <linux/writeback.h>
>  #include "ubifs.h"
>
> +bool ubifs_enable_debug;
> +
>  /*
>   * Maximum amount of memory we may 'kmalloc()' without worrying that we are
>   * allocating too much.
> @@ -1756,6 +1758,11 @@ static void ubifs_remount_ro(struct ubifs_info *c)
>         err = dbg_check_space_info(c);
>         if (err)
>                 ubifs_ro_mode(c, err);
> +       pr_info("we are now a read-only mount\n");
> +       pr_info("bdi.work_list = %p, .next = %p\n", &c->bdi.work_list, c->bdi.work_list.next);
> +       pr_info("bdi.wb.b_dirty = %p, .next = %p\n", &c->bdi.wb.b_dirty, c->bdi.wb.b_dirty.next);
> +       pr_info("bdi.wb.b_io = %p, .next = %p\n", &c->bdi.wb.b_io, c->bdi.wb.b_io.next);
> +       pr_info("bdi.wb.b_more_io = %p, .next = %p\n", &c->bdi.wb.b_more_io, c->bdi.wb.b_more_io.next);
>         mutex_unlock(&c->umount_mutex);
>  }
>
>
> ______________________________________________________
> Linux MTD discussion mailing list
> http://lists.infradead.org/mailman/listinfo/linux-mtd/
>



-- 
Thanks,
//richard