Re: kern/103602: drive gets wedged on READ CD CAPACITY if no disc is in

SCSI guys,

kern/103602 is a long-standing issue with a Sony DVD drive
that has a
strange behaviour (failing to attach and causing an
interrupt storm).

One aspect of this PR was that an ATAPI command timing out
was not
correctly reported by the ATAPI/CAM SIM to the XPT layer.
This has been
fixed in atapi-cam.c rev. 1.49.

Now we have a second issue: if there is no disc in the
drive, it
times out a READ CD CAPACITY (and any subsequent retry, even
if a disc
is then inserted in the drive), instead of returning an
appropriate
error (the expected behaviour would be a NOT READY sense key
and a
MEDIUM NOT PRESENT ASC). A TEST UNIT READY command seems to
behave
properly (reporting the appropriate error if no disc is
present,
reporting no error and resetting the drive to a proper state
if
one is).

The timeout causes the unit to fail to attach at boot time
if no disc is
present. How should we deal with this situation? One
possible option is
to make sure that we first issue a TEST UNIT READY at attach
time prior
to issuing READ CD CAPACITY, and not issue the second
command if the TUR
returned a NOT READY status.

The traces below show how the drive behaves in response to
TEST UNIT
READY and READ CD CAPACITY in various cases. Complete boot
messages are
available in the PR history.

Thomas.

----- Forwarded message from Josh Carroll
<josh.carrollgmail.com> -----

From: Josh Carroll <josh.carrollgmail.com>
Reply-To: josh.carrollpsualum.com
To: Thomas Quinot <thomasfreebsd.org>
Subject: Re: kern/103602: atapi device not working on
JMicron 363 Controller
Cc: bug-followupfreebsd.org
In-Reply-To: <20070309182253.GA3998melamine.cuivre.fr.eu.org>

>OK, we're getting closer. So, to summarize:
>  * if there's a CD in the drive at boot time, things
work OK
>  * if not the cd0 entry appears transiently and then
disappears

Exactly, it appears to work with a cd in the drive, and I
get a
transient cd0 dev entry without the disc. Below is the
output from
each command you requested. I got a timeout in the last read
capacity
command, even after the prior steps. I sent a TEST UNIT
READY command,
then it worked, though.

> * run this command (TEST UNIT READY):
>   camcontrol cmd cd0 -v -t 20 -c "0 0 0 0 0
0"

(pass0:ata2:0:1:0): entering cdgetccb
(pass0:ata2:0:1:0): xpt_schedule
(pass0:ata2:0:1:0):    added periph to queue
cam_debug: xpt_schedule_dev
cam_debug: Inserting onto queue
(pass0:ata2:0:1:0):    calling xpt_run_devq
cam_debug: xpt_run_dev_allocq
cam_debug:    qfrozen_cnt == 0x0, entries == 1, openings ==
16, active == 0
cam_debug: running device 0xc53bbc00
(pass0:ata2:0:1:0): xpt_setup_ccb
cam_debug: calling periph start
(pass0:ata2:0:1:0): xpt_setup_ccb
(pass0:ata2:0:1:0): xpt_action
(pass0:ata2:0:1:0): xpt_action
cam_debug: xpt_release_ccb
(pass0:ata2:0:1:0): xpt_setup_ccb
(pass0:ata2:0:1:0): xpt_action
(pass0:ata2:0:1:0): xpt_done
(pass0:ata2:0:1:0): xpt_setup_ccb
(pass0:ata2:0:1:0): xpt_action
(pass0:ata2:0:1:0): xpt_setup_ccb
(pass0:ata2:0:1:0): xpt_action
(pass0:ata2:0:1:0): GET_TRAN_SETTINGS
(pass0:ata2:0:1:0): xpt_done
(pass0:ata2:0:1:0): entering cdgetccb
(pass0:ata2:0:1:0): xpt_schedule
(pass0:ata2:0:1:0):    added periph to queue
cam_debug: xpt_schedule_dev
cam_debug: Inserting onto queue
(pass0:ata2:0:1:0):    calling xpt_run_devq
cam_debug: xpt_run_dev_allocq
cam_debug:    qfrozen_cnt == 0x0, entries == 1, openings ==
16, active == 0
cam_debug: running device 0xc53bbc00
(pass0:ata2:0:1:0): xpt_setup_ccb
cam_debug: calling periph start
(pass0:ata2:0:1:0): xpt_action
(pass0:ata2:0:1:0): TEST UNIT READY. CDB: 0 0 0 0 0 0
cam_debug: xpt_schedule_dev
cam_debug: Inserting onto queue
cam_debug: xpt_run_dev_sendq
cam_debug: running device 0xc53bbc00
(pass0:ata2:0:1:0): XPT_SCSI_IO
atapi_action: hcb0xc55b8440: 0 0 0 0 0 0
acd0: req=0xc5582540 TEST_UNIT_READY queued
acd0: req=0xc5582540 TEST_UNIT_READY starting
acd0: req=0xc5582540 TEST_UNIT_READY begin transaction
acd0: req=0xc5582540 TEST_UNIT_READY interrupt
acd0: req=0xc5582540 TEST_UNIT_READY end transaction
acd0: req=0xc5582540 TEST_UNIT_READY finish taskqueue_swi
acd0: req=0xc5582540 TEST_UNIT_READY completed entered
acd0: req=0xc5582540 TEST_UNIT_READY autoissue request
sense
acd0: req=0xc5582540 REQUEST_SENSE queued
acd0: req=0xc5582540 REQUEST_SENSE starting
acd0: req=0xc5582540 REQUEST_SENSE begin transaction
acd0: req=0xc5582540 REQUEST_SENSE interrupt
acd0: req=0xc5582540 REQUEST_SENSE end transaction
acd0: req=0xc5582540 TEST_UNIT_READY interrupt
acd0: req=0xc5582540 TEST_UNIT_READY end transaction
acd0: req=0xc5582540 TEST_UNIT_READY finish taskqueue_swi
acd0: req=0xc5582540 TEST_UNIT_READY completed entered
acd0: req=0xc5582540 TEST_UNIT_READY completed
callback/wakeup
atapi_cb: hcb0xc55b8440 sense = 02: sk = 2)
acd0: cmd TEST_UNIT_READY status 50 result 05 error 00
(pass0:ata2:0:1:0): xpt_done
(pass0:ata2:0:1:0): camisr
cam_debug: xpt_release_ccb


> * run this command (READ CD RECORDED CAPACITY):
>   camcontrol cmd cd0 -v -t 20 -c "25 0 0 0 0 0 0 0
0 0" -i 8 "i4 i4"

This times out with 20, 40 and 60 seconds. Here's the output
from the
20 second timeout period:

