Skip site navigation (1)Skip section navigation (2)
Date:      Tue, 13 Mar 2007 21:57:31 +0100
From:      Thomas Quinot <thomas@FreeBSD.ORG>
To:        freebsd-scsi@freebsd.org
Cc:        josh.carroll@gmail.com, bug-followup@freebsd.org
Subject:   Re: kern/103602: drive gets wedged on READ CD CAPACITY if no disc is in
Message-ID:  <20070313205731.GB3866@melamine.cuivre.fr.eu.org>

next in thread | raw e-mail | index | archive | help
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.carroll@gmail.com> -----

From: Josh Carroll <josh.carroll@gmail.com>
Reply-To: josh.carroll@psualum.com
To: Thomas Quinot <thomas@freebsd.org>
Subject: Re: kern/103602: atapi device not working on JMicron 363 Controller
Cc: bug-followup@freebsd.org
In-Reply-To: <20070309182253.GA3998@melamine.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: hcb@0xc55b8440: 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: hcb@0xc55b8440 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: hcb@0xc55b8700: 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: hcb@0xc55b8700 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 \
>      "{Valid} b1 {RespCode} b7
>       {Obsolete} i1
>       {Filemark} b1 {EOM} b1 {ILI} b1 {Reserved} b1 {SenseKey} b4
>       {Info} i4 {AddLen} i1 {CommSpec} i4
>       {ASC} i1 {ASCQ} i1 {FRU} i1 {SKSV} b1 {SKS} 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: hcb@0xc55885c0: 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: hcb@0xc55885c0 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: hcb@0xc5588780: 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: hcb@0xc5588780 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: hcb@0xc55885c0: 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: hcb@0xc55885c0 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: hcb@0xc5588780: 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: hcb@0xc5588780 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: hcb@0xc55897c0: 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: hcb@0xc55897c0 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: hcb@0xc55885c0: 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: hcb@0xc55885c0 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: hcb@0xc5588780: 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: hcb@0xc5588780 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: hcb@0xc55897c0: 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: hcb@0xc55897c0 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: hcb@0xc55b8900: 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: hcb@0xc55b8900 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: hcb@0xc55b8700: 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: hcb@0xc55b8700 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.




Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20070313205731.GB3866>