Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unsupported mode page $81 (actually $01) with SPARCstation IPC #614

Closed
xelalexv opened this issue Jan 16, 2022 · 20 comments · Fixed by #617
Closed

Unsupported mode page $81 (actually $01) with SPARCstation IPC #614

xelalexv opened this issue Jan 16, 2022 · 20 comments · Fixed by #617
Labels
bug Something isn't working

Comments

@xelalexv
Copy link

First off, great project! I'm still pretty stoked on how well this works!

Info

  • Which version of Pi are you using: Pi Zero W
  • Which github revision of software: 21.12.1, using official release ISO
  • Which board version: 68kmla 2.4a
  • Which computer is the RaSCSI connected to: SUN SPARCstation IPC (SUN 4/40)

Describe the issue

I'm mounting a Solaris 2.3 install CD-ROM ISO at id 6. This essentially works, and I can mount the CD from within SunOS. However, when I try booting from the CD, the boot process starts, but after a short while errors out and triggers a reboot from the internal HDD:

ok boot sd(0,6,2)
Booting from: sd(0,6,2) 
SunOS Release 5.3 Version Generic [UNIX(R) System V Release 4.0]
Copyright (c) 1983-1993, Sun Microsystems, Inc.
Cannot mount root on /sbus@1,f8000000/esp@0,800000/sd@6,0:c fstype ufs
panic: vfs_mountroot: cannot mount root
rebooting...
Booting from: sd(0,0,0)vmunix 
root on sd0a fstype 4.2

When this happens, the rascsi logs have this to say:

Jan 16 15:16:05 rascsi RASCSI[352]: [2022-01-16 15:16:05.165] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $08
Jan 16 15:16:05 rascsi RASCSI[352]: [2022-01-16 15:16:05.165] [trace] virtual bool SCSICD::Dispatch(SCSIDEV*) Calling base class for dispatching $08
Jan 16 15:16:05 rascsi RASCSI[352]: [2022-01-16 15:16:05.165] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing Read6 ($08)
Jan 16 15:16:05 rascsi RASCSI[352]: [2022-01-16 15:16:05.165] [debug] virtual void Disk::Read6(SASIDEV*) READ(6) command record=$00000000 blocks=1
Jan 16 15:16:05 rascsi RASCSI[352]: [2022-01-16 15:16:05.165] [trace] bool Disk::CheckReady() Disk is ready
Jan 16 15:16:05 rascsi RASCSI[352]: [2022-01-16 15:16:05.165] [trace] virtual int Disk::Read(const DWORD*, BYTE*, uint64_t)
Jan 16 15:16:05 rascsi RASCSI[352]: [2022-01-16 15:16:05.165] [trace] bool Disk::CheckReady() Disk is ready
Jan 16 15:16:05 rascsi RASCSI[352]: [2022-01-16 15:16:05.177] [trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 0
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:05.177] [trace] void Disk::Read(SASIDEV*, uint64_t) ctrl.length is 512
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:05.177] [trace] void SASIDEV::DataIn() Going into Data-in Phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:05.178] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 512
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:05.178] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:05.178] [trace] void SASIDEV::Status() Status phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:05.178] [trace] void SASIDEV::Status() Status Phase $00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:05.178] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:05.178] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:05.178] [trace] void SASIDEV::MsgIn() Starting Message in phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:05.179] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:05.179] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:05.179] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:05.179] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:05.179] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.191] [trace] Received DEVICES_INFO command
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.204] [trace] Received CHECK_AUTHENTICATION command
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.455] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.455] [trace] void SCSIDEV::MsgOut() ID 6
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.455] [trace] Message Out Phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] void SCSIDEV::MsgOut() ID 6
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] virtual void SCSIDEV::Receive()
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] virtual void SCSIDEV::Receive() length is 1
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] void SCSIDEV::MsgOut() ID 6
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] virtual void SCSIDEV::Receive()
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] Message code IDENTIFY $C0, LUN 0 selected
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] virtual void SASIDEV::Command() Command Phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] virtual void SASIDEV::Command() CDB[0]=$00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] virtual void SASIDEV::Command() CDB[4]=$00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] virtual void SCSIDEV::Execute() Execution phase command $00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] virtual bool SCSICD::Dispatch(SCSIDEV*) Calling base class for dispatching $00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing TestUnitReady ($00)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] bool Disk::CheckReady() Disk is ready
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] void SASIDEV::Status() Status phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] void SASIDEV::Status() Status Phase $00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.456] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.457] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.457] [trace] void SASIDEV::MsgIn() Starting Message in phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.457] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.457] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.457] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.457] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.457] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.458] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.458] [trace] void SCSIDEV::MsgOut() ID 6
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.458] [trace] Message Out Phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.458] [trace] void SCSIDEV::MsgOut() ID 6
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.458] [trace] virtual void SCSIDEV::Receive()
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.458] [trace] virtual void SCSIDEV::Receive() length is 1
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.458] [trace] void SCSIDEV::MsgOut() ID 6
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.458] [trace] virtual void SCSIDEV::Receive()
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.458] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.458] [trace] Message code IDENTIFY $C0, LUN 0 selected
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.458] [trace] virtual void SASIDEV::Command() Command Phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.458] [trace] virtual void SASIDEV::Command() CDB[0]=$1A
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [trace] virtual void SASIDEV::Command() CDB[2]=$81
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [trace] virtual void SASIDEV::Command() CDB[4]=$14
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [trace] virtual void SCSIDEV::Execute() Execution phase command $1A
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $1A
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [trace] virtual bool SCSICD::Dispatch(SCSIDEV*) Calling base class for dispatching $1A
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ModeSense6 ($1A)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [debug] Error status: Sense Key $05, ASC $24, ASCQ $00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [trace] virtual void Disk::ModeSense6(SASIDEV*) Unsupported mode page $81
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [trace] void SASIDEV::Status() Status phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [trace] void SASIDEV::Status() Status Phase $02
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [trace] void SASIDEV::MsgIn() Starting Message in phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.459] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.460] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.460] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.460] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.460] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.460] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.460] [trace] void SCSIDEV::MsgOut() ID 6
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.460] [trace] Message Out Phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.460] [trace] void SCSIDEV::MsgOut() ID 6
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.460] [trace] virtual void SCSIDEV::Receive()
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.460] [trace] virtual void SCSIDEV::Receive() length is 1
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.460] [trace] void SCSIDEV::MsgOut() ID 6
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.460] [trace] virtual void SCSIDEV::Receive()
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.460] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.460] [trace] Message code IDENTIFY $80, LUN 0 selected
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.460] [trace] virtual void SASIDEV::Command() Command Phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.460] [trace] virtual void SASIDEV::Command() CDB[0]=$03
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.461] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.461] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.461] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.461] [trace] virtual void SASIDEV::Command() CDB[4]=$14
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.461] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.461] [trace] virtual void SCSIDEV::Execute() Execution phase command $03
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.461] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $03
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.461] [trace] virtual bool SCSICD::Dispatch(SCSIDEV*) Calling base class for dispatching $03
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.461] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing RequestSense ($03)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.461] [trace] virtual void Disk::RequestSense(SASIDEV*) Status $00, Sense Key $05, ASC $24
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.461] [trace] void SASIDEV::DataIn() Going into Data-in Phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.461] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 20
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.461] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.461] [trace] void SASIDEV::Status() Status phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.461] [trace] void SASIDEV::Status() Status Phase $00
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.461] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.461] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.462] [trace] void SASIDEV::MsgIn() Starting Message in phase
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.462] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.462] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.462] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.462] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Jan 16 15:16:06 rascsi RASCSI[352]: [2022-01-16 15:16:06.462] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Jan 16 15:16:07 rascsi RASCSI[352]: [2022-01-16 15:16:07.346] [trace] Received DEVICES_INFO command
Jan 16 15:16:07 rascsi RASCSI[352]: [2022-01-16 15:16:07.368] [trace] Received CHECK_AUTHENTICATION command
Jan 16 15:16:07 rascsi RASCSI[352]: [2022-01-16 15:16:07.875] [trace] Received LOG_LEVEL command
Jan 16 15:16:07 rascsi RASCSI[352]: [2022-01-16 15:16:07.877] [info] Set log level to 'info'

