OOPS in 2.4.25-rc1 -- video1394

OOPS in 2.4.25-rc1 -- video1394

[Roland Mas]

  Hi there,

You'll remember Christmas was not that long ago, and the number of
digital camcorders in my possession has grown from nil to one.  And
I've been trying to make the best use of it, with kino as the video
edition/capture/effects/whatever software.

  To the point: I can grab video from it (using the raw1394 system),
but exporting video to it results in an oops.  I've only attached the
ksymoops output from kernel 2.4.25-rc1, but I had similar problems
with 2.4.24.  Of course, when that oops happens, kino crashes with a
segmentation fault.

  Interesting fact: when I export video to the camcorder with a
non-GUI application (dvconnect), I get neither oops nor segfault.
It's just that it doesn't start the recording on the camcorder, so it
isn't very useful: the video appears on the camcorder's screen, but
doesn't go onto tape.

Relevant data (I hope):

- Vanilla 2.4.25-rc1 kernel;
- Debian system (up-to-date sid);
- Sony DRC-TRV33E camcorder;
- lspci shows "00:05.0 FireWire (IEEE 1394): VIA Technologies,
  Inc. IEEE 1394 Host Controller (rev 46)"
- ksymoopsed oops (from kern.log):
,----
| ksymoops 2.4.9 on i686 2.4.25-rc1.  Options used
|      -V (default)
|      -k /proc/ksyms (default)
|      -l /proc/modules (default)
|      -o /lib/modules/2.4.25-rc1/ (default)
|      -m /boot/System.map-2.4.25-rc1 (default)
| 
| Warning: You did not tell me where to find symbol information.  I will
| assume that the log matches the kernel and modules that are running
| right now and I'll use the default options above for symbol resolution.
| If the current kernel and/or modules do not match the log, you can get
| more accurate output by telling me the kernel version and where to find
| map, modules, ksyms etc.  ksymoops -h explains the options.
| 
| Unable to handle kernel NULL pointer dereference at virtual address 00000004
| fcd81136
| *pde = 00000000
| Oops: 0002
| CPU:    0
| EIP:    0010:[<fcd81136>]    Not tainted
| Using defaults from ksymoops -t elf32-i386 -a i386
| EFLAGS: 00210246
| eax: 00000000   ebx: f775eb28   ecx: f775eb78   edx: 00000000
| esi: f775ead4   edi: 80000000   ebp: 00000200   esp: f2c87e80
| ds: 0018   es: 0018   ss: 0018
| Process kino (pid: 1276, stackpage=f2c87000)
| Stack: f775eb28 00000000 00000000 f775eb28 f775ead4 fcd813af f775ead4 00000000
|        c1c3c000 00000000 0000000a 00000400 fcd838bf f2c87eec 00000000 00000030
|        c1d46310 00000000 00000004 80000000 00000000 fcd821c1 f61b1cdc 00000000
| Call Trace:    [<fcd813af>] [<fcd838bf>] [<fcd821c1>] [devfs_open+333/432] [vfs_permission+122/272]
| Code: 89 50 04 89 02 c7 41 04 00 00 00 00 c7 86 a4 00 00 00 00 00
| 
| 
| >>EIP; fcd81136 <[video1394]free_dma_iso_ctx+b6/140>   <=====
| 
| >>ebx; f775eb28 <_end+374711fc/38521754>
| >>ecx; f775eb78 <_end+3747124c/38521754>
| >>esi; f775ead4 <_end+374711a8/38521754>
| >>esp; f2c87e80 <_end+3299a554/38521754>
| 
| Trace; fcd813af <[video1394]alloc_dma_iso_ctx+1ef/5d0>
| Trace; fcd838bf <[video1394].text.end+42a/b13>
| Trace; fcd821c1 <[video1394]video1394_ioctl+2d1/e80>
| 
| Code;  fcd81136 <[video1394]free_dma_iso_ctx+b6/140>
| 00000000 <_EIP>:
| Code;  fcd81136 <[video1394]free_dma_iso_ctx+b6/140>   <=====
|    0:   89 50 04                  mov    %edx,0x4(%eax)   <=====
| Code;  fcd81139 <[video1394]free_dma_iso_ctx+b9/140>
|    3:   89 02                     mov    %eax,(%edx)
| Code;  fcd8113b <[video1394]free_dma_iso_ctx+bb/140>
|    5:   c7 41 04 00 00 00 00      movl   $0x0,0x4(%ecx)
| Code;  fcd81142 <[video1394]free_dma_iso_ctx+c2/140>
|    c:   c7 86 a4 00 00 00 00      movl   $0x0,0xa4(%esi)
| Code;  fcd81149 <[video1394]free_dma_iso_ctx+c9/140>
|   13:   00 00 00 
| 
| 
| 1 warning issued.  Results may not be reliable.
`----

  The "interesting fact" I mentioned above tells me there might be a
bug in kino, but I'm not sure it should trigger the kernel oops.
Especially since the oops sort of locks the video1394 device so it
can't be used (including by dvconnect) until I reboot the box.

Thanks,

Roland.
-- 
Roland Mas

Death *was* hereditary.  You got it from your ancestors.
  -- in Hogfather (Terry Pratchett)

Re: OOPS in 2.4.25-rc1 -- video1394

[Ben Collins]

> | Trace; fcd813af <[video1394]alloc_dma_iso_ctx+1ef/5d0>
> | Trace; fcd838bf <[video1394].text.end+42a/b13>
> | Trace; fcd821c1 <[video1394]video1394_ioctl+2d1/e80>
> | 
> | Code;  fcd81136 <[video1394]free_dma_iso_ctx+b6/140>
> | 00000000 <_EIP>:
> | Code;  fcd81136 <[video1394]free_dma_iso_ctx+b6/140>   <=====
> |    0:   89 50 04                  mov    %edx,0x4(%eax)   <=====
> | Code;  fcd81139 <[video1394]free_dma_iso_ctx+b9/140>
> |    3:   89 02                     mov    %eax,(%edx)
> | Code;  fcd8113b <[video1394]free_dma_iso_ctx+bb/140>
> |    5:   c7 41 04 00 00 00 00      movl   $0x0,0x4(%ecx)
> | Code;  fcd81142 <[video1394]free_dma_iso_ctx+c2/140>
> |    c:   c7 86 a4 00 00 00 00      movl   $0x0,0xa4(%esi)
> | Code;  fcd81149 <[video1394]free_dma_iso_ctx+c9/140>
> |   13:   00 00 00 
> | 
> | 
> | 1 warning issued.  Results may not be reliable.
> `----

