search

PiSCSI / piscsi

PiSCSI allows a Raspberry Pi to function as emulated SCSI devices (hard disk, CD-ROM, and others) for vintage SCSI-based computers and devices. This is a fork of the RaSCSI project by GIMONS.
https://piscsi.org
BSD 3-Clause "New" or "Revised" License
537 stars 82 forks source link

DaynaPort interface not recognized on Mac Plus on "develop" branch #750

Closed marciot closed 2 years ago

marciot commented 2 years ago

Info

Describe the issue

I've recently upgraded my RaSCSI to the latest "develop" code and I'm running into a couple issues. I was previously using cf9a578c82160eafa79ce36b9cc27457de5fd254

Some disk images no longer mount

Some disk images that previously worked fine no longer appear in my Mac Plus. Others still work as expected. I don't have any more info to go on, but am curious if something about the way disk images are presented to the host changed.

Disk image with MacTCP and DaynaPort drivers pre-installed no longer works

This is similar to the issue above. I used to have a disk image with MacTCP and DaynaPort drivers pre-installed. Now this image starts up, but fails to initialize the network.

Update: I tried starting from scratch, with a new disk image, a new System 7.1 install, then followed the steps on this page. On the step in which I install the DaynaPort 7.5.3 drivers, the installer says "Please install your DaynaPort hardware, or make sure the hardware is installed correctly". If I switch to Custom Install, I can force and install of the "DaynaPort SCSI/Link" but the device will not work.

No longer able to enable DaynaPort device in Web UI without a bridge

With the older versions of RaSCSI, it was possible to start the DaynaPort device without configuring a network bridge. It was then possible to secure shell into the RaSCSI and use port forwarding to connect to services running on the Macintosh via the "private" IP address. I used it this way because I had my RaSCSI configured in a DMZ, also acting as a web server, and I did not want to expose the Mac to the network at large.

With the latest version in "develop", it brings up a message "Configure IPv4 forwarding before using a wireless network device. Please follow the instructions at https://github.com/akuker/RASCSI/wiki/Dayna-Port-SCSI-Link" and then refuses to start up the DynaPort device.

Though this isn't a bug per se, I feel like this is a regression because it is assuming the user wants to do things a certain way. Anyhow, configuring the device as a bridge did resolve the message, but I feel like this message should be a suggestion rather than blocking the user from connecting the device.

pendleton115 commented 2 years ago

I am having the same problem on my hardware, Macintosh Classic, I've tried System 7.0.1, and 7.5.3. The Dayna Port hardware is not detected in the installer but shows up in SCSI Probe and the DaynaPort Hardware Diagnostic.

rdmark commented 2 years ago

@marciot Please separate each of your issues into separate tickets! This is the only way to cleanly track and troubleshoot each of them.

With regards to the third issue, this is something that we introduced in the stable November release last year. See https://github.com/akuker/RASCSI/issues/407 . The reason that we're doing it like this is that if you don't have the bridge configured, attaching a network device may disrupt the Pi's network connectivity. A user who's not familiar with Linux networking may end up with a non-functional environment at that point. You may still attach it via rasctl if you know what you're doing.

The real solution to this would be to change the logic in the rascsi backend to somehow be aware of the network environment and act accordingly.

marciot commented 2 years ago

I am going through the process of testing individual releases to see whether the DaynaPort drivers break. It takes a few hours to compile each release, but I will update this table as I go along:

DaynaPort
develop (Bullseye) Fails
develop (Buster) Fails
v22.02.01 (Bullseye) OK
v22.02.01 (Buster) OK
v21.12.01 (Bullseye) OK
v21.11.01 (Bullseye) OK
v21.11.01 (Buster) OK
v21.10.01 (Buster) OK
marciot commented 2 years ago

Just an update on this thread. After trying a bunch of combinations, I think the only firm conclusion I came to is that the DaynaPort is not working on the develop branch for whatever reason. This is all. It works on all the release versions running on Buster and Bullseye, however.

I do not think there was anything in fact wrong with disk images. That was a red herring. There are a bazillion factors that go into whether or not a particular disk image will work on a given Mac and I must have gotten confused about which ones worked on the Mac Plus to start with. The images which I thought had stopped working after my upgrade also did not work with my old RaSCSI build when I tested them again, so you can disregard my suggestion that disk images had begun failing after my upgrade. This was false. I now think they never worked in the first place.

marciot commented 2 years ago

I am having the same problem on my hardware, Macintosh Classic, I've tried System 7.0.1, and 7.5.3. The Dayna Port hardware is not detected in the installer but shows up in SCSI Probe and the DaynaPort Hardware Diagnostic.

@pendleton115: I've confirmed that the "develop" branch is not working, but the tagged releases seem to work fine. Can you verify what checkout of RaSCSI you are using?

pendleton115 commented 2 years ago

I will have to check which version I am running, but I updated it recently using the "Easyinstall.sh" script. I would assume this would update to the most recent release build.

@pendleton115: I've confirmed that the "develop" branch is not working, but the tagged releases seem to work fine. Can you verify what checkout of RaSCSI you are using?

pendleton115 commented 2 years ago

Just checked, the version I am using is RaSCSI version: 22.3.-1 f2aa2db

rdmark commented 2 years ago

Ignore my previous comment. I could confirm that the DaynaPort device isn't able to initialize on neither my Classic II nor my SE. I The Classic II runs System 7.5.3 and Open Transport 1.1.4. The SE runs System 7.0.1 and MacTCP 2.1. Code is develop a684aa65ad2be67e740c0d761aac066c68d8a995

The DaynaPort device is recognized by the system and driver, but the moment we go and try to initialize it (e.g. launching MacTCP Ping) we get an error.

rdmark commented 2 years ago

This is a trace log from when I attempt to initialize the network interface on my SE.

