OOPS in UDF

OOPS in UDF

[Norbert Kiesel]

Hi,

I just got an OOPS while copying between two loopback-mounted UDF filesystems.
One or both of the UDF file systems are corrupted (some files not readable by
root), but kernel should not OOPS anyway.

I get the corrupted file systems reliably by rsync'ing big directories onto the
UDF filesystem (while trying to prepare a backup DVD).  I saw the OOPS only once
so far.  The system continued to work after the OOPS.

This happens on an old AMD K7 system running Debian unstable, but with self-
compiled vanilla kernel 2.6.16.19 (compiled with gcc version 4.0.4 20060507
(prerelease) (Debian 4.0.3-3)).

Best,
  Norbert

Jun 15 07:33:14 defiant kernel: [18278818.772000] UDF-fs INFO UDF 0.9.8.1 (2004/29/09) Mounting volume 'LinuxUDF', timestamp 2006/06/15 06:31 (1e5c)
Jun 15 07:34:54 defiant kernel: [18278915.636000] udf: udf_read_inode(ino 1553042) failed !bh
Jun 15 07:34:54 defiant kernel: [18278915.636000] udf: udf_get_filelongad() invalidparms
Jun 15 07:38:57 defiant kernel: [18279161.240000] udf: udf_read_inode(ino 1183786) failed !bh
Jun 15 07:40:26 defiant kernel: [18279250.016000] udf: udf_read_inode(ino 1183786) failed !bh
Jun 15 07:40:30 defiant kernel: [18279253.996000] udf: udf_read_inode(ino 1183786) failed !bh
Jun 15 07:40:30 defiant kernel: [18279253.996000] udf: udf_get_filelongad() invalidparms
Jun 15 07:41:13 defiant kernel: [18279297.464000] udf: udf_read_inode(ino 1553048) failed !bh
Jun 15 07:41:13 defiant kernel: [18279297.476000] udf: udf_read_inode(ino 1553044) failed !bh
Jun 15 07:41:13 defiant kernel: [18279297.476000] Unable to handle kernel paging request at virtual address 010000fb
Jun 15 07:41:13 defiant kernel: [18279297.476000]  printing eip:
Jun 15 07:41:13 defiant kernel: [18279297.476000] f0af2b01
Jun 15 07:41:13 defiant kernel: [18279297.476000] *pde = 00000000
Jun 15 07:41:13 defiant kernel: [18279297.476000] Oops: 0000 [#1]
Jun 15 07:41:13 defiant kernel: [18279297.476000] Modules linked in: udf loop iptable_nat ip_nat ip_conntrack iptable_mangle iptable_filter ip_tables x_tables i2c_dev binfmt_misc pktcdvd capability commoncap thermal fan processor autofs4 ipv6 nfs twofish serpent aes blowfish sha256 crypto_null nfsd exportfs lockd sunrpc snd_pcm_oss snd_mixer_oss evdev uhci_hcd usbcore i2c_viapro via686a i2c_isa i2c_core parport_pc parport
Jun 15 07:41:13 defiant kernel: [18279297.476000] CPU:    0
Jun 15 07:41:13 defiant kernel: [18279297.476000] EIP:    0060:[<f0af2b01>]    Not tainted VLI
Jun 15 07:41:13 defiant kernel: [18279297.476000] EFLAGS: 00010293   (2.6.16.19 #82) 
Jun 15 07:41:13 defiant kernel: [18279297.476000] EIP is at udf_get_filelongad+0x30/0x47 [udf]
Jun 15 07:41:13 defiant kernel: [18279297.476000] eax: 010001d3   ebx: 010000fb   ecx: dcd0dd78   edx: 010001e3
Jun 15 07:41:13 defiant kernel: [18279297.476000] esi: 01408dd8   edi: 010000fb   ebp: 010000fb   esp: dcd0dce8
Jun 15 07:41:13 defiant kernel: [18279297.476000] ds: 007b   es: 007b   ss: 0068
Jun 15 07:41:13 defiant kernel: [18279297.476000] Process cp (pid: 9670, threadinfo=dcd0c000 task=e434aa50)
Jun 15 07:41:13 defiant kernel: [18279297.476000] Stack: <0>d7e00e2c dcd0dd78 f0ae95f1 00000001 dcd0dd68 d7e00e2c dcd0dd70 dcd0dd60 
Jun 15 07:41:13 defiant kernel: [18279297.476000]        f0ae96a1 dcd0dd60 dcd0dd74 dcd0dd70 00000001 dcd0dd78 ffffffff d7e00e2c 
Jun 15 07:41:13 defiant kernel: [18279297.476000]        e7f3ceb4 b84d1aac f0af222c dcd0dd60 dcd0dd74 dcd0dd70 00000001 01cd26a0 
Jun 15 07:41:13 defiant kernel: [18279297.476000] Call Trace:
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<f0ae95f1>] udf_current_aext+0xf7/0x132 [udf]
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<f0ae96a1>] udf_next_aext+0x75/0x85 [udf]
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<f0af222c>] udf_discard_prealloc+0x16a/0x286 [udf]
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<f0ae94e9>] udf_clear_inode+0x16/0x27 [udf]
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<b0150f67>] clear_inode+0x80/0xad
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<b0151489>] generic_drop_inode+0x101/0x114
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<b01509b3>] iput+0x64/0x66
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<f0aeb01a>] udf_iget+0x84/0x8b [udf]
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<f0aef4ac>] udf_lookup+0x62/0x86 [udf]
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<b0148bbd>] do_lookup+0xa3/0x137
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<b0149304>] __link_path_walk+0x6b3/0xa8e
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<b0149726>] link_path_walk+0x47/0xb9
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<b014f8e1>] dput+0x22/0x116
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<b01525b3>] mntput_no_expire+0x11/0x52
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<b0149b4b>] do_path_lookup+0x181/0x19c
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<b014a011>] __user_walk_fd+0x29/0x3f
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<b0144cf3>] vfs_lstat_fd+0x12/0x39
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<b014f8e1>] dput+0x22/0x116
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<b01525b3>] mntput_no_expire+0x11/0x52
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<b0145378>] sys_lstat64+0xf/0x23
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<b013caa9>] sys_chmod+0x11/0x15
Jun 15 07:41:13 defiant kernel: [18279297.476000]  [<b0102387>] sysenter_past_esp+0x54/0x75
Jun 15 07:41:13 defiant kernel: [18279297.476000] Code: 0f 94 c2 85 c9 53 89 c3 0f 94 c0 08 c2 74 0f 68 19 46 af f0 e8 ba 0a 62 bf 5a 31 c0 eb 21 8b 01 85 c0 78 19 8d 50 10 39 f2 77 12 <83> 3b 00 89 d8 74 0b 83 7c 24 0c 00 74 06 89 11 eb 02 31 c0 5b 

Re: OOPS in UDF

[Andrew Morton]

On Thu, 15 Jun 2006 08:58:28 -0700
nkiesel@tbdnetworks.com (Norbert Kiesel) wrote:

> I just got an OOPS while copying between two loopback-mounted UDF filesystems.
> One or both of the UDF file systems are corrupted (some files not readable by
> root), but kernel should not OOPS anyway.
> 
> I get the corrupted file systems reliably by rsync'ing big directories onto the
> UDF filesystem (while trying to prepare a backup DVD).  I saw the OOPS only once
> so far.  The system continued to work after the OOPS.

Are you able to get a copy of one of these filesystem images up onto a
server somewhere so others can reproduce the crash?

Re: OOPS in UDF

[Norbert Kiesel]

On Fri, 2006-06-23 at 17:50 -0700, Andrew Morton wrote:
> On Thu, 15 Jun 2006 08:58:28 -0700
> nkiesel@tbdnetworks.com (Norbert Kiesel) wrote:
> 
> > I just got an OOPS while copying between two loopback-mounted UDF filesystems.
> > One or both of the UDF file systems are corrupted (some files not readable by
> > root), but kernel should not OOPS anyway.
> > 
> > I get the corrupted file systems reliably by rsync'ing big directories onto the
> > UDF filesystem (while trying to prepare a backup DVD).  I saw the OOPS only once
> > so far.  The system continued to work after the OOPS.
> 
> Are you able to get a copy of one of these filesystem images up onto a
> server somewhere so others can reproduce the crash?

I will try to recreate them.  If i succeed, I will report back.

</nk>

Re: OOPS in UDF

[Norbert Kiesel]

On Fri, 2006-06-23 at 17:50 -0700, Andrew Morton wrote:
> On Thu, 15 Jun 2006 08:58:28 -0700
> nkiesel@tbdnetworks.com (Norbert Kiesel) wrote:
> 
> > I just got an OOPS while copying between two loopback-mounted UDF filesystems.
> > One or both of the UDF file systems are corrupted (some files not readable by
> > root), but kernel should not OOPS anyway.
> > 
> > I get the corrupted file systems reliably by rsync'ing big directories onto the
> > UDF filesystem (while trying to prepare a backup DVD).  I saw the OOPS only once
> > so far.  The system continued to work after the OOPS.
> 
> Are you able to get a copy of one of these filesystem images up onto a
> server somewhere so others can reproduce the crash?
> 

I tried to reproduce it by filling a loop-mounted UDF filesystem with multiple
copies of my kernel tree (i.e similar to what I had done when I saw the OOPS).
However, now the "cp -a kernel kernel3" hangs, and so does a simple "w"
or "ps". echo p > /proc/sys/kernel/sysrq shows this for one of the
hanging "ps":
[17442714.056000] ps            D E214EB78     0 10874  10870
(NOTLB)
[17442714.056000]        f1571ed8 00000001 00000008 e214eb78 e214ea70
923e5c00 003df798 00000000
[17442714.056000]        923e5c00 003df798 016e3600 00000000 0000003b
e6ebe5d4 00000000 e214ea70
[17442714.056000]        c02c1d03 000003ab e6ebe5d8 ebcf5ee8 c0e03ee8
e214ea70 00000001 0000003b
[17442714.056000] Call Trace:
[17442714.056000]  <c02c1d03> rwsem_down_read_failed+0x12a/0x144
<c0118b0a> .text.lock.ptrace+0x7/0x25
[17442714.056000]  <c012bc61> __alloc_pages+0xd8/0x270  <c01630da>
proc_pid_cmdline+0x4e/0xdc
[17442714.056000]  <c016344f> proc_info_read+0x37/0x72  <c0163418>
proc_info_read+0x0/0x72
[17442714.056000]  <c013e402> vfs_read+0x9f/0x13e  <c013e766> sys_read
+0x3c/0x63
[17442714.056000]  <c0102443> sysenter_past_esp+0x54/0x75

I'm not sure if this is related to the UDF problem I saw before. The
other thing that changed is that I'm now running a newer kernel compiled
with a newer gcc: Linux version 2.6.17.1 (nkiesel@defiant) (gcc version
4.1.2 20060613 (prerelease) (Debian 4.1.1-5)) #84 Wed Jun 21 16:31:05
PDT 2006.

All things not related to proc_info work as usual (e.g. login, vi,
filesystem access).  I can't see the stacktrace for the cp because the
output of sysrq is clipped.  Once I find out how to extend the buffer I
will try to get a stacktrace for that process, too.

I will also reboot using the 2.6.16.19 kernel and check if the same
happens.  However, the machine is 5500 miles away and does not always
boot without intervention, so I have to wait for Monday.

</nk>