From owner-freebsd-bugs@FreeBSD.ORG Sun Feb 7 02:10:02 2010 Return-Path: Delivered-To: freebsd-bugs@hub.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 0BBA81065672 for ; Sun, 7 Feb 2010 02:10:02 +0000 (UTC) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (freefall.freebsd.org [IPv6:2001:4f8:fff6::28]) by mx1.freebsd.org (Postfix) with ESMTP id C38F98FC12 for ; Sun, 7 Feb 2010 02:10:01 +0000 (UTC) Received: from freefall.freebsd.org (localhost [127.0.0.1]) by freefall.freebsd.org (8.14.3/8.14.3) with ESMTP id o172A1i7038261 for ; Sun, 7 Feb 2010 02:10:01 GMT (envelope-from gnats@freefall.freebsd.org) Received: (from gnats@localhost) by freefall.freebsd.org (8.14.3/8.14.3/Submit) id o172A15j038260; Sun, 7 Feb 2010 02:10:01 GMT (envelope-from gnats) Resent-Date: Sun, 7 Feb 2010 02:10:01 GMT Resent-Message-Id: <201002070210.o172A15j038260@freefall.freebsd.org> Resent-From: FreeBSD-gnats-submit@FreeBSD.org (GNATS Filer) Resent-To: freebsd-bugs@FreeBSD.org Resent-Reply-To: FreeBSD-gnats-submit@FreeBSD.org, RandomUser Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id F28DF1065670 for ; Sun, 7 Feb 2010 02:06:49 +0000 (UTC) (envelope-from nobody@FreeBSD.org) Received: from www.freebsd.org (www.freebsd.org [IPv6:2001:4f8:fff6::21]) by mx1.freebsd.org (Postfix) with ESMTP id E18F58FC18 for ; Sun, 7 Feb 2010 02:06:49 +0000 (UTC) Received: from www.freebsd.org (localhost [127.0.0.1]) by www.freebsd.org (8.14.3/8.14.3) with ESMTP id o1726n9W082478 for ; Sun, 7 Feb 2010 02:06:49 GMT (envelope-from nobody@www.freebsd.org) Received: (from nobody@localhost) by www.freebsd.org (8.14.3/8.14.3/Submit) id o1726nju082477; Sun, 7 Feb 2010 02:06:49 GMT (envelope-from nobody) Message-Id: <201002070206.o1726nju082477@www.freebsd.org> Date: Sun, 7 Feb 2010 02:06:49 GMT From: RandomUser To: freebsd-gnats-submit@FreeBSD.org X-Send-Pr-Version: www-3.1 Cc: Subject: kern/143623: firewire fails to attach DV camera and download DV stream X-BeenThere: freebsd-bugs@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Bug reports List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sun, 07 Feb 2010 02:10:02 -0000 >Number: 143623 >Category: kern >Synopsis: firewire fails to attach DV camera and download DV stream >Confidential: no >Severity: non-critical >Priority: medium >Responsible: freebsd-bugs >State: open >Quarter: >Keywords: >Date-Required: >Class: sw-bug >Submitter-Id: current-users >Arrival-Date: Sun Feb 07 02:10:01 UTC 2010 >Closed-Date: >Last-Modified: >Originator: RandomUser >Release: 7.2-STABLE >Organization: >Environment: 7.2-STABLE FreeBSD 7.2-STABLE #7: Sun Jan 17 11:54:45 CST 2010 >Description: Connect DV camera to firewire -> apparent fireware problems occur. Attempt to download DV stream -> error message about "Bad file descriptor" ===== firewire dmesg entries ===== fwohci0: <1394 Open Host Controller Interface> mem 0xfc004000-0xfc0047ff irq 23 at device 9.4 on pci2 fwohci0: [FILTER] fwohci0: OHCI version 1.10 (ROM=1) fwohci0: No. of Isochronous channels is 4. fwohci0: EUI64 00:90:e6:39:00:00:01:a4 fwohci0: Phy 1394a available S400, 2 ports. fwohci0: Link S400, max_rec 2048 bytes. firewire0: on fwohci0 fwe0: on firewire0 if_fwe0: Fake Ethernet address: 02:90:e6:00:01:a4 fwe0: Ethernet address: 02:90:e6:00:01:a4 fwip0: on firewire0 fwip0: Firewire address: 00:90:e6:39:00:00:01:a4 @ 0xfffe00000000, S400, maxrec 2048 sbp0: on firewire0 dcons_crom0: on firewire0 dcons_crom0: bus_addr 0x1f88000 wohci0: Initiate bus reset fwohci0: BUS reset fwohci0: node_id=0xc800ffc0, gen=1, CYCLEMASTER mode firewire0: 1 nodes, maxhop <= 0, cable IRM = 0 (me) firewire0: bus manager 0 (me) ===== attach DV camera via firewire cable ===== fwohci0: Initiate bus reset fwohci0: BUS reset fwohci0: node_id=0xc800ffc0, gen=2, CYCLEMASTER mode firewire0: 1 nodes, maxhop <= 0, cable IRM = 0 (me) firewire0: bus manager 0 (me) fwohci0: BUS reset fwohci0: node_id=0x8800ffc0, gen=3, non CYCLEMASTER mode firewire0: 2 nodes, maxhop <= 1, cable IRM = 1 fwohci0: too many cycle lost, no cycle master presents? fwohci0: txd err= 3 miss Ack err fwohci0: txd err= 3 miss Ack err fwohci0: txd err= 3 miss Ack err fwohci0: BUS reset fwohci0: node_id=0x8800ffc0, gen=4, non CYCLEMASTER mode firewire0: 2 nodes, maxhop <= 1, cable IRM = 1 firewire0: New S400 device ID:0000f000ffffffff fwohci0: Initiate bus reset fwohci0: BUS reset fwohci0: node_id=0xc800ffc1, gen=5, CYCLEMASTER mode firewire0: 2 nodes, maxhop <= 1, cable IRM = 1 (me) firewire0: bus manager 1 (me) fwohci0: BUS reset fwohci0: node_id=0x8800ffc0, gen=6, non CYCLEMASTER mode firewire0: 2 nodes, maxhop <= 1, cable IRM = 1 fwohci0: too many cycle lost, no cycle master presents? fwohci0: BUS reset fwohci0: node_id=0xc800ffc0, gen=7, CYCLEMASTER mode firewire0: 1 nodes, maxhop <= 0, cable IRM = 0 (me) firewire0: bus manager 0 (me) ==== attempt to use fwcontrol to download DV stream ===== fwcontrol -R recording.dv fwcontrol: detect_recv_fn: ioctl FW_SSTBUF: Bad file descriptor ==== check firewire configuration ==== 2 devices (info_len=2) node EUI64 status hostname 0 00-90-e6-39-00-00-01-a4 0 1 00-00-f0-00-ff-ff-ff-ff 1 ==== ktrace dump of fwcontrol -R ==== 1796 ktrace CALL execve(0xbfbfe5a8,0xbfbfeb34,0xbfbfeb44) 1796 ktrace NAMI "/bin/fwcontrol" 1796 ktrace RET execve -1 errno 2 No such file or directory 1796 ktrace CALL execve(0xbfbfe5a8,0xbfbfeb34,0xbfbfeb44) 1796 ktrace NAMI "/sbin/fwcontrol" 1796 ktrace RET execve -1 errno 2 No such file or directory 1796 ktrace CALL execve(0xbfbfe5a8,0xbfbfeb34,0xbfbfeb44) 1796 ktrace NAMI "/usr/sbin/fwcontrol" 1796 ktrace NAMI "/libexec/ld-elf.so.1" 1796 fwcontrol RET execve 0 1796 fwcontrol CALL __sysctl(0xbfbfe464,0x2,0xbfbfe46c,0xbfbfe470,0,0) 1796 fwcontrol SCTL "kern.osreldate" 1796 fwcontrol RET __sysctl 0 1796 fwcontrol CALL mmap(0,0x130,PROT_READ|PROT_WRITE,MAP_ANON,0xffffffff,0,0) 1796 fwcontrol RET mmap 671592448/0x2807b000 1796 fwcontrol CALL munmap(0x2807b000,0x130) 1796 fwcontrol RET munmap 0 1796 fwcontrol CALL __sysctl(0xbfbfe4c8,0x2,0x28077c7c,0xbfbfe4d0,0,0) 1796 fwcontrol SCTL "hw.pagesize" 1796 fwcontrol RET __sysctl 0 1796 fwcontrol CALL mmap(0,0x8000,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,0xffffffff,0,0) 1796 fwcontrol RET mmap 671592448/0x2807b000 1796 fwcontrol CALL issetugid 1796 fwcontrol RET issetugid 0 1796 fwcontrol CALL open(0x28072532,O_RDONLY,0x1b6) 1796 fwcontrol NAMI "/etc/libmap.conf" 1796 fwcontrol RET open -1 errno 2 No such file or directory 1796 fwcontrol CALL open(0x28071783,O_RDONLY,0) 1796 fwcontrol NAMI "/var/run/ld-elf.so.hints" 1796 fwcontrol RET open 3 1796 fwcontrol CALL read(0x3,0xbfbfe21c,0x80) 1796 fwcontrol GIO fd 3 read 128 bytes 0x0000 4568 6e74 0100 0000 8000 0000 f800 0000 0000 |Ehnt..............| 0x0012 0000 f700 0000 0000 0000 0000 0000 0000 0000 |..................| 0x0024 0000 0000 0000 0000 0000 0000 0000 0000 0000 |..................| 0x0036 0000 0000 0000 0000 0000 0000 0000 0000 0000 |..................| 0x0048 0000 0000 0000 0000 0000 0000 0000 0000 0000 |..................| 0x005a 0000 0000 0000 0000 0000 0000 0000 0000 0000 |..................| 0x006c 0000 0000 0000 0000 0000 0000 0000 0000 0000 |..................| 0x007e 0000 |..| 1796 fwcontrol RET read 128/0x80 1796 fwcontrol CALL lseek(0x3,0x80,SEEK_SET,0) 1796 fwcontrol RET lseek 128/0x80 1796 fwcontrol CALL read(0x3,0x2807f000,0xf8) 1796 fwcontrol GIO fd 3 read 248 bytes "/lib:/usr/lib:/usr/lib/compat:/usr/local/lib:/usr/local/lib/compat/pkg:/usr\ /local/lib/compat:/usr/local/lib/gegl-0.0:/usr/local/lib/graphviz:/usr/loca\ l/lib/mysql:/usr/local/lib/nss:/usr/local/lib/portaudio2:/usr/local/lib/pth\ :/usr/local/lib/sublib\0" 1796 fwcontrol RET read 248/0xf8 1796 fwcontrol CALL close(0x3) 1796 fwcontrol RET close 0 1796 fwcontrol CALL access(0x28080000,F_OK) 1796 fwcontrol NAMI "/lib/libc.so.7" 1796 fwcontrol RET access 0 1796 fwcontrol CALL open(0x2807c020,O_RDONLY,0) 1796 fwcontrol NAMI "/lib/libc.so.7" 1796 fwcontrol RET open 3 1796 fwcontrol CALL fstat(0x3,0xbfbfe4bc) 1796 fwcontrol STRU struct stat {dev=113, ino=24164355, mode=-r--r--r-- , nlink=1, uid=0, gid=0, rdev=96538368, atime=1265494611, stime=1263730855, ctime=1263730855, birthtime=1263730855, size=1032700, blksize=4096, blocks=2080, flags=0x20000 } 1796 fwcontrol RET fstat 0 1796 fwcontrol CALL read(0x3,0x28076bc0,0x1000) 1796 fwcontrol GIO fd 3 read 4096 bytes 0x0000 7f45 4c46 0101 0109 0000 0000 0000 0000 0300 |.ELF..............| . . . 0x0ff6 0000 0000 0000 e107 0000 |..........| 1796 fwcontrol RET read 4096/0x1000 1796 fwcontrol CALL mmap(0,0xff000,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,0xffffffff,0,0) 1796 fwcontrol RET mmap 671625216/0x28083000 1796 fwcontrol CALL mmap(0x28083000,0xe3000,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE,0x3,0,0) 1796 fwcontrol RET mmap 671625216/0x28083000 1796 fwcontrol CALL mmap(0x28166000,0x6000,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED,0x3,0xe3000,0) 1796 fwcontrol RET mmap 672555008/0x28166000 1796 fwcontrol CALL mprotect(0x2816c000,0x16000,PROT_READ|PROT_WRITE) 1796 fwcontrol RET mprotect 0 1796 fwcontrol CALL close(0x3) 1796 fwcontrol RET close 0 1796 fwcontrol CALL sysarch(0xa,0xbfbfe530) 1796 fwcontrol RET sysarch 0 1796 fwcontrol CALL mmap(0,0x170,PROT_READ|PROT_WRITE,MAP_ANON,0xffffffff,0,0) 1796 fwcontrol RET mmap 672669696/0x28182000 1796 fwcontrol CALL munmap(0x28182000,0x170) 1796 fwcontrol RET munmap 0 1796 fwcontrol CALL mmap(0,0x52f0,PROT_READ|PROT_WRITE,MAP_ANON,0xffffffff,0,0) 1796 fwcontrol RET mmap 672669696/0x28182000 1796 fwcontrol CALL munmap(0x28182000,0x52f0) 1796 fwcontrol RET munmap 0 1796 fwcontrol CALL sigprocmask(SIG_BLOCK,0x28076b00,0xbfbfe50c) 1796 fwcontrol RET sigprocmask 0 1796 fwcontrol CALL sigprocmask(SIG_SETMASK,0x28076b10,0) 1796 fwcontrol RET sigprocmask 0 1796 fwcontrol CALL __sysctl(0xbfbfe4e4,0x2,0x2816cb40,0xbfbfe4ec,0,0) 1796 fwcontrol SCTL "kern.arandom" 1796 fwcontrol RET __sysctl 0 1796 fwcontrol CALL sigprocmask(SIG_BLOCK,0x28076b00,0xbfbfe4dc) 1796 fwcontrol RET sigprocmask 0 1796 fwcontrol CALL sigprocmask(SIG_SETMASK,0x28076b10,0) 1796 fwcontrol RET sigprocmask 0 1796 fwcontrol CALL __sysctl(0xbfbfe0c8,0x2,0x28170820,0xbfbfe0d0,0,0) 1796 fwcontrol SCTL "hw.ncpu" 1796 fwcontrol RET __sysctl 0 1796 fwcontrol CALL __sysctl(0xbfbfdbd8,0x2,0x2817f13c,0xbfbfdbe0,0,0) 1796 fwcontrol SCTL "hw.pagesize" 1796 fwcontrol RET __sysctl 0 1796 fwcontrol CALL __sysctl(0xbfbfdc28,0x2,0xbfbfdc34,0xbfbfdc38,0,0) 1796 fwcontrol SCTL "p1003_1b.pagesize" 1796 fwcontrol RET __sysctl 0 1796 fwcontrol CALL readlink(0x2815db67,0xbfbfdcbb,0x400) 1796 fwcontrol NAMI "/etc/malloc.conf" 1796 fwcontrol RET readlink -1 errno 2 No such file or directory 1796 fwcontrol CALL issetugid 1796 fwcontrol RET issetugid 0 1796 fwcontrol CALL break(0x8100000) 1796 fwcontrol RET break 0 1796 fwcontrol CALL __sysctl(0xbfbfdf64,0x2,0xbfbfdf6c,0xbfbfdf70,0,0) 1796 fwcontrol SCTL "kern.osreldate" 1796 fwcontrol RET __sysctl 0 1796 fwcontrol CALL mmap(0,0x100000,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,0xffffffff,0,0) 1796 fwcontrol RET mmap 672669696/0x28182000 1796 fwcontrol CALL mmap(0x28282000,0x7e000,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,0xffffffff,0,0) 1796 fwcontrol RET mmap 673718272/0x28282000 1796 fwcontrol CALL munmap(0x28182000,0x7e000) 1796 fwcontrol RET munmap 0 1796 fwcontrol CALL ioctl(0xffffffff,FW_SSTBUF,0xbfbfea74) 1796 fwcontrol RET ioctl -1 errno 9 Bad file descriptor 1796 fwcontrol CALL write(0x2,0xbfbfd9e0,0xb) 1796 fwcontrol GIO fd 2 wrote 11 bytes "fwcontrol: " 1796 fwcontrol RET write 11/0xb 1796 fwcontrol CALL write(0x2,0xbfbfda10,0x1f) 1796 fwcontrol GIO fd 2 wrote 31 bytes "detect_recv_fn: ioctl FW_SSTBUF" ==== listing of firewire special files ==== ls -l /dev/fw* lrwxr-xr-x 1 root wheel 5 Feb 6 19:33 /dev/fw0 -> fw0.0 crw-rw-rw- 1 root operator 0, 49 Feb 6 19:33 /dev/fw0.0 lrwxr-xr-x 1 root wheel 8 Feb 6 19:33 /dev/fwmem0 -> fwmem0.0 crw-rw---- 1 root operator 0, 50 Feb 6 19:33 /dev/fwmem0.0 ==== sysctl -A|grep fw ===== debug.fwmem_debug: 0 debug.if_fwe_debug: 0 debug.if_fwip_debug: 0 hw.firewire.fwmem.speed: 2 hw.firewire.fwmem.eui64_lo: 0 hw.firewire.fwmem.eui64_hi: 0 hw.firewire.fwe.rx_queue_len: 128 hw.firewire.fwe.tx_speed: 2 hw.firewire.fwe.stream_ch: 1 hw.firewire.fwip.rx_queue_len: 128 hw.nvidia.agp.card.fw: supported hw.nvidia.agp.status.fw: enabled dev.fwohci.0.%desc: 1394 Open Host Controller Interface dev.fwohci.0.%driver: fwohci dev.fwohci.0.%location: slot=9 function=4 dev.fwohci.0.%pnpinfo: vendor=0x10b9 device=0x5253 subvendor=0x17fc subdevice=0x5253 class=0x0c0010 dev.fwohci.0.%parent: pci2 dev.firewire.0.%parent: fwohci0 dev.fwe.0.%desc: Ethernet over FireWire dev.fwe.0.%driver: fwe dev.fwe.0.%parent: firewire0 dev.fwip.0.%desc: IP over FireWire dev.fwip.0.%driver: fwip dev.fwip.0.%parent: firewire0 ==== sysctl -A|grep firewire ===== debug.firewire_debug: 0 hw.firewire.hold_count: 3 hw.firewire.try_bmr: 1 hw.firewire.fwmem.speed: 2 hw.firewire.fwmem.eui64_lo: 0 hw.firewire.fwmem.eui64_hi: 0 hw.firewire.phydma_enable: 1 hw.firewire.nocyclemaster: 0 hw.firewire.fwe.rx_queue_len: 128 hw.firewire.fwe.tx_speed: 2 hw.firewire.fwe.stream_ch: 1 hw.firewire.fwip.rx_queue_len: 128 hw.firewire.sbp.tags: 0 hw.firewire.sbp.use_doorbell: 0 hw.firewire.sbp.scan_delay: 500 hw.firewire.sbp.login_delay: 1000 hw.firewire.sbp.exclusive_login: 1 hw.firewire.sbp.max_speed: 2 hw.firewire.sbp.auto_login: 1 dev.firewire.0.%desc: IEEE1394(FireWire) bus dev.firewire.0.%driver: firewire dev.firewire.0.%parent: fwohci0 dev.fwe.0.%parent: firewire0 dev.fwip.0.%parent: firewire0 dev.sbp.0.%parent: firewire0 dev.dcons_crom.0.%parent: firewire0 >How-To-Repeat: Detach, reattach DV camera, and attempt to download DV stream. >Fix: >Release-Note: >Audit-Trail: >Unformatted: