Date: Mon, 26 Sep 2011 16:58:42 -0600 From: "Kenneth D. Merry" <ken@freebsd.org> To: Fabian Keil <freebsd-listen@fabiankeil.de> Cc: freebsd-current@freebsd.org Subject: Re: SCSI descriptor sense changes, testing needed Message-ID: <20110926225842.GA88443@nargothrond.kdm.org> In-Reply-To: <20110924212722.4ce229e9@fabiankeil.de> References: <20110922193305.GA24939@nargothrond.kdm.org> <20110924212722.4ce229e9@fabiankeil.de>
next in thread | previous in thread | raw e-mail | index | archive | help
--YZ5djTAD1cGYuMQK Content-Type: text/plain; charset=us-ascii Content-Disposition: inline On Sat, Sep 24, 2011 at 21:27:22 +0200, Fabian Keil wrote: > "Kenneth D. Merry" <ken@freebsd.org> wrote: > > > I have attached a set of patches against head that implement SCSI > > descriptor sense support for CAM. > > > Anyway, I'd appreciate any testing and feedback on these changes. As I > > said, they will probably be in 9.0, so if there are any issues it would > > be better to find them now. :) > > I've been using the patch on a ThinkPad R500 since yesterday and > just reverted it today again to get my kernel closer to HEAD before > looking into some (probably unrelated) panics. > > I didn't notice it while using the patch, but it looks like the > kernel wasn't able to pick up cd0 anymore: Hmm. I don't think any of the changes would have caused this, but evidently something did... Let's see if we can debug it... I have attached a patch to add some debugging output, and I see at least one interesting thing in the logs below. Can you re-apply the descriptor sense patch, and then try the attached debugging patch as well? > fk@r500 ~ $grep -h "new dis" /var/log/messages /var/log/messages.[123] | sort > Sep 21 23:40:23 r500 kernel: GEOM: new disk da0 > Sep 21 23:40:30 r500 kernel: GEOM: new disk da1 > Sep 21 23:45:21 r500 kernel: GEOM: new disk ada0 > Sep 21 23:45:21 r500 kernel: GEOM: new disk cd0 > Sep 21 23:45:21 r500 kernel: GEOM: new disk da0 > Sep 21 23:45:21 r500 kernel: GEOM: new disk da1 > Sep 21 23:52:44 r500 kernel: GEOM: new disk ada0 > Sep 21 23:52:44 r500 kernel: GEOM: new disk cd0 > Sep 21 23:53:14 r500 kernel: GEOM: new disk da0 > Sep 21 23:56:23 r500 kernel: GEOM: new disk da1 > Sep 22 21:14:17 r500 kernel: GEOM: new disk ada0 > Sep 22 21:14:17 r500 kernel: GEOM: new disk cd0 > Sep 22 22:10:20 r500 kernel: GEOM: new disk da0 > [patch applied] > Sep 22 23:29:45 r500 kernel: GEOM: new disk da0 > Sep 23 14:38:31 r500 kernel: GEOM: new disk ada0 > Sep 23 17:19:40 r500 kernel: GEOM: new disk da0 > Sep 23 19:20:21 r500 kernel: GEOM: new disk da0 > Sep 23 19:20:42 r500 kernel: GEOM: new disk da1 > Sep 23 22:58:56 r500 kernel: GEOM: new disk da0 > Sep 24 09:31:02 r500 kernel: GEOM: new disk ada0 > Sep 24 14:17:22 r500 kernel: GEOM: new disk da0 > Sep 24 14:44:03 r500 kernel: GEOM: new disk ada0 > Sep 24 14:44:03 r500 kernel: GEOM: new disk da0 > Sep 24 14:53:30 r500 kernel: GEOM: new disk ada0 > Sep 24 15:03:24 r500 kernel: GEOM: new disk da0 > Sep 24 15:06:03 r500 kernel: GEOM: new disk da0 > Sep 24 15:13:57 r500 kernel: GEOM: new disk ada0 > Sep 24 15:14:16 r500 kernel: GEOM: new disk da0 > Sep 24 15:27:11 r500 kernel: GEOM: new disk ada0 > Sep 24 15:28:05 r500 kernel: GEOM: new disk da0 > Sep 24 15:32:10 r500 kernel: GEOM: new disk ada0 > Sep 24 15:32:10 r500 kernel: GEOM: new disk da0 > Sep 24 15:38:16 r500 kernel: GEOM: new disk ada0 > Sep 24 15:38:16 r500 kernel: GEOM: new disk da0 > Sep 24 15:43:33 r500 kernel: GEOM: new disk ada0 > Sep 24 15:43:33 r500 kernel: GEOM: new disk da0 > Sep 24 15:49:30 r500 kernel: GEOM: new disk ada0 > [patch reverted] > Sep 24 19:32:51 r500 kernel: GEOM: new disk ada0 > Sep 24 19:32:51 r500 kernel: GEOM: new disk cd0 > Sep 24 19:32:51 r500 kernel: GEOM: new disk da0 > Sep 24 19:38:07 r500 kernel: GEOM: new disk ada0 > Sep 24 19:38:07 r500 kernel: GEOM: new disk cd0 > > Without the patch I'm used to getting the following kernel > messages when booting (without a disc in cd0): > > Sep 24 19:32:51 r500 kernel: ahcich0: AHCI reset: device ready after 100ms > Sep 24 19:32:51 r500 kernel: (aprobe0:ahcich0:0:0:0): SIGNATURE: 0000 > Sep 24 19:32:51 r500 kernel: ahcich1: AHCI reset: device ready after 100ms > Sep 24 19:32:51 r500 kernel: (aprobe1:ahcich1:0:0:0): SIGNATURE: eb14 > Sep 24 19:32:51 r500 kernel: GEOM: new disk cd0 > Sep 24 19:32:51 r500 kernel: pass0 at ahcich0 bus 0 scbus0 target 0 lun 0 > Sep 24 19:32:51 r500 kernel: pass0: <HITACHI HTS543225L9SA00 FBEZC4EC> ATA-8 SATA 1.x device > Sep 24 19:32:51 r500 kernel: pass0: Serial Number 090509FB2F32LLEY6D8A > Sep 24 19:32:51 r500 kernel: pass0: 150.000MB/s transfers (SATA 1.x, UDMA5, PIO 8192bytes) > Sep 24 19:32:51 r500 kernel: pass0: Command Queueing enabled > Sep 24 19:32:51 r500 kernel: pass1 at ahcich1 bus 0 scbus1 target 0 lun 0 > Sep 24 19:32:51 r500 kernel: pass1: <HL-DT-ST DVDRAM GSA-T50N RX05> Removable CD-ROM SCSI-0 device > Sep 24 19:32:51 r500 kernel: pass1: Serial Number M2R96NC0647 > Sep 24 19:32:51 r500 kernel: pass1: 150.000MB/s transfers (SATA 1.x, UDMA6, ATAPI 12bytes, PIO 8192bytes) > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI status error > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): READ CAPACITY. CDB: 25 0 0 0 0 0 0 0 0 0 > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): CAM status: SCSI Status Error > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI status: Check Condition > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI sense: UNIT ATTENTION asc:29,0 (Power on, reset, or bus device reset occurred) > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): Retrying command (per sense data) > Sep 24 19:32:51 r500 kernel: ada0 at ahcich0 bus 0 scbus0 target 0 lun 0 > Sep 24 19:32:51 r500 kernel: ada0: <HITACHI HTS543225L9SA00 FBEZC4EC> ATA-8 SATA 1.x device > Sep 24 19:32:51 r500 kernel: ada0: Serial Number 090509FB2F32LLEY6D8A > Sep 24 19:32:51 r500 kernel: ada0: 150.000MB/s transfers (SATA 1.x, UDMA5, PIO 8192bytes) > Sep 24 19:32:51 r500 kernel: ada0: Command Queueing enabled > Sep 24 19:32:51 r500 kernel: ada0: 238475MB (488397168 512 byte sectors: 16H 63S/T 16383C) > Sep 24 19:32:51 r500 kernel: ada0: Previously was known as ad4 > Sep 24 19:32:51 r500 kernel: SMP: AP CPU #1 Launched! > Sep 24 19:32:51 r500 kernel: cpu1 AP: > Sep 24 19:32:51 r500 kernel: ID: 0x01000000 VER: 0x00050014 LDR: 0x00000000 DFR: 0xffffffff > Sep 24 19:32:51 r500 kernel: lint0: 0x00010700 lint1: 0x00000400 TPR: 0x00000000 SVR: 0x000001ff > Sep 24 19:32:51 r500 kernel: timer: 0x000100ef therm: 0x00010200 err: 0x000000f0 pmc: 0x00010400 > Sep 24 19:32:51 r500 kernel: TSC timecounter disabled: C3 enabled. > Sep 24 19:32:51 r500 kernel: Timecounter "TSC" frequency 1995048630 Hz quality -1000 > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI status error > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): READ CAPACITY. CDB: 25 0 0 0 0 0 0 0 0 0 > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): CAM status: SCSI Status Error > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI status: Check Condition > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI sense: NOT READY asc:4,1 (Logical unit is in process of becoming ready) > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): Polling device for readiness > Sep 24 19:32:51 r500 kernel: uhub0: 2 ports with 2 removable, self powered > Sep 24 19:32:51 r500 kernel: uhub1: 2 ports with 2 removable, self powered > Sep 24 19:32:51 r500 kernel: uhub2: 2 ports with 2 removable, self powered > Sep 24 19:32:51 r500 kernel: uhub4: 2 ports with 2 removable, self powered > Sep 24 19:32:51 r500 kernel: uhub5: 2 ports with 2 removable, self powered > Sep 24 19:32:51 r500 kernel: uhub6: 2 ports with 2 removable, self powered > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI status error > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): READ CAPACITY. CDB: 25 0 0 0 0 0 0 0 0 0 > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): CAM status: SCSI Status Error > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI status: Check Condition > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI sense: NOT READY asc:3a,1 (Medium not present - tray closed) > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): Error 6, Unretryable error > Sep 24 19:32:51 r500 kernel: cd0 at ahcich1 bus 0 scbus1 target 0 lun 0 > Sep 24 19:32:51 r500 kernel: cd0: <HL-DT-ST DVDRAM GSA-T50N RX05> Removable CD-ROM SCSI-0 device > Sep 24 19:32:51 r500 kernel: cd0: Serial Number M2R96NC0647 > Sep 24 19:32:51 r500 kernel: cd0: 150.000MB/s transfers (SATA 1.x, UDMA6, ATAPI 12bytes, PIO 8192bytes) > Sep 24 19:32:51 r500 kernel: cd0: Attempt to query device size failed: NOT READY, Medium not present - tray closed > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI status error > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): READ CAPACITY. CDB: 25 0 0 0 0 0 0 0 0 0 > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): CAM status: SCSI Status Error > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI status: Check Condition > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI sense: NOT READY asc:3a,1 (Medium not present - tray closed) > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): Error 6, Unretryable error > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI status error > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): READ CAPACITY. CDB: 25 0 0 0 0 0 0 0 0 0 > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): CAM status: SCSI Status Error > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI status: Check Condition > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI sense: NOT READY asc:3a,1 (Medium not present - tray closed) > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): Error 6, Unretryable error > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI status error > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): READ CAPACITY. CDB: 25 0 0 0 0 0 0 0 0 0 > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): CAM status: SCSI Status Error > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI status: Check Condition > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI sense: NOT READY asc:3a,1 (Medium not present - tray closed) > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): Error 6, Unretryable error > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI status error > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): READ CAPACITY. CDB: 25 0 0 0 0 0 0 0 0 0 > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): CAM status: SCSI Status Error > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI status: Check Condition > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): SCSI sense: NOT READY asc:3a,1 (Medium not present - tray closed) > Sep 24 19:32:51 r500 kernel: (cd0:ahcich1:0:0:0): Error 6, Unretryable error > Sep 24 19:32:51 r500 kernel: GEOM: new disk ada0 > Sep 24 19:32:51 r500 kernel: GEOM: ada0s1: geometry does not match label (255h,63s != 16h,63s). > > With the patch I got: > > Sep 24 17:29:16 r500 kernel: ahcich0: AHCI reset... > Sep 24 17:29:16 r500 kernel: ahcich0: SATA connect time=900us status=00000113 > Sep 24 17:29:16 r500 kernel: ahcich0: AHCI reset: device found > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset... > Sep 24 17:29:16 r500 kernel: ahcich1: SATA connect time=1000us status=00000113 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device found > Sep 24 17:29:16 r500 kernel: battery0: battery initialization start > Sep 24 17:29:16 r500 kernel: ugen0.1: <Intel> at usbus0 > Sep 24 17:29:16 r500 kernel: uhub0: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus0 > Sep 24 17:29:16 r500 kernel: ugen1.1: <Intel> at usbus1 > Sep 24 17:29:16 r500 kernel: uhub1: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus1 > Sep 24 17:29:16 r500 kernel: ugen2.1: <Intel> at usbus2 > Sep 24 17:29:16 r500 kernel: uhub2: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus2 > Sep 24 17:29:16 r500 kernel: ugen3.1: <Intel> at usbus3 > Sep 24 17:29:16 r500 kernel: uhub3: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus3 > Sep 24 17:29:16 r500 kernel: ugen4.1: <Intel> at usbus4 > Sep 24 17:29:16 r500 kernel: uhub4: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus4 > Sep 24 17:29:16 r500 kernel: ugen5.1: <Intel> at usbus5 > Sep 24 17:29:16 r500 kernel: uhub5: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus5 > Sep 24 17:29:16 r500 kernel: ugen6.1: <Intel> at usbus6 > Sep 24 17:29:16 r500 kernel: uhub6: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus6 > Sep 24 17:29:16 r500 kernel: ugen7.1: <Intel> at usbus7 > Sep 24 17:29:16 r500 kernel: uhub7: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus7 > Sep 24 17:29:16 r500 kernel: acpi_acad0: acline initialization start > Sep 24 17:29:16 r500 kernel: battery0: battery initialization done, tried 1 times > Sep 24 17:29:16 r500 kernel: acpi_acad0: On Line > Sep 24 17:29:16 r500 kernel: acpi_acad0: acline initialization done, tried 1 times > Sep 24 17:29:16 r500 kernel: ahcich0: AHCI reset: device ready after 100ms > Sep 24 17:29:16 r500 kernel: (aprobe0:ahcich0:0:0:0): SIGNATURE: 0000 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device ready after 100ms > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): SIGNATURE: eb14 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset... > Sep 24 17:29:16 r500 kernel: ahcich1: SATA connect time=1000us status=00000113 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device found > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): INQUIRY. CDB: 12 0 0 24 0 0 > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): CAM status: CCB request was invalid > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device ready after 100ms At this stage in the previous log, the CD driver and pass driver were probing the drive. It looks like in this case, we're getting CAM_REQ_INVALID in response to a SCSI inquiry. I've looked around in the likely code paths, and I don't see too many places where that could happen. One is in the ahci driver, I guess we'll see if that's what we're hitting. > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): SIGNATURE: eb14 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset... > Sep 24 17:29:16 r500 kernel: ahcich1: SATA connect time=1000us status=00000113 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device found > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): INQUIRY. CDB: 12 0 0 24 0 0 > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): CAM status: CCB request was invalid > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device ready after 100ms > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): SIGNATURE: eb14 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset... > Sep 24 17:29:16 r500 kernel: ahcich1: SATA connect time=1000us status=00000113 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device found > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): INQUIRY. CDB: 12 0 0 24 0 0 > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): CAM status: CCB request was invalid > Sep 24 17:29:16 r500 kernel: uhub0: 2 ports with 2 removable, self powered > Sep 24 17:29:16 r500 kernel: uhub1: 2 ports with 2 removable, self powered > Sep 24 17:29:16 r500 kernel: uhub2: 2 ports with 2 removable, self powered > Sep 24 17:29:16 r500 kernel: uhub4: 2 ports with 2 removable, self powered > Sep 24 17:29:16 r500 kernel: uhub5: 2 ports with 2 removable, self powered > Sep 24 17:29:16 r500 kernel: uhub6: 2 ports with 2 removable, self powered > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device ready after 200ms > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): SIGNATURE: eb14 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset... > Sep 24 17:29:16 r500 kernel: ahcich1: SATA connect time=1000us status=00000113 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device found > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): INQUIRY. CDB: 12 0 0 24 0 0 > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): CAM status: CCB request was invalid > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device ready after 101ms > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): SIGNATURE: eb14 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset... > Sep 24 17:29:16 r500 kernel: ahcich1: SATA connect time=1000us status=00000113 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device found > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): INQUIRY. CDB: 12 0 0 24 0 0 > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): CAM status: CCB request was invalid > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device ready after 100ms > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): SIGNATURE: eb14 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset... > Sep 24 17:29:16 r500 kernel: ahcich1: SATA connect time=1000us status=00000113 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device found > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): INQUIRY. CDB: 12 0 0 24 0 0 > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): CAM status: CCB request was invalid > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device ready after 200ms > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): SIGNATURE: eb14 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset... > Sep 24 17:29:16 r500 kernel: ahcich1: SATA connect time=1000us status=00000113 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device found > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): INQUIRY. CDB: 12 0 0 24 0 0 > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): CAM status: CCB request was invalid > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device ready after 200ms > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): SIGNATURE: eb14 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset... > Sep 24 17:29:16 r500 kernel: ahcich1: SATA connect time=1000us status=00000113 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device found > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): INQUIRY. CDB: 12 0 0 24 0 0 > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): CAM status: CCB request was invalid > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device ready after 200ms > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): SIGNATURE: eb14 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset... > Sep 24 17:29:16 r500 kernel: ahcich1: SATA connect time=1000us status=00000113 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device found > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): INQUIRY. CDB: 12 0 0 24 0 0 > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): CAM status: CCB request was invalid > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device ready after 101ms > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): SIGNATURE: eb14 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset... > Sep 24 17:29:16 r500 kernel: ahcich1: SATA connect time=1000us status=00000113 > Sep 24 17:29:16 r500 kernel: ahcich1: AHCI reset: device found > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): INQUIRY. CDB: 12 0 0 24 0 0 > Sep 24 17:29:16 r500 kernel: (aprobe1:ahcich1:0:0:0): CAM status: CCB request was invalid > Sep 24 17:29:16 r500 kernel: pass0 at ahcich0 bus 0 scbus0 target 0 lun 0 > Sep 24 17:29:16 r500 kernel: pass0: <HITACHI HTS543225L9SA00 FBEZC4EC> ATA-8 SATA 1.x device > Sep 24 17:29:16 r500 kernel: pass0: Serial Number 090509FB2F32LLEY6D8A > Sep 24 17:29:16 r500 kernel: pass0: 150.000MB/s transfers (SATA 1.x, UDMA5, PIO 8192bytes) > Sep 24 17:29:16 r500 kernel: pass0: Command Queueing enabled > Sep 24 17:29:16 r500 kernel: ada0 at ahcich0 bus 0 scbus0 target 0 lun 0 > Sep 24 17:29:16 r500 kernel: GEOM: new disk ada0 > Sep 24 17:29:16 r500 kernel: ada0: <HITACHI HTS543225L9SA00 FBEZC4EC> ATA-8 SATA 1.x device > Sep 24 17:29:16 r500 kernel: ada0: Serial Number 090509FB2F32LLEY6D8A > Sep 24 17:29:16 r500 kernel: ada0: 150.000MB/s transfers (SATA 1.x, UDMA5, PIO 8192bytes) > Sep 24 17:29:16 r500 kernel: ada0: Command Queueing enabled > Sep 24 17:29:16 r500 kernel: ada0: 238475MB (488397168 512 byte sectors: 16H 63S/T 16383C) > Sep 24 17:29:16 r500 kernel: ada0: Previously was known as ad4 > > I'm using a couple of other patches, but the only > one that is related to SCSI is: > http://www.freebsd.org/cgi/query-pr.cgi?pr=159611 It doesn't look like that should cause a problem, since it's just a quirk entry. > > Fabian Ken -- Kenneth Merry ken@FreeBSD.ORG --YZ5djTAD1cGYuMQK Content-Type: text/plain; charset=us-ascii Content-Disposition: attachment; filename="ahci_debug.20110926.1.txt" ==== //depot/users/kenm/FreeBSD-test/sys/dev/ahci/ahci.c#5 - /usr/home/kenm/perforce4/kenm/FreeBSD-test/sys/dev/ahci/ahci.c ==== *** /tmp/tmp.87438.78 Mon Sep 26 16:52:37 2011 --- /usr/home/kenm/perforce4/kenm/FreeBSD-test/sys/dev/ahci/ahci.c Mon Sep 26 16:52:04 2011 *************** *** 2121,2126 **** --- 2121,2134 ---- case AHCI_ERR_INVALID: ch->fatalerr = 1; ccb->ccb_h.status |= CAM_REQ_INVALID; + printf("%s: got AHCI_ERR_INVALID!\n", __func__); + if (ccb->ccb_h.func_code == XPT_SCSI_IO) { + printf("%s: op %x dxfer_len %d sense_len %u " + "sense_resid %u\n", __func__, + ccb->csio.cdb_io.cdb_bytes[0], + ccb->csio.dxfer_len, ccb->csio.sense_len, + ccb->csio.sense_resid); + } break; case AHCI_ERR_INNOCENT: ccb->ccb_h.status |= CAM_REQUEUE_REQ; --YZ5djTAD1cGYuMQK--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20110926225842.GA88443>