From mboxrd@z Thu Jan 1 00:00:00 1970 From: andy@aeruder.net (Andrew Ruder) Date: Tue, 28 Jan 2014 23:32:38 -0600 Subject: [BUG] reproducable ubifs reboot assert and corruption In-Reply-To: <20140127163939.GA27809@gmail.com> References: <20140122051510.GB17284@gmail.com> <20140127163939.GA27809@gmail.com> Message-ID: <20140129053238.GA6035@gmail.com> To: linux-arm-kernel@lists.infradead.org List-Id: linux-arm-kernel.lists.infradead.org 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: [] (unwind_backtrace+0x0/0x128) from [] (show_stack+0x20/0x24) 7: [] (show_stack+0x20/0x24) from [] (dump_stack+0x20/0x28) 8: [] (dump_stack+0x20/0x28) from [] (warn_slowpath_common+0x78/0x98) 9: [] (warn_slowpath_common+0x78/0x98) from [] (warn_slowpath_null+0x2c/0x34) 10: [] (warn_slowpath_null+0x2c/0x34) from [] (bdi_queue_work+0xc8/0x130) 11: [] (bdi_queue_work+0xc8/0x130) from [] (writeback_inodes_sb_nr+0xb4/0xd4) 12: [] (writeback_inodes_sb_nr+0xb4/0xd4) from [] (writeback_inodes_sb+0x30/0x34) 13: [] (writeback_inodes_sb+0x30/0x34) from [] (sync_filesystem+0x50/0xbc) 14: [] (sync_filesystem+0x50/0xbc) from [] (do_remount_sb+0xb8/0x1fc) 15: [] (do_remount_sb+0xb8/0x1fc) from [] (do_mount+0x2e8/0x81c) 16: [] (do_mount+0x2e8/0x81c) from [] (SyS_mount+0x94/0xc8) 17: [] (SyS_mount+0x94/0xc8) from [] (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: [] (unwind_backtrace+0x0/0x128) from [] (show_stack+0x20/0x24) 28: [] (show_stack+0x20/0x24) from [] (dump_stack+0x20/0x28) 29: [] (dump_stack+0x20/0x28) from [] (warn_slowpath_common+0x78/0x98) 30: [] (warn_slowpath_common+0x78/0x98) from [] (warn_slowpath_null+0x2c/0x34) 31: [] (warn_slowpath_null+0x2c/0x34) from [] (bdi_queue_work+0xc8/0x130) 32: [] (bdi_queue_work+0xc8/0x130) from [] (sync_inodes_sb+0xbc/0x1bc) 33: [] (sync_inodes_sb+0xbc/0x1bc) from [] (sync_filesystem+0x88/0xbc) 34: [] (sync_filesystem+0x88/0xbc) from [] (do_remount_sb+0xb8/0x1fc) 35: [] (do_remount_sb+0xb8/0x1fc) from [] (do_mount+0x2e8/0x81c) 36: [] (do_mount+0x2e8/0x81c) from [] (SyS_mount+0x94/0xc8) 37: [] (SyS_mount+0x94/0xc8) from [] (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: [] (unwind_backtrace+0x0/0x128) from [] (show_stack+0x20/0x24) 47: [] (show_stack+0x20/0x24) from [] (dump_stack+0x20/0x28) 48: [] (dump_stack+0x20/0x28) from [] (warn_slowpath_common+0x78/0x98) 49: [] (warn_slowpath_common+0x78/0x98) from [] (warn_slowpath_null+0x2c/0x34) 50: [] (warn_slowpath_null+0x2c/0x34) from [] (__mark_inode_dirty+0x2dc/0x32c) 51: [] (__mark_inode_dirty+0x2dc/0x32c) from [] (__set_page_dirty_nobuffers+0xf4/0x110) 52: [] (__set_page_dirty_nobuffers+0xf4/0x110) from [] (ubifs_write_end+0x1c8/0x294) 53: [] (ubifs_write_end+0x1c8/0x294) from [] (generic_file_buffered_write+0x17c/0x260) 54: [] (generic_file_buffered_write+0x17c/0x260) from [] (__generic_file_aio_write+0x420/0x448) 55: [] (__generic_file_aio_write+0x420/0x448) from [] (generic_file_aio_write+0x68/0xac) 56: [] (generic_file_aio_write+0x68/0xac) from [] (ubifs_aio_write+0x17c/0x18c) 57: [] (ubifs_aio_write+0x17c/0x18c) from [] (do_sync_write+0x7c/0xa0) 58: [] (do_sync_write+0x7c/0xa0) from [] (vfs_write+0xe4/0x194) 59: [] (vfs_write+0xe4/0x194) from [] (SyS_write+0x4c/0x7c) 60: [] (SyS_write+0x4c/0x7c) from [] (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: [] (unwind_backtrace+0x0/0x128) from [] (show_stack+0x20/0x24) 68: [] (show_stack+0x20/0x24) from [] (dump_stack+0x20/0x28) 69: [] (dump_stack+0x20/0x28) from [] (warn_slowpath_common+0x78/0x98) 70: [] (warn_slowpath_common+0x78/0x98) from [] (warn_slowpath_null+0x2c/0x34) 71: [] (warn_slowpath_null+0x2c/0x34) from [] (__mark_inode_dirty+0x2dc/0x32c) 72: [] (__mark_inode_dirty+0x2dc/0x32c) from [] (ubifs_setattr+0x40c/0x49c) 73: [] (ubifs_setattr+0x40c/0x49c) from [] (notify_change+0x204/0x2e8) 74: [] (notify_change+0x204/0x2e8) from [] (chown_common.isra.14+0x80/0x98) 75: [] (chown_common.isra.14+0x80/0x98) from [] (SyS_fchownat+0x8c/0xd4) 76: [] (SyS_fchownat+0x8c/0xd4) from [] (SyS_lchown+0x3c/0x44) 77: [] (SyS_lchown+0x3c/0x44) from [] (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: [] (unwind_backtrace+0x0/0x128) from [] (show_stack+0x20/0x24) 85: [] (show_stack+0x20/0x24) from [] (dump_stack+0x20/0x28) 86: [] (dump_stack+0x20/0x28) from [] (warn_slowpath_common+0x78/0x98) 87: [] (warn_slowpath_common+0x78/0x98) from [] (warn_slowpath_null+0x2c/0x34) 88: [] (warn_slowpath_null+0x2c/0x34) from [] (__mark_inode_dirty+0x2dc/0x32c) 89: [] (__mark_inode_dirty+0x2dc/0x32c) from [] (ubifs_setattr+0x40c/0x49c) 90: [] (ubifs_setattr+0x40c/0x49c) from [] (notify_change+0x204/0x2e8) 91: [] (notify_change+0x204/0x2e8) from [] (chown_common.isra.14+0x80/0x98) 92: [] (chown_common.isra.14+0x80/0x98) from [] (SyS_fchownat+0x8c/0xd4) 93: [] (SyS_fchownat+0x8c/0xd4) from [] (SyS_lchown+0x3c/0x44) 94: [] (SyS_lchown+0x3c/0x44) from [] (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: [] (unwind_backtrace+0x0/0x128) from [] (show_stack+0x20/0x24) 102: [] (show_stack+0x20/0x24) from [] (dump_stack+0x20/0x28) 103: [] (dump_stack+0x20/0x28) from [] (warn_slowpath_common+0x78/0x98) 104: [] (warn_slowpath_common+0x78/0x98) from [] (warn_slowpath_null+0x2c/0x34) 105: [] (warn_slowpath_null+0x2c/0x34) from [] (__mark_inode_dirty+0x2dc/0x32c) 106: [] (__mark_inode_dirty+0x2dc/0x32c) from [] (ubifs_rename+0x4a4/0x600) 107: [] (ubifs_rename+0x4a4/0x600) from [] (vfs_rename+0x280/0x3f4) 108: [] (vfs_rename+0x280/0x3f4) from [] (SyS_renameat+0x18c/0x218) 109: [] (SyS_renameat+0x18c/0x218) from [] (SyS_rename+0x2c/0x30) 110: [] (SyS_rename+0x2c/0x30) from [] (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: [] (unwind_backtrace+0x0/0x128) from [] (show_stack+0x20/0x24) 118: [] (show_stack+0x20/0x24) from [] (dump_stack+0x20/0x28) 119: [] (dump_stack+0x20/0x28) from [] (warn_slowpath_common+0x78/0x98) 120: [] (warn_slowpath_common+0x78/0x98) from [] (warn_slowpath_null+0x2c/0x34) 121: [] (warn_slowpath_null+0x2c/0x34) from [] (__mark_inode_dirty+0x2dc/0x32c) 122: [] (__mark_inode_dirty+0x2dc/0x32c) from [] (__set_page_dirty_nobuffers+0xf4/0x110) 123: [] (__set_page_dirty_nobuffers+0xf4/0x110) from [] (ubifs_write_end+0x1c8/0x294) 124: [] (ubifs_write_end+0x1c8/0x294) from [] (generic_file_buffered_write+0x17c/0x260) 125: [] (generic_file_buffered_write+0x17c/0x260) from [] (__generic_file_aio_write+0x420/0x448) 126: [] (__generic_file_aio_write+0x420/0x448) from [] (generic_file_aio_write+0x68/0xac) 127: [] (generic_file_aio_write+0x68/0xac) from [] (ubifs_aio_write+0x17c/0x18c) 128: [] (ubifs_aio_write+0x17c/0x18c) from [] (do_sync_write+0x7c/0xa0) 129: [] (do_sync_write+0x7c/0xa0) from [] (vfs_write+0xe4/0x194) 130: [] (vfs_write+0xe4/0x194) from [] (SyS_write+0x4c/0x7c) 131: [] (SyS_write+0x4c/0x7c) from [] (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: [] (unwind_backtrace+0x0/0x128) from [] (show_stack+0x20/0x24) 139: [] (show_stack+0x20/0x24) from [] (dump_stack+0x20/0x28) 140: [] (dump_stack+0x20/0x28) from [] (warn_slowpath_common+0x78/0x98) 141: [] (warn_slowpath_common+0x78/0x98) from [] (warn_slowpath_null+0x2c/0x34) 142: [] (warn_slowpath_null+0x2c/0x34) from [] (__mark_inode_dirty+0x2dc/0x32c) 143: [] (__mark_inode_dirty+0x2dc/0x32c) from [] (__set_page_dirty_nobuffers+0xf4/0x110) 144: [] (__set_page_dirty_nobuffers+0xf4/0x110) from [] (ubifs_write_end+0x1c8/0x294) 145: [] (ubifs_write_end+0x1c8/0x294) from [] (generic_file_buffered_write+0x17c/0x260) 146: [] (generic_file_buffered_write+0x17c/0x260) from [] (__generic_file_aio_write+0x420/0x448) 147: [] (__generic_file_aio_write+0x420/0x448) from [] (generic_file_aio_write+0x68/0xac) 148: [] (generic_file_aio_write+0x68/0xac) from [] (ubifs_aio_write+0x17c/0x18c) 149: [] (ubifs_aio_write+0x17c/0x18c) from [] (do_sync_write+0x7c/0xa0) 150: [] (do_sync_write+0x7c/0xa0) from [] (vfs_write+0xe4/0x194) 151: [] (vfs_write+0xe4/0x194) from [] (SyS_write+0x4c/0x7c) 152: [] (SyS_write+0x4c/0x7c) from [] (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: [] (unwind_backtrace+0x0/0x128) from [] (show_stack+0x20/0x24) 160: [] (show_stack+0x20/0x24) from [] (dump_stack+0x20/0x28) 161: [] (dump_stack+0x20/0x28) from [] (warn_slowpath_common+0x78/0x98) 162: [] (warn_slowpath_common+0x78/0x98) from [] (warn_slowpath_null+0x2c/0x34) 163: [] (warn_slowpath_null+0x2c/0x34) from [] (__mark_inode_dirty+0x2dc/0x32c) 164: [] (__mark_inode_dirty+0x2dc/0x32c) from [] (ubifs_setattr+0x40c/0x49c) 165: [] (ubifs_setattr+0x40c/0x49c) from [] (notify_change+0x204/0x2e8) 166: [] (notify_change+0x204/0x2e8) from [] (chown_common.isra.14+0x80/0x98) 167: [] (chown_common.isra.14+0x80/0x98) from [] (SyS_fchownat+0x8c/0xd4) 168: [] (SyS_fchownat+0x8c/0xd4) from [] (SyS_lchown+0x3c/0x44) 169: [] (SyS_lchown+0x3c/0x44) from [] (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: [] (unwind_backtrace+0x0/0x128) from [] (show_stack+0x20/0x24) 177: [] (show_stack+0x20/0x24) from [] (dump_stack+0x20/0x28) 178: [] (dump_stack+0x20/0x28) from [] (warn_slowpath_common+0x78/0x98) 179: [] (warn_slowpath_common+0x78/0x98) from [] (warn_slowpath_null+0x2c/0x34) 180: [] (warn_slowpath_null+0x2c/0x34) from [] (__mark_inode_dirty+0x2dc/0x32c) 181: [] (__mark_inode_dirty+0x2dc/0x32c) from [] (ubifs_setattr+0x40c/0x49c) 182: [] (ubifs_setattr+0x40c/0x49c) from [] (notify_change+0x204/0x2e8) 183: [] (notify_change+0x204/0x2e8) from [] (chown_common.isra.14+0x80/0x98) 184: [] (chown_common.isra.14+0x80/0x98) from [] (SyS_fchownat+0x8c/0xd4) 185: [] (SyS_fchownat+0x8c/0xd4) from [] (SyS_lchown+0x3c/0x44) 186: [] (SyS_lchown+0x3c/0x44) from [] (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: [] (unwind_backtrace+0x0/0x128) from [] (show_stack+0x20/0x24) 203: [] (show_stack+0x20/0x24) from [] (dump_stack+0x20/0x28) 204: [] (dump_stack+0x20/0x28) from [] (warn_slowpath_common+0x78/0x98) 205: [] (warn_slowpath_common+0x78/0x98) from [] (warn_slowpath_null+0x2c/0x34) 206: [] (warn_slowpath_null+0x2c/0x34) from [] (bdi_queue_work+0xc8/0x130) 207: [] (bdi_queue_work+0xc8/0x130) from [] (__bdi_start_writeback+0x114/0x128) 208: [] (__bdi_start_writeback+0x114/0x128) from [] (wakeup_flusher_threads+0x70/0x90) 209: [] (wakeup_flusher_threads+0x70/0x90) from [] (sys_sync+0x34/0xa4) 210: [] (sys_sync+0x34/0xa4) from [] (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: [] (unwind_backtrace+0x0/0x128) from [] (show_stack+0x20/0x24) 219: [] (show_stack+0x20/0x24) from [] (dump_stack+0x20/0x28) 220: [] (dump_stack+0x20/0x28) from [] (make_reservation+0x8c/0x560) 221: [] (make_reservation+0x8c/0x560) from [] (ubifs_jnl_write_inode+0xbc/0x214) 222: [] (ubifs_jnl_write_inode+0xbc/0x214) from [] (ubifs_write_inode+0xec/0x17c) 223: [] (ubifs_write_inode+0xec/0x17c) from [] (ubifs_writepage+0x180/0x288) 224: [] (ubifs_writepage+0x180/0x288) from [] (__writepage+0x24/0x6c) 225: [] (__writepage+0x24/0x6c) from [] (write_cache_pages+0x2e8/0x3e8) 226: [] (write_cache_pages+0x2e8/0x3e8) from [] (generic_writepages+0x4c/0x68) 227: [] (generic_writepages+0x4c/0x68) from [] (do_writepages+0x3c/0x48) 228: [] (do_writepages+0x3c/0x48) from [] (__writeback_single_inode+0xf8/0x37c) 229: [] (__writeback_single_inode+0xf8/0x37c) from [] (writeback_sb_inodes+0x1f8/0x3dc) 230: [] (writeback_sb_inodes+0x1f8/0x3dc) from [] (__writeback_inodes_wb+0x80/0xc0) 231: [] (__writeback_inodes_wb+0x80/0xc0) from [] (wb_writeback+0x1b4/0x364) 232: [] (wb_writeback+0x1b4/0x364) from [] (bdi_writeback_workfn+0xbc/0x4d4) 233: [] (bdi_writeback_workfn+0xbc/0x4d4) from [] (process_one_work+0x298/0x44c) 234: [] (process_one_work+0x298/0x44c) from [] (worker_thread+0x240/0x380) 235: [] (worker_thread+0x240/0x380) from [] (kthread+0xbc/0xc8) 236: [] (kthread+0xbc/0xc8) from [] (ret_from_fork+0x14/0x20)