2617:cam_debug: xpt_release_ccb
2618:(pass0:ata2:0:1:0): entering cdgetccb
2619:(pass0:ata2:0:1:0): xpt_schedule
2620:(pass0:ata2:0:1:0):    added periph to queue
2621:cam_debug: xpt_schedule_dev
2622:cam_debug: Inserting onto queue
2623:(pass0:ata2:0:1:0):    calling xpt_run_devq
2624:cam_debug: xpt_run_dev_allocq
2625:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2626:cam_debug: running device 0xc53bbc00
2627:(pass0:ata2:0:1:0): xpt_setup_ccb
2628:cam_debug: calling periph start
2629:(pass0:ata2:0:1:0): xpt_setup_ccb
2630:(pass0:ata2:0:1:0): xpt_action
2631:(pass0:ata2:0:1:0): xpt_action
2632:cam_debug: xpt_release_ccb
2633:(pass0:ata2:0:1:0): xpt_setup_ccb
2634:(pass0:ata2:0:1:0): xpt_action
2635:(pass0:ata2:0:1:0): xpt_done
2636:(pass0:ata2:0:1:0): xpt_setup_ccb
2637:(pass0:ata2:0:1:0): xpt_action
2638:(pass0:ata2:0:1:0): xpt_setup_ccb
2639:(pass0:ata2:0:1:0): xpt_action
2640:(pass0:ata2:0:1:0): GET_TRAN_SETTINGS
2641:(pass0:ata2:0:1:0): xpt_done
2642:(pass0:ata2:0:1:0): entering cdgetccb
2643:(pass0:ata2:0:1:0): xpt_schedule
2644:(pass0:ata2:0:1:0):    added periph to queue
2645:cam_debug: xpt_schedule_dev
2646:cam_debug: Inserting onto queue
2647:(pass0:ata2:0:1:0):    calling xpt_run_devq
2648:cam_debug: xpt_run_dev_allocq
2649:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2650:cam_debug: running device 0xc53bbc00
2651:(pass0:ata2:0:1:0): xpt_setup_ccb
2652:cam_debug: calling periph start
2653:(pass0:ata2:0:1:0): xpt_action
2654:(pass0:ata2:0:1:0): READ CD RECORDED CAPACITY. CDB: 25
0 0 0 0 0 0 0 0 0
2655:cam_debug: xpt_schedule_dev
2656:cam_debug: Inserting onto queue
2657:cam_debug: xpt_run_dev_sendq
2658:cam_debug: running device 0xc53bbc00
2659:(pass0:ata2:0:1:0): XPT_SCSI_IO
2660:atapi_action: hcb0xc55b8700: 25 0 0 0 0 0 0 0 0 0
2661:acd0: req=0xc5556cc0 READ_CAPACITY queued
2662:acd0: req=0xc5556cc0 READ_CAPACITY starting
2663:acd0: req=0xc5556cc0 READ_CAPACITY begin transaction
2664:acd0: req=0xc5556cc0 READ_CAPACITY timeout
2665:acd0: req=0xc5556cc0 READ_CAPACITY finish
taskqueue_swi
2666:acd0: req=0xc5556cc0 READ_CAPACITY completed entered
2667:(noperiph:ata2:0:-1:-1): xpt_async
2668:(noperiph:ata2:0:1:0): xpt_compile_path
2669:(noperiph:ata2:0:1:0): xpt_release_path
2670:(cd0:ata2:0:1:0): xpt_setup_ccb
2671:(cd0:ata2:0:1:0): xpt_action
2672:(cd0:ata2:0:1:0): xpt_setup_ccb
2673:(cd0:ata2:0:1:0): xpt_action
2674:(cd0:ata2:0:1:0): xpt_setup_ccb
2675:(cd0:ata2:0:1:0): xpt_action
2676:acd0: FAILURE - READ_CAPACITY timed out
2677:acd0: req=0xc5556cc0 READ_CAPACITY completed
callback/wakeup
2678:atapi_cb: hcb0xc55b8700 sense = 00: sk = 0)
2679:acd0: cmd READ_CAPACITY status 00 result 05 error 00
2680:(pass0:ata2:0:1:0): xpt_done
2681:(pass0:ata2:0:1:0): camisr
2682:cam_debug: xpt_release_ccb


> * Assuming it times out, run it again without -v:
>   camcontrol cmd cd0 -t 20 -c "25 0 0 0 0 0 0 0 0
0" -i 8 "i4 i4"
>   and then this one (REQUEST SENSE):
>   camcontrol cmd cd0 -t 20 -c "03 0 0 0 12 0"
-i 18 
>      " b1  b7
>        i1
>        b1  b1  b1  b1
 b4
>        i4  i1  i4
>        i1  i1  i1  b1 
b23"

2812:cam_debug: xpt_release_ccb
2813:(pass0:ata2:0:1:0): entering cdgetccb
2814:(pass0:ata2:0:1:0): xpt_schedule
2815:(pass0:ata2:0:1:0):    added periph to queue
2816:cam_debug: xpt_schedule_dev
2817:cam_debug: Inserting onto queue
2818:(pass0:ata2:0:1:0):    calling xpt_run_devq
2819:cam_debug: xpt_run_dev_allocq
2820:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2821:cam_debug: running device 0xc53bbc00
2822:(pass0:ata2:0:1:0): xpt_setup_ccb
2823:cam_debug: calling periph start
2824:(pass0:ata2:0:1:0): xpt_setup_ccb
2825:(pass0:ata2:0:1:0): xpt_action
2826:(pass0:ata2:0:1:0): xpt_action
2827:cam_debug: xpt_release_ccb
2828:(pass0:ata2:0:1:0): xpt_setup_ccb
2829:(pass0:ata2:0:1:0): xpt_action
2830:(pass0:ata2:0:1:0): xpt_done
2831:(pass0:ata2:0:1:0): xpt_setup_ccb
2832:(pass0:ata2:0:1:0): xpt_action
2833:(pass0:ata2:0:1:0): xpt_setup_ccb
2834:(pass0:ata2:0:1:0): xpt_action
2835:(pass0:ata2:0:1:0): GET_TRAN_SETTINGS
2836:(pass0:ata2:0:1:0): xpt_done
2837:(pass0:ata2:0:1:0): entering cdgetccb
2838:(pass0:ata2:0:1:0): xpt_schedule
2839:(pass0:ata2:0:1:0):    added periph to queue
2840:cam_debug: xpt_schedule_dev
2841:cam_debug: Inserting onto queue
2842:(pass0:ata2:0:1:0):    calling xpt_run_devq
2843:cam_debug: xpt_run_dev_allocq
2844:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2845:cam_debug: running device 0xc53bbc00
2846:(pass0:ata2:0:1:0): xpt_setup_ccb
2847:cam_debug: calling periph start
2848:(pass0:ata2:0:1:0): xpt_action
2849:(pass0:ata2:0:1:0): READ CD RECORDED CAPACITY. CDB: 25
0 0 0 0 0 0 0 0 0
2850:cam_debug: xpt_schedule_dev
2851:cam_debug: Inserting onto queue
2852:cam_debug: xpt_run_dev_sendq
2853:cam_debug: running device 0xc53bbc00
2854:(pass0:ata2:0:1:0): XPT_SCSI_IO
2855:atapi_action: hcb0xc55885c0: 25 0 0 0 0 0 0 0 0 0
2856:acd0: req=0xc5582b40 READ_CAPACITY queued
2857:acd0: req=0xc5582b40 READ_CAPACITY starting
2858:acd0: req=0xc5582b40 READ_CAPACITY begin transaction
2859:acd0: req=0xc5582b40 READ_CAPACITY timeout
2860:acd0: req=0xc5582b40 READ_CAPACITY finish
taskqueue_swi
2861:acd0: req=0xc5582b40 READ_CAPACITY completed entered
2862:(noperiph:ata2:0:-1:-1): xpt_async
2863:(noperiph:ata2:0:1:0): xpt_compile_path
2864:(noperiph:ata2:0:1:0): xpt_release_path
2865:(cd0:ata2:0:1:0): xpt_setup_ccb
2866:(cd0:ata2:0:1:0): xpt_action
2867:(cd0:ata2:0:1:0): xpt_setup_ccb
2868:(cd0:ata2:0:1:0): xpt_action
2869:(cd0:ata2:0:1:0): xpt_setup_ccb
2870:(cd0:ata2:0:1:0): xpt_action
2871:acd0: FAILURE - READ_CAPACITY timed out
2872:acd0: req=0xc5582b40 READ_CAPACITY completed
callback/wakeup
2873:atapi_cb: hcb0xc55885c0 sense = 00: sk = 0)
2874:acd0: cmd READ_CAPACITY status 00 result 05 error 00
2875:(pass0:ata2:0:1:0): xpt_done
2876:(pass0:ata2:0:1:0): camisr
2877:cam_debug: xpt_release_ccb
2878:(pass0:ata2:0:1:0): entering cdgetccb
2879:(pass0:ata2:0:1:0): xpt_schedule
2880:(pass0:ata2:0:1:0):    added periph to queue
2881:cam_debug: xpt_schedule_dev
2882:cam_debug: Inserting onto queue
2883:(pass0:ata2:0:1:0):    calling xpt_run_devq
2884:cam_debug: xpt_run_dev_allocq
2885:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2886:cam_debug: running device 0xc53bbc00
2887:(pass0:ata2:0:1:0): xpt_setup_ccb
2888:cam_debug: calling periph start
2889:(pass0:ata2:0:1:0): xpt_setup_ccb
2890:(pass0:ata2:0:1:0): xpt_action
2891:(pass0:ata2:0:1:0): xpt_action
2892:cam_debug: xpt_release_ccb
2893:(pass0:ata2:0:1:0): xpt_setup_ccb
2894:(pass0:ata2:0:1:0): xpt_action
2895:(pass0:ata2:0:1:0): xpt_done
2896:(pass0:ata2:0:1:0): xpt_setup_ccb
2897:(pass0:ata2:0:1:0): xpt_action
2898:(pass0:ata2:0:1:0): xpt_setup_ccb
2899:(pass0:ata2:0:1:0): xpt_action
2900:(pass0:ata2:0:1:0): GET_TRAN_SETTINGS
2901:(pass0:ata2:0:1:0): xpt_done
2902:(pass0:ata2:0:1:0): entering cdgetccb
2903:(pass0:ata2:0:1:0): xpt_schedule
2904:(pass0:ata2:0:1:0):    added periph to queue
2905:cam_debug: xpt_schedule_dev
2906:cam_debug: Inserting onto queue
2907:(pass0:ata2:0:1:0):    calling xpt_run_devq
2908:cam_debug: xpt_run_dev_allocq
2909:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2910:cam_debug: running device 0xc53bbc00
2911:(pass0:ata2:0:1:0): xpt_setup_ccb
2912:cam_debug: calling periph start
2913:(pass0:ata2:0:1:0): xpt_action
2914:(pass0:ata2:0:1:0): REQUEST SENSE. CDB: 3 0 0 0 12 0
2915:cam_debug: xpt_schedule_dev
2916:cam_debug: Inserting onto queue
2917:cam_debug: xpt_run_dev_sendq
2918:cam_debug: running device 0xc53bbc00
2919:(pass0:ata2:0:1:0): XPT_SCSI_IO
2920:atapi_action: hcb0xc5588780: 3 0 0 0 12 0
2921:acd0: req=0xc5582d80 REQUEST_SENSE queued
2922:acd0: req=0xc5582d80 REQUEST_SENSE starting
2923:acd0: req=0xc5582d80 REQUEST_SENSE begin transaction
2924:acd0: req=0xc5582d80 REQUEST_SENSE interrupt
2925:acd0: req=0xc5582d80 REQUEST_SENSE end transaction
2926:acd0: req=0xc5582d80 REQUEST_SENSE finish
taskqueue_swi
2927:acd0: req=0xc5582d80 REQUEST_SENSE completed entered
2928:acd0: req=0xc5582d80 REQUEST_SENSE completed
callback/wakeup
2929:atapi_cb: hcb0xc5588780 sense = 00: sk = 0)
2930:acd0: cmd REQUEST_SENSE status 50 result 00 error 00
2931:(pass0:ata2:0:1:0): xpt_done
2932:(pass0:ata2:0:1:0): camisr
2933:cam_debug: xpt_release_ccb