Looks to me like it is failing in alloc_dma_iso_ctx(), and then calling
free_dma_iso_ctx() where it encounters some bad data. I can't see off
hand where this might happen. Was there any message prior to this, like
maybe a video1394 error message?

-- 
Debian     - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
WatchGuard - http://www.watchguard.com/

Re: OOPS in 2.4.25-rc1 -- video1394

[Roland Mas]

Ben Collins, 2004-02-09 12:57:31 -0500 :

[...]

> Looks to me like it is failing in alloc_dma_iso_ctx(), and then calling
> free_dma_iso_ctx() where it encounters some bad data. I can't see off
> hand where this might happen. Was there any message prior to this, like
> maybe a video1394 error message?

There were messages before that, yes.  Here come bits of my kern.log.
,----
| Feb  9 12:11:11 mirexpress kernel: mask: 8000000000000000 usage: 0000000000000000
| Feb  9 12:11:11 mirexpress kernel: video1394_0: Iso transmit DMA: 8 buffers of size 163840 allocated for a frame size 163840, each with 320 prgs
| Feb  9 12:11:11 mirexpress kernel: video1394_0: Iso context 0 talk on channel 63
| Feb  9 12:11:21 mirexpress kernel: video1394_0: Iso context 0 stop talking on channel 63
| Feb  9 12:12:51 mirexpress kernel: mask: 8000000000000000 usage: 0000000000000000
| Feb  9 12:12:51 mirexpress kernel: dma_region_alloc: vmalloc_32() failed
| Feb  9 12:12:51 mirexpress kernel: video1394_0: Failed to allocate dma buffer
| Feb  9 12:12:51 mirexpress kernel: Unable to handle kernel NULL pointer dereference at virtual address 00000004Feb  9 12:12:51 mirexpress kernel:  printing eip:
| Feb  9 12:12:51 mirexpress kernel: fcd81136
| Feb  9 12:12:51 mirexpress kernel: *pde = 00000000
| Feb  9 12:12:51 mirexpress kernel: Oops: 0002
| Feb  9 12:12:51 mirexpress kernel: CPU:    0
| Feb  9 12:12:51 mirexpress kernel: EIP:    0010:[<fcd81136>]    Not tainted
| Feb  9 12:12:51 mirexpress kernel: EFLAGS: 00210246
| [snip]
`----
The entries until 12:11:21 are when I used dvconnect (which worked).
So there are indeed three lines before the actual oops, including two
that look like error messages.

  If there's anything else I can povide, just say so, I just can't
think of anything.

  Thanks,

Roland.
-- 
Roland Mas

A man walks into a bar.
Bang.

Re: OOPS in 2.4.25-rc1 -- video1394

[Roland Mas]

Roland Mas, 2004-02-09 23:16:19 +0100 :

> Ben Collins, 2004-02-09 12:57:31 -0500 :
>
> [...]
>
>> Looks to me like it is failing in alloc_dma_iso_ctx(), and then
>> calling free_dma_iso_ctx() where it encounters some bad data. I
>> can't see off hand where this might happen. Was there any message
>> prior to this, like maybe a video1394 error message?
>
> There were messages before that, yes.  Here come bits of my kern.log.

[...]

>   If there's anything else I can povide, just say so, I just can't
> think of anything.

  I have new data: if I reduce the "Frame Buffers" (tooltip: "The
number of frames that will be buffered to prevent underrun")
configuration entry in Kino from 300 to 50, then Kino doesn't crash
and the kernel doesn't oops.  On the other hand, only three seconds
can be exported to the camcorder before what's transmitted becomes a
flashing blue/white screen, with small blocks of image transmitted
occasionnally.  During the same time, top(1) displays my XFree86
process as using a very large amount of CPU (more than 95%, and load
indeed goes from about 0 to about 1).  Since my CPU *should* be fast
enough (Athlon 2200+, 1 GB of RAM), I now think the bug is at least
partially in userspace.  If you have ideas on how to debug further,
I'd be glad to hear about them, otherwise I'll turn my attention to
Kino's maintainer and/or author.  My personal (hence probably wrong)
interpretation is that Kino tried to allocate lots and lots of space
for its 300 buffers, doesn't check the result, and tries to access the
freshly (non-)allocated space.

  I still think the kernel shouldn't oops, but if I can find a
userspace fix, I won't mind that much :-)

Roland.
-- 
Roland Mas

- Ogenki desuka, yau de poêle ?
- Genki desu, ture en zinc.

Re: OOPS in 2.4.25-rc1 -- video1394

[Ben Collins]

>   I still think the kernel shouldn't oops, but if I can find a
> userspace fix, I won't mind that much :-)

Yeah, the kernel definitely shoudln't oops, even if kino doesn't
something wrong. It's probably doing something wrong, and the video1394
driver just isn't doing the proper checks.

-- 
Debian     - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
WatchGuard - http://www.watchguard.com/