I also burnt the ISO and tried with an actual CD-ROM drive, which works fine and boots up the installer as expected. I'm happy to provide more logs or test as required. Just let me know.

Again, thanks for a great project!

@uweseimet
Copy link
Contributor

uweseimet commented Jan 17, 2022

@xelalexv I just noticed that I might have confused the ID numbers used by SunOs: 0,6,2 is this SCSI ID 6 LUN 2, or is the "2" the SCSI ID and not the LUN? In the latter case, i.e. if it is indeed the CD-ROM that is affected, do you have information on the layout of mode page $81? This is a vendor-specific page, which is not covered by the SCSI standard.

@xelalexv
Copy link
Author

@uweseimet sd(0,6,2) is the device specifier as used in OpenBoot, and means ID 6 (typically used for CD-ROM), partition c. I need to research about mode page $81, I'm still a newb when it comes to SCSI.

@uweseimet
Copy link
Contributor

uweseimet commented Jan 17, 2022

@xelalexv The mode page layout may depend on the CD-ROM drive type. Can you add information about the CD-ROM model you were using for a successful boot attempt?
Note that I just deleted my very first comment, because it was misleading and is now obsolete.

@uweseimet
Copy link
Contributor

uweseimet commented Jan 17, 2022

@xelalexv I just checked the RASCSI implementation against the specification and found that RaSCSI does not correctly/fully log the mode page data. In your case the default values for mode page $01 were requested (and not mode page $81), which is something RaSCSI should be able to return.
I am going to update the logging output and then will try to fix what appears to be wrong. Are you prepared to run some tests on a feature branch?

@xelalexv
Copy link
Author

@uweseimet Sure, I'll gladly test! The CD-ROM drive is an external drive, labelled Plextor ULTRAPLEX 40max at the front, PX-40TSe at the bottom, and gets recognized by OpenBoot as this:

Target 6 
  Unit 0   Removable Read Only device     PLEXTOR CD-ROM PX-40TS  1.0504/06/01 01:05      

@uweseimet
Copy link
Contributor

uweseimet commented Jan 17, 2022

@xelalexv Can you please run a test with the "fix_mode_sense" branch? This branch contains updated logging on trace level, which should provide details on why RaSCSI returns a SCSI error. Mode page 1 is actually supported by RaSCSI, but for a yet unknown reason RaSCSI rejects the received command for this page. We just need the log for the MODE SENSE command.

@xelalexv
Copy link
Author

@uweseimet Here's the log output for MODE SENSE using the branch:

Jan 18 07:14:28 rascsi RASCSI[344]: [2022-01-18 07:14:09.233] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $1A
Jan 18 07:14:28 rascsi RASCSI[344]: [2022-01-18 07:14:09.233] [trace] virtual bool SCSICD::Dispatch(SCSIDEV*) Calling base class for dispatching $1A
Jan 18 07:14:28 rascsi RASCSI[344]: [2022-01-18 07:14:09.233] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ModeSense6 ($1A)
Jan 18 07:14:28 rascsi RASCSI[344]: [2022-01-18 07:14:09.234] [trace] int Disk::ModeSense6(const DWORD*, BYTE*) Mode page size 24 exceeds requested size 20
Jan 18 07:14:28 rascsi RASCSI[344]: [2022-01-18 07:14:09.234] [debug] Error status: Sense Key $05, ASC $24, ASCQ $00
Jan 18 07:14:28 rascsi RASCSI[344]: [2022-01-18 07:14:09.234] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Jan 18 07:14:28 rascsi RASCSI[344]: [2022-01-18 07:14:09.234] [trace] void SASIDEV::Status() Status phase
Jan 18 07:14:28 rascsi RASCSI[344]: [2022-01-18 07:14:09.234] [trace] void SASIDEV::Status() Status Phase $02
Jan 18 07:14:28 rascsi RASCSI[344]: [2022-01-18 07:14:09.235] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Jan 18 07:14:28 rascsi RASCSI[344]: [2022-01-18 07:14:09.235] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Jan 18 07:14:28 rascsi RASCSI[344]: [2022-01-18 07:14:09.235] [trace] void SASIDEV::MsgIn() Starting Message in phase
Jan 18 07:14:28 rascsi RASCSI[344]: [2022-01-18 07:14:09.235] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.235] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.235] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.235] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.235] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.235] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.235] [trace] void SCSIDEV::MsgOut() ID 6
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.235] [trace] Message Out Phase
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.236] [trace] void SCSIDEV::MsgOut() ID 6
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.236] [trace] virtual void SCSIDEV::Receive()
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.236] [trace] virtual void SCSIDEV::Receive() length is 1
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.236] [trace] void SCSIDEV::MsgOut() ID 6
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.236] [trace] virtual void SCSIDEV::Receive()
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.236] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.236] [trace] Message code IDENTIFY $80, LUN 0 selected
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.236] [trace] virtual void SASIDEV::Command() Command Phase
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.236] [trace] virtual void SASIDEV::Command() CDB[0]=$03
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.236] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.236] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.236] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.236] [trace] virtual void SASIDEV::Command() CDB[4]=$14
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.236] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Jan 18 07:14:29 rascsi RASCSI[344]: [2022-01-18 07:14:09.236] [trace] virtual void SCSIDEV::Execute() Execution phase command $03

@uweseimet
Copy link
Contributor

@xelalexv OK, so this is about the ALLOCATION LENGTH field in the CDB being less than the available data. Can you please try the latest fix_mode_sense branch? I just pushed an update. Regardless of the outcome I will have to double-check once more with the SCSI spec.

@uweseimet uweseimet changed the title Unsupported mode page $81 with SPARCstation IPC Unsupported mode page $81 (actually $01) with SPARCstation IPC Jan 18, 2022
@uweseimet uweseimet linked a pull request Jan 18, 2022 that will close this issue
@uweseimet uweseimet added the bug Something isn't working label Jan 18, 2022
@xelalexv
Copy link
Author

Here's the error with latest commit:

Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.733] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $15
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.733] [trace] virtual bool SCSICD::Dispatch(SCSIDEV*) Calling base class for dispatching $15
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.733] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ModeSelect6 ($15)
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.733] [trace] virtual void Disk::ModeSelect6(SASIDEV*) Unsupported mode page $15
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.733] [trace] void SASIDEV::DataOut() Data out phase
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.733] [trace] virtual void SCSIDEV::Receive()
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.733] [trace] virtual void SCSIDEV::Receive() length is 20
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.733] [trace] virtual void SCSIDEV::Receive()
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.733] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 7 (dataout)
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.733] [debug] Error status: Sense Key $05, ASC $26, ASCQ $00
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.733] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.733] [trace] void SASIDEV::Status() Status phase
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.733] [trace] void SASIDEV::Status() Status Phase $02
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.734] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.734] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.734] [trace] void SASIDEV::MsgIn() Starting Message in phase
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.734] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.734] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.734] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.734] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.734] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] void SCSIDEV::MsgOut() ID 6
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] Message Out Phase
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] void SCSIDEV::MsgOut() ID 6
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] virtual void SCSIDEV::Receive()
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] virtual void SCSIDEV::Receive() length is 1
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] void SCSIDEV::MsgOut() ID 6
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] virtual void SCSIDEV::Receive()
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] Message code IDENTIFY $80, LUN 0 selected
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] virtual void SASIDEV::Command() Command Phase
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] virtual void SASIDEV::Command() CDB[0]=$03
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] virtual void SASIDEV::Command() CDB[4]=$14
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Jan 18 12:37:44 rascsi RASCSI[351]: [2022-01-18 12:36:49.735] [trace] virtual void SCSIDEV::Execute() Execution phase command $03