Apr 21 05:51:28 rascsiZW RASCSI[361]: [2022-04-21 05:51:28.922] [trace] void SASIDEV::DataIn() Going into Data-in Phase
Apr 21 05:51:28 rascsiZW RASCSI[361]: [2022-04-21 05:51:28.922] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 18
Apr 21 05:51:28 rascsiZW RASCSI[361]: [2022-04-21 05:51:28.922] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
Apr 21 05:51:28 rascsiZW RASCSI[361]: [2022-04-21 05:51:28.922] [trace] void SASIDEV::Status() Status phase
Apr 21 05:51:28 rascsiZW RASCSI[361]: [2022-04-21 05:51:28.922] [trace] void SASIDEV::Status() Status Phase $00
Apr 21 05:51:28 rascsiZW RASCSI[361]: [2022-04-21 05:51:28.922] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
Apr 21 05:51:29 rascsiZW RASCSI[361]: [2022-04-21 05:51:28.923] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Apr 21 05:51:29 rascsiZW RASCSI[361]: [2022-04-21 05:51:28.923] [trace] void SASIDEV::MsgIn() Starting Message in phase
Apr 21 05:51:29 rascsiZW RASCSI[361]: [2022-04-21 05:51:28.923] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Apr 21 05:51:29 rascsiZW RASCSI[361]: [2022-04-21 05:51:28.923] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
Apr 21 05:51:29 rascsiZW RASCSI[361]: [2022-04-21 05:51:28.923] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Apr 21 05:51:29 rascsiZW RASCSI[361]: [2022-04-21 05:51:28.923] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Apr 21 05:51:29 rascsiZW RASCSI[361]: [2022-04-21 05:51:28.923] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.915] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=3 (with device)
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.916] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.916] [trace] virtual void SASIDEV::Command() Command Phase
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.916] [trace] virtual void SASIDEV::Command() CDB[0]=$00
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.916] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.916] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.916] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.916] [trace] virtual void SASIDEV::Command() CDB[4]=$00
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.917] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.917] [trace] virtual void SCSIDEV::Execute() Execution phase command $00
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.917] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $00
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.917] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = PrimaryDevice; U = SASIDEV] Executing TestUnitReady ($00)
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.917] [debug] Error status: Sense Key $02, ASC $3A, ASCQ $00
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.917] [trace] bool PrimaryDevice::CheckReady() Device not ready
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.917] [trace] virtual void SCSIDEV::Error(scsi_defs::sense_key, scsi_defs::asc, scsi_defs::status) Error (to status phase)
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.917] [trace] void SASIDEV::Status() Status phase
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.917] [trace] void SASIDEV::Status() Status Phase $02
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.917] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.917] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.917] [trace] void SASIDEV::MsgIn() Starting Message in phase
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.917] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.917] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.918] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.918] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.918] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.919] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=3 (with device)
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.919] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.919] [trace] virtual void SASIDEV::Command() Command Phase
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.920] [trace] virtual void SASIDEV::Command() CDB[0]=$03
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.920] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.920] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.920] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.920] [trace] virtual void SASIDEV::Command() CDB[4]=$12
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.920] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.920] [trace] virtual void SCSIDEV::Execute() Execution phase command $03
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.920] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $03
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.920] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = PrimaryDevice; U = SASIDEV] Executing RequestSense ($03)
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.920] [trace] virtual std::vector<unsigned char> PrimaryDevice::RequestSense(int) Status $00, Sense Key $00, ASC $3A
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.920] [trace] void SASIDEV::DataIn() Going into Data-in Phase
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.920] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 18
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.921] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.921] [trace] void SASIDEV::Status() Status phase
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.921] [trace] void SASIDEV::Status() Status Phase $00
Apr 21 05:51:30 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.921] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
Apr 21 05:51:31 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.921] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Apr 21 05:51:31 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.921] [trace] void SASIDEV::MsgIn() Starting Message in phase
Apr 21 05:51:31 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.921] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Apr 21 05:51:31 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.921] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
Apr 21 05:51:31 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.921] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Apr 21 05:51:31 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.921] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Apr 21 05:51:31 rascsiZW RASCSI[361]: [2022-04-21 05:51:30.921] [trace] virtual void SCSIDEV::BusFree() Bus free phase
rdmark commented 2 years ago

@uweseimet So it seems we have a regression bug in develop. I think this should be addressed before we cut a release. I'll keep trying to narrow down when the regression happened using binary search later this week (work is keeping me busy....)

uweseimet commented 2 years ago

@rdmark @marciot Yes, it would be good to know the commit that causes the problem.

rdmark commented 2 years ago

@uweseimet Through binary search I narrowed it down to this commit to develop: 1df7cdb1f3cc70fce9b163db2dad5eae8dc87520

uweseimet commented 2 years ago

@rdmark Is there any difference in the trace logs between this and the previous commit?

@marciot There are not many changes related to the DaynaPort in this commit, mainly regarding INQUIRY. Since you can reproduce the problem and know C++ you can probably find out what's wrong by reverting the DaynaPort changes step by step?

rdmark commented 2 years ago

An example trace log from the same stage when it initializes the network interface on the Mac.

[2022-04-25 09:12:43.448] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 09:12:43.448] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 09:12:43.448] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 09:12:43.448] [trace] virtual void SASIDEV::Command() CDB[0]=$12
[2022-04-25 09:12:43.448] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-25 09:12:43.448] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 09:12:43.448] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-25 09:12:43.448] [trace] virtual void SASIDEV::Command() CDB[4]=$25
[2022-04-25 09:12:43.448] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-25 09:12:43.448] [trace] virtual void SCSIDEV::Execute() Execution phase command $12
[2022-04-25 09:12:43.449] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $12
[2022-04-25 09:12:43.449] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = PrimaryDevice; U = SASIDEV] Executing Inquiry ($12)
[2022-04-25 09:12:43.449] [trace] void SASIDEV::DataIn() Going into Data-in Phase
[2022-04-25 09:12:43.449] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 37
[2022-04-25 09:12:43.449] [trace] virtual int GPIOBUS::SendHandShake(BYTE*, int, int) DELAYING for 100us after 6 bytes
[2022-04-25 09:12:43.449] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[2022-04-25 09:12:43.450] [trace] void SASIDEV::Status() Status phase
[2022-04-25 09:12:43.450] [trace] void SASIDEV::Status() Status Phase $00
[2022-04-25 09:12:43.450] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 09:12:43.450] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2022-04-25 09:12:43.450] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2022-04-25 09:12:43.450] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 09:12:43.450] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 09:12:43.450] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 09:12:43.450] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2022-04-25 09:12:43.450] [trace] virtual void SCSIDEV::BusFree() Bus free phase
[2022-04-25 09:12:43.451] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 09:12:43.451] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 09:12:43.451] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 09:12:43.451] [trace] virtual void SASIDEV::Command() CDB[0]=$0E
[2022-04-25 09:12:43.451] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-25 09:12:43.451] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 09:12:43.451] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-25 09:12:43.451] [trace] virtual void SASIDEV::Command() CDB[4]=$00
[2022-04-25 09:12:43.451] [trace] virtual void SASIDEV::Command() CDB[5]=$80
[2022-04-25 09:12:43.452] [trace] virtual void SCSIDEV::Execute() Execution phase command $0E
[2022-04-25 09:12:43.452] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $0E
[2022-04-25 09:12:43.452] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = SCSIDaynaPort; U = SASIDEV] Executing EnableInterface ($0E)
[2022-04-25 09:12:43.452] [debug] bool CTapDriver::Enable(): ip link set ras0 up
[2022-04-25 09:12:43.452] [info] The DaynaPort interface has been ENABLED.
rdmark commented 2 years ago

@uweseimet The differences that I see between a failed and successful process is that different commands are being executed by Dispatcher. The failed case executes TestUnitReady and RequestSense which I couldn't find anywhere in the successful case. The successful case executes Inquiry and EnableInterface.

This could be that I'm looking at different spots in the logs, but I tried to capture them right around where it tries to initialize the interface, so they should be equivalent.

I've been capturing longer logs but only posting the parts that seem relevant.

marciot commented 2 years ago

@marciot There are not many changes related to the DaynaPort in this commit, mainly regarding INQUIRY. Since you can reproduce the problem and know C++ you can probably find out what's wrong by reverting the DaynaPort changes step by step?

I won't have the time to work on this until next weekend, and even then I am hobbled by the fact that it takes several hours to compile RaSCSI on my Raspberry Pi Zero W, due to the swap issue I mentioned earlier. If anyone wants to donate a Raspberry Pi 4 to the cause it would definitely help (not that there are any in stock anywhere right now).

