Ext3 users - Jan 2002 - Assertion Failure

I got this.. The system was usuable, but not very.  If I tried to access the
ext3 volume, it would hang.  Reboot hung too, complaining about too many
open files.  Any ideas?  I have no idea what triggered it; this is a big
file/web/mail server, with all of that on the ext3 volume.  And I've never
run ksymoops before, but I think I did it right.

- Josh

Assertion failure in do_get_write_access() at transaction.c:609:
"!(((jh2bh(jh))
->b_state & (1UL << BH_Lock)) != 0)"
invalid operand: 0000
CPU:    1
EIP:    0010:[<e094e941>]    Not tainted
EFLAGS: 00010286
eax: 00000078   ebx: d89c0d90   ecx: 00000046   edx: 00000001
esi: d9a36c60   edi: d89c0d90   ebp: de2dbc94   esp: d7d0dd98
ds: 0018   es: 0018   ss: 0018
Process su (pid: 13601, stackpage=d7d0d000)
Stack: e0954980 e0954bc6 e0954960 00000261 e0954c20 de2dbc00 d9a36c60
d89c0d90
       de2dbc94 c1862618 00000000 00000000 de2dbc00 c8bcf7a0 e094ece5
d9a36c60
       d89c0d90 00000000 00000000 c1573100 0000003d 00000000 e095dc09
d9a36c60
Call Trace: [<e0954980>] [<e0954bc6>] [<e0954960>]
[<e0954c20>] [<e094ece5>]
   [<e095dc09>] [<e094e349>] [<e095c01d>] [<e095e3ec>]
[<c01441c9>]
[<c013ef33>]

   [<c0122f5b>] [<c0146e47>] [<e095f182>] [<c0146fcc>]
[<c0130eda>]
[<c0131f2a>]

   [<c013126f>] [<c0106fd3>]

Code: 0f 0b 83 c4 14 8b 4c 24 28 bd e2 ff ff ff f6 41 10 04 0f 85

Ksymoops output:
ksymoops 2.4.3 on i686 2.4.17.  Options used
     -v /home/jmd/linux/linux/vmlinux (specified)
     -k /proc/ksyms (default)
     -l /proc/modules (default)
     -o /lib/modules/2.4.17/ (default)
     -m /home/jmd/linux/linux/System.map (specified)

Error (expand_objects): cannot stat(/lib/ide-disk.o) for ide-disk
Error (expand_objects): cannot stat(/lib/ide-probe-mod.o) for ide-probe-mod
Error (expand_objects): cannot stat(/lib/ide-mod.o) for ide-mod
Error (expand_objects): cannot stat(/lib/aic7xxx.o) for aic7xxx
Error (expand_objects): cannot stat(/lib/sd_mod.o) for sd_mod
Error (expand_objects): cannot stat(/lib/scsi_mod.o) for scsi_mod
Warning (compare_maps): mismatch on symbol __module_description  , ide-disk
says e0858688, /lib/modules/2.4.17/kernel/drivers/ide/ide-disk.o says
e0857028.  Ignoring /lib/modules/2.4.17/kernel/drivers/ide/ide-disk.o entry
Warning (compare_maps): mismatch on symbol __module_author  , aic7xxx says
e08386a0, /lib/modules/2.4.17/kernel/drivers/scsi/aic7xxx/aic7xxx.o says
e0820040.  Ignoring
/lib/modules/2.4.17/kernel/drivers/scsi/aic7xxx/aic7xxx.o entry
Warning (compare_maps): mismatch on symbol __module_description  , aic7xxx
says e08386e0, /lib/modules/2.4.17/kernel/drivers/scsi/aic7xxx/aic7xxx.o
says e0820080.  Ignoring
/lib/modules/2.4.17/kernel/drivers/scsi/aic7xxx/aic7xxx.o entry
Warning (compare_maps): mismatch on symbol __module_parm_aic7xxx  , aic7xxx
says e0838732, /lib/modules/2.4.17/kernel/drivers/scsi/aic7xxx/aic7xxx.o
says e08200d2.  Ignoring
/lib/modules/2.4.17/kernel/drivers/scsi/aic7xxx/aic7xxx.o entry
Warning (compare_maps): mismatch on symbol __module_parm_desc_aic7xxx  ,
aic7xxx says e0838760,
/lib/modules/2.4.17/kernel/drivers/scsi/aic7xxx/aic7xxx.o says e0820100.
Ignoring /lib/modules/2.4.17/kernel/drivers/scsi/aic7xxx/aic7xxx.o entry
CPU:    1
EIP:    0010:[<e094e941>]    Not tainted
Using defaults from ksymoops -t elf32-i386 -a i386
EFLAGS: 00010286
eax: 00000078   ebx: d89c0d90   ecx: 00000046   edx: 00000001
esi: d9a36c60   edi: d89c0d90   ebp: de2dbc94   esp: d7d0dd98
ds: 0018   es: 0018   ss: 0018
Process su (pid: 13601, stackpage=d7d0d000)
Stack: e0954980 e0954bc6 e0954960 00000261 e0954c20 de2dbc00 d9a36c60
d89c0d90
       de2dbc94 c1862618 00000000 00000000 de2dbc00 c8bcf7a0 e094ece5