> * put back the CD in the drive
> * run the READ CD RECORDED CAPACITY command again:
>   camcontrol cmd cd0 -v -t 20 -c "25 0 0 0 0 0 0 0
0 0" -i 8 "i4 i4"
>   (I assume it should work this time)

Output prior to sending the TEST UNIT READY command:

2812:cam_debug: xpt_release_ccb
2813:(pass0:ata2:0:1:0): entering cdgetccb
2814:(pass0:ata2:0:1:0): xpt_schedule
2815:(pass0:ata2:0:1:0):    added periph to queue
2816:cam_debug: xpt_schedule_dev
2817:cam_debug: Inserting onto queue
2818:(pass0:ata2:0:1:0):    calling xpt_run_devq
2819:cam_debug: xpt_run_dev_allocq
2820:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2821:cam_debug: running device 0xc53bbc00
2822:(pass0:ata2:0:1:0): xpt_setup_ccb
2823:cam_debug: calling periph start
2824:(pass0:ata2:0:1:0): xpt_setup_ccb
2825:(pass0:ata2:0:1:0): xpt_action
2826:(pass0:ata2:0:1:0): xpt_action
2827:cam_debug: xpt_release_ccb
2828:(pass0:ata2:0:1:0): xpt_setup_ccb
2829:(pass0:ata2:0:1:0): xpt_action
2830:(pass0:ata2:0:1:0): xpt_done
2831:(pass0:ata2:0:1:0): xpt_setup_ccb
2832:(pass0:ata2:0:1:0): xpt_action
2833:(pass0:ata2:0:1:0): xpt_setup_ccb
2834:(pass0:ata2:0:1:0): xpt_action
2835:(pass0:ata2:0:1:0): GET_TRAN_SETTINGS
2836:(pass0:ata2:0:1:0): xpt_done
2837:(pass0:ata2:0:1:0): entering cdgetccb
2838:(pass0:ata2:0:1:0): xpt_schedule
2839:(pass0:ata2:0:1:0):    added periph to queue
2840:cam_debug: xpt_schedule_dev
2841:cam_debug: Inserting onto queue
2842:(pass0:ata2:0:1:0):    calling xpt_run_devq
2843:cam_debug: xpt_run_dev_allocq
2844:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2845:cam_debug: running device 0xc53bbc00
2846:(pass0:ata2:0:1:0): xpt_setup_ccb
2847:cam_debug: calling periph start
2848:(pass0:ata2:0:1:0): xpt_action
2849:(pass0:ata2:0:1:0): READ CD RECORDED CAPACITY. CDB: 25
0 0 0 0 0 0 0 0 0
2850:cam_debug: xpt_schedule_dev
2851:cam_debug: Inserting onto queue
2852:cam_debug: xpt_run_dev_sendq
2853:cam_debug: running device 0xc53bbc00
2854:(pass0:ata2:0:1:0): XPT_SCSI_IO
2855:atapi_action: hcb0xc55885c0: 25 0 0 0 0 0 0 0 0 0
2856:acd0: req=0xc5582b40 READ_CAPACITY queued
2857:acd0: req=0xc5582b40 READ_CAPACITY starting
2858:acd0: req=0xc5582b40 READ_CAPACITY begin transaction
2859:acd0: req=0xc5582b40 READ_CAPACITY timeout
2860:acd0: req=0xc5582b40 READ_CAPACITY finish
taskqueue_swi
2861:acd0: req=0xc5582b40 READ_CAPACITY completed entered
2862:(noperiph:ata2:0:-1:-1): xpt_async
2863:(noperiph:ata2:0:1:0): xpt_compile_path
2864:(noperiph:ata2:0:1:0): xpt_release_path
2865:(cd0:ata2:0:1:0): xpt_setup_ccb
2866:(cd0:ata2:0:1:0): xpt_action
2867:(cd0:ata2:0:1:0): xpt_setup_ccb
2868:(cd0:ata2:0:1:0): xpt_action
2869:(cd0:ata2:0:1:0): xpt_setup_ccb
2870:(cd0:ata2:0:1:0): xpt_action
2871:acd0: FAILURE - READ_CAPACITY timed out
2872:acd0: req=0xc5582b40 READ_CAPACITY completed
callback/wakeup
2873:atapi_cb: hcb0xc55885c0 sense = 00: sk = 0)
2874:acd0: cmd READ_CAPACITY status 00 result 05 error 00
2875:(pass0:ata2:0:1:0): xpt_done
2876:(pass0:ata2:0:1:0): camisr
2877:cam_debug: xpt_release_ccb
2878:(pass0:ata2:0:1:0): entering cdgetccb
2879:(pass0:ata2:0:1:0): xpt_schedule
2880:(pass0:ata2:0:1:0):    added periph to queue
2881:cam_debug: xpt_schedule_dev
2882:cam_debug: Inserting onto queue
2883:(pass0:ata2:0:1:0):    calling xpt_run_devq
2884:cam_debug: xpt_run_dev_allocq
2885:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2886:cam_debug: running device 0xc53bbc00
2887:(pass0:ata2:0:1:0): xpt_setup_ccb
2888:cam_debug: calling periph start
2889:(pass0:ata2:0:1:0): xpt_setup_ccb
2890:(pass0:ata2:0:1:0): xpt_action
2891:(pass0:ata2:0:1:0): xpt_action
2892:cam_debug: xpt_release_ccb
2893:(pass0:ata2:0:1:0): xpt_setup_ccb
2894:(pass0:ata2:0:1:0): xpt_action
2895:(pass0:ata2:0:1:0): xpt_done
2896:(pass0:ata2:0:1:0): xpt_setup_ccb
2897:(pass0:ata2:0:1:0): xpt_action
2898:(pass0:ata2:0:1:0): xpt_setup_ccb
2899:(pass0:ata2:0:1:0): xpt_action
2900:(pass0:ata2:0:1:0): GET_TRAN_SETTINGS
2901:(pass0:ata2:0:1:0): xpt_done
2902:(pass0:ata2:0:1:0): entering cdgetccb
2903:(pass0:ata2:0:1:0): xpt_schedule
2904:(pass0:ata2:0:1:0):    added periph to queue
2905:cam_debug: xpt_schedule_dev
2906:cam_debug: Inserting onto queue
2907:(pass0:ata2:0:1:0):    calling xpt_run_devq
2908:cam_debug: xpt_run_dev_allocq
2909:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2910:cam_debug: running device 0xc53bbc00
2911:(pass0:ata2:0:1:0): xpt_setup_ccb
2912:cam_debug: calling periph start
2913:(pass0:ata2:0:1:0): xpt_action
2914:(pass0:ata2:0:1:0): REQUEST SENSE. CDB: 3 0 0 0 12 0
2915:cam_debug: xpt_schedule_dev
2916:cam_debug: Inserting onto queue
2917:cam_debug: xpt_run_dev_sendq
2918:cam_debug: running device 0xc53bbc00
2919:(pass0:ata2:0:1:0): XPT_SCSI_IO
2920:atapi_action: hcb0xc5588780: 3 0 0 0 12 0
2921:acd0: req=0xc5582d80 REQUEST_SENSE queued
2922:acd0: req=0xc5582d80 REQUEST_SENSE starting
2923:acd0: req=0xc5582d80 REQUEST_SENSE begin transaction
2924:acd0: req=0xc5582d80 REQUEST_SENSE interrupt
2925:acd0: req=0xc5582d80 REQUEST_SENSE end transaction
2926:acd0: req=0xc5582d80 REQUEST_SENSE finish
taskqueue_swi
2927:acd0: req=0xc5582d80 REQUEST_SENSE completed entered
2928:acd0: req=0xc5582d80 REQUEST_SENSE completed
callback/wakeup
2929:atapi_cb: hcb0xc5588780 sense = 00: sk = 0)
2930:acd0: cmd REQUEST_SENSE status 50 result 00 error 00
2931:(pass0:ata2:0:1:0): xpt_done
2932:(pass0:ata2:0:1:0): camisr
2933:cam_debug: xpt_release_ccb
2934:(pass0:ata2:0:1:0): entering cdgetccb
2935:(pass0:ata2:0:1:0): xpt_schedule
2936:(pass0:ata2:0:1:0):    added periph to queue
2937:cam_debug: xpt_schedule_dev
2938:cam_debug: Inserting onto queue
2939:(pass0:ata2:0:1:0):    calling xpt_run_devq
2940:cam_debug: xpt_run_dev_allocq
2941:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2942:cam_debug: running device 0xc53bbc00
2943:(pass0:ata2:0:1:0): xpt_setup_ccb
2944:cam_debug: calling periph start
2945:(pass0:ata2:0:1:0): xpt_setup_ccb
2946:(pass0:ata2:0:1:0): xpt_action
2947:(pass0:ata2:0:1:0): xpt_action
2948:cam_debug: xpt_release_ccb
2949:(pass0:ata2:0:1:0): xpt_setup_ccb
2950:(pass0:ata2:0:1:0): xpt_action
2951:(pass0:ata2:0:1:0): xpt_done
2952:(pass0:ata2:0:1:0): xpt_setup_ccb
2953:(pass0:ata2:0:1:0): xpt_action
2954:(pass0:ata2:0:1:0): xpt_setup_ccb
2955:(pass0:ata2:0:1:0): xpt_action
2956:(pass0:ata2:0:1:0): GET_TRAN_SETTINGS
2957:(pass0:ata2:0:1:0): xpt_done
2958:(pass0:ata2:0:1:0): entering cdgetccb
2959:(pass0:ata2:0:1:0): xpt_schedule
2960:(pass0:ata2:0:1:0):    added periph to queue
2961:cam_debug: xpt_schedule_dev
2962:cam_debug: Inserting onto queue
2963:(pass0:ata2:0:1:0):    calling xpt_run_devq
2964:cam_debug: xpt_run_dev_allocq
2965:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2966:cam_debug: running device 0xc53bbc00
2967:(pass0:ata2:0:1:0): xpt_setup_ccb
2968:cam_debug: calling periph start
2969:(pass0:ata2:0:1:0): xpt_action
2970:(pass0:ata2:0:1:0): READ CD RECORDED CAPACITY. CDB: 25
0 0 0 0 0 0 0 0 0
2971:cam_debug: xpt_schedule_dev
2972:cam_debug: Inserting onto queue
2973:cam_debug: xpt_run_dev_sendq
2974:cam_debug: running device 0xc53bbc00
2975:(pass0:ata2:0:1:0): XPT_SCSI_IO
2976:atapi_action: hcb0xc55897c0: 25 0 0 0 0 0 0 0 0 0
2977:acd0: req=0xc55823c0 READ_CAPACITY queued
2978:acd0: req=0xc55823c0 READ_CAPACITY starting
2979:acd0: req=0xc55823c0 READ_CAPACITY begin transaction
2980:acd0: req=0xc55823c0 READ_CAPACITY timeout
2981:acd0: req=0xc55823c0 READ_CAPACITY finish
taskqueue_swi
2982:acd0: req=0xc55823c0 READ_CAPACITY completed entered
2983:(noperiph:ata2:0:-1:-1): xpt_async
2984:(noperiph:ata2:0:1:0): xpt_compile_path
2985:(noperiph:ata2:0:1:0): xpt_release_path
2986:(cd0:ata2:0:1:0): xpt_setup_ccb
2987:(cd0:ata2:0:1:0): xpt_action
2988:(cd0:ata2:0:1:0): xpt_setup_ccb
2989:(cd0:ata2:0:1:0): xpt_action
2990:(cd0:ata2:0:1:0): xpt_setup_ccb
2991:(cd0:ata2:0:1:0): xpt_action
2992:acd0: FAILURE - READ_CAPACITY timed out
2993:acd0: req=0xc55823c0 READ_CAPACITY completed
callback/wakeup
2994:atapi_cb: hcb0xc55897c0 sense = 00: sk = 0)
2995:acd0: cmd READ_CAPACITY status 00 result 05 error 00
2996:(pass0:ata2:0:1:0): xpt_done
2997:(pass0:ata2:0:1:0): camisr
2998:cam_debug: xpt_release_ccb