marciot commented 2 years ago

I would think a sensible approach for this bug is to revert this entire commit and then separate out the INQUIRY changes from all the other code refactoring changes.

Basically with the Raspberry Pi Zero W being as slow as it is, it would be very helpful if I didn't have to wade through all the syntax errors I would run into if I tried separating out the INQUIRY stuff myself.

uweseimet commented 2 years ago

@marciot We cannot revert, because other commits are based on it, and reverting it causes numerous conflicts.

marciot commented 2 years ago

Well, I'll see what I can do this weekend. But like I said, any preliminary work that can be done in advance on a more capable Raspberry Pi would be very helpful.

uweseimet commented 2 years ago

@rdmark I will have a look at the logs, maybe I can find something. Currently I don't have a working network setup, so that I can't test myself.

uweseimet commented 2 years ago

@rdmark Looks as if your log contains the INQUIRY and the first (@marciot's) log does not? Can you attach the INQUIRY log for both commits, i.e. the commits with and without the bug? The first difference in these logs might reveal important information.

uweseimet commented 2 years ago

@marciot What about setitng up a cross-compilation environment? That would even be faster than a Pi 4.

rdmark commented 2 years ago

@uweseimet do you mean the section of the log that begins with [2022-04-25 09:12:43.449] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = PrimaryDevice; U = SASIDEV] Executing Inquiry ($12) ?

uweseimet commented 2 years ago

@rdmark Yes, that's whay I mean.

marciot commented 2 years ago

@marciot What about setitng up a cross-compilation environment? That would even be faster than a Pi 4.

@uweseimet: Is there documentation on how to do this? I tried compiling it under WSL Ubuntu and it failed spectacularly, so I gave up on trying that.

uweseimet commented 2 years ago

@marciot There should be plenty of information in the internet, as cross-compilation with gcc is a standard approach for many environments. For the Pi I have never tried this myself, though.

marciot commented 2 years ago

@uweseimet: What are you all using for development then? I assume a Pi 4?

uweseimet commented 2 years ago

@marciot Usually I use a regular Linux PC with the Eclipse IDE. I only use a Pi 4 when I need to test SCSI low level stuff. A lot of the relevant code does not deal with Pi-specific features, so that I can also test most changes on the PC. For serious development, e.g. refactoring, one needs an IDE, and even the Pi 4 does not have enough resources (CPU and memory) for that.

uweseimet commented 2 years ago

@rdmark @marciot After comparing the offending commit with the previous one I cannot find anything obviously wrong. Most changes do not affect the Daynaport emulation, and those that affect it essentially deal with INQUIRY and REQUEST SENSE, which is code also shared with other devices. Can you please both confirm that the last working commit is da02eccb and the first non working commit is 1df7cdb1? I would like to ensure that you are both observing the same problem and that I am really comparing the right commits. Thanks a lot! If you have any tools that show the complete INQUIRY data please also compare those for both commits.

rdmark commented 2 years ago

@uweseimet I tested again in my environment (Power Mac 8600 / Mac OS 8.6) and can confirm that there's a breakage between those two commits.

Here's a log from a failure case, from when Mac OS has about halfway booted, until I open MacTCP and get an error that it cannot initialize the network interface.

