Re: Bug#252391: kernel-source-2.6.6: Assertion failure in journal_flush() ... "!journal->j_running_transaction"

Re: Bug#252391: kernel-source-2.6.6: Assertion failure in journal_flush() ... "!journal->j_running_transaction"

[Herbert Xu]

On Wed, Jun 02, 2004 at 11:40:37PM -0400, David Coe wrote:
> Package: kernel-source-2.6.6
> Version: 2.6.6-1
> Severity: normal
> 
> I've been using a locally-compiled kernel from this source since May
> 17, without problems; tonight when I tried to "mount -o remount,ro
> /usr" I got the following failure, after which I was unable to sync or
> kill any processes -- a hard reboot "fixed" it, ext3 recovered cleanly.

... 

> A search of the ext3-users mailing list turned up a previous
> discussion of a similar problem, which was apparently left
> unresolved (or at least that thread ended inconclusively) -- see
>   https://www.redhat.com/archives/ext3-users/2003-May/msg00093.html
> which suggests where the problem is.  I see that
> ext3_mark_recovery_complete() still doesn't call
> journal_lock_updates(), as that thread suggests it should.  I haven't
> researched further yet.

Yes that code does look racy.

Andrew, what's stopping a journal_start() from setting j_running_transaction
just before the last spin_lock(&journal->j_state_lock) that guards the
J_ASSERT that was hit below?
 
> Jun  2 21:33:15 zona kernel: Assertion failure in journal_flush() at fs/jbd/journal.c:1309: "!journal->j_running_transaction"
> Jun  2 21:33:15 zona kernel: ------------[ cut here ]------------
> Jun  2 21:33:15 zona kernel: kernel BUG at fs/jbd/journal.c:1309!
> Jun  2 21:33:15 zona kernel: invalid operand: 0000 [#1]
> Jun  2 21:33:15 zona kernel: SMP 
> Jun  2 21:33:15 zona kernel: CPU:    1
> Jun  2 21:33:15 zona kernel: EIP:    0060:[journal_flush+228/460]    Not tainted
> Jun  2 21:33:15 zona kernel: EFLAGS: 00010216   (2.6.6zona-06009se) 
> Jun  2 21:33:15 zona kernel: EIP is at journal_flush+0xe4/0x1cc
> Jun  2 21:33:15 zona kernel: eax: 00000064   ebx: 000016e3   ecx: 00000000   edx: c03548ac
> Jun  2 21:33:15 zona kernel: esi: e716ba00   edi: 00000000   ebp: ce5d3f6c   esp: ce5d3ebc
> Jun  2 21:33:15 zona kernel: ds: 007b   es: 007b   ss: 0068
> Jun  2 21:33:15 zona kernel: Process mount (pid: 5202, threadinfo=ce5d2000 task=e13f4390)
> Jun  2 21:33:15 zona kernel: Stack: c02f45c0 c02f4c80 c02f44b5 0000051d c02f4c60 e716be00 e6e0b400 e716be00 
> Jun  2 21:33:15 zona kernel:        c018161b e716ba00 e716bc00 c01818ea e716be00 e6e0b400 e716be00 e716be50 
> Jun  2 21:33:15 zona kernel:        ce5d3f6c c0147c1b c014c784 e716be00 ce5d3f24 c8412000 e716be00 e716be40 
> Jun  2 21:33:15 zona kernel: Call Trace:
> Jun  2 21:33:15 zona kernel:  [ext3_mark_recovery_complete+23/76] ext3_mark_recovery_complete+0x17/0x4c
> Jun  2 21:33:15 zona kernel:  [ext3_remount+198/296] ext3_remount+0xc6/0x128
> Jun  2 21:33:15 zona kernel:  [fs_may_remount_ro+51/114] fs_may_remount_ro+0x33/0x72
> Jun  2 21:33:15 zona kernel:  [do_remount_sb+152/200] do_remount_sb+0x98/0xc8
> Jun  2 21:33:15 zona kernel:  [do_remount+112/188] do_remount+0x70/0xbc
> Jun  2 21:33:15 zona kernel:  [do_mount+293/392] do_mount+0x125/0x188
> Jun  2 21:33:15 zona kernel:  [copy_mount_options+85/164] copy_mount_options+0x55/0xa4
> Jun  2 21:33:15 zona kernel:  [sys_mount+189/320] sys_mount+0xbd/0x140
> Jun  2 21:33:15 zona kernel:  [sysenter_past_esp+82/113] sysenter_past_esp+0x52/0x71
> Jun  2 21:33:15 zona kernel: 
> Jun  2 21:33:15 zona kernel: Code: 0f 0b 1d 05 b5 44 2f c0 83 c4 14 83 7e 34 00 74 29 68 a0 4c 
-- 
Visit Openswan at http://www.openswan.org/
Email:  Herbert Xu ~{PmV>HI~} <herbert@gondor.apana.org.au>
Home Page: http://gondor.apana.org.au/~herbert/
PGP Key: http://gondor.apana.org.au/~herbert/pubkey.txt

Re: Bug#252391: kernel-source-2.6.6: Assertion failure in journal_flush() ... "!journal->j_running_transaction"

[Andrew Morton]

Herbert Xu <herbert@gondor.apana.org.au> wrote:
>
> Andrew, what's stopping a journal_start() from setting j_running_transaction
>  just before the last spin_lock(&journal->j_state_lock) that guards the
>  J_ASSERT that was hit below?

Not much, it appears.  I'll queue the below for post-2.6.7.


--- 25/fs/ext3/super.c~ext3-journal_flush-needs-journal_lock_updates	2004-06-03 21:15:57.911628872 -0700
+++ 25-akpm/fs/ext3/super.c	2004-06-03 21:15:57.916628112 -0700
@@ -1907,13 +1907,17 @@ static void ext3_commit_super (struct su
 static void ext3_mark_recovery_complete(struct super_block * sb,
 					struct ext3_super_block * es)
 {
-	journal_flush(EXT3_SB(sb)->s_journal);
+	journal_t *journal = EXT3_SB(sb)->s_journal;
+
+	journal_lock_updates(journal);
+	journal_flush(journal);
 	if (EXT3_HAS_INCOMPAT_FEATURE(sb, EXT3_FEATURE_INCOMPAT_RECOVER) &&
 	    sb->s_flags & MS_RDONLY) {
 		EXT3_CLEAR_INCOMPAT_FEATURE(sb, EXT3_FEATURE_INCOMPAT_RECOVER);
 		sb->s_dirt = 0;
 		ext3_commit_super(sb, es, 1);
 	}
+	journal_unlock_updates(journal);
 }
 
 /*
_