And here's the output after a TEST UNIT READY command, then
the read
capacity command (it worked):

2812:cam_debug: xpt_release_ccb
2813:(pass0:ata2:0:1:0): entering cdgetccb
2814:(pass0:ata2:0:1:0): xpt_schedule
2815:(pass0:ata2:0:1:0):    added periph to queue
2816:cam_debug: xpt_schedule_dev
2817:cam_debug: Inserting onto queue
2818:(pass0:ata2:0:1:0):    calling xpt_run_devq
2819:cam_debug: xpt_run_dev_allocq
2820:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2821:cam_debug: running device 0xc53bbc00
2822:(pass0:ata2:0:1:0): xpt_setup_ccb
2823:cam_debug: calling periph start
2824:(pass0:ata2:0:1:0): xpt_setup_ccb
2825:(pass0:ata2:0:1:0): xpt_action
2826:(pass0:ata2:0:1:0): xpt_action
2827:cam_debug: xpt_release_ccb
2828:(pass0:ata2:0:1:0): xpt_setup_ccb
2829:(pass0:ata2:0:1:0): xpt_action
2830:(pass0:ata2:0:1:0): xpt_done
2831:(pass0:ata2:0:1:0): xpt_setup_ccb
2832:(pass0:ata2:0:1:0): xpt_action
2833:(pass0:ata2:0:1:0): xpt_setup_ccb
2834:(pass0:ata2:0:1:0): xpt_action
2835:(pass0:ata2:0:1:0): GET_TRAN_SETTINGS
2836:(pass0:ata2:0:1:0): xpt_done
2837:(pass0:ata2:0:1:0): entering cdgetccb
2838:(pass0:ata2:0:1:0): xpt_schedule
2839:(pass0:ata2:0:1:0):    added periph to queue
2840:cam_debug: xpt_schedule_dev
2841:cam_debug: Inserting onto queue
2842:(pass0:ata2:0:1:0):    calling xpt_run_devq
2843:cam_debug: xpt_run_dev_allocq
2844:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2845:cam_debug: running device 0xc53bbc00
2846:(pass0:ata2:0:1:0): xpt_setup_ccb
2847:cam_debug: calling periph start
2848:(pass0:ata2:0:1:0): xpt_action
2849:(pass0:ata2:0:1:0): READ CD RECORDED CAPACITY. CDB: 25
0 0 0 0 0 0 0 0 0
2850:cam_debug: xpt_schedule_dev
2851:cam_debug: Inserting onto queue
2852:cam_debug: xpt_run_dev_sendq
2853:cam_debug: running device 0xc53bbc00
2854:(pass0:ata2:0:1:0): XPT_SCSI_IO
2855:atapi_action: hcb0xc55885c0: 25 0 0 0 0 0 0 0 0 0
2856:acd0: req=0xc5582b40 READ_CAPACITY queued
2857:acd0: req=0xc5582b40 READ_CAPACITY starting
2858:acd0: req=0xc5582b40 READ_CAPACITY begin transaction
2859:acd0: req=0xc5582b40 READ_CAPACITY timeout
2860:acd0: req=0xc5582b40 READ_CAPACITY finish
taskqueue_swi
2861:acd0: req=0xc5582b40 READ_CAPACITY completed entered
2862:(noperiph:ata2:0:-1:-1): xpt_async
2863:(noperiph:ata2:0:1:0): xpt_compile_path
2864:(noperiph:ata2:0:1:0): xpt_release_path
2865:(cd0:ata2:0:1:0): xpt_setup_ccb
2866:(cd0:ata2:0:1:0): xpt_action
2867:(cd0:ata2:0:1:0): xpt_setup_ccb
2868:(cd0:ata2:0:1:0): xpt_action
2869:(cd0:ata2:0:1:0): xpt_setup_ccb
2870:(cd0:ata2:0:1:0): xpt_action
2871:acd0: FAILURE - READ_CAPACITY timed out
2872:acd0: req=0xc5582b40 READ_CAPACITY completed
callback/wakeup
2873:atapi_cb: hcb0xc55885c0 sense = 00: sk = 0)
2874:acd0: cmd READ_CAPACITY status 00 result 05 error 00
2875:(pass0:ata2:0:1:0): xpt_done
2876:(pass0:ata2:0:1:0): camisr
2877:cam_debug: xpt_release_ccb
2878:(pass0:ata2:0:1:0): entering cdgetccb
2879:(pass0:ata2:0:1:0): xpt_schedule
2880:(pass0:ata2:0:1:0):    added periph to queue
2881:cam_debug: xpt_schedule_dev
2882:cam_debug: Inserting onto queue
2883:(pass0:ata2:0:1:0):    calling xpt_run_devq
2884:cam_debug: xpt_run_dev_allocq
2885:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2886:cam_debug: running device 0xc53bbc00
2887:(pass0:ata2:0:1:0): xpt_setup_ccb
2888:cam_debug: calling periph start
2889:(pass0:ata2:0:1:0): xpt_setup_ccb
2890:(pass0:ata2:0:1:0): xpt_action
2891:(pass0:ata2:0:1:0): xpt_action
2892:cam_debug: xpt_release_ccb
2893:(pass0:ata2:0:1:0): xpt_setup_ccb
2894:(pass0:ata2:0:1:0): xpt_action
2895:(pass0:ata2:0:1:0): xpt_done
2896:(pass0:ata2:0:1:0): xpt_setup_ccb
2897:(pass0:ata2:0:1:0): xpt_action
2898:(pass0:ata2:0:1:0): xpt_setup_ccb
2899:(pass0:ata2:0:1:0): xpt_action
2900:(pass0:ata2:0:1:0): GET_TRAN_SETTINGS
2901:(pass0:ata2:0:1:0): xpt_done
2902:(pass0:ata2:0:1:0): entering cdgetccb
2903:(pass0:ata2:0:1:0): xpt_schedule
2904:(pass0:ata2:0:1:0):    added periph to queue
2905:cam_debug: xpt_schedule_dev
2906:cam_debug: Inserting onto queue
2907:(pass0:ata2:0:1:0):    calling xpt_run_devq
2908:cam_debug: xpt_run_dev_allocq
2909:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2910:cam_debug: running device 0xc53bbc00
2911:(pass0:ata2:0:1:0): xpt_setup_ccb
2912:cam_debug: calling periph start
2913:(pass0:ata2:0:1:0): xpt_action
2914:(pass0:ata2:0:1:0): REQUEST SENSE. CDB: 3 0 0 0 12 0
2915:cam_debug: xpt_schedule_dev
2916:cam_debug: Inserting onto queue
2917:cam_debug: xpt_run_dev_sendq
2918:cam_debug: running device 0xc53bbc00
2919:(pass0:ata2:0:1:0): XPT_SCSI_IO
2920:atapi_action: hcb0xc5588780: 3 0 0 0 12 0
2921:acd0: req=0xc5582d80 REQUEST_SENSE queued
2922:acd0: req=0xc5582d80 REQUEST_SENSE starting
2923:acd0: req=0xc5582d80 REQUEST_SENSE begin transaction
2924:acd0: req=0xc5582d80 REQUEST_SENSE interrupt
2925:acd0: req=0xc5582d80 REQUEST_SENSE end transaction
2926:acd0: req=0xc5582d80 REQUEST_SENSE finish
taskqueue_swi
2927:acd0: req=0xc5582d80 REQUEST_SENSE completed entered
2928:acd0: req=0xc5582d80 REQUEST_SENSE completed
callback/wakeup
2929:atapi_cb: hcb0xc5588780 sense = 00: sk = 0)
2930:acd0: cmd REQUEST_SENSE status 50 result 00 error 00
2931:(pass0:ata2:0:1:0): xpt_done
2932:(pass0:ata2:0:1:0): camisr
2933:cam_debug: xpt_release_ccb
2934:(pass0:ata2:0:1:0): entering cdgetccb
2935:(pass0:ata2:0:1:0): xpt_schedule
2936:(pass0:ata2:0:1:0):    added periph to queue
2937:cam_debug: xpt_schedule_dev
2938:cam_debug: Inserting onto queue
2939:(pass0:ata2:0:1:0):    calling xpt_run_devq
2940:cam_debug: xpt_run_dev_allocq
2941:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2942:cam_debug: running device 0xc53bbc00
2943:(pass0:ata2:0:1:0): xpt_setup_ccb
2944:cam_debug: calling periph start
2945:(pass0:ata2:0:1:0): xpt_setup_ccb
2946:(pass0:ata2:0:1:0): xpt_action
2947:(pass0:ata2:0:1:0): xpt_action
2948:cam_debug: xpt_release_ccb
2949:(pass0:ata2:0:1:0): xpt_setup_ccb
2950:(pass0:ata2:0:1:0): xpt_action
2951:(pass0:ata2:0:1:0): xpt_done
2952:(pass0:ata2:0:1:0): xpt_setup_ccb
2953:(pass0:ata2:0:1:0): xpt_action
2954:(pass0:ata2:0:1:0): xpt_setup_ccb
2955:(pass0:ata2:0:1:0): xpt_action
2956:(pass0:ata2:0:1:0): GET_TRAN_SETTINGS
2957:(pass0:ata2:0:1:0): xpt_done
2958:(pass0:ata2:0:1:0): entering cdgetccb
2959:(pass0:ata2:0:1:0): xpt_schedule
2960:(pass0:ata2:0:1:0):    added periph to queue
2961:cam_debug: xpt_schedule_dev
2962:cam_debug: Inserting onto queue
2963:(pass0:ata2:0:1:0):    calling xpt_run_devq
2964:cam_debug: xpt_run_dev_allocq
2965:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
2966:cam_debug: running device 0xc53bbc00
2967:(pass0:ata2:0:1:0): xpt_setup_ccb
2968:cam_debug: calling periph start
2969:(pass0:ata2:0:1:0): xpt_action
2970:(pass0:ata2:0:1:0): READ CD RECORDED CAPACITY. CDB: 25
0 0 0 0 0 0 0 0 0
2971:cam_debug: xpt_schedule_dev
2972:cam_debug: Inserting onto queue
2973:cam_debug: xpt_run_dev_sendq
2974:cam_debug: running device 0xc53bbc00
2975:(pass0:ata2:0:1:0): XPT_SCSI_IO
2976:atapi_action: hcb0xc55897c0: 25 0 0 0 0 0 0 0 0 0
2977:acd0: req=0xc55823c0 READ_CAPACITY queued
2978:acd0: req=0xc55823c0 READ_CAPACITY starting
2979:acd0: req=0xc55823c0 READ_CAPACITY begin transaction
2980:acd0: req=0xc55823c0 READ_CAPACITY timeout
2981:acd0: req=0xc55823c0 READ_CAPACITY finish
taskqueue_swi
2982:acd0: req=0xc55823c0 READ_CAPACITY completed entered
2983:(noperiph:ata2:0:-1:-1): xpt_async
2984:(noperiph:ata2:0:1:0): xpt_compile_path
2985:(noperiph:ata2:0:1:0): xpt_release_path
2986:(cd0:ata2:0:1:0): xpt_setup_ccb
2987:(cd0:ata2:0:1:0): xpt_action
2988:(cd0:ata2:0:1:0): xpt_setup_ccb
2989:(cd0:ata2:0:1:0): xpt_action
2990:(cd0:ata2:0:1:0): xpt_setup_ccb
2991:(cd0:ata2:0:1:0): xpt_action
2992:acd0: FAILURE - READ_CAPACITY timed out
2993:acd0: req=0xc55823c0 READ_CAPACITY completed
callback/wakeup
2994:atapi_cb: hcb0xc55897c0 sense = 00: sk = 0)
2995:acd0: cmd READ_CAPACITY status 00 result 05 error 00
2996:(pass0:ata2:0:1:0): xpt_done
2997:(pass0:ata2:0:1:0): camisr
2998:cam_debug: xpt_release_ccb
2999:(pass0:ata2:0:1:0): entering cdgetccb
3000:(pass0:ata2:0:1:0): xpt_schedule
3001:(pass0:ata2:0:1:0):    added periph to queue
3002:cam_debug: xpt_schedule_dev
3003:cam_debug: Inserting onto queue
3004:(pass0:ata2:0:1:0):    calling xpt_run_devq
3005:cam_debug: xpt_run_dev_allocq
3006:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
3007:cam_debug: running device 0xc53bbc00
3008:(pass0:ata2:0:1:0): xpt_setup_ccb
3009:cam_debug: calling periph start
3010:(pass0:ata2:0:1:0): xpt_setup_ccb
3011:(pass0:ata2:0:1:0): xpt_action
3012:(pass0:ata2:0:1:0): xpt_action
3013:cam_debug: xpt_release_ccb
3014:(pass0:ata2:0:1:0): xpt_setup_ccb
3015:(pass0:ata2:0:1:0): xpt_action
3016:(pass0:ata2:0:1:0): xpt_done
3017:(pass0:ata2:0:1:0): xpt_setup_ccb
3018:(pass0:ata2:0:1:0): xpt_action
3019:(pass0:ata2:0:1:0): xpt_setup_ccb
3020:(pass0:ata2:0:1:0): xpt_action
3021:(pass0:ata2:0:1:0): GET_TRAN_SETTINGS
3022:(pass0:ata2:0:1:0): xpt_done
3023:(pass0:ata2:0:1:0): entering cdgetccb
3024:(pass0:ata2:0:1:0): xpt_schedule
3025:(pass0:ata2:0:1:0):    added periph to queue
3026:cam_debug: xpt_schedule_dev
3027:cam_debug: Inserting onto queue
3028:(pass0:ata2:0:1:0):    calling xpt_run_devq
3029:cam_debug: xpt_run_dev_allocq
3030:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
3031:cam_debug: running device 0xc53bbc00
3032:(pass0:ata2:0:1:0): xpt_setup_ccb
3033:cam_debug: calling periph start
3034:(pass0:ata2:0:1:0): xpt_action
3035:(pass0:ata2:0:1:0): TEST UNIT READY. CDB: 0 0 0 0 0 0
3036:cam_debug: xpt_schedule_dev
3037:cam_debug: Inserting onto queue
3038:cam_debug: xpt_run_dev_sendq
3039:cam_debug: running device 0xc53bbc00
3040:(pass0:ata2:0:1:0): XPT_SCSI_IO
3041:atapi_action: hcb0xc55b8900: 0 0 0 0 0 0
3042:acd0: req=0xc5556780 TEST_UNIT_READY queued
3043:acd0: req=0xc5556780 TEST_UNIT_READY starting
3044:acd0: req=0xc5556780 TEST_UNIT_READY begin transaction
3045:acd0: req=0xc5556780 TEST_UNIT_READY interrupt
3046:acd0: req=0xc5556780 TEST_UNIT_READY end transaction
3047:acd0: req=0xc5556780 TEST_UNIT_READY finish
taskqueue_swi
3048:acd0: req=0xc5556780 TEST_UNIT_READY completed entered
3049:acd0: req=0xc5556780 TEST_UNIT_READY completed
callback/wakeup
3050:atapi_cb: hcb0xc55b8900 sense = 00: sk = 0)
3051:acd0: cmd TEST_UNIT_READY status 50 result 00 error 00
3052:(pass0:ata2:0:1:0): xpt_done
3053:(pass0:ata2:0:1:0): camisr
3054:cam_debug: xpt_release_ccb
3055:(pass0:ata2:0:1:0): entering cdgetccb
3056:(pass0:ata2:0:1:0): xpt_schedule
3057:(pass0:ata2:0:1:0):    added periph to queue
3058:cam_debug: xpt_schedule_dev
3059:cam_debug: Inserting onto queue
3060:(pass0:ata2:0:1:0):    calling xpt_run_devq
3061:cam_debug: xpt_run_dev_allocq
3062:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
3063:cam_debug: running device 0xc53bbc00
3064:(pass0:ata2:0:1:0): xpt_setup_ccb
3065:cam_debug: calling periph start
3066:(pass0:ata2:0:1:0): xpt_setup_ccb
3067:(pass0:ata2:0:1:0): xpt_action
3068:(pass0:ata2:0:1:0): xpt_action
3069:cam_debug: xpt_release_ccb
3070:(pass0:ata2:0:1:0): xpt_setup_ccb
3071:(pass0:ata2:0:1:0): xpt_action
3072:(pass0:ata2:0:1:0): xpt_done
3073:(pass0:ata2:0:1:0): xpt_setup_ccb
3074:(pass0:ata2:0:1:0): xpt_action
3075:(pass0:ata2:0:1:0): xpt_setup_ccb
3076:(pass0:ata2:0:1:0): xpt_action
3077:(pass0:ata2:0:1:0): GET_TRAN_SETTINGS
3078:(pass0:ata2:0:1:0): xpt_done
3079:(pass0:ata2:0:1:0): entering cdgetccb
3080:(pass0:ata2:0:1:0): xpt_schedule
3081:(pass0:ata2:0:1:0):    added periph to queue
3082:cam_debug: xpt_schedule_dev
3083:cam_debug: Inserting onto queue
3084:(pass0:ata2:0:1:0):    calling xpt_run_devq
3085:cam_debug: xpt_run_dev_allocq
3086:cam_debug:    qfrozen_cnt == 0x0, entries == 1,
openings == 16, active 
== 0
3087:cam_debug: running device 0xc53bbc00
3088:(pass0:ata2:0:1:0): xpt_setup_ccb
3089:cam_debug: calling periph start
3090:(pass0:ata2:0:1:0): xpt_action
3091:(pass0:ata2:0:1:0): READ CD RECORDED CAPACITY. CDB: 25
0 0 0 0 0 0 0 0 0
3092:cam_debug: xpt_schedule_dev
3093:cam_debug: Inserting onto queue
3094:cam_debug: xpt_run_dev_sendq
3095:cam_debug: running device 0xc53bbc00
3096:(pass0:ata2:0:1:0): XPT_SCSI_IO
3097:atapi_action: hcb0xc55b8700: 25 0 0 0 0 0 0 0 0 0
3098:acd0: req=0xc5556600 READ_CAPACITY queued
3099:acd0: req=0xc5556600 READ_CAPACITY starting
3100:acd0: req=0xc5556600 READ_CAPACITY begin transaction
3101:acd0: req=0xc5556600 READ_CAPACITY interrupt
3102:acd0: req=0xc5556600 READ_CAPACITY end transaction
3103:acd0: req=0xc5556600 READ_CAPACITY finish
taskqueue_swi
3104:acd0: req=0xc5556600 READ_CAPACITY completed entered
3105:acd0: req=0xc5556600 READ_CAPACITY completed
callback/wakeup
3106:atapi_cb: hcb0xc55b8700 sense = 00: sk = 0)
3107:acd0: cmd READ_CAPACITY status 50 result 00 error 00
3108:(pass0:ata2:0:1:0): xpt_done
3109:(pass0:ata2:0:1:0): camisr
3110:cam_debug: xpt_release_ccb