[2022-04-25 13:38:06.334] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 13:38:06.335] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 13:38:06.335] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 13:38:06.335] [trace] virtual void SASIDEV::Command() CDB[0]=$12
[2022-04-25 13:38:06.335] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-25 13:38:06.335] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 13:38:06.335] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-25 13:38:06.335] [trace] virtual void SASIDEV::Command() CDB[4]=$01
[2022-04-25 13:38:06.335] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-25 13:38:06.335] [trace] virtual void SCSIDEV::Execute() Execution phase command $12
[2022-04-25 13:38:06.335] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $12
[2022-04-25 13:38:06.336] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = PrimaryDevice; U = SASIDEV] Executing Inquiry ($12)
[2022-04-25 13:38:06.336] [trace] void SASIDEV::DataIn() Going into Data-in Phase
[2022-04-25 13:38:06.336] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:06.336] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[2022-04-25 13:38:06.336] [trace] void SASIDEV::Status() Status phase
[2022-04-25 13:38:06.336] [trace] void SASIDEV::Status() Status Phase $00
[2022-04-25 13:38:06.336] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:06.337] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2022-04-25 13:38:06.337] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2022-04-25 13:38:06.337] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:06.337] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:06.337] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:06.337] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2022-04-25 13:38:06.337] [trace] virtual void SCSIDEV::BusFree() Bus free phase
[2022-04-25 13:38:06.337] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 13:38:06.338] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 13:38:06.338] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 13:38:06.338] [trace] virtual void SASIDEV::Command() CDB[0]=$12
[2022-04-25 13:38:06.338] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-25 13:38:06.338] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 13:38:06.338] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-25 13:38:06.338] [trace] virtual void SASIDEV::Command() CDB[4]=$05
[2022-04-25 13:38:06.338] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-25 13:38:06.338] [trace] virtual void SCSIDEV::Execute() Execution phase command $12
[2022-04-25 13:38:06.338] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $12
[2022-04-25 13:38:06.338] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = PrimaryDevice; U = SASIDEV] Executing Inquiry ($12)
[2022-04-25 13:38:06.339] [trace] void SASIDEV::DataIn() Going into Data-in Phase
[2022-04-25 13:38:06.339] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 5
[2022-04-25 13:38:06.339] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[2022-04-25 13:38:06.339] [trace] void SASIDEV::Status() Status phase
[2022-04-25 13:38:06.339] [trace] void SASIDEV::Status() Status Phase $00
[2022-04-25 13:38:06.339] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:06.339] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2022-04-25 13:38:06.339] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2022-04-25 13:38:06.340] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:06.340] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:06.340] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:06.340] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2022-04-25 13:38:06.340] [trace] virtual void SCSIDEV::BusFree() Bus free phase
[2022-04-25 13:38:06.340] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 13:38:06.340] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 13:38:06.340] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 13:38:06.341] [trace] virtual void SASIDEV::Command() CDB[0]=$12
[2022-04-25 13:38:06.341] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-25 13:38:06.341] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 13:38:06.341] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-25 13:38:06.341] [trace] virtual void SASIDEV::Command() CDB[4]=$24
[2022-04-25 13:38:06.341] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-25 13:38:06.341] [trace] virtual void SCSIDEV::Execute() Execution phase command $12
[2022-04-25 13:38:06.341] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $12
[2022-04-25 13:38:06.341] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = PrimaryDevice; U = SASIDEV] Executing Inquiry ($12)
[2022-04-25 13:38:06.341] [trace] void SASIDEV::DataIn() Going into Data-in Phase
[2022-04-25 13:38:06.341] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 36
[2022-04-25 13:38:06.342] [trace] virtual int GPIOBUS::SendHandShake(BYTE*, int, int) DELAYING for 100us after 6 bytes
[2022-04-25 13:38:06.342] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[2022-04-25 13:38:06.342] [trace] void SASIDEV::Status() Status phase
[2022-04-25 13:38:06.342] [trace] void SASIDEV::Status() Status Phase $00
[2022-04-25 13:38:06.342] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:06.342] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2022-04-25 13:38:06.342] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2022-04-25 13:38:06.342] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:06.343] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:06.343] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:06.343] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2022-04-25 13:38:06.343] [trace] virtual void SCSIDEV::BusFree() Bus free phase
[2022-04-25 13:38:06.343] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 13:38:06.343] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 13:38:06.343] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 13:38:06.344] [trace] virtual void SASIDEV::Command() CDB[0]=$12
[2022-04-25 13:38:06.344] [trace] virtual void SASIDEV::Command() CDB[1]=$20
[2022-04-25 13:38:06.344] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 13:38:06.344] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-25 13:38:06.344] [trace] virtual void SASIDEV::Command() CDB[4]=$01
[2022-04-25 13:38:06.344] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-25 13:38:06.344] [trace] virtual void SCSIDEV::Execute() Execution phase command $12
[2022-04-25 13:38:06.344] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $12
[2022-04-25 13:38:06.344] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = PrimaryDevice; U = SASIDEV] Executing Inquiry ($12)
[2022-04-25 13:38:06.344] [trace] Reporting LUN 1 for device ID 6 as not supported
[2022-04-25 13:38:06.344] [trace] void SASIDEV::DataIn() Going into Data-in Phase
[2022-04-25 13:38:06.345] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:06.345] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[2022-04-25 13:38:06.345] [trace] void SASIDEV::Status() Status phase
[2022-04-25 13:38:06.345] [trace] void SASIDEV::Status() Status Phase $00
[2022-04-25 13:38:06.345] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:06.345] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2022-04-25 13:38:06.345] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2022-04-25 13:38:06.345] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:06.345] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:06.345] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:06.346] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2022-04-25 13:38:06.346] [trace] virtual void SCSIDEV::BusFree() Bus free phase
[2022-04-25 13:38:17.636] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 13:38:17.636] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 13:38:17.636] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:17.636] [trace] Message Out Phase
[2022-04-25 13:38:17.637] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:17.637] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:17.637] [trace] virtual void SCSIDEV::Receive() Length is 1 bytes
[2022-04-25 13:38:17.637] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:17.637] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:17.637] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
[2022-04-25 13:38:17.637] [trace] Message code IDENTIFY $80, LUN 0 selected
[2022-04-25 13:38:17.637] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 13:38:17.637] [trace] virtual void SASIDEV::Command() CDB[0]=$12
[2022-04-25 13:38:17.637] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-25 13:38:17.637] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 13:38:17.638] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-25 13:38:17.638] [trace] virtual void SASIDEV::Command() CDB[4]=$60
[2022-04-25 13:38:17.638] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-25 13:38:17.638] [trace] virtual void SCSIDEV::Execute() Execution phase command $12
[2022-04-25 13:38:17.638] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $12
[2022-04-25 13:38:17.638] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = PrimaryDevice; U = SASIDEV] Executing Inquiry ($12)
[2022-04-25 13:38:17.638] [trace] void SASIDEV::DataIn() Going into Data-in Phase
[2022-04-25 13:38:17.638] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 36
[2022-04-25 13:38:17.638] [trace] virtual int GPIOBUS::SendHandShake(BYTE*, int, int) DELAYING for 100us after 6 bytes
[2022-04-25 13:38:17.639] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[2022-04-25 13:38:17.639] [trace] void SASIDEV::Status() Status phase
[2022-04-25 13:38:17.639] [trace] void SASIDEV::Status() Status Phase $00
[2022-04-25 13:38:17.639] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:17.639] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2022-04-25 13:38:17.639] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2022-04-25 13:38:17.639] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:17.639] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:17.639] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:17.640] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2022-04-25 13:38:17.640] [trace] virtual void SCSIDEV::BusFree() Bus free phase
[2022-04-25 13:38:23.615] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 13:38:23.615] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 13:38:23.615] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.615] [trace] Message Out Phase
[2022-04-25 13:38:23.615] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.615] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.615] [trace] virtual void SCSIDEV::Receive() Length is 1 bytes
[2022-04-25 13:38:23.615] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.615] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.615] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
[2022-04-25 13:38:23.616] [trace] Message code IDENTIFY $80, LUN 0 selected
[2022-04-25 13:38:23.616] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 13:38:23.616] [trace] virtual void SASIDEV::Command() CDB[0]=$12
[2022-04-25 13:38:23.616] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-25 13:38:23.616] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 13:38:23.616] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-25 13:38:23.616] [trace] virtual void SASIDEV::Command() CDB[4]=$24
[2022-04-25 13:38:23.616] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-25 13:38:23.616] [trace] virtual void SCSIDEV::Execute() Execution phase command $12
[2022-04-25 13:38:23.616] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $12
[2022-04-25 13:38:23.616] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = PrimaryDevice; U = SASIDEV] Executing Inquiry ($12)
[2022-04-25 13:38:23.617] [trace] void SASIDEV::DataIn() Going into Data-in Phase
[2022-04-25 13:38:23.617] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 36
[2022-04-25 13:38:23.617] [trace] virtual int GPIOBUS::SendHandShake(BYTE*, int, int) DELAYING for 100us after 6 bytes
[2022-04-25 13:38:23.617] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[2022-04-25 13:38:23.617] [trace] void SASIDEV::Status() Status phase
[2022-04-25 13:38:23.617] [trace] void SASIDEV::Status() Status Phase $00
[2022-04-25 13:38:23.617] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.618] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2022-04-25 13:38:23.618] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2022-04-25 13:38:23.618] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.618] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.618] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.618] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2022-04-25 13:38:23.618] [trace] virtual void SCSIDEV::BusFree() Bus free phase
[2022-04-25 13:38:23.618] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 13:38:23.619] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 13:38:23.619] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.619] [trace] Message Out Phase
[2022-04-25 13:38:23.619] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.619] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.619] [trace] virtual void SCSIDEV::Receive() Length is 1 bytes
[2022-04-25 13:38:23.619] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.619] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.619] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
[2022-04-25 13:38:23.620] [trace] Message code IDENTIFY $80, LUN 0 selected
[2022-04-25 13:38:23.620] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 13:38:23.620] [trace] virtual void SASIDEV::Command() CDB[0]=$00
[2022-04-25 13:38:23.620] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-25 13:38:23.620] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 13:38:23.620] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-25 13:38:23.620] [trace] virtual void SASIDEV::Command() CDB[4]=$00
[2022-04-25 13:38:23.620] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-25 13:38:23.620] [trace] virtual void SCSIDEV::Execute() Execution phase command $00
[2022-04-25 13:38:23.620] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $00
[2022-04-25 13:38:23.621] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = SCSIDaynaPort; U = SASIDEV] Executing TestUnitReady ($00)
[2022-04-25 13:38:23.621] [trace] void SASIDEV::Status() Status phase
[2022-04-25 13:38:23.621] [trace] void SASIDEV::Status() Status Phase $00
[2022-04-25 13:38:23.621] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.621] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2022-04-25 13:38:23.621] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2022-04-25 13:38:23.621] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.621] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.621] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.621] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2022-04-25 13:38:23.622] [trace] virtual void SCSIDEV::BusFree() Bus free phase
[2022-04-25 13:38:23.622] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 13:38:23.622] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 13:38:23.622] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.622] [trace] Message Out Phase
[2022-04-25 13:38:23.622] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.622] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.622] [trace] virtual void SCSIDEV::Receive() Length is 1 bytes
[2022-04-25 13:38:23.623] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.623] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.623] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
[2022-04-25 13:38:23.623] [trace] Message code IDENTIFY $80, LUN 0 selected
[2022-04-25 13:38:23.623] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 13:38:23.623] [trace] virtual void SASIDEV::Command() CDB[0]=$25
[2022-04-25 13:38:23.623] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-25 13:38:23.623] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 13:38:23.623] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-25 13:38:23.623] [trace] virtual void SASIDEV::Command() CDB[4]=$00
[2022-04-25 13:38:23.624] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-25 13:38:23.624] [trace] virtual void SASIDEV::Command() CDB[6]=$00
[2022-04-25 13:38:23.624] [trace] virtual void SASIDEV::Command() CDB[7]=$00
[2022-04-25 13:38:23.624] [trace] virtual void SASIDEV::Command() CDB[8]=$00
[2022-04-25 13:38:23.624] [trace] virtual void SASIDEV::Command() CDB[9]=$00
[2022-04-25 13:38:23.624] [trace] virtual void SCSIDEV::Execute() Execution phase command $25
[2022-04-25 13:38:23.624] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $25
[2022-04-25 13:38:23.624] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = Disk; U = SASIDEV] Executing ReadCapacity10 ($25)
[2022-04-25 13:38:23.624] [trace] bool PrimaryDevice::CheckReady() Device is ready
[2022-04-25 13:38:23.624] [debug] Error status: Sense Key $05, ASC $3A, ASCQ $00
[2022-04-25 13:38:23.625] [trace] virtual void SCSIDEV::Error(scsi_defs::sense_key, scsi_defs::asc, scsi_defs::status) Error (to status phase)
[2022-04-25 13:38:23.625] [trace] void SASIDEV::Status() Status phase
[2022-04-25 13:38:23.625] [trace] void SASIDEV::Status() Status Phase $02
[2022-04-25 13:38:23.625] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.625] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2022-04-25 13:38:23.625] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2022-04-25 13:38:23.625] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.625] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.625] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.625] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2022-04-25 13:38:23.626] [trace] virtual void SCSIDEV::BusFree() Bus free phase
[2022-04-25 13:38:23.626] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 13:38:23.626] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 13:38:23.626] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.626] [trace] Message Out Phase
[2022-04-25 13:38:23.626] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.626] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.626] [trace] virtual void SCSIDEV::Receive() Length is 1 bytes
[2022-04-25 13:38:23.627] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.627] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.627] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
[2022-04-25 13:38:23.627] [trace] Message code IDENTIFY $80, LUN 0 selected
[2022-04-25 13:38:23.627] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 13:38:23.627] [trace] virtual void SASIDEV::Command() CDB[0]=$03
[2022-04-25 13:38:23.627] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-25 13:38:23.627] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 13:38:23.627] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-25 13:38:23.627] [trace] virtual void SASIDEV::Command() CDB[4]=$12
[2022-04-25 13:38:23.628] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-25 13:38:23.628] [trace] virtual void SCSIDEV::Execute() Execution phase command $03
[2022-04-25 13:38:23.628] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $03
[2022-04-25 13:38:23.628] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = PrimaryDevice; U = SASIDEV] Executing RequestSense ($03)
[2022-04-25 13:38:23.628] [trace] virtual void PrimaryDevice::RequestSense(SASIDEV*) Status $00, Sense Key $05, ASC $3A
[2022-04-25 13:38:23.628] [trace] void SASIDEV::DataIn() Going into Data-in Phase
[2022-04-25 13:38:23.628] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 18
[2022-04-25 13:38:23.628] [trace] virtual int GPIOBUS::SendHandShake(BYTE*, int, int) DELAYING for 100us after 6 bytes
[2022-04-25 13:38:23.629] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[2022-04-25 13:38:23.629] [trace] void SASIDEV::Status() Status phase
[2022-04-25 13:38:23.629] [trace] void SASIDEV::Status() Status Phase $00
[2022-04-25 13:38:23.629] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.629] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2022-04-25 13:38:23.629] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2022-04-25 13:38:23.629] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.629] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.629] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.630] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2022-04-25 13:38:23.630] [trace] virtual void SCSIDEV::BusFree() Bus free phase
[2022-04-25 13:38:23.630] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 13:38:23.630] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 13:38:23.630] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.630] [trace] Message Out Phase
[2022-04-25 13:38:23.630] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.631] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.631] [trace] virtual void SCSIDEV::Receive() Length is 1 bytes
[2022-04-25 13:38:23.631] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.631] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.631] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
[2022-04-25 13:38:23.631] [trace] Message code IDENTIFY $80, LUN 0 selected
[2022-04-25 13:38:23.631] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 13:38:23.631] [trace] virtual void SASIDEV::Command() CDB[0]=$08
[2022-04-25 13:38:23.631] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-25 13:38:23.631] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 13:38:23.632] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-25 13:38:23.632] [trace] virtual void SASIDEV::Command() CDB[4]=$01
[2022-04-25 13:38:23.632] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-25 13:38:23.632] [trace] virtual void SCSIDEV::Execute() Execution phase command $08
[2022-04-25 13:38:23.632] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $08
[2022-04-25 13:38:23.632] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = SCSIDaynaPort; U = SASIDEV] Executing Read6 ($08)
[2022-04-25 13:38:23.632] [trace] virtual void SCSIDaynaPort::Read6(SASIDEV*) Control value 0, (0000), returning invalid CDB
[2022-04-25 13:38:23.632] [debug] Error status: Sense Key $05, ASC $24, ASCQ $00
[2022-04-25 13:38:23.632] [trace] virtual void SCSIDEV::Error(scsi_defs::sense_key, scsi_defs::asc, scsi_defs::status) Error (to status phase)
[2022-04-25 13:38:23.632] [trace] void SASIDEV::Status() Status phase
[2022-04-25 13:38:23.632] [trace] void SASIDEV::Status() Status Phase $02
[2022-04-25 13:38:23.633] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.633] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2022-04-25 13:38:23.633] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2022-04-25 13:38:23.633] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.633] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.633] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.633] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2022-04-25 13:38:23.633] [trace] virtual void SCSIDEV::BusFree() Bus free phase
[2022-04-25 13:38:23.634] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 13:38:23.634] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 13:38:23.634] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.634] [trace] Message Out Phase
[2022-04-25 13:38:23.634] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.634] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.634] [trace] virtual void SCSIDEV::Receive() Length is 1 bytes
[2022-04-25 13:38:23.634] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.634] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.634] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
[2022-04-25 13:38:23.635] [trace] Message code IDENTIFY $80, LUN 0 selected
[2022-04-25 13:38:23.635] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 13:38:23.635] [trace] virtual void SASIDEV::Command() CDB[0]=$03
[2022-04-25 13:38:23.635] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-25 13:38:23.635] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 13:38:23.635] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-25 13:38:23.635] [trace] virtual void SASIDEV::Command() CDB[4]=$12
[2022-04-25 13:38:23.635] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-25 13:38:23.635] [trace] virtual void SCSIDEV::Execute() Execution phase command $03
[2022-04-25 13:38:23.635] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $03
[2022-04-25 13:38:23.636] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = PrimaryDevice; U = SASIDEV] Executing RequestSense ($03)
[2022-04-25 13:38:23.636] [trace] virtual void PrimaryDevice::RequestSense(SASIDEV*) Status $00, Sense Key $05, ASC $24
[2022-04-25 13:38:23.636] [trace] void SASIDEV::DataIn() Going into Data-in Phase
[2022-04-25 13:38:23.636] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 18
[2022-04-25 13:38:23.636] [trace] virtual int GPIOBUS::SendHandShake(BYTE*, int, int) DELAYING for 100us after 6 bytes
[2022-04-25 13:38:23.636] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[2022-04-25 13:38:23.636] [trace] void SASIDEV::Status() Status phase
[2022-04-25 13:38:23.636] [trace] void SASIDEV::Status() Status Phase $00
[2022-04-25 13:38:23.637] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.637] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2022-04-25 13:38:23.637] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2022-04-25 13:38:23.637] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.637] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.637] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.637] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2022-04-25 13:38:23.637] [trace] virtual void SCSIDEV::BusFree() Bus free phase
[2022-04-25 13:38:23.638] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 13:38:23.638] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 13:38:23.638] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.638] [trace] Message Out Phase
[2022-04-25 13:38:23.638] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.638] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.638] [trace] virtual void SCSIDEV::Receive() Length is 1 bytes
[2022-04-25 13:38:23.638] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.638] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.638] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
[2022-04-25 13:38:23.639] [trace] Message code IDENTIFY $80, LUN 0 selected
[2022-04-25 13:38:23.639] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 13:38:23.639] [trace] virtual void SASIDEV::Command() CDB[0]=$08
[2022-04-25 13:38:23.639] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-25 13:38:23.639] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 13:38:23.639] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-25 13:38:23.639] [trace] virtual void SASIDEV::Command() CDB[4]=$01
[2022-04-25 13:38:23.639] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-25 13:38:23.639] [trace] virtual void SCSIDEV::Execute() Execution phase command $08
[2022-04-25 13:38:23.639] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $08
[2022-04-25 13:38:23.640] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = SCSIDaynaPort; U = SASIDEV] Executing Read6 ($08)
[2022-04-25 13:38:23.640] [trace] virtual void SCSIDaynaPort::Read6(SASIDEV*) Control value 0, (0000), returning invalid CDB
[2022-04-25 13:38:23.640] [debug] Error status: Sense Key $05, ASC $24, ASCQ $00
[2022-04-25 13:38:23.640] [trace] virtual void SCSIDEV::Error(scsi_defs::sense_key, scsi_defs::asc, scsi_defs::status) Error (to status phase)
[2022-04-25 13:38:23.640] [trace] void SASIDEV::Status() Status phase
[2022-04-25 13:38:23.640] [trace] void SASIDEV::Status() Status Phase $02
[2022-04-25 13:38:23.640] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.640] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2022-04-25 13:38:23.640] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2022-04-25 13:38:23.640] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.641] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.641] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.641] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2022-04-25 13:38:23.641] [trace] virtual void SCSIDEV::BusFree() Bus free phase
[2022-04-25 13:38:23.641] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 13:38:23.641] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 13:38:23.641] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.641] [trace] Message Out Phase
[2022-04-25 13:38:23.641] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.642] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.642] [trace] virtual void SCSIDEV::Receive() Length is 1 bytes
[2022-04-25 13:38:23.642] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.642] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.642] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
[2022-04-25 13:38:23.642] [trace] Message code IDENTIFY $80, LUN 0 selected
[2022-04-25 13:38:23.642] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 13:38:23.642] [trace] virtual void SASIDEV::Command() CDB[0]=$03
[2022-04-25 13:38:23.642] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-25 13:38:23.642] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 13:38:23.643] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-25 13:38:23.643] [trace] virtual void SASIDEV::Command() CDB[4]=$12
[2022-04-25 13:38:23.643] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-25 13:38:23.643] [trace] virtual void SCSIDEV::Execute() Execution phase command $03
[2022-04-25 13:38:23.643] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $03
[2022-04-25 13:38:23.643] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = PrimaryDevice; U = SASIDEV] Executing RequestSense ($03)
[2022-04-25 13:38:23.643] [trace] virtual void PrimaryDevice::RequestSense(SASIDEV*) Status $00, Sense Key $05, ASC $24
[2022-04-25 13:38:23.643] [trace] void SASIDEV::DataIn() Going into Data-in Phase
[2022-04-25 13:38:23.643] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 18
[2022-04-25 13:38:23.644] [trace] virtual int GPIOBUS::SendHandShake(BYTE*, int, int) DELAYING for 100us after 6 bytes
[2022-04-25 13:38:23.644] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[2022-04-25 13:38:23.644] [trace] void SASIDEV::Status() Status phase
[2022-04-25 13:38:23.644] [trace] void SASIDEV::Status() Status Phase $00
[2022-04-25 13:38:23.644] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.644] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2022-04-25 13:38:23.644] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2022-04-25 13:38:23.644] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.644] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.645] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.645] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2022-04-25 13:38:23.645] [trace] virtual void SCSIDEV::BusFree() Bus free phase
[2022-04-25 13:38:23.645] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 13:38:23.645] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 13:38:23.645] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.645] [trace] Message Out Phase
[2022-04-25 13:38:23.646] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.646] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.646] [trace] virtual void SCSIDEV::Receive() Length is 1 bytes
[2022-04-25 13:38:23.646] [trace] void SCSIDEV::MsgOut() ID 6
[2022-04-25 13:38:23.646] [trace] virtual void SCSIDEV::Receive()
[2022-04-25 13:38:23.646] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
[2022-04-25 13:38:23.646] [trace] Message code IDENTIFY $81, LUN 1 selected
[2022-04-25 13:38:23.646] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 13:38:23.646] [trace] virtual void SASIDEV::Command() CDB[0]=$12
[2022-04-25 13:38:23.646] [trace] virtual void SASIDEV::Command() CDB[1]=$20
[2022-04-25 13:38:23.646] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 13:38:23.647] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-25 13:38:23.647] [trace] virtual void SASIDEV::Command() CDB[4]=$24
[2022-04-25 13:38:23.647] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-25 13:38:23.647] [trace] virtual void SCSIDEV::Execute() Execution phase command $12
[2022-04-25 13:38:23.647] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $12
[2022-04-25 13:38:23.647] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = PrimaryDevice; U = SASIDEV] Executing Inquiry ($12)
[2022-04-25 13:38:23.647] [trace] Reporting LUN 1 for device ID 6 as not supported
[2022-04-25 13:38:23.647] [trace] void SASIDEV::DataIn() Going into Data-in Phase
[2022-04-25 13:38:23.647] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 36
[2022-04-25 13:38:23.648] [trace] virtual int GPIOBUS::SendHandShake(BYTE*, int, int) DELAYING for 100us after 6 bytes
[2022-04-25 13:38:23.648] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[2022-04-25 13:38:23.648] [trace] void SASIDEV::Status() Status phase
[2022-04-25 13:38:23.648] [trace] void SASIDEV::Status() Status Phase $00
[2022-04-25 13:38:23.648] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.648] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2022-04-25 13:38:23.648] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2022-04-25 13:38:23.648] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.649] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:23.649] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:23.649] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2022-04-25 13:38:23.649] [trace] virtual void SCSIDEV::BusFree() Bus free phase
[2022-04-25 13:38:44.945] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 13:38:44.946] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 13:38:44.946] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 13:38:44.946] [trace] virtual void SASIDEV::Command() CDB[0]=$12
[2022-04-25 13:38:44.946] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-25 13:38:44.946] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 13:38:44.946] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-25 13:38:44.946] [trace] virtual void SASIDEV::Command() CDB[4]=$25
[2022-04-25 13:38:44.946] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-25 13:38:44.946] [trace] virtual void SCSIDEV::Execute() Execution phase command $12
[2022-04-25 13:38:44.947] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $12
[2022-04-25 13:38:44.947] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = PrimaryDevice; U = SASIDEV] Executing Inquiry ($12)
[2022-04-25 13:38:44.947] [trace] void SASIDEV::DataIn() Going into Data-in Phase
[2022-04-25 13:38:44.947] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 36
[2022-04-25 13:38:44.947] [trace] virtual int GPIOBUS::SendHandShake(BYTE*, int, int) DELAYING for 100us after 6 bytes
[2022-04-25 13:38:44.947] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[2022-04-25 13:38:44.947] [trace] void SASIDEV::Status() Status phase
[2022-04-25 13:38:44.948] [trace] void SASIDEV::Status() Status Phase $00
[2022-04-25 13:38:44.948] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:44.948] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2022-04-25 13:38:44.948] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2022-04-25 13:38:44.948] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:44.948] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 13:38:44.948] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 13:38:44.948] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2022-04-25 13:38:44.949] [trace] virtual void SCSIDEV::BusFree() Bus free phase
uweseimet commented 2 years ago

