From owner-freebsd-scsi@FreeBSD.ORG Tue Mar 13 20:57:34 2007 Return-Path: X-Original-To: freebsd-scsi@freebsd.org Delivered-To: freebsd-scsi@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [69.147.83.52]) by hub.freebsd.org (Postfix) with ESMTP id 3ACB516A406; Tue, 13 Mar 2007 20:57:34 +0000 (UTC) (envelope-from thomas@FreeBSD.ORG) Received: from melamine.cuivre.fr.eu.org (melusine.cuivre.fr.eu.org [82.225.155.84]) by mx1.freebsd.org (Postfix) with ESMTP id 9396813C4BA; Tue, 13 Mar 2007 20:57:32 +0000 (UTC) (envelope-from thomas@FreeBSD.ORG) Received: by melamine.cuivre.fr.eu.org (Postfix, from userid 1000) id 993C85C1A7; Tue, 13 Mar 2007 21:57:31 +0100 (CET) Date: Tue, 13 Mar 2007 21:57:31 +0100 From: Thomas Quinot To: freebsd-scsi@freebsd.org Message-ID: <20070313205731.GB3866@melamine.cuivre.fr.eu.org> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline X-message-flag: WARNING! Using Outlook can damage your computer. User-Agent: Mutt/1.5.11 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 X-BeenThere: freebsd-scsi@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: SCSI subsystem List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 13 Mar 2007 20:57:34 -0000 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 ----- From: Josh Carroll Reply-To: josh.carroll@psualum.com To: Thomas Quinot 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.