@uweseimet
Copy link
Contributor

uweseimet commented Jan 18, 2022

@xelalexv This means that the original problem (with MODE SENSE) appears to be resolved. You have encountered a different issue now, related to MODE SELECT. I'm afraid I cannot provide any help with this. RaSCSI currently does not support any MODE SELECT functionality.
The only thing I can do is to create a PR for the original MODE SENSE problem, in order for my changes to MODE SENSE to be added to the develop branch.
Regarding MODE SELECT I suggest that you create a new ticket, only containing information (the log above) related to MODE SELECT. Can you please also add the lines before your logfile excerpt to this new ticket, where the 6 bytes of the CDB are logged?

@xelalexv
Copy link
Author

@uweseimet Ah, didn't notice that the error this time happened with MODE SELECT. I'll open a new ticket. Thanks for resolving the MODE SENSE issue!

@uweseimet
Copy link
Contributor

uweseimet commented Jan 18, 2022

@xelalexv Sounds good! Can you run one more test, please? Please start rascsi with the "-b 512" option for your emulated CD-ROM drive. This will set the block size to 512 bytes instead of the default size of 2048 bytes. Old SunOS versions require this. I doubt that it will make a difference in your case, but it is worth trying.

@xelalexv
Copy link
Author

You're right, and I'm already attaching the ISO with 512 bytes block size. For my very first try, I used the GUI to attach the ISO, and didn't notice that it uses 2048 bytes there. In that case it errored out much earlier. After realizing that, I've been using rasctl to attach and specified -b 512.

@uweseimet
Copy link
Contributor

uweseimet commented Jan 18, 2022

@xelalexv Which error is reported by RaSCSI when using 2048 bytes? 512 bytes is only required by old versions of SunOS as far as I know. Solaris should be fine with 2048 bytes. I would not be surprised if the failing MODE SELECT is dealing with trying to modify the CD-ROM's sector size setting from 512 to 2048 bytes. So maybe checking what goes wrong with 2048 bytes and assuming that 2048 bytes is actually the correct setting is more promising. It might be the case that with 2048 bytes per sector MODE SELECT is not even used at all, because no configuration change is required.
By the way, I have the same Plextor CD-ROM drive as you (sometimes connected to my Atari), and the default sector size for this drive is definitely 2048 bytes. I doubt that it supports 512 bytes per sector at all.

@xelalexv
Copy link
Author

@uweseimet I did not check for the RaSCSI logs during my first trial, but can re-run that test. It may be possible to access the CD-ROM with 2048 from SunOS, not sure, but I can check that too. But booting from CD-ROM definitely requires 512 bytes. That's a reason why I bought this particular Plextor drive, because it has a DIP switch in the back for switching between 512 and 2048.

@uweseimet
Copy link
Contributor

uweseimet commented Jan 18, 2022

@xelalexv It has a DIP switch for that? I did not know/expect that. Which one is it (in case there are several)? It might be useful for me to know that because I have the same drive, this is why I am asking. My Atari might be able to boot from this drive with 512 byters per sector. Usually Ataris can only boot from hard disk drives, because the OS does not support other sector sizes than 512 bytes during the boot stage.
Correct me if I am wrong, but what you say is that Solaris can only boot from this drive whey you set the DIP switch to 512 instead of 2048 per sector? In this case there may not be no way to boot Solaris from RaSCSI without a working MODE SELECT.

@uweseimet
Copy link
Contributor

@xelalexv Just found the jumper settings in the manual. Must be the BLOCK jumper.

