Unsupported mode pages $01 and $15 / ASR-10 "File Operation Error"

Open lukexi opened this issue 2 years ago • 18 comments

Info

Which version of Pi are you using: Pi 3+
Which github revision of software: 2.10.1
Which board version: 2.4
Which computer is the RaSCSI connected to: Ensoniq ASR-10

Describe the issue

I've got a new RaSCSI 2.4 to use with my ASR-10, which was previously using a SCSI2SD perfectly. Trying to format an RaSCSI attached disk or read an attached CD ISO results in "FILE OPERATION ERROR" on the ASR-10.

I've tried 512 and 1024 block sizes and multiple varieties of image types with the same result. Termination is on on the RaSCSI and it's the only device.

Here is the log starting with attaching a blank Seagate Barracuda 2GB image and then initiating "Format SCSI Drive" for SCSI Device 6 on the ASR-10, which ends with virtual void Disk::ModeSense6(SASIDEV*) Unsupported mode page $01

Dec 01 19:31:35 seascape-seastone RASCSI[550]: [2021-12-01 19:31:35.977] [trace] Received DEVICES_INFO command
Dec 01 19:31:35 seascape-seastone RASCSI[550]: [2021-12-01 19:31:35.985] [info] Validating: operation=ATTACH, device id=6, unit=0, type=SCHD, device params='file=Seagate_Barracuda_2GB.hds', vendor='SEAGATE', product='ST32550N', revision='0019', block size=512
Dec 01 19:31:35 seascape-seastone RASCSI[550]: [2021-12-01 19:31:35.987] [info] Executing: operation=ATTACH, device id=6, unit=0, type=SCHD, device params='file=Seagate_Barracuda_2GB.hds', vendor='SEAGATE', product='ST32550N', revision='0019', block size=512
Dec 01 19:31:35 seascape-seastone RASCSI[550]: [2021-12-01 19:31:35.989] [info] Attached SCHD device, ID 6, unit 0
Dec 01 19:31:36 seascape-seastone RASCSI[550]: [2021-12-01 19:31:36.033] [trace] Received SERVER_INFO command
Dec 01 19:31:36 seascape-seastone RASCSI[550]: [2021-12-01 19:31:36.051] [trace] Received DEVICES_INFO command
Dec 01 19:31:36 seascape-seastone RASCSI[550]: [2021-12-01 19:31:36.058] [trace] Received DEVICE_TYPES_INFO command
Dec 01 19:31:36 seascape-seastone RASCSI[550]: [2021-12-01 19:31:36.069] [trace] Received DEFAULT_IMAGE_FILES_INFO command
Dec 01 19:31:36 seascape-seastone RASCSI[550]: [2021-12-01 19:31:36.075] [trace] Received SERVER_INFO command
Dec 01 19:31:36 seascape-seastone RASCSI[550]: [2021-12-01 19:31:36.234] [trace] Received NETWORK_INTERFACES_INFO command
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.781] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.781] [trace] virtual void SASIDEV::Command() Command Phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] virtual void SASIDEV::Command() Command Byte 0: $03
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] virtual void SASIDEV::Command() Command Byte 4: $0E
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] virtual void SCSIDEV::Execute() Execution phase command $03
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $03
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing RequestSense ($03)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] virtual void Disk::RequestSense(SASIDEV*) Status $00, Sense Key $00, ASC $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] void SASIDEV::DataIn() Going into Data-in Phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 14
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] void SASIDEV::Status() Status phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] void SASIDEV::Status() Status Phase $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] void SASIDEV::MsgIn() Starting Message in phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.782] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.783] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.783] [trace] virtual void SASIDEV::Command() Command Phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.783] [trace] virtual void SASIDEV::Command() Command Byte 0: $12
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.783] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.783] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.783] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.783] [trace] virtual void SASIDEV::Command() Command Byte 4: $24
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.783] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.783] [trace] virtual void SCSIDEV::Execute() Execution phase command $12
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.783] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $12
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.783] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Inquiry ($12)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.783] [trace] void SASIDEV::DataIn() Going into Data-in Phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.783] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 36
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.784] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.784] [trace] void SASIDEV::Status() Status phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.784] [trace] void SASIDEV::Status() Status Phase $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.784] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.784] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.784] [trace] void SASIDEV::MsgIn() Starting Message in phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.784] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.784] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.784] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.784] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.784] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.784] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.784] [trace] virtual void SASIDEV::Command() Command Phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] virtual void SASIDEV::Command() Command Byte 0: $03
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] virtual void SASIDEV::Command() Command Byte 4: $0E
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] virtual void SCSIDEV::Execute() Execution phase command $03
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $03
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing RequestSense ($03)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] virtual void Disk::RequestSense(SASIDEV*) Status $00, Sense Key $00, ASC $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] void SASIDEV::DataIn() Going into Data-in Phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 14
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] void SASIDEV::Status() Status phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] void SASIDEV::Status() Status Phase $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] void SASIDEV::MsgIn() Starting Message in phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.785] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] virtual void SASIDEV::Command() Command Phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] virtual void SASIDEV::Command() Command Byte 0: $25
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] virtual void SASIDEV::Command() Command Byte 4: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] virtual void SASIDEV::Command() Command Byte 6: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] virtual void SASIDEV::Command() Command Byte 7: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] virtual void SASIDEV::Command() Command Byte 8: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] virtual void SASIDEV::Command() Command Byte 9: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] virtual void SCSIDEV::Execute() Execution phase command $25
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $25
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ReadCapacity10 ($25)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] bool Disk::CheckReady() Disk is ready
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] void SASIDEV::DataIn() Going into Data-in Phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 8
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] void SASIDEV::Status() Status phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.786] [trace] void SASIDEV::Status() Status Phase $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.787] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.787] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.787] [trace] void SASIDEV::MsgIn() Starting Message in phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.787] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.787] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.787] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.787] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.787] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.787] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.787] [trace] virtual void SASIDEV::Command() Command Phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] virtual void SASIDEV::Command() Command Byte 0: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] virtual void SASIDEV::Command() Command Byte 4: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] virtual void SCSIDEV::Execute() Execution phase command $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing TestUnitReady ($00)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] bool Disk::CheckReady() Disk is ready
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] void SASIDEV::Status() Status phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] void SASIDEV::Status() Status Phase $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] void SASIDEV::MsgIn() Starting Message in phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.788] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [trace] virtual void SASIDEV::Command() Command Phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [trace] virtual void SASIDEV::Command() Command Byte 0: $28
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [trace] virtual void SASIDEV::Command() Command Byte 4: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [trace] virtual void SASIDEV::Command() Command Byte 5: $02
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [trace] virtual void SASIDEV::Command() Command Byte 6: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [trace] virtual void SASIDEV::Command() Command Byte 7: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [trace] virtual void SASIDEV::Command() Command Byte 8: $01
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [trace] virtual void SASIDEV::Command() Command Byte 9: $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [trace] virtual void SCSIDEV::Execute() Execution phase command $28
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000002 blocks=1
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.789] [trace] bool Disk::CheckReady() Disk is ready
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.790] [trace] bool DiskTrack::Read(BYTE*, int) const reading sector: 2
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.790] [trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.790] [trace] void SASIDEV::DataIn() Going into Data-in Phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.790] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.796] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.796] [trace] void SASIDEV::Status() Status phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.796] [trace] void SASIDEV::Status() Status Phase $00
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.796] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.796] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.796] [trace] void SASIDEV::MsgIn() Starting Message in phase
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.796] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.796] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.796] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.796] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Dec 01 19:31:54 seascape-seastone RASCSI[550]: [2021-12-01 19:31:54.797] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.336] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.336] [trace] virtual void SASIDEV::Command() Command Phase
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.336] [trace] virtual void SASIDEV::Command() Command Byte 0: $00
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.336] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.336] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.336] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.336] [trace] virtual void SASIDEV::Command() Command Byte 4: $00
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.336] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.336] [trace] virtual void SCSIDEV::Execute() Execution phase command $00
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.336] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $00
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.336] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing TestUnitReady ($00)
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.336] [trace] bool Disk::CheckReady() Disk is ready
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.336] [trace] void SASIDEV::Status() Status phase
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.336] [trace] void SASIDEV::Status() Status Phase $00
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.337] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.337] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.337] [trace] void SASIDEV::MsgIn() Starting Message in phase
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.337] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.337] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.337] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.337] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.337] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.337] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.337] [trace] virtual void SASIDEV::Command() Command Phase
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.337] [trace] virtual void SASIDEV::Command() Command Byte 0: $1A
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.337] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.337] [trace] virtual void SASIDEV::Command() Command Byte 2: $01
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.337] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.338] [trace] virtual void SASIDEV::Command() Command Byte 4: $04
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.338] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.338] [trace] virtual void SCSIDEV::Execute() Execution phase command $1A
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.338] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $1A
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.338] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ModeSense6 ($1A)
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.338] [debug] Error status: Sense Key $05, ASC $24, ASCQ $00
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.338] [trace] virtual void Disk::ModeSense6(SASIDEV*) Unsupported mode page $01
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.338] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.338] [trace] void SASIDEV::Status() Status phase
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.338] [trace] void SASIDEV::Status() Status Phase $02
Dec 01 19:31:59 seascape-seastone RASCSI[550]: [2021-12-01 19:31:59.338] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 19:32:03 seascape-seastone RASCSI[550]: [2021-12-01 19:32:03.336] [trace] virtual void SCSIDEV::BusFree() Bus free phase