Thanks!
Josh

----- End forwarded message -----

Thomas.

_______________________________________________
freebsd-scsifreebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-scsi

To unsubscribe, send any mail to
"freebsd-scsi-unsubscribefreebsd.org"

Thomas Quinot wrote:
> SCSI guys,
> 
> kern/103602 is a long-standing issue with a Sony DVD
drive that has a
> strange behaviour (failing to attach and causing an
interrupt storm).
> 
> One aspect of this PR was that an ATAPI command timing
out was not
> correctly reported by the ATAPI/CAM SIM to the XPT
layer. This has been
> fixed in atapi-cam.c rev. 1.49.
> 
> Now we have a second issue: if there is no disc in the
drive, it
> times out a READ CD CAPACITY (and any subsequent retry,
even if a disc
> is then inserted in the drive), instead of returning an
appropriate
> error (the expected behaviour would be a NOT READY
sense key and a
> MEDIUM NOT PRESENT ASC). A TEST UNIT READY command
seems to behave
> properly (reporting the appropriate error if no disc is
present,
> reporting no error and resetting the drive to a proper
state if
> one is).
> 
> The timeout causes the unit to fail to attach at boot
time if no disc is
> present. How should we deal with this situation? One
possible option is
> to make sure that we first issue a TEST UNIT READY at
attach time prior
> to issuing READ CD CAPACITY, and not issue the second
command if the TUR
> returned a NOT READY status.
> 
> The traces below show how the drive behaves in response
to TEST UNIT
> READY and READ CD CAPACITY in various cases. Complete
boot messages are
> available in the PR history.
> 
> Thomas.
> 