@rdmark Can you please attach the corresponding log for the working commit? On first sight this part of the log

debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $08
[2022-04-25 13:38:23.640] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = SCSIDaynaPort; U = SASIDEV] Executing Read6 ($08)
[2022-04-25 13:38:23.640] [trace] virtual void SCSIDaynaPort::Read6(SASIDEV*) Control value 0, (0000), returning invalid CDB
[2022-04-25 13:38:23.640] [debug] Error status: Sense Key $05, ASC $24, ASCQ $00
[2022-04-25 13:38:23.640] [

looks suspicious to me.

uweseimet commented 2 years ago

@rdmark No, this part of the log is probably fine. It means that a non-Daynaport driver (hard disk driver) tried to access the Daynaport, trying to read the root sector. This is most likely normal, it's just the hard disk driver's default behavior. One can see that there are two drivers accessing the Daynaport, because one of them (the hard disk driver I guess) selects the LUN in a MESSAGE OUT phase (SCSI-2 compliant) with an IDENTIFY message, the other (IMO the Daynaport driver) does not use IDENTIFY but the deprecated LUN bits in the CDB.

@rdmark You say "when Mac OS has about halfway booted". Can you avoid accessing the Daynaport with your TCP software until the system has fully booted? It would be good to avoid the hard disk driver to interfere. This will make comparing the logs and identifying the relevant parts easier.

rdmark commented 2 years ago

@uweseimet FYI this system is only using RaSCSI for the DaynaPort device in this configuration. The hard drive is a different SCSI device.

Here's a log from the good commit surrounding that Read6 message:

[2022-04-25 14:16:39.321] [trace] virtual void SCSIDEV::Execute() Execution phase command $08
[2022-04-25 14:16:39.322] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $08
[2022-04-25 14:16:39.322] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = SCSIDaynaPort; U = SASIDEV] Executing Read6 ($08)
[2022-04-25 14:16:39.322] [trace] virtual void SCSIDaynaPort::Read6(SASIDEV*) READ(6) command record=5 blocks=1
[2022-04-25 14:16:39.322] [trace] virtual int SCSIDaynaPort::Read(const DWORD*, BYTE*, uint64_t) Read maximum length 244, (00F4)
[2022-04-25 14:16:39.322] [trace] bool CTapDriver::PendingPackets() 0 revents
[2022-04-25 14:16:39.322] [trace] virtual int SCSIDaynaPort::Read(const DWORD*, BYTE*, uint64_t) No packet received
[2022-04-25 14:16:39.322] [trace] virtual void SCSIDaynaPort::Read6(SASIDEV*) ctrl.length is 6
[2022-04-25 14:16:39.322] [trace] void SASIDEV::DataIn() Going into Data-in Phase
[2022-04-25 14:16:39.322] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 6
[2022-04-25 14:16:39.323] [trace] virtual void SCSIDEV::Send() Move to next phase datain (6)
[2022-04-25 14:16:39.323] [trace] void SASIDEV::Status() Status phase
[2022-04-25 14:16:39.323] [trace] void SASIDEV::Status() Status Phase $00
[2022-04-25 14:16:39.323] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 14:16:39.323] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2022-04-25 14:16:39.323] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2022-04-25 14:16:39.323] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 14:16:39.323] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 1
[2022-04-25 14:16:39.323] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2022-04-25 14:16:39.324] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2022-04-25 14:16:39.324] [trace] virtual void SCSIDEV::BusFree() Bus free phase
[2022-04-25 14:16:39.325] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-25 14:16:39.325] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-25 14:16:39.325] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-25 14:16:39.325] [trace] virtual void SASIDEV::Command() CDB[0]=$08
[2022-04-25 14:16:39.326] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-25 14:16:39.326] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-25 14:16:39.326] [trace] virtual void SASIDEV::Command() CDB[3]=$05
[2022-04-25 14:16:39.326] [trace] virtual void SASIDEV::Command() CDB[4]=$F4
[2022-04-25 14:16:39.326] [trace] virtual void SASIDEV::Command() CDB[5]=$C0
[2022-04-25 14:16:39.326] [trace] virtual void SCSIDEV::Execute() Execution phase command $08
uweseimet commented 2 years ago

