Ext. firewire disk disconnection and persistence of da* entry...

[Barry Bouwsma]

[I'm mostly offline, so drop my IPv6-only address above and I'll catch
 the list archives shortly, if you reply]

I wrote:
 
> > Could you describe a detail of the problem?

> I believe -- but I am not certain, because I've been running with my
> hacked codes from half a year ago, that the drive is not reliably
> recognized every time it's attached, but it is recognized every second

Okay, I checked -- When the drive is attached before booting into a kernel
from sources about 01.Sep (two patches applied -- the detach patch I gave
earlier, plus one to eliminate the tons of debug messages with verbose
booting), it is not attached as a da0 drive.  If I unplug it and then
reconnect it, it then is made available as da0, and apparently repeated
dis-/re-connects all make it reappear -- at least with my detach patch.
(Hmm, have I tried mounting it?  Ummm...)

Following significant parts of the 4.9-PRERELEASE dmesg, I'm also giving
selected parts from my 4.7 kernel from 09.Dec with hacks to log some debug
info and reliably find and attach (though probably incorrectly) the drive,
if any of my debug info would be of help.  (FYI, I also needed to do some
hacking to get NetBSD-current of the same date to recognize the drive though
I didn't succeed in getting it mounted successfully.)

Here's the dmesg, drive attached before boot, 4.9-beginning-of-September:

fwohci0: vendor=1033, dev=e7
fwohci0: <1394 Open Host Controller Interface> mem 0xdf800000-0xdf800fff irq 9 at device 9.0 on pci0
	using shared irq9.
fwohci0: OHCI version 1.10 (ROM=1)
fwohci0: No. of Isochronous channel is 4.
fwohci0: EUI64 00:00:4c:02:08:00:5e:45
fwohci0: resetting OHCI...done (loop=0)
fwohci0: fwphy_rddata: 0x2 loop=1, retry=0
fwohci0: fwphy_rddata: 0x3 loop=1, retry=0
fwohci0: Phy 1394a available S400, 2 ports.
fwohci0: fwphy_rddata: 0x5 loop=1, retry=0
fwohci0: Enable 1394a Enhancements
fwohci0: fwphy_rddata: 0x5 loop=1, retry=0
fwohci0: fwphy_rddata: 0x2 loop=1, retry=0
fwohci0: fwphy_rddata: 0x4 loop=1, retry=0
fwohci0: fwphy_rddata: 0x4 loop=1, retry=0
fwohci0: fwphy_rddata: 0x4 loop=1, retry=0
fwohci0: Link S400, max_rec 2048 bytes.
fwohci0: BUS_OPT 0xf800a002 -> 0xf800a002
fwohci0: fwohci_set_intr: 1
firewire0: <IEEE1394(FireWire) bus> on fwohci0
sbp0: <SBP2/SCSI over firewire> on firewire0
sbp_attach (cold=1)
fwohci0: Initiate bus reset
fwohci0: fwphy_rddata: 0x1 loop=1, retry=0
fwohci0: fwphy_rddata: 0x1 loop=1, retry=0
fwohci0: BUS reset
sbp_post_busreset
fwohci0: node_id=0xc800ffc1, gen=1, CYCLEMASTER mode
firewire0: 2 nodes, maxhop <= 1, cable IRM = 1 (me)
fwohci0: fw_set_bus_manager: 1->1 (loop=0)
firewire0: bus manager 1 (me)
fwohci0: maxdesc: 2
fwohci0: start AT DMA status=0
    [ snip ... ]
fwohci0: BUS reset
sbp_post_busreset
fwohci0: node_id=0xc800ffc1, gen=2, CYCLEMASTER mode
fw_xfer_done: pending
firewire0: 2 nodes, maxhop <= 1, cable IRM = 1 (me)
fwohci0: fw_set_bus_manager: 1->1 (loop=0)
firewire0: bus manager 1 (me)
fwohci0: start AT DMA status=11
    [ snip ... ]
firewire0: New S400 device ID:0010b920003dbcb3
sbp_post_explore (sbp_cold=2)
sbp_post_explore: EUI:0010b920003dbcb3 attached
target 0 lun 0 found
sbp0:0:0 ordered:1 type:14 EUI:0010b920003dbcb3 node:0 speed:2 maxrec:0 new!
sbp0:0:0 'Maxtor' '5000XT  v1.00.00' '010000'
fw_attach_dev: 1 pending handlers called
    [ snip ... ]
sbp0:0:0 LOGIN
sbp: alloc 1 xfer
fwohci0: maxdesc: 3
sbp0:0:0 login: len 16, ID 0, cmd 0000fffff0100000, recon_hold 0
sbp0:0:0 sbp_busy_timeout
sbp0:0:0 sbp_agent_reset
sbp0:0:0 sbp_do_attach

Somewhere like here, I detach the cable:

fwohci0: BUS reset
sbp_post_busreset
fwohci0: node_id=0xc800ffc0, gen=3, CYCLEMASTER mode
firewire0: 1 nodes, maxhop <= 0, cable IRM = 0 (me)
fwohci0: fw_set_bus_manager: 0->0 (loop=0)
firewire0: bus manager 0 (me)
fwohci0: start AT DMA status=12
sbp_post_explore (sbp_cold=1)
sbp_post_explore: EUI:0010b920003dbcb3 not attached, state=3.
sbp0:0:0 lost target
  So... calling sbp_cam_detach_target
sbp_detach_target 0
fwohci0: BUS reset
sbp_post_busreset
fwohci0: node_id=0x8800ffc0, gen=5, non CYCLEMASTER mode
firewire0: 2 nodes, maxhop <= 1, cable IRM = 0 (me)
fwohci0: fw_set_bus_manager: 0->0 (loop=0)
firewire0: root node is not cycle master capable
firewire0: bus manager 0 (me)
fwohci0: start AT DMA status=11
sbp_post_explore (sbp_cold=0)
sbp_post_explore: EUI:0010b920003dbcb3 not attached, state=3.

Then I reattach it right away, somewhere around here, I think:

fwohci0: BUS reset
sbp_post_busreset
fwohci0: node_id=0xc800ffc1, gen=6, CYCLEMASTER mode
firewire0: 2 nodes, maxhop <= 1, cable IRM = 1 (me)
fwohci0: fw_set_bus_manager: 1->1 (loop=0)
firewire0: bus manager 1 (me)
fwohci0: start AT DMA status=12
sbp_post_explore (sbp_cold=0)
sbp_post_explore: EUI:0010b920003dbcb3 attached
sbp0:0:0 ordered:1 type:14 EUI:0010b920003dbcb3 node:0 speed:2 maxrec:0
sbp0:0:0 'Maxtor' '5000XT  v1.00.00' '010000'
sbp0:0:0 RECONNECT
sbp0:0:0 reconnect failed
sbp0:0:0 LOGIN
sbp0:0:0 login: len 16, ID 0, cmd 0000fffff0100000, recon_hold 0
sbp0:0:0 sbp_busy_timeout
sbp0:0:0 sbp_agent_reset
sbp0:0:0 sbp_do_attach
sbp0:0:0 sbp_cam_scan_target
sbp0:0:0 XPT_SCSI_IO: cmd: 1a 00 0a 00 14 00 00 00 00 00, flags: 0x40, 6b cmd/20b data/32b sense
sbp0:0:0 SCSI status 2 sfmt 0 valid 0 key 5 code 24 qlfr 0 len 3
(probe0:sbp0:0:0:0): MODE SENSE(06). CDB: 1a 0 a 0 14 0 
(probe0:sbp0:0:0:0): ILLEGAL REQUEST asc:24,0
(probe0:sbp0:0:0:0): Invalid field in CDB
pass1 at sbp0 bus 0 target 0 lun 0
pass1: <Maxtor 5000XT  v1.00.00 0000> Fixed Simplified Direct Access SCSI-4 device 
pass1: Serial Number A80A06AE            
pass1: 50.000MB/s transfers, Tagged Queueing Enabled
Creating DISK da0
sbp0:0:0 sbp_cam_scan_lun
da0 at sbp0 bus 0 target 0 lun 0
da0: <Maxtor 5000XT  v1.00.00 0000> Fixed Simplified Direct Access SCSI-4 device 
da0: Serial Number A80A06AE            
da0: 50.000MB/s transfers, Tagged Queueing Enabled
da0: 239371MB (490232832 512 byte sectors: 255H 63S/T 30515C)

Hmmm, gotta boot with the unpatched new kernel modules for sbp and firewire,
and see how or if it performs differently.

The following attach/detaches look like the above from quick inspection,
so I'm not including them here.



Now, here's the hacked 09.Dec.2002 kernel with my added debug messages:

XXXfw: vendid=1033, dev=e7
fwohci0: <1394 Open Host Controller Interface> mem 0xdf800000-0xdf800fff irq 9 at device 9.0 on pci0
fwohci0: PCI bus latency was changing to 250.
cache size 8.
	using shared irq9.
fwohci0: OHCI version 1.10 (ROM=1)
fwohci0: No. of Isochronous channel is 4.
fwohci0: resetting OHCI...done (0)
fwohci0: BUS_OPT 0xf800a002 -> 0xf800a002
fwohci0: Link 1394a available S400, 2 ports, maxrec 2048 bytes.
fwohci0: Enable 1394a Enhancements
fwohci0: EUI64 00:00:4c:02:08:00:5e:45
fwochi_set_intr: 1
firewire0: <IEEE1394(Firewire) bus> on fwohci0
firewire0: firewire bus attach
sbp_identify
sbp_probe
sbp0: <SBP2/SCSI over firewire> on firewire0
sbp_attach
calling sbp_detach_target
doing sbp_detach_target
calling sbp_detach_target
doing sbp_detach_target
calling sbp_detach_target
doing sbp_detach_target
calling sbp_detach_target
doing sbp_detach_target
calling sbp_detach_target
doing sbp_detach_target
calling sbp_detach_target
doing sbp_detach_target
calling sbp_detach_target
doing sbp_detach_target
calling sbp_detach_target
doing sbp_detach_target
    [ snip ... ]
firewire0: BUS reset
firewire0: node_id = 0x8800ffc0, non CYCLEMASTER mode
firewire0: 2 nodes, maxhop <= 1, cable IRM = 0 (me)
fw_set_bus_manager: 63->0 (loop=0)
send phy_config root_node=-1 gap_count=1
start AT DMA status=0
    [ snip ... ]
ad3: piomode=4 dmamode=2 udmamode=6 cblid=1
firewire0:Discover new S400 device ID:0010b920003dbcb3
bus_explore done
Found neither ANSIT10 nor 1394TA fwdev->spec is 10b9 and fwdev->ver is ceb001
sbp_post_explore: EUI:0010b920003dbcb3 spec=0 key=0.
fwdev->status (should be 2) is 2
spec is 4281 or 0x10b9
version is 13545473 or 0xceb001
alive was 0
alive is now 1
Calling sbp_probe_target with alive 1
sbp_probe_target 0
sbp0:0:0 LOGIN
sbp0:0:0 ordered:1 type:14 EUI:0010b920003dbcb3 node:1 speed:2 maxrec:5 new!
sbp0:0:0 'Maxtor' '1394 Storage Front Panel*' '010000'
sbp0:0:0 login: len 16, ID 0, cmd 0000fffff0100000, recon_hold 0
sbp0:0:0 sbp_busy_timeout
sbp0:0:0 sbp_agent_reset
sbp0:0:0 sbp_do_attach
sbp0:0:0 sbp_cam_scan_lun
Creating DISK da0
pass0 at sbp0 bus 0 target 0 lun 0
pass0: <Maxtor 1394 Storage Fro 0000> Fixed Simplified Direct Access SCSI-4 device 
pass0: Serial Number A80A06AE            
pass0: 50.000MB/s transfers
da0 at sbp0 bus 0 target 0 lun 0
da0: <Maxtor 1394 Storage Fro 0000> Fixed Simplified Direct Access SCSI-4 device 
da0: Serial Number A80A06AE            
da0: 50.000MB/s transfers
da0: 239371MB (490232832 512 byte sectors: 255H 63S/T 30515C)


As you can see, the device is identified differently here.  I have some
much more debugging info from the device, from my hacks to NetBSD, that
I'll include a few juicy pieces here:

fwohci0: Config ROM:
    04042eb6 31333934 6800a002 00004c02 08005e45 000590d5 0300005e 81000004
    0c0083c0 d1000007 d1000019 00049b20 00000000 00000000 4e657442 53440000
    0005635c 1200005e 81000004 13000001 81000006 95000009 0003c150 00000000
    00000000 49414e41 0003170d 00000000 00000000 49507634 0004127c 0000ffff
    f0010001 0000ffff f0010000 00054e18 1200005e 81000004 13000002 81000006
    95000009 0003c150 00000000 00000000 49414e41 0003374f 00000000 00000000
    49507636 0004127c 0000ffff f0010001 0000ffff f0010000
fwohci0: nodeid=0xffc0(0), rootid=1, irmid=0
fw0: Updating nodeid to 0
Doing fwnode_match...
fwnode0 at fwohci0Doing fwnode_attach...
 Node 1: UID 00:10:b9:20:00:3d:bc:b3
Doing fwnode_configrom_input...
Doing fwnode_configrom_input...
Doing p1212_validate_offset...
 val is 57...
Doing p1212_validate_offset...
 val is 56...
Must have a unit location in each unit directory when more than one unit directo
ry exists.

    [ snip ... ]

fwnode0: Link Speed: 400Mb/s, max_rec: 64 bytes
 Doing sbpscsi_match...
 Doing sbp2_match...
sbp2_match: SPEC_ID val is 4281 or 0x10b9  sbp2_match: SW_VERSION val is 1354547
3 or 0xceb001  case default...
case default...
case SBP2_KEYVAL_Firmwar_Rev
case SBP2_KEYVAL_Cmd_Set
Unknown    SBP2 key and value: 0x00000039 0x00009400
case SBP2_KEYVAL_Unit_Chars
case SBP2_KEYVAL_Cmd_Set_Spec_Id
Unknown    SBP2 key and value: 0x00000038 0x00009480
case SBP2_KEYVAL_Cmd_Set_Rev
case default...
  luncnt is 0.
doing free(luns...)...  done free(luns...).
Unknown device at fwnode0 not configured
 Doing sbpscsi_match...
 Doing sbp2_match...
sbp2_match: SPEC_ID val is 24734 or 0x609e  sbp2_match: SW_VERSION val is 66691
or 0x10483  case default...
case default...
case SBP2_KEYVAL_Firmwar_Rev
case SBP2_KEYVAL_Log_Unit_No
case SBP2_KEYVAL_Unit_Chars
case SBP2_KEYVAL_Cmd_Set_Spec_Id
case SBP2_KEYVAL_Cmd_Set
case SBP2_KEYVAL_Cmd_Set_Rev
case SBP2_KEYVAL_Reconn_Time
case SBP2_KEYVAL_Log_Unit_No
case default...
case default...
case default...
case default...
  luncnt is 1.
doing free(luns...)...  done free(luns...).
lun->cmd_spec_id is 24734 or 0x609e  and cmd_set is 66776 or 0x104d8  sbpscsi0 a
t fwnode0 Doing sbpscsi_attach...
 Doing sbp2_match...
sbp2_match: SPEC_ID val is 24734 or 0x609e  sbp2_match: SW_VERSION val is 66691
or 0x10483  case default...

    [ snip ... ]

scsibus0 at sbpscsi0: 1 target, 1 lun per target
fwnode0: Config rom dump:
fwnode0: 0x00: 0x044435c9 0x31333934 0x00ff5022 0x0010b920
fwnode0: 0x10: 0x003dbcb3 0x0007e92f 0x0c0083c0 0x030010b9
fwnode0: 0x20: 0x8100001f 0x04000400 0x81000022 0xd1000002
fwnode0: 0x30: 0xd100000b 0x00097409 0x120010b9 0x13ceb001
fwnode0: 0x40: 0x3c010000 0x79009400 0x3a000003 0x78009480
fwnode0: 0x50: 0x3b000001 0x17005000 0x81000025 0x000fc520
fwnode0: 0x60: 0x1200609e 0x13010483 0x3c010000 0x5400c000
fwnode0: 0x70: 0x3a003c08 0x3800609e 0x390104d8 0x3b000000
fwnode0: 0x80: 0x3d000003 0x144e0000 0x17005000 0x8100000e
fwnode0: 0x90: 0x00000000 0x00000000 0x00000000 0x00044cc5
fwnode0: 0xa0: 0x00000000 0x00000000 0x4d617874 0x6f720000
fwnode0: 0xb0: 0x00043617 0x00000000 0x00000000 0x76302e30
fwnode0: 0xc0: 0x34000000 0x00063bf2 0x00000000 0x00000000
fwnode0: 0xd0: 0x35303030 0x58542020 0x76312e30 0x302e3030
fwnode0: 0xe0: 0x00020000 0x00000000 0x00000000 0x00094cce
fwnode0: 0xf0: 0x00000000 0x00000000 0x31333934 0x2053746f
fwnode0: 0x100: 0x72616765 0x2046726f 0x6e742050 0x616e656c
fwnode0: 0x110: 0x2a000000
Directory: Root-Directory

Node-Capabilities: 0x000083c0
Module-Vendor-Id: 0x000010b9
Text descriptor: Maxtor
Module-Hw-Version: 0x00000400
Text descriptor: v0.04

    Directory: Unit-Directory

    Unit-Spec-Id: 0x000010b9
    Unit-Sw-Version: 0x00ceb001
    SBP2 Firmware Revision: 0x00010000
    Unknown type 0x0039: 0x00009400
    SBP2 Unit Characteristics: 0x00000003
    Unknown type 0x0038: 0x00009480
    SBP2 Command Set Revision: 0x00000001
    Model: 0x00005000
    Text descriptor: 1394 Storage Front Panel*

    Directory: Unit-Directory

    Unit-Spec-Id: 0x0000609e
    Unit-Sw-Version: 0x00010483
    SBP2 Firmware Revision: 0x00010000
    SBP2 Management Agent: 0x0000c000
    SBP2 Unit Characteristics: 0x00003c08
    SBP2 Command Set Spec Id: 0x0000609e
    SBP2 Command Set: SCSI 2
    SBP2 Command Set Revision: 0x00000000
    SBP2 Reconnect Timeout: 0x00000003
    SBP2 Logical Unit Number: 0x004e0000
    Model: 0x00005000
    Text descriptor: 5000XT  v1.00.00
    Root-Directory: 0x00000000
    Root-Directory: 0x00000000
    Root-Directory: 0x00000000

Called sbpscsi_scsipi_request

    [ major snip ... ]

scsibus0 target 0 lun 0: <Maxtor, 5000XT, 0100> simplified direct fixed not conf
igured


That provided in case the info is useful.  As noted, I couldn't mount it
successfully then (even when it was configured, unlike that particularly
verbose dmesg), and I haven't built a more recent NetBSD kernel yet.


Will be happy to provide more info as desired.  Also, I'm slowly working
through the last 9 months of mailing list archives, mostly with glazed
eyes, and can't remember if I've read all firewire archives yet.

Thanks,
Barry Bouwsma