I'm confused.  CAM actually sends a READ_CAPACITY command to
the drive, 
not a READ_CD_CAPACITY command.  Are you saying that issuing
both a
READ_CAPACITY and a READ_CD_CAPACITY to an empty Sony drive
results in
the same bad behavior?

Re-arranging the probe process to issue a TUR first is
tricky.  I'd 
rather not do it if possible.

Scott
_______________________________________________
freebsd-scsifreebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-scsi

To unsubscribe, send any mail to
"freebsd-scsi-unsubscribefreebsd.org"

Scott Long wrote:
> Thomas Quinot wrote:
>> SCSI guys,
>>
>> kern/103602 is a long-standing issue with a Sony
DVD drive that has a
>> strange behaviour (failing to attach and causing an
interrupt storm).
>>
>> One aspect of this PR was that an ATAPI command
timing out was not
>> correctly reported by the ATAPI/CAM SIM to the XPT
layer. This has been
>> fixed in atapi-cam.c rev. 1.49.
>>
>> Now we have a second issue: if there is no disc in
the drive, it
>> times out a READ CD CAPACITY (and any subsequent
retry, even if a disc
>> is then inserted in the drive), instead of
returning an appropriate
>> error (the expected behaviour would be a NOT READY
sense key and a
>> MEDIUM NOT PRESENT ASC). A TEST UNIT READY command
seems to behave
>> properly (reporting the appropriate error if no
disc is present,
>> reporting no error and resetting the drive to a
proper state if
>> one is).
>>
>> The timeout causes the unit to fail to attach at
boot time if no disc is
>> present. How should we deal with this situation?
One possible option is
>> to make sure that we first issue a TEST UNIT READY
at attach time prior
>> to issuing READ CD CAPACITY, and not issue the
second command if the TUR
>> returned a NOT READY status.
>>
>> The traces below show how the drive behaves in
response to TEST UNIT
>> READY and READ CD CAPACITY in various cases.
Complete boot messages are
>> available in the PR history.
>>
>> Thomas.
>>
> 
> I'm confused.  CAM actually sends a READ_CAPACITY
command to the drive, 
> not a READ_CD_CAPACITY command.  Are you saying that
issuing both a
> READ_CAPACITY and a READ_CD_CAPACITY to an empty Sony
drive results in
> the same bad behavior?
> 
> Re-arranging the probe process to issue a TUR first is
tricky.  I'd 
> rather not do it if possible.
> 

Actually, I take that back, adding a TUR phase isn't as hard
as I
thought.  I'd like to know if doing a READ_CD_CAPACITY makes
a
difference, though.

Scott
_______________________________________________
freebsd-scsifreebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-scsi

To unsubscribe, send any mail to
"freebsd-scsi-unsubscribefreebsd.org"

* Scott Long, 2007-03-13 :

> >I'm confused.  CAM actually sends a READ_CAPACITY
command to the drive, 
> >not a READ_CD_CAPACITY command.  Are you saying
that issuing both a
> >READ_CAPACITY and a READ_CD_CAPACITY to an empty
Sony drive results in
> >the same bad behavior?

Er, now *I* am confused. As I understand it, READ CAPACITY
and READ CD
RECORDED CAPACITY both refer to the same opcode (0x25), READ
CAPACITY
being the SBC terminology, while READ CD RECORDED CAPACITY
is the MMC
terminology.

> Actually, I take that back, adding a TUR phase isn't as
hard as I
> thought.  I'd like to know if doing a READ_CD_CAPACITY
makes a
> difference, though.

Josh can probably test some commands and report the results,
if you send
him some camcontrol cmd's to experiment with.

Thomas.

_______________________________________________
freebsd-scsifreebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-scsi

To unsubscribe, send any mail to
"freebsd-scsi-unsubscribefreebsd.org"