@rdmark The hard disk driver may initially access all devices, and this is what iti is actually doing. One can see that because it is using besides other commands READ CAPACITY, which ia disk-specific. All commands that use an IDENTIFY message are very likely those sent by the hard disk driver. We definitely need the logfile from the working commit in order to compare the command sequence, not just READ(6), but more, just like in your comment from an hour ago. We need to know what's different. The logging as such has not changed between the commits, i.e. everything is logged on the same log level and with the same text. Based on the different command setups by the hard disk and the Daynaport driver (with/without IDENTIFY) it should be possible to extract the Daynaport driver commands and compare the success with the failure case.

rdmark commented 2 years ago

@uweseimet I see. Is there a good way to know when the hard drive activity has ended after a boot, by looking at the logs? I try to wait until the OS has seemingly finished starting up fully, but there may be residual hard disk activity that is not apparent.

uweseimet commented 2 years ago

@rdmark Based on the usage of the IDENTIFY message it should be possible to identify (and discard) the hard disk driver commands, see my comment above. I woudl expect the hard disk driver not to send command anymore after it has learned that the Daynaport is not a disk. Unfortunately the Daynaport inherits from the Disk class, which means that it might sometimes react like a disk would :-(. I already started addressing that (there is an open ticket), but I am not sure whether I will continue with this cleanup. The legacy SASI code makes working on this very inconvenient, and I guess I will not contribute that much to this project anymore as long as there is still SASI support. (But no SASI users willing to maintain or test or clean up the SASI code.)

rdmark commented 2 years ago

@marciot Would you be able to take a look as well? The trick I'm using is to compile one rascsi binary before the commit, rename it to 'rascsi-good' or something, and then compile another binary that has the bug. That way you don't have to go back and forth compiling all the time.

I won't have much time tomorrow to spend on this due to a busy day at work...

marciot commented 2 years ago

@rdmark: I started the first compilation when @uweseimet asked me to. It's finishing up the second compile now, about nine hours later. Commit da02eccb worked, commit 1df7cdb1 is not working.

uweseimet commented 2 years ago

@rdmark @marciot I would like to ask again whether one of you can run a Mac tool that provides full information about the INQUIRY data returned by the Daynaport device for the two relevant commits. And it would also be great if there was a logfiles of the success case with about the scope covered by @rdmark's logfile for the failure case from about 10 hours ago. A comparison of the failure and success case for all Daynaport commands is needed. There must be a difference somewhere.

@marciot Maybe you can also have a look at the diffs of the two commits. I did not find anything obviously wrong in the Daynaport-related code. You can ignore everything in the diffs that is related to CD-ROM drives, hard disk drives, the host interface, the printer and the host bridge. The remaining code is not that much.

marciot commented 2 years ago

@uweseimet do you have any particular tool you recommend, or do I need to write my own?

uweseimet commented 2 years ago

@marciot For the diffs you mean? In this case I was looking at the raw diffs created with 'git diff', but you can most likely use any IDE. I assume google will very likely find a bunch of other diff tools.

uweseimet commented 2 years ago

Just for the record: As already mentioned I have issues with my setup which affects testing. Nevertheless I found a difference in the logs for the failure and success case.

Success:

[2022-04-26 10:30:08.658] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-26 10:30:08.658] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-26 10:30:08.658] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-26 10:30:08.658] [trace] virtual void SASIDEV::Command() CDB[0]=$12
[2022-04-26 10:30:08.658] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-26 10:30:08.659] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-26 10:30:08.659] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-26 10:30:08.659] [trace] virtual void SASIDEV::Command() CDB[4]=$25
[2022-04-26 10:30:08.659] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-26 10:30:08.659] [trace] virtual void SCSIDEV::Execute() Execution phase command $12
[2022-04-26 10:30:08.659] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $12
[2022-04-26 10:30:08.659] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = PrimaryDevice; U = SASIDEV] Executing Inquiry ($12)
[2022-04-26 10:30:08.659] [trace] void SASIDEV::DataIn() Going into Data-in Phase
[2022-04-26 10:30:08.659] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 37
[2022-04-26 10:30:08.659] [trace] virtual int GPIOBUS::SendHandShake(BYTE*, int, int) DELAYING for 100us after 6 bytes

Failure:

[2022-04-26 10:36:10.703] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2022-04-26 10:36:10.703] [trace] virtual void SCSIDEV::Selection() Initiator ID is 7
[2022-04-26 10:36:10.703] [trace] virtual void SASIDEV::Command() Command Phase
[2022-04-26 10:36:10.703] [trace] virtual void SASIDEV::Command() CDB[0]=$12
[2022-04-26 10:36:10.704] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2022-04-26 10:36:10.704] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2022-04-26 10:36:10.704] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2022-04-26 10:36:10.704] [trace] virtual void SASIDEV::Command() CDB[4]=$25
[2022-04-26 10:36:10.704] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2022-04-26 10:36:10.704] [trace] virtual void SCSIDEV::Execute() Execution phase command $12
[2022-04-26 10:36:10.704] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $12
[2022-04-26 10:36:10.704] [debug] bool Dispatcher<T, U>::Dispatch(T*, U*) [with T = PrimaryDevice; U = SASIDEV] Executing Inquiry ($12)
[2022-04-26 10:36:10.704] [trace] void SASIDEV::DataIn() Going into Data-in Phase
[2022-04-26 10:36:10.704] [trace] virtual void SCSIDEV::Send() Sending handhake with offset 0, length 36
[2022-04-26 10:36:10.704] [trace] virtual int GPIOBUS::SendHandShake(BYTE*, int, int) DELAYING for 100us after 6 bytes