d9a36c60
       d89c0d90 00000000 00000000 c1573100 0000003d 00000000 e095dc09
d9a36c60
Call Trace: [<e0954980>] [<e0954bc6>] [<e0954960>]
[<e0954c20>] [<e094ece5>]
   [<e095dc09>] [<e094e349>] [<e095c01d>] [<e095e3ec>]
[<c01441c9>]
[<c013ef33>]
   [<c0122f5b>] [<c0146e47>] [<e095f182>] [<c0146fcc>]
[<c0130eda>]
[<c0131f2a>]
   [<c013126f>] [<c0106fd3>]
Code: 0f 0b 83 c4 14 8b 4c 24 28 bd e2 ff ff ff f6 41 10 04 0f 85
>>EIP; e094e940 <[lockd]nlmsvc_decode_testargs+b8/1f0>  
<====Trace; e0954980 <[lockd].rodata.end+1b8/1c0>
Trace; e0954bc6 <[lockd]nlmsvc_procedures+186/300>
Trace; e0954960 <[lockd].rodata.end+198/1c0>
Trace; e0954c20 <[lockd]nlmsvc_procedures+1e0/300>
Trace; e094ece4 <[lockd]nlmsvc_decode_lockargs+22c/230>
Trace; e095dc08 <[nfsd]exp_delclient+6c/84>
Trace; e094e348 <[lockd]nsm_mon_unmon+88/9c>
Trace; e095c01c <[nfsd]nfsd_link+204/2e0>
Trace; e095e3ec <[nfsd]nfsd_cache_lookup+c0/2a4>
Trace; c01441c8 <dput+18/144>
Trace; c013ef32 <vfs_follow_link+112/188>
Trace; c0122f5a <vmtruncate+142/180>
Trace; c0146e46 <inode_setattr+22/b4>
Trace; e095f182 <[nfsd]nfssvc_decode_symlinkargs+1e2/208>
Trace; c0146fcc <notify_change+7c/240>
Trace; c0130eda <do_truncate+4a/60>
Trace; c0131f2a <filp_open+52/5c>
Trace; c013126e <sys_ftruncate+136/154>
Trace; c0106fd2 <system_call+2e/34>
Code;  e094e940 <[lockd]nlmsvc_decode_testargs+b8/1f0>
00000000 <_EIP>:
Code;  e094e940 <[lockd]nlmsvc_decode_testargs+b8/1f0>   <====   0:  
0f 0b                     ud2a      <====Code;  e094e942
<[lockd]nlmsvc_decode_testargs+ba/1f0>
   2:   83 c4 14                  add    $0x14,%esp
Code;  e094e944 <[lockd]nlmsvc_decode_testargs+bc/1f0>
   5:   8b 4c 24 28               mov    0x28(%esp,1),%ecx
Code;  e094e948 <[lockd]nlmsvc_decode_testargs+c0/1f0>
   9:   bd e2 ff ff ff            mov    $0xffffffe2,%ebp
Code;  e094e94e <[lockd]nlmsvc_decode_testargs+c6/1f0>
   e:   f6 41 10 04               testb  $0x4,0x10(%ecx)
Code;  e094e952 <[lockd]nlmsvc_decode_testargs+ca/1f0>
  12:   0f 85 00 00 00 00         jne    18 <_EIP+0x18> e094e958
<[lockd]nlmsvc_decode_testargs+d0/1f0>


5 warnings and 6 errors issued.  Results may not be reliable.

Hi,