Dec 01 '21 19:12 lukexi

Here is a similar log for attempting to load a Roland ISO image attached at SCSI 6

pi@seascape-seastone:~ $ journalctl -u rascsi -f
-- Logs begin at Wed 2021-12-01 20:39:25 GMT. --
Dec 01 20:41:42 seascape-seastone RASCSI[548]: [2021-12-01 20:41:42.996] [info] Detached SCHD device with ID 6, unit 0
Dec 01 20:41:54 seascape-seastone RASCSI[548]: [2021-12-01 20:41:54.973] [info] Validating: operation=ATTACH, device id=6, unit=0, type=SCCD, device params='file=Roland_-_L-CD1_S-50_Factory_Library.iso', vendor='', product='', revision='', block size=0
Dec 01 20:41:54 seascape-seastone RASCSI[548]: [2021-12-01 20:41:54.976] [info] Executing: operation=ATTACH, device id=6, unit=0, type=SCCD, device params='file=Roland_-_L-CD1_S-50_Factory_Library.iso', vendor='', product='', revision='', block size=0
Dec 01 20:41:54 seascape-seastone RASCSI[548]: [2021-12-01 20:41:54.977] [info] Attached read-only SCCD device, ID 6, unit 0
Dec 01 20:42:19 seascape-seastone RASCSI[548]: [2021-12-01 20:42:19.694] [trace] Received SERVER_INFO command
Dec 01 20:42:19 seascape-seastone RASCSI[548]: [2021-12-01 20:42:19.711] [trace] Received DEVICES_INFO command
Dec 01 20:42:19 seascape-seastone RASCSI[548]: [2021-12-01 20:42:19.716] [trace] Received DEVICE_TYPES_INFO command
Dec 01 20:42:19 seascape-seastone RASCSI[548]: [2021-12-01 20:42:19.726] [trace] Received DEFAULT_IMAGE_FILES_INFO command
Dec 01 20:42:19 seascape-seastone RASCSI[548]: [2021-12-01 20:42:19.731] [trace] Received SERVER_INFO command
Dec 01 20:42:19 seascape-seastone RASCSI[548]: [2021-12-01 20:42:19.948] [trace] Received NETWORK_INTERFACES_INFO command
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.111] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.111] [trace] virtual void SASIDEV::Command() Command Phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.111] [trace] virtual void SASIDEV::Command() CDB[0]=$03
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.111] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.111] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.111] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.111] [trace] virtual void SASIDEV::Command() CDB[4]=$0E
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.111] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.111] [trace] virtual void SCSIDEV::Execute() Execution phase command $03
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.111] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $03
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.111] [trace] virtual bool SCSICD::Dispatch(SCSIDEV*) Calling base class for dispatching $03
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.111] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing RequestSense ($03)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.111] [trace] virtual void Disk::RequestSense(SASIDEV*) Status $00, Sense Key $00, ASC $00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.111] [trace] void SASIDEV::DataIn() Going into Data-in Phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.112] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 14
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.112] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.112] [trace] void SASIDEV::Status() Status phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.112] [trace] void SASIDEV::Status() Status Phase $00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.112] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.112] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.112] [trace] void SASIDEV::MsgIn() Starting Message in phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.112] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.112] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.112] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.112] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.112] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.112] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.113] [trace] virtual void SASIDEV::Command() Command Phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.113] [trace] virtual void SASIDEV::Command() CDB[0]=$12
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.113] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.113] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.113] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.113] [trace] virtual void SASIDEV::Command() CDB[4]=$24
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.113] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.113] [trace] virtual void SCSIDEV::Execute() Execution phase command $12
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.113] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $12
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.113] [trace] virtual bool SCSICD::Dispatch(SCSIDEV*) Calling base class for dispatching $12
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.113] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Inquiry ($12)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.113] [trace] void SASIDEV::DataIn() Going into Data-in Phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.113] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 36
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.113] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.114] [trace] void SASIDEV::Status() Status phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.114] [trace] void SASIDEV::Status() Status Phase $00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.114] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.114] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.114] [trace] void SASIDEV::MsgIn() Starting Message in phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.114] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.114] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.114] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.114] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.114] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.114] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.114] [trace] virtual void SASIDEV::Command() Command Phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.114] [trace] virtual void SASIDEV::Command() CDB[0]=$03
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.114] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] virtual void SASIDEV::Command() CDB[4]=$0E
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] virtual void SCSIDEV::Execute() Execution phase command $03
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $03
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] virtual bool SCSICD::Dispatch(SCSIDEV*) Calling base class for dispatching $03
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing RequestSense ($03)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] virtual void Disk::RequestSense(SASIDEV*) Status $00, Sense Key $00, ASC $00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] void SASIDEV::DataIn() Going into Data-in Phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 14
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] void SASIDEV::Status() Status phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] void SASIDEV::Status() Status Phase $00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] void SASIDEV::MsgIn() Starting Message in phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.115] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [trace] virtual void SASIDEV::Command() Command Phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [trace] virtual void SASIDEV::Command() CDB[0]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [trace] virtual void SASIDEV::Command() CDB[4]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [trace] virtual void SCSIDEV::Execute() Execution phase command $00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [trace] virtual bool SCSICD::Dispatch(SCSIDEV*) Calling base class for dispatching $00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing TestUnitReady ($00)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [trace] bool Disk::CheckReady() Disk is ready
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [trace] void SASIDEV::Status() Status phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [trace] void SASIDEV::Status() Status Phase $00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [trace] void SASIDEV::MsgIn() Starting Message in phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.116] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] virtual void SASIDEV::Command() Command Phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] virtual void SASIDEV::Command() CDB[0]=$15
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] virtual void SASIDEV::Command() CDB[4]=$0C
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] virtual void SCSIDEV::Execute() Execution phase command $15
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $15
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] virtual bool SCSICD::Dispatch(SCSIDEV*) Calling base class for dispatching $15
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ModeSelect6 ($15)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] virtual void Disk::ModeSelect6(SASIDEV*) Unsupported mode page $15
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] void SASIDEV::DataOut() Data out phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] virtual void SCSIDEV::Receive()
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.117] [trace] virtual void SCSIDEV::Receive() length was != 0
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.118] [trace] virtual void SCSIDEV::Receive()
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.118] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.118] [debug] Error status: Sense Key $05, ASC $26, ASCQ $00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.118] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.118] [trace] void SASIDEV::Status() Status phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.118] [trace] void SASIDEV::Status() Status Phase $02
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.118] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.118] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.118] [trace] void SASIDEV::MsgIn() Starting Message in phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.118] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.118] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.118] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.118] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.118] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.118] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] virtual void SASIDEV::Command() Command Phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] virtual void SASIDEV::Command() CDB[0]=$03
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] virtual void SASIDEV::Command() CDB[4]=$0E
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] virtual void SCSIDEV::Execute() Execution phase command $03
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $03
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] virtual bool SCSICD::Dispatch(SCSIDEV*) Calling base class for dispatching $03
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing RequestSense ($03)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] virtual void Disk::RequestSense(SASIDEV*) Status $00, Sense Key $05, ASC $26
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] void SASIDEV::DataIn() Going into Data-in Phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 14
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] void SASIDEV::Status() Status phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] void SASIDEV::Status() Status Phase $00
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] void SASIDEV::MsgIn() Starting Message in phase
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.119] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Dec 01 20:42:34 seascape-seastone RASCSI[548]: [2021-12-01 20:42:34.120] [trace] virtual void SCSIDEV::BusFree() Bus free phase

Dec 01 '21 20:12 lukexi

@lukexi Your issue can only be addressed if the data to be returned by the missing mode pages are known. Otherwise it is impossible to support these pages. Do you have any information on the structure of these mode pages?

Dec 01 '21 22:12 uweseimet

If I understand right 01 is "Read-Write Error Recovery" and 15 is "Completed" or "Extended", according to https://www.seagate.com/files/staticfiles/support/docs/manual/Interface%20manuals/100293068j.pdf (Page 59) and https://en.wikipedia.org/wiki/SCSI_mode_page — would it be enough to look at how SCSI2SD handles them, since it works very nicely with the ASR-10?

Dec 01 '21 23:12 lukexi

@lukexi If somebody should implement these pages it's best (in the case of well-documented pages) to use an official documentation. Looking at other software instead of the specification can result in potentially copying wrong or incomplete behavior. In case you know C++ I'd like to encourage you to give it a try yourself.

Dec 01 '21 23:12 uweseimet

C++ isn't the issue, understanding SCSI is : )

(especially since I can't seem to access any of the documents on t10.org... will do my best though!)

@rdmark suggested these might be spurious errors as well — I assume someone more familiar with RaSCSI and SCSI can suss that out quicker than I can at the moment (from what I could tell from perusing SCSI2SD it handles neither of these mode pages specially, though I could be wrong...).

Dec 02 '21 00:12 lukexi

Okay, I think I've found the first issue — according to Oracle and IBM we should be truncating responses to Mode Sense to the requested data length. Instead here https://github.com/akuker/RASCSI/blob/master/src/raspberrypi/devices/disk.cpp#L796 RaSCSI is erroring out if we have more data to send than the request.

Deleting lines 796-802 to remove that check + the attempt to change length to fit our data, and truncating instead (i.e. returning the same length requested) lets me get quite a bit further, with the format seeming to complete after a few minutes with no errors on RaSCSI's side, though then failing again on the ASR with a new message "Bad Device ID" that I'll start investigating now.

Dec 02 '21 01:12 lukexi

@lukexi Yes, this may indeed be an issue with how RaSCSI handles the length. There is also an indication about an issue with the length in the logs. Would be great if you could create a PR (against the develop branch) as soon as you have identified/fixed the issue. Regarding the T10 documents, the final specifications need a registration, but you can download the latest drafts, which are totally fine for our purposes. And there are also free download sites for some of the specs, just search for the document names on Google.

Dec 02 '21 09:12 uweseimet

@lukexi Any news on this? You sounded as if you could prepare a PR in order to address at least a part of this issue.

Dec 14 '21 14:12 uweseimet

Hi Uwe, I haven't had a time to do a second dive yet — I'm hoping to figure out the final issue on the ASR-10 (since what I've done so far seems to only half-fix it) before I send a pull request. Should have some time to dig in again in the next week or two!

Dec 16 '21 22:12 lukexi

@lukexi Any news? Note that your issue may be related to https://github.com/akuker/RASCSI/issues/614. There currently is a bugfix branch fix_mode_sense. It would be very helpful if you could test against this branch asap.

Jan 18 '22 11:01 uweseimet

@lukexi The latest MODE SENSE changes are now available in the develop branch. Can you please test with this branch and provide feedback?

Jan 20 '22 15:01 uweseimet

@uweseimet hello!! I had a chance to test the develop branch just now and while I can confirm that it provides the same progress my experimental patch did, the ASR still fails with "Bad Device ID" after seeming to make it through the formatting process, suggesting either that formatting wasn't successful or that the disk isn't being read successfully (according to https://www.chickensys.com/ensoniq/epsasr/005.html), so something's still not quite right...

Jan 21 '22 23:01 lukexi

@lukexi Whenever something is not expected please add a rascsi log on trace level, covering the operation that failed. By the way, just like with real SCSI drives there should not be any need to format a drive on SCSI level, just creating the filesystems should be sufficient. Formatting on SCSI level is only required in case a drive has bad sectors, so that during formatting the drive can map those to spare sectors. In the case of RaSCSI there cannot really be bad sectors, so formatting is even less relevant with RaSCSI than it is for real SCSI drives.

Jan 21 '22 23:01 uweseimet

yep, I'm running the trace right now : ) — will post as soon as it's done. (I don't think there's an option to just create the filesystem on the ASR, it's part of the formatting process as far as I know)

Jan 21 '22 23:01 lukexi

@lukexi Please try to limit the trace log to the relevant part (most likely the SCSI FORMAT command and some commands executed after it), if possible.

Jan 21 '22 23:01 uweseimet

Sure thing — here's the beginning

[trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$03
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$0E
[trace] virtual void SASIDEV::Command() CDB[5]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $03
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $03
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing RequestSense ($03)
[trace] virtual void Disk::RequestSense(SASIDEV*) Status $00, Sense Key $00, ASC $00
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 14
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$12
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$24
[trace] virtual void SASIDEV::Command() CDB[5]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $12

SNIP and transitioning from formatting to reading...

[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $2A
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Write10 ($2A)
[debug] virtual void Disk::Write10(SASIDEV*) WRITE(10) command record=$00005E21 blocks=1
[trace] bool Disk::CheckReady() Disk is ready
[trace] void SASIDEV::DataOut() Data out phase
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$2A
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$5E
[trace] virtual void SASIDEV::Command() CDB[5]=$22
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$01
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $2A
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $2A
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Write10 ($2A)
[debug] virtual void Disk::Write10(SASIDEV*) WRITE(10) command record=$00005E22 blocks=1
[trace] bool Disk::CheckReady() Disk is ready
[trace] void SASIDEV::DataOut() Data out phase
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$00
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$5E
[trace] virtual void SASIDEV::Command() CDB[8]=$23
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000000 blocks=24099
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 0
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] bool SASIDEV::XferIn(BYTE*) ctrl.cmd[0]=28
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 1
[trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 24098
[trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 24098
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] bool SASIDEV::XferIn(BYTE*) ctrl.cmd[0]=28
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready

SNIP and the end.

[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 32
[trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 3
[trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 3
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] bool SASIDEV::XferIn(BYTE*) ctrl.cmd[0]=28
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 33
[trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 2
[trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 2
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] bool SASIDEV::XferIn(BYTE*) ctrl.cmd[0]=28
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 34
[trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 1
[trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 1
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$00
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $00
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $00
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing TestUnitReady ($00)
[trace] bool Disk::CheckReady() Disk is ready
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$01
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$01
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000001 blocks=1
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 1
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$01
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$01
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000001 blocks=1
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 1
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase

Jan 21 '22 23:01 lukexi

A bit more information — testing with a 1 megabyte disk image, the format seems to complete successfully (DISK COMMAND COMPLETED) — great! But then fails with "FILE OPERATION ERROR" when trying to write either the OS or a simple instrument file to the SCSI drive.

Log of trying to write a file to the disk

[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$00
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $00
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $00
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing TestUnitReady ($00)
[trace] bool Disk::CheckReady() Disk is ready
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$12
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$04
[trace] virtual void SASIDEV::Command() CDB[5]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $12
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $12
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Inquiry ($12)
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 4
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$05
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$01
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000005 blocks=1
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 5
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$2A
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$05
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$01
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $2A
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $2A
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Write10 ($2A)
[debug] virtual void Disk::Write10(SASIDEV*) WRITE(10) command record=$00000005 blocks=1
[trace] bool Disk::CheckReady() Disk is ready
[trace] void SASIDEV::DataOut() Data out phase
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase

SNIP

[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$0A
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$01
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$0000000A blocks=1
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 10
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$2A
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$01
[trace] virtual void SASIDEV::Command() CDB[5]=$46
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$7F
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $2A
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $2A
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Write10 ($2A)
[debug] virtual void Disk::Write10(SASIDEV*) WRITE(10) command record=$00000146 blocks=127
[trace] bool Disk::CheckReady() Disk is ready
[trace] void SASIDEV::DataOut() Data out phase
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)
[trace] bool Disk::CheckReady() Disk is ready
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)
[trace] bool Disk::CheckReady() Disk is ready
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)

SNIP

[trace] bool Disk::CheckReady() Disk is ready
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$01
[trace] virtual void SASIDEV::Command() CDB[5]=$46
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$7F
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000146 blocks=127
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 70
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] bool SASIDEV::XferIn(BYTE*) ctrl.cmd[0]=28
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 71
[trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 126
[trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 126
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] bool SASIDEV::XferIn(BYTE*) ctrl.cmd[0]=28
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 72
[trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 125
[trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 125
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] bool SASIDEV::XferIn(BYTE*) ctrl.cmd[0]=28
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 73
[trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 124
[trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 124
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] bool SASIDEV::XferIn(BYTE*) ctrl.cmd[0]=28
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready

SNIP

[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 195
[trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 2
[trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 2
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] bool SASIDEV::XferIn(BYTE*) ctrl.cmd[0]=28
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 196
[trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 1
[trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 1
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$2A
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$02
[trace] virtual void SASIDEV::Command() CDB[5]=$45
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$7F
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $2A
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $2A
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Write10 ($2A)
[debug] virtual void Disk::Write10(SASIDEV*) WRITE(10) command record=$00000245 blocks=127
[trace] bool Disk::CheckReady() Disk is ready
[trace] void SASIDEV::DataOut() Data out phase
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)
[trace] bool Disk::CheckReady() Disk is ready
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)
[trace] bool Disk::CheckReady() Disk is ready

SNIP

[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)
[trace] bool Disk::CheckReady() Disk is ready
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$02
[trace] virtual void SASIDEV::Command() CDB[5]=$45
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$7F
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000245 blocks=127
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 69
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] bool SASIDEV::XferIn(BYTE*) ctrl.cmd[0]=28
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 70
[trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 126
[trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 126
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] bool SASIDEV::XferIn(BYTE*) ctrl.cmd[0]=28
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready

SNIP

[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 195
[trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 1
[trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 1
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$2A
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$02
[trace] virtual void SASIDEV::Command() CDB[5]=$44
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$7F
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $2A
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $2A
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Write10 ($2A)
[debug] virtual void Disk::Write10(SASIDEV*) WRITE(10) command record=$00000244 blocks=127
[trace] bool Disk::CheckReady() Disk is ready
[trace] void SASIDEV::DataOut() Data out phase
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)
[trace] bool Disk::CheckReady() Disk is ready
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)
[trace] bool Disk::CheckReady() Disk is ready

SNIP

[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$02
[trace] virtual void SASIDEV::Command() CDB[5]=$44
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$7F
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000244 blocks=127
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 68
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] bool SASIDEV::XferIn(BYTE*) ctrl.cmd[0]=28
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready

SNIP

[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 194
[trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 1
[trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 1
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$2A
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$03
[trace] virtual void SASIDEV::Command() CDB[5]=$43
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$37
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $2A
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $2A
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Write10 ($2A)
[debug] virtual void Disk::Write10(SASIDEV*) WRITE(10) command record=$00000343 blocks=55
[trace] bool Disk::CheckReady() Disk is ready
[trace] void SASIDEV::DataOut() Data out phase
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)
[trace] bool Disk::CheckReady() Disk is ready
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)
[trace] bool Disk::CheckReady() Disk is ready

SNIP

[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$03
[trace] virtual void SASIDEV::Command() CDB[5]=$43
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$37
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000343 blocks=55
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 67
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] bool SASIDEV::XferIn(BYTE*) ctrl.cmd[0]=28
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 68
[trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 54
[trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 54
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] bool SASIDEV::XferIn(BYTE*) ctrl.cmd[0]=28
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 69
[trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 53
[trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 53
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] bool SASIDEV::XferIn(BYTE*) ctrl.cmd[0]=28
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 70
[trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 52
[trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 52
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] bool SASIDEV::XferIn(BYTE*) ctrl.cmd[0]=28
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)

SNIP

[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 120
[trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 2
[trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 2
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] bool SASIDEV::XferIn(BYTE*) ctrl.cmd[0]=28
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 121
[trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 1
[trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 1
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$2A
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$0A
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$01
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $2A
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $2A
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Write10 ($2A)
[debug] virtual void Disk::Write10(SASIDEV*) WRITE(10) command record=$0000000A blocks=1
[trace] bool Disk::CheckReady() Disk is ready
[trace] void SASIDEV::DataOut() Data out phase
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() length is 512
[trace] virtual void SCSIDEV::Receive()
[trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
[trace] virtual bool Disk::Write(const DWORD*, const BYTE*, DWORD)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$05
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$01
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000005 blocks=1
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 5
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$06
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$01
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000006 blocks=1
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 6
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$07
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$01
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000007 blocks=1
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 7
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$06
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$01
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000006 blocks=1
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 6
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$07
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$01
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000007 blocks=1
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 7
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$06
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$01
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000006 blocks=1
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 6
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$07
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$01
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000007 blocks=1
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 7
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$06
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$01
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000006 blocks=1
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 6
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase
[trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[trace] virtual void SASIDEV::Command() Command Phase
[trace] virtual void SASIDEV::Command() CDB[0]=$28
[trace] virtual void SASIDEV::Command() CDB[1]=$00
[trace] virtual void SASIDEV::Command() CDB[2]=$00
[trace] virtual void SASIDEV::Command() CDB[3]=$00
[trace] virtual void SASIDEV::Command() CDB[4]=$00
[trace] virtual void SASIDEV::Command() CDB[5]=$07
[trace] virtual void SASIDEV::Command() CDB[6]=$00
[trace] virtual void SASIDEV::Command() CDB[7]=$00
[trace] virtual void SASIDEV::Command() CDB[8]=$01
[trace] virtual void SASIDEV::Command() CDB[9]=$00
[trace] virtual void SCSIDEV::Execute() Execution phase command $28
[debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $28
[debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read10 ($28)
[debug] virtual void Disk::Read10(SASIDEV*) READ(10) command record=$00000007 blocks=1
[trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
[trace] bool Disk::CheckReady() Disk is ready
[trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 7
[trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
[trace] void SASIDEV::DataIn() Going into Data-in Phase
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
[trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[trace] void SASIDEV::Status() Status phase
[trace] void SASIDEV::Status() Status Phase $00
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[trace] void SASIDEV::MsgIn() Starting Message in phase
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[trace] void SASIDEV::MsgIn() Transitioning to Send()
[trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[trace] virtual void SCSIDEV::BusFree() Bus free phase

Jan 22 '22 00:01 lukexi

@lukexi I'm afraid there is no SCSI FORMAT command anywhere, unless I missed it. In addition, the logs do not appear to contain show any error.

Jan 22 '22 09:01 uweseimet

@lukexi Can you please check my last comment from January and double-check? Regarding mode page 1, with the current release 22.07.02 or the develop branch it should be returned. Can you please verify?

Aug 27 '22 06:08 uweseimet

@lukexi Just a reminder: If there is no feedback we will have to close this ticket because it is unresolvable without feedback and it is not even clear, if the problem still exists.

Sep 01 '22 05:09 uweseimet

Thanks Uwe! I had it on my todo list, I'll get down to check it out on the ASR it in the next few days!

Sep 01 '22 05:09 lukexi

@lukexi Sounds good!

Sep 01 '22 05:09 uweseimet

@uweseimet I just got my Pi rebuilt on the latest develop branch and we're still ending the format with "Bad Device ID" on the ASR-10. I'll run another format with tracing enabled and post it here when done!

Sep 04 '22 03:09 lukexi

With [trace] level debugging, we get a different error on the ASR shortly after beginning formatting, "Unconnected SCSI device". Here's the end of that log with a visible error...

[2022-09-04 04:20:11.318] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $2A
[2022-09-04 04:20:11.318] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Write10 ($2A)
[2022-09-04 04:20:11.318] [trace] bool Disk::CheckAndGetStartAndCount(uint64_t&, uint32_t&, Disk::access_mode) READ/WRITE/VERIFY/SEEK command record=$00000173 blocks=1
[2022-09-04 04:20:11.318] [trace] void PrimaryDevice::CheckReady() Device is ready
[2022-09-04 04:20:11.318] [trace] virtual void ScsiController::DataOut() Data out phase
[2022-09-04 04:20:11.318] [trace] virtual BUS::phase_t ScsiController::Process(int) Initiator ID is 3
[2022-09-04 04:20:11.318] [trace] void ScsiController::Receive()
[2022-09-04 04:20:11.318] [trace] void ScsiController::Receive() Length is 512 bytes
[2022-09-04 04:20:11.323] [trace] virtual BUS::phase_t ScsiController::Process(int) Initiator ID is 3
[2022-09-04 04:20:11.323] [trace] void ScsiController::Receive()
[2022-09-04 04:20:11.323] [trace] void ScsiController::Receive() ctrl.phase: 7 (dataout)
[2022-09-04 04:20:11.323] [trace] virtual void Disk::Write(const DWORD*, BYTE*, uint64_t)
[2022-09-04 04:20:11.323] [trace] virtual void ScsiController::Status() Status Phase $00
[2022-09-04 04:20:11.323] [trace] virtual BUS::phase_t ScsiController::Process(int) Initiator ID is 3
[2022-09-04 04:20:11.323] [trace] void ScsiController::Send() Sending handhake with offset 0, length 1
[2022-09-04 04:20:11.323] [trace] virtual BUS::phase_t ScsiController::Process(int) Initiator ID is 3
[2022-09-04 04:20:11.323] [trace] void ScsiController::Send() Move to next phase status (8)
[2022-09-04 04:20:11.323] [trace] virtual void ScsiController::MsgIn() Message In phase
[2022-09-04 04:20:11.323] [trace] virtual BUS::phase_t ScsiController::Process(int) Initiator ID is 3
[2022-09-04 04:20:11.323] [trace] virtual void ScsiController::MsgIn() Transitioning to Send()
[2022-09-04 04:20:11.323] [trace] void ScsiController::Send() Sending handhake with offset 0, length 1
[2022-09-04 04:20:11.323] [trace] virtual BUS::phase_t ScsiController::Process(int) Initiator ID is 3
[2022-09-04 04:20:11.323] [trace] virtual void ScsiController::MsgIn() Transitioning to Send()
[2022-09-04 04:20:11.324] [trace] void ScsiController::Send() Move to next phase msgin (9)
[2022-09-04 04:20:11.324] [trace] virtual void ScsiController::BusFree() Bus free phase
[2022-09-04 04:20:11.324] [trace] virtual BUS::phase_t ScsiController::Process(int) Initiator ID is 3
[2022-09-04 04:20:11.324] [trace] virtual void ScsiController::Selection() Selection Phase Target ID=0
[2022-09-04 04:20:11.502] [trace] virtual BUS::phase_t ScsiController::Process(int) Initiator ID is 3
[2022-09-04 04:20:11.502] [trace] virtual void ScsiController::Command() Command Phase
[2022-09-04 04:20:14.502] [error] virtual void ScsiController::Command() No command bytes received
[2022-09-04 04:20:14.502] [debug] Error status: Sense Key $0B, ASC $00, ASCQ $00
[2022-09-04 04:20:14.502] [trace] virtual void ScsiController::Error(scsi_defs::sense_key, scsi_defs::asc, scsi_defs::status) Error (to status phase)
[2022-09-04 04:20:14.502] [trace] virtual void ScsiController::Status() Status Phase $02
[2022-09-04 04:20:14.502] [trace] virtual BUS::phase_t ScsiController::Process(int) Initiator ID is 3
[2022-09-04 04:20:14.502] [trace] void ScsiController::Send() Sending handhake with offset 0, length 1
[2022-09-04 04:20:17.502] [trace] virtual void ScsiController::BusFree() Bus free phase

Sep 04 '22 03:09 lukexi

Dropping to [debug] fixes that, so we can at least see a debug trace which looks like this

[2022-09-04 04:24:01.283] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $03
[2022-09-04 04:24:01.283] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = PrimaryDevice; DWORD = unsigned int] Executing RequestSense ($03)
[2022-09-04 04:24:01.284] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $12
[2022-09-04 04:24:01.284] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = PrimaryDevice; DWORD = unsigned int] Executing Inquiry ($12)
[2022-09-04 04:24:01.285] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $03
[2022-09-04 04:24:01.286] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = PrimaryDevice; DWORD = unsigned int] Executing RequestSense ($03)
[2022-09-04 04:24:01.287] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $25
[2022-09-04 04:24:01.287] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing ReadCapacity10 ($25)
[2022-09-04 04:24:01.288] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $00
[2022-09-04 04:24:01.288] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = PrimaryDevice; DWORD = unsigned int] Executing TestUnitReady ($00)
[2022-09-04 04:24:01.289] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $28
[2022-09-04 04:24:01.289] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Read10 ($28)
[2022-09-04 04:24:02.139] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $00
[2022-09-04 04:24:02.139] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = PrimaryDevice; DWORD = unsigned int] Executing TestUnitReady ($00)
[2022-09-04 04:24:02.140] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $1A
[2022-09-04 04:24:02.140] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = ModePageDevice; DWORD = unsigned int] Executing ModeSense6 ($1A)
[2022-09-04 04:24:02.141] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $04
[2022-09-04 04:24:02.141] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing FormatUnit ($04)
[2022-09-04 04:24:02.141] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $1A
[2022-09-04 04:24:02.142] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = ModePageDevice; DWORD = unsigned int] Executing ModeSense6 ($1A)
[2022-09-04 04:24:02.142] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $12
[2022-09-04 04:24:02.142] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = PrimaryDevice; DWORD = unsigned int] Executing Inquiry ($12)
[2022-09-04 04:24:02.144] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $25
[2022-09-04 04:24:02.144] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing ReadCapacity10 ($25)
[2022-09-04 04:24:02.145] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $2A
[2022-09-04 04:24:02.145] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Write10 ($2A)
[2022-09-04 04:24:02.150] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $2A
[2022-09-04 04:24:02.150] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Write10 ($2A)
[2022-09-04 04:24:02.158] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $2A
[2022-09-04 04:24:02.158] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Write10 ($2A)
[2022-09-04 04:24:02.171] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $2A
[2022-09-04 04:24:02.171] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Write10 ($2A)
[2022-09-04 04:24:02.180] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $2A
[2022-09-04 04:24:02.180] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Write10 ($2A)
[2022-09-04 04:24:02.189] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $2A
[~48000 repeats]
[2022-09-04 04:26:17.400] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Write10 ($2A)
[2022-09-04 04:26:17.406] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $2A
[2022-09-04 04:26:17.406] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Write10 ($2A)
[2022-09-04 04:26:17.411] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $2A
[2022-09-04 04:26:17.411] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Write10 ($2A)
[2022-09-04 04:26:17.417] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $2A
[2022-09-04 04:26:17.417] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Write10 ($2A)
[2022-09-04 04:26:17.422] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $2A
[2022-09-04 04:26:17.422] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Write10 ($2A)
[2022-09-04 04:26:17.428] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $2A
[2022-09-04 04:26:17.428] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Write10 ($2A)
[2022-09-04 04:26:17.434] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $2A
[2022-09-04 04:26:17.434] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Write10 ($2A)
[2022-09-04 04:26:17.439] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $2A
[2022-09-04 04:26:17.439] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Write10 ($2A)
[2022-09-04 04:26:17.445] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $28
[2022-09-04 04:26:17.445] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Read10 ($28)
[2022-09-04 04:27:19.322] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $00
[2022-09-04 04:27:19.322] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = PrimaryDevice; DWORD = unsigned int] Executing TestUnitReady ($00)
[2022-09-04 04:27:19.323] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $28
[2022-09-04 04:27:19.323] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Read10 ($28)
[2022-09-04 04:27:19.330] [debug] ++++ CMD ++++ void ScsiController::Execute() Executing command $28
[2022-09-04 04:27:19.330] [debug] bool Dispatcher<T>::Dispatch(T*, DWORD) [with T = Disk; DWORD = unsigned int] Executing Read10 ($28)

Sep 04 '22 03:09 lukexi

@lukexi Thank you for the logs. Unless I have missed something the logs contain no error messages, and also do not contain the FORMAT command and also no MODE SENSE command for page 1. Can you please attach a log where these commands are visible? Maybe we should concentrate on the MODE SENSE for pages $01 and $15. My claim was that there should not be an error message when page $01 is requested, that this is what I would like to verify. Page $15 is not supported, so an error message is expected here. The commands for $28 (READ) and $2A (WRITE) are not that interested, they just read and write sectors.

Sep 04 '22 06:09 uweseimet

I see "Executing FormatUnit ($04)" in the [debug] log, line 18? I'll try running some more operations to get page 01 to trigger today!

Sep 04 '22 16:09 lukexi

And yes, there are no RaSCSI errors reported in the [debug] log, the error is on the ASR-10 at the end of the Formatting process, just after the final Read commands which I assume are checking that the format operation succeeded and it's not liking what it sees, suggesting RaSCSI is either not writing something correctly or sending back bad data during the reads I suppose.

Sep 04 '22 16:09 lukexi

@lukexi I'm afraid I cannot help with the format operation problem, if the rascsi logs do not reveal anything unusual. But if the mode page problem is gone (which appears to be the case) that's a step forwared. I suggest that you create a new ticket with the remaining (format) issue, so that this ticket can be closed. A new, more precise and up to date ticket about the remaining issue would make it easier for somebody to work on it. Do you agree with this approach?

Sep 04 '22 16:09 uweseimet

Yes very much so! I'll do a run through today and capture some precise logs and make an issue for each. Thanks for all your help!

Sep 04 '22 16:09 lukexi

piscsi piscsi copied to clipboard

Unsupported mode pages $01 and $15 / ASR-10 "File Operation Error"

Info

Describe the issue

piscsi
piscsi copied to clipboard