Josh Carroll wrote:
>> Ok, so the problem is happening long before the
READ_CAPACITY command
>> is sent.  If it's dying on the INQ then it's going
to be quite a bit
>> harder to fix; every device under the sun needs to
respond to an INQ
>> so that the OS knows what kind of device it is. 
Skipping that will make
>> the device pretty much useless to the OS.
> 
> I'm rebuilding a -CURRENT kernel with the cumulative
and scsi patches
> now. What I didn't realize is the cam_xpt.c patch that
adds the quirk
> to work around the serial # lookup wasn't patched in.
At least I don't
> think so. I've re-added that patch and I'm trying again
and will
> report back.
> 
> Sorry for the confusion, hopefully I get past the
INQUIRY with the
> cam_xpt.c patch.
> 
> Thanks,
> Josh

Any update on this?

Scott

_______________________________________________
freebsd-scsifreebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-scsi

To unsubscribe, send any mail to
"freebsd-scsi-unsubscribefreebsd.org"

> Any update on this?

I'm unable to get past the INQUIRY with the cam_xpt.c patch
with the
serial inquiry workaround along with the cam and scsi_cd
patches. I'm
hoping Thomas can provide a cumulative patch from the many
we were
working with to date, as I'm not sure at this point which to
use. I
thought using patches 1-11 from the thread along with your
patch and
the cam_xpt.c patch it would work, but no such luck.

Josh
_______________________________________________
freebsd-scsifreebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-scsi

To unsubscribe, send any mail to
"freebsd-scsi-unsubscribefreebsd.org"

> I'm unable to get past the INQUIRY with the cam_xpt.c
patch with the
> serial inquiry workaround along with the cam and
scsi_cd patches.

Ok, I was able to find the right combination of patches to
get this to
work. I cvsup'd today (4/2/2007) so all the patches to the
files in
sys/dev/ata appear to already have been committed. I patched
cam_xpt.c
with the patch that removes "REQUIRE_GIANT" in two
places, and sets
the serial inquiry quirk for my drive. I also patched with
Scott's
scsi_cd.c patch.

Rather than paste thousands of lines of code in this update
again, I'm
throwing the dmesg output up on my web server, so I hope
that's ok. I
figure it's easier to follow without it (the SNR is too high
)

Anyway, I was able to get booted again to test. Without a CD
in the
drive after boot, I get a huge number of interrupts still on
the ata
controller, and I see a lot of READ CAPACITY timeouts. But
it finally
stops and I still have /dev/cd0 and the interrupts are no
longer
"storming". Here is the dmesg output from the
start of the boot
process up to the point where the interrupt storm stops and
things
settle down:

http://p
flog.net/atapicam/dmesg.post_boot.gz

I then issued the following cdrecord command:

cdrecord -scanbus

Here is the dmesg output from that command:

h
ttp://pflog.net/atapicam/dmesg.cdrecord.scanbus.gz

I then issued a cdrecord command to burn a CD-RW at 4x:

cdrecord -v dev=2,1,0 /path/to/file.iso

There were some long timeouts during which the interrupts
were
storming as well (based on the delta in the # before and
after the
cdrecord command). But it ultimately finished, and I was
able to mount
the resulting burned disc. The only data I could get from
dmesg was
during the tail end of the cd write, since the dmesg buffer
was
clobbered. Here's that dmesg output:

http
://pflog.net/atapicam/dmesg.cdrecord.burn.gz

What's odd is the drive still hangs on various commands when
there is
no disc in the drive, or there is a blank CD-RW in the
drive. For
example, trying to mount the blank'd CD-RW disc with
/dev/cd0 takes
almost a few minutes to timeout during which I see:

acd0: FAILURE - READ_TOC timed out    (I see this 6 times)
g_vfs_done(): cd0[READ(offset=32768, length=2048)]error = 5
mount_cd9660: /dev/cd0: Input/output error

If I issue the same mount command against /dev/acd0, it
immediately
gives me the Input/output error.

Another note. On a different boot, I tried using cdrecord to
blank the
disc, which worked, though I saw quite a few errors
(camcontrol debug
off prior). The command issued was:

cdrecord dev=2,1,0 blank=fast

The errors I saw in dmesg were:

acd0: FAILURE - READ_DVD_STRUCTURE timed out   (I imagine
this is
because I didn't specify a media type)
acd0: FAILURE - READ_BUFFER timed out
acd0: FAILURE - MODE_SELECT_BIG ILLEGAL REQUEST asc=0x24
ascq=0x00  (I
saw this right before the cdrecord command finished)

I hope this updated info helps. It seems to still hang on
the READ
CAPACITY command, though at least now I'm able to use the
device after
the drive calms down. Though I am still seeing other
commands time out
as well, cdrecord appears to still work albeit very slowly
(due in
part I'm sure to WITNESS, but also due to these multi-second
(minute?)
timeouts).

Thanks,
Josh
_______________________________________________
freebsd-scsifreebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-scsi

To unsubscribe, send any mail to
"freebsd-scsi-unsubscribefreebsd.org"

Thinking out of the box, I decided to use sg3_utils on both
the
semi-working 7.0-CURRENT kernel I had, and on a Linux
Knoppix 5.1 live
CD.

Pretty much every sg utility resulted in a acd0 FAILURE
message (I ran
the commands against /dev/cd0 though of course). Here are
the various
dmesg messages:

acd0: FAILURE - INQUIRY timed out
acd0: FAILURE - MODE_SENSE_BIG timed out
acd0: FAILURE - READ_CAPACITY timed out
acd0: FAILURE - SEND_KEY timed out
acd0: FAILURE - unknown CMD (0x46) timed out

It seems like every atapi command is timing out when I boot
without a
disc in the drive. The only command that semi-worked was
sg_turs.
Without a CD in the drive, I get the following output:

    test unit ready cdb: 00 00 00 00 00 00
test unit ready: Probably uninitialized data.
  Try to view as SCSI-1 non-extended sense:
  AdValid=0  Error class=0  Error code=0

 Raw sense data (in hex):
        00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
        00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00

If I insert a CD and run it, I get normal output (e.g.
matching that
of what I saw on Knoppix):

    test unit ready cdb: 00 00 00 00 00 00

Perhaps there is a subtle difference with TUR with and
without a disc,
which the kernel can sense and take appropriate action? When
running
any of these sg* commands in Knoppix with no disc in the
drive, I get
a message similar to this:

sg_readcap.no_disc.out:READ CAPACITY (10) failed, device not
ready

Interestingly, the sg_vpd command fails to read the serial #
as well,
so that is definitely a known bug with this drive I think.
Here is the
sg_vpd output on Knoppix:

Supported VPD pages VPD page:
fetching VPD page failed

I don't know if the output of any of these sg commands on
Knoppix is
useful (e.g. sg_get_config, sg_modes, sginfo) in terms of
finding out
details of the device, but if interested I've posted a
tarball of the
outputs here:

http://pflog.net
/floyd/sg_output.tgz

Anyway, I thought some of this might be useful. At least I
hope 

Josh
_______________________________________________
freebsd-scsifreebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-scsi

To unsubscribe, send any mail to
"freebsd-scsi-unsubscribefreebsd.org"

> Thinking out of the box, I decided to use sg3_utils on
both the
> semi-working 7.0-CURRENT kernel I had, and on a Linux
Knoppix 5.1 live
> CD.

Hi Scott / Thomas,

Is there any update on this? Do you require any additional
information
at this point from my end?

Thanks!
Josh
_______________________________________________
freebsd-scsifreebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-scsi

To unsubscribe, send any mail to
"freebsd-scsi-unsubscribefreebsd.org"

Josh Carroll wrote:
>> Thinking out of the box, I decided to use sg3_utils
on both the
>> semi-working 7.0-CURRENT kernel I had, and on a
Linux Knoppix 5.1 live
>> CD.
> 
> Hi Scott / Thomas,
> 
> Is there any update on this? Do you require any
additional information
> at this point from my end?
> 
> Thanks!
> Josh

Sorry, I'm out of ideas for this problem.  Hopefully Thomas
can help you
out.

Scott

_______________________________________________
freebsd-scsifreebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-scsi

To unsubscribe, send any mail to
"freebsd-scsi-unsubscribefreebsd.org"