On Mon, Jan 21, 2002 at 03:29:02PM -0500, jdurham@vt.edu
wrote:
> I got this.. The system was usuable, but not very.  If I tried to access
the
> ext3 volume, it would hang.  Reboot hung too, complaining about too many
> open files.  Any ideas?  I have no idea what triggered it; this is a big
> file/web/mail server, with all of that on the ext3 volume.  And I've
never
> run ksymoops before, but I think I did it right.
> 
> - Josh
> 
> Assertion failure in do_get_write_access() at transaction.c:609:
> "!(((jh2bh(jh))
> ->b_state & (1UL << BH_Lock)) != 0)"
Should be fixed in 

	http://www.zip.com.au/~akpm/ext3-2.4-0.9.17-2418p3.gzHi,
> >>EIP; e094e940 <[lockd]nlmsvc_decode_testargs+b8/1f0>  
<====
There's definitely something wrong with the ksymoops decoding, as this
is clearly a jbd assert failure yet you've decoded it as somewhere
inside nfsd!

Cheers,
 Stephen

When using copydir to copy to my optical drive, it hung and the process went 
into D mode.  This doesn't always happen.  Usually it works OK.

I suppose the likelihood is that it is a harware problem, but I should be 
grateful for confirmation of this.

/var/log/messages gives:

kernel: Assertion failure in do_get_write_access() at
  transaction.c:725: "(((jh2bh(jh))->b_state & (1UL <<
BH_Uptodate)) != 0)"
kernel: invalid operand: 0000
kernel: CPU:    0
kernel: EIP:    0010:[do_get_write_access+1196/1296]
kernel: EIP:    0010:[<c0159adc>]
kernel: EFLAGS: 00010292
kernel: eax: 0000007b   ebx: 00000000   ecx: 00000005   edx: cefb7f64
kernel: esi: 00000001   edi: c728c000   ebp: c8aef190   esp: cab5bdc8
kernel: ds: 0018   es: 0018   ss: 0018      kernel: Process copydir (pid: 
10208, stackpage=cab5b000)
kernel: Stack: c0225420 c022582e c0225400 000002d5 c02259e0 00000001 00000000 
c44d8400
kernel:        ce980720 c44d8494 c44d8400 c91e79c0 c8aef190 c0159b76 c91e79c0 
c8aef190
kernel:        00000000 c217ca40 c91e79c0 cf74f400 c95ea900 c0155477 c91e79c0 
c217ca40
kernel: Call Trace: [journal_get_write_access+54/96] [ext3_orphan_add+135/656]
  [ext3_mark_iloc_dirty+53/80] [__jbd_kmalloc+43/192] 
[start_this_handle+452/640]
kernel: Call Trace: [<c0159b76>] [<c0155477>] [<c0153a65>]
[<c015f37b>]
[<c0158e24>]
kernel:    [journal_start+174/224] [ext3_setattr+132/272] 
[notify_change+79/208]
  [do_truncate+107/160] [lookup_hash+66/144] [open_namei+1033/1328]
kernel:    [<c0158f8e>] [<c0153924>] [<c01423af>]
[<c012dfdb>] [<c0139032>]
[<c0139609>]
kernel:    [dentry_open+195/320] [filp_open+54/96] [sys_open+52/144] 
[system_call+51/56]
kernel:    [<c012ef23>] [<c012ee36>] [<c012f124>]
[<c0106edb>]
kernel:
kernel: Code: 0f 0b 8b 45 00 83 c4 14 8b 50 38 8b 70 34 8b 7d 0c 0f b7 40
kernel:  SCSI disk error : host 0 channel 0 id 4 lun 0 return code = 28000002
kernel: Current sd08:15: sense key Data Protect
kernel: Additional sense indicates Medium format corrupted

scsi id 4 lun 0 is the optical disk (Panasonic PD drive) but Ext3 fs reports 
on mounting the drive that the disk is sd08:21 and not sd08:15 as above

Using copydir is the only time I ever have problems with this disk/drive in 
practice.

There have also been a couple of, perhaps unrelated, oddities:
kernel: spurious 8259A interrupt: IRQ7.
I also have frequently seen this:
kernel: end_request: I/O error, dev 02:00 (floppy), sector 0
It seems odd that the kernel should generate an error when there is no disk 
in the drive and it isn't intended that there should be. All sorts of other 
things don't happen that don't generate errors :)

I'm using Mandrake 8.1, with a recompiled  2.4.8-34.1
- Richard.
-- 
Richard Kimber
Political Science Resources:       http://www.psr.keele.ac.uk/