The Daynaport driver requests 37 INQUIRY bytes but after the problematic commit only 36 bytes are returned. It is legal to return less than the required amount of bytes, but either the Dayanport driver cannot deal with less than 37 bytes or there is an issue with the changes in the INQUIRY code that deals with the number of bytes to be returned.

uweseimet commented 2 years ago

@rdmark @marciot Can you please change line 166 in devices/primary_device.cpp from

        vector<BYTE> buf = vector<BYTE>(0x1F + 5);

to

        vector<BYTE> buf = vector<BYTE>(0x1F + 6);

and see whether this resolves your issue? Even if this works it will not be the final resolution, because if the Daynaport requires 37 bytes this has to be dealt with in the Daynaport-specific code and not in the general INQUIRY code.

There are 36 standard INQUIRY bytes according to the SCSI specification (please correct me if I am wrong), but it looks as if the Daynaport driver expects one byte more, which can only be a vendor specific byte. In the working code this byte is 0. For 37 bytes to be returned the additional_length field would have to be 0x20 instead of 0x1f, but it always was 0x1f, even in old revisions of the Daynaport code. The additional length field for the Daynaport may have to be changed to 0x20 in order to be really correct. The old Daynaport code (commit 62f6c8d9, for instance) actually has 8 more bytes, but additional_length is only 0x1f. Any idea why?

uweseimet commented 2 years ago

@rdmark @marciot In case the proposed fix above works, please also test the new fix_issue_750 branch, which is based on the develop branch. As far as I can test it, it appears to work, using an additional length of 0x20 and returning 37 INQUIRY bytes for the Daynaport only.

rdmark commented 2 years ago

@uweseimet The buffer size change made it work again on my Power Mac! I've tested both the quick hack and and the code in fix_issue_750 branch. Great job figuring that out!

uweseimet commented 2 years ago

@rdmark Sounds good, thank you for testing! @marciot As soon as you have confirmed that the fix_issue_750 branch also works for you I will create a PR in order to unblock the next release.

marciot commented 2 years ago

@uweseimet: Compiling now. Will let you know if it resolves the issue. @rdmark, thank you for your efforts in troubleshooting this. I apologize that I was not able to help more. It's been a tough week for me.

marciot commented 2 years ago

@uweseimet: It's all good! The network is properly initializing now!

uweseimet commented 2 years ago

@marciot Good news! Thank you for testing. I am going to create the PR.