Skip site navigation (1)Skip section navigation (2)
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>