@xelalexv
Copy link
Author

Yes, it's the BLOCK switch. And yes, SunOS and older Solaris versions (don't know about the later ones) can only boot with 512 bytes. I've just tried attaching the ISO in RaSCSI with 2048 bytes, booted into SunOS from the internal HDD, and tried to mount the CD-ROM, but that didn't work. SunOS complains:

nd1 / 9% mount -t hsfs -o ro /dev/sr0 /mnt
esp0:   data transfer overrun
        State=DATA Last State=DATA_DONE
        Latched stat=0x11<XZERO,IO> intr=0x10<BUS> fifo 0x0
        last msg out: <unknown msg 0xff>; last msg in: COMMAND COMPLETE
        DMA csr=0x80000000
        addr=fff31000 last=fff22000 last_count=f000
        Cmd dump for Target 6 Lun 0:
        cdb=[ 0x8 0x0 0x0 0x0 0xf8 0x0 ]
        pkt_state 0xf<XFER,CMD,SEL,ARB> pkt_flags 0x0 pkt_statistics 0x0
        cmd_flags=0x21 cmd_timeout 180
        Mapped Dma Space:
                Base = 0x12000 Count = 0x1f000
        Transfer History:
                Base = 0x12000 Count = 0x1f000
sr0:    SCSI transport failed: reason 'data_ovr': retrying command

In the RaSCSI logs, there's this error:

Jan 18 16:01:08 rascsi RASCSI[8863]: [2022-01-18 16:00:59.558] [trace] bool Disk::CheckReady() Disk is ready
Jan 18 16:01:08 rascsi RASCSI[8863]: [2022-01-18 16:00:59.558] [trace] bool DiskTrack::ReadSector(BYTE*, int) const reading sector: 62
Jan 18 16:01:08 rascsi RASCSI[8863]: [2022-01-18 16:00:59.558] [trace] virtual void SCSIDEV::Send() Processing after data collection. Blocks: 186
Jan 18 16:01:08 rascsi RASCSI[8863]: [2022-01-18 16:00:59.559] [trace] virtual void SCSIDEV::Send() Continuing to send. Blocks: 186
Jan 18 16:01:08 rascsi RASCSI[8863]: [2022-01-18 16:00:59.559] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 2048
Jan 18 16:01:08 rascsi RASCSI[8863]: [2022-01-18 16:01:00.132] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Jan 18 16:01:08 rascsi RASCSI[8863]: [2022-01-18 16:01:00.132] [trace] void SASIDEV::Status() Status phase
Jan 18 16:01:08 rascsi RASCSI[8863]: [2022-01-18 16:01:00.132] [trace] void SASIDEV::Status() Status Phase $02
Jan 18 16:01:08 rascsi RASCSI[8863]: [2022-01-18 16:01:00.132] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Jan 18 16:01:08 rascsi RASCSI[8863]: [2022-01-18 16:01:03.132] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Jan 18 16:01:08 rascsi RASCSI[8863]: [2022-01-18 16:01:03.132] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
Jan 18 16:01:08 rascsi RASCSI[8863]: [2022-01-18 16:01:03.132] [trace] void SCSIDEV::MsgOut() ID 6
Jan 18 16:01:08 rascsi RASCSI[8863]: [2022-01-18 16:01:03.133] [trace] Message Out Phase

If I try to boot with this setup, I get a complaint from OpenBoot:

ok boot sd(0,6,2)
Booting from: sd(0,6,2) 

Bad magic number in disk label!
The file just loaded does not appear to be executable.

No errors in the RaSCSI log.

@uweseimet
Copy link
Contributor

@xelalexv "data transfer overrun" most likely refers to the fact that without -b 512 RaSCSI wants to transfer more data (2048 bytes) than expected (512 bytes). So without a working MODE SELECT there appears to be no way indeed to boot Solaris from RaSCSI.

@uweseimet
Copy link
Contributor

Merged into develop branch.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants