Closed predecker closed 8 months ago
@predecker That there is the same issue is not that surprising. But this ticket is most likely a duplicate, as far as I can tell. Please see https://github.com/uweseimet/scsi2pi/issues/71. Can you please check whether the work-around (source code patch) mentioned in https://github.com/uweseimet/scsi2pi/issues/71 also works for you? Please use the current develop branch with this patch applied for testing.
@predecker One more question: Do you have any real SCSI hard drive that works with your Mac? In case you have, which drive model is it?
I applied the patch from #71, but I get a slightly different result. Copying system files (6.0.8) from floppy to the image works now, but the messages did not disappear completely:
Mar 3 22:12:40 raspi-rascsi s2p[825]: [2024-03-03 22:12:40.014] [warning] (ID 6) - Received 0 byte(s) in DATA OUT phase, command requires 512
Everytime the bytes were 0. I got four messages for about 800kB of data. The copy was good enough that the system could boot from it.
I'll do further testing tomorrow. I have to find out how to compare files.
So this is a kind of "hack" as you mentioned in the other issue and not according to the standard. I want to share my piscsi between the Mac Plus and a Classic. Do I have to switch between this hacked version and a normal one everytime I switch the Macs? Can you implement a version with a command line switch or do I have to script something to change the executables for that?
@predecker I am sorry, but I will not implement anything (also not optional) that is not compliant with the SCSI standard. It looks as if the patch in https://github.com/uweseimet/scsi2pi/issues/71 does not work for you anyway, because there are still errors reported in the DATA OUT phase.
As explained in https://github.com/uweseimet/scsi2pi/issues/71, s2p (and also piscsi as far as I can tell) only change the REQ line during the data transfer, and they use the timing required by the SCSI specification, i.e. they wait for a bus settle delay before reading the data byte. These are just a few lines of code and, of course, if somebody finds something wrong I would appreciate feedback. This is the respective code in bus.cpp:
int Bus::ReceiveHandShake(uint8_t *buf, int count)
{
int bytes_received;
DisableIRQ();
if (target_mode) {
for (bytes_received = 0; bytes_received < count; bytes_received++) {
SetREQ(true);
const bool ack = WaitSignal(PIN_ACK, true);
WaitBusSettle();
*buf = GetDAT();
SetREQ(false);
// Timeout waiting for ACK to change
if (!ack || !WaitSignal(PIN_ACK, false)) {
break;
}
buf++;
}
} else {
Either ACK is not set correctly by the Mac, so that the handshake terminates before all data have been transferred, or the Mac interrupts the transfer by raising the SCSI RST signal, which also terminates the handshake. A wrong handling of the ACK signal or the RST signal being set are the only ways to prematurely terminate the handshake and produce the "Received x bytes" message, which indicates that less bytes have been received than required. The reset condition and also the ACK timeout have not been logged explicitly yet. There is an issue_82 branch now which logs these conditions. When you do further testing, can you please test with the issue_82 branch? This should reveal which of the two signals is in an unexpected state.
@predecker One more question: Do you have any real SCSI hard drive that works with your Mac? In case you have, which drive model is it?
I have a Apple SC 20 external disk somewhere in my storage, but I don't actually know which disk is inside. I'm sure it's not 20MB, it's bigger. That enclosure worked all the time with the Mac Plus but I didn't trust the harddisk no more, so I bought the rascsi.
Moin, I'm running on the issue_82 branch. I compiled with DEBUG=1, but I'm only seeing the same messages as with the development branch. I'm not able to write to an image. If I boot from one with 6.0.8 the Finder crashes with different messages and the Mac freezes. I now try to format a fresh image while booting from floppy but that does not work. No freeze of the Mac. First Aid is not able to verify, repair or initialize. Same with HD SC Setup. Next step?
@predecker Are you running s2p on trace level? Only on trace level all releavant messages are logged. There should be either a message about the reset signal having been received, or about a handshake timeout right, before the warning about the problem with the DATA OUT phase. Maybe you can post a small part of your log, in particular the lines right before the DATA OUT warning. You do not have to compile with DEBUG=1, by the way, but you can also use an optimized build. The messages logged are not affected by the optimization level.
This block repeats every few seconds:
Mar 4 09:38:31 raspi-rascsi s2p[1860]: [2024-03-04 09:38:31.459] [trace] (ID 6) - All data transferred Mar 4 09:38:31 raspi-rascsi s2p[1860]: [2024-03-04 09:38:31.459] [trace] (ID 6) - BUS FREE phase Mar 4 09:38:31 raspi-rascsi s2p[1860]: [2024-03-04 09:38:31.460] [trace] (ID 6) - ++++ Starting processing for initiator ID 7 Mar 4 09:38:31 raspi-rascsi s2p[1860]: [2024-03-04 09:38:31.460] [trace] (ID 6) - SELECTION phase Mar 4 09:38:31 raspi-rascsi s2p[1860]: [2024-03-04 09:38:31.461] [trace] (ID 6) - COMMAND phase Mar 4 09:38:31 raspi-rascsi s2p[1860]: [2024-03-04 09:38:31.461] [debug] (ID 6) - Controller is executing WRITE(10), CDB $2a:00:00:00:00:64:00:00:01:00 Mar 4 09:38:31 raspi-rascsi s2p[1860]: [2024-03-04 09:38:31.461] [debug] (ID:LUN 6:0) - Device is executing WRITE(10) ($2a) Mar 4 09:38:31 raspi-rascsi s2p[1860]: [2024-03-04 09:38:31.461] [trace] (ID:LUN 6:0) - READ/WRITE/VERIFY/SEEK, start sector: 100, sector count: 1 Mar 4 09:38:31 raspi-rascsi s2p[1860]: [2024-03-04 09:38:31.461] [trace] (ID 6) - DATA OUT phase Mar 4 09:38:31 raspi-rascsi s2p[1860]: [2024-03-04 09:38:31.461] [trace] (ID 6) - Receiving 512 byte(s) Mar 4 09:38:34 raspi-rascsi s2p[1860]: [2024-03-04 09:38:34.462] [trace] Timeout while waiting for ACK/REQ to change Mar 4 09:38:34 raspi-rascsi s2p[1860]: [2024-03-04 09:38:34.462] [warning] (ID 6) - Received 22 byte(s) in DATA OUT phase, command requires 512 Mar 4 09:38:34 raspi-rascsi s2p[1860]: [2024-03-04 09:38:34.462] [debug] (ID 6) - ABORTED COMMAND (Sense Key $0b), DATA PHASE ERROR (ASC $4b), ASCQ $00 Mar 4 09:38:34 raspi-rascsi s2p[1860]: [2024-03-04 09:38:34.462] [trace] (ID 6) - Status phase, status is CHECK CONDITION (status code $02) Mar 4 09:38:34 raspi-rascsi s2p[1860]: [2024-03-04 09:38:34.462] [trace] (ID 6) - Sending 1 byte(s) Mar 4 09:38:34 raspi-rascsi s2p[1860]: [2024-03-04 09:38:34.462] [trace] (ID 6) - All data transferred
I booted from floppy. As I messed up this image in previous tests, the system is trying to initlalize the image. Took about 5 minutes to "create directory".
@predecker Your log shows that there is a timeout (> 3 s) while waiting for the ACK signal to change. You can see that 3 s elapse before the timeout is reported from the timestamps in the log.
Mar 4 09:38:31 raspi-rascsi s2p[1860]: [2024-03-04 09:38:31.461] [trace] (ID 6) - Receiving 512 byte(s)
Mar 4 09:38:34 raspi-rascsi s2p[1860]: [2024-03-04 09:38:34.462] [trace] Timeout while waiting for ACK/REQ to change
Mar 4 09:38:34 raspi-rascsi s2p[1860]: [2024-03-04 09:38:34.462] [warning] (ID 6) - Received 22 byte(s) in DATA OUT phase, command requires 512
Mar 4 09:38:34 raspi-rascsi s2p[1860]: [2024-03-04 09:38:34.462] [debug] (ID 6) - ABORTED COMMAND (Sense Key $0b), DATA PHASE ERROR (ASC $4b), ASCQ $00
With the latest issue_82 sources (from some hours ago) the log will also tell whether the error happens when waiting for a signal to be set or to be cleared. You might want to update and re-compile your sources to also collect this piece of information.
It's the Mac that controls the ACK line during a data transfer to the board. SCSI2PI/PiSCSI just wait for this signal to change. Obviously the ACK line is not set/cleared as it should. This either means that the Mac does not handle the ACK signal correctly, or that there is a hardware issue that results in the Pi not noticing that the line status has changed. This problem is nothing that can be compensated for by software. You mentioned in the respective PiSCSI ticket that you have an oscilloscope. It should confirm that the ACK line is in a static state for at least 3 s. The ACK line is GPIO pin 21.
I thought I run the issue_82 version. There must have been something wrong with my git commands ... I'm not that expert with it. I did git pull , that announced the issue_82 branch git checkout issue_82 make DEBUG=1 stopped the services sudo make install reboot
I see the ACK line on the SCSI-side staying on a negative potential for 3 seconds on the oszilloscope. It repeats while copying files.
@predecker This means that the oscilloscope confirms what we see in the logfile. I'm afraid I do not know if negative potential means whether the ACK signal is true or false. In order to get the latest sources, which report the line status waited for from the SCSI2Pi perspective, please run "git pull" and re-compile. Please shut down the service before running make install. There is no need to reboot. After make install you can just re-start the service.
Can you please also check the status of the REQ line during the 3 s SCSI2Pi is waiting for ACK to change? During the handshake the Pi manages the REQ line, while the Mac manages the ACK line.
I mixed up the pins on the connector, forget about the potentials. The ACK and REQ lines are low (0V) active. When the ACK line is low in the 3 second phase, the REQ line stays high.
This means that we are at the beginning of the handshake for a new data byte. s2p has set REQ and is waiting for ACK to be set by the Mac (lines 150-152 in bus.cpp of the issue_82 branch):
SetREQ(true);
const bool ack = WaitSignal(PIN_ACK, true); <--- This results in a timeout, i.e. ACK is not set
Please correct me if I am wrong. I would like to confirm this with a logfile from the latest issue_82 branch. Can you please provide the respective log?
Or is it the other way round, because you say "low active"? The log will definitely help me ;-).
I don't know what I'm doing wrong, but the log looks identical to the above one to me.
Mar 4 11:04:38 raspi-rascsi s2p[2394]: [2024-03-04 11:04:38.275] [trace] (ID 6) - ++++ Starting processing for initiator ID 7 Mar 4 11:04:38 raspi-rascsi s2p[2394]: [2024-03-04 11:04:38.275] [trace] (ID 6) - SELECTION phase Mar 4 11:04:38 raspi-rascsi s2p[2394]: [2024-03-04 11:04:38.276] [trace] (ID 6) - COMMAND phase Mar 4 11:04:38 raspi-rascsi s2p[2394]: [2024-03-04 11:04:38.276] [debug] (ID 6) - Controller is executing WRITE(10), CDB $2a:00:00:00:10:6a:00:00:01:00 Mar 4 11:04:38 raspi-rascsi s2p[2394]: [2024-03-04 11:04:38.276] [debug] (ID:LUN 6:0) - Device is executing WRITE(10) ($2a) Mar 4 11:04:38 raspi-rascsi s2p[2394]: [2024-03-04 11:04:38.276] [trace] (ID:LUN 6:0) - READ/WRITE/VERIFY/SEEK, start sector: 4202, sector count: 1 Mar 4 11:04:38 raspi-rascsi s2p[2394]: [2024-03-04 11:04:38.276] [trace] (ID 6) - DATA OUT phase Mar 4 11:04:38 raspi-rascsi s2p[2394]: [2024-03-04 11:04:38.277] [trace] (ID 6) - Receiving 512 byte(s) Mar 4 11:04:41 raspi-rascsi s2p[2394]: [2024-03-04 11:04:41.277] [trace] Timeout while waiting for ACK/REQ to change to false Mar 4 11:04:41 raspi-rascsi s2p[2394]: [2024-03-04 11:04:41.277] [warning] (ID 6) - Received 1 byte(s) in DATA OUT phase, command requires 512 Mar 4 11:04:41 raspi-rascsi s2p[2394]: [2024-03-04 11:04:41.277] [debug] (ID 6) - ABORTED COMMAND (Sense Key $0b), DATA PHASE ERROR (ASC $4b), ASCQ $00 Mar 4 11:04:41 raspi-rascsi s2p[2394]: [2024-03-04 11:04:41.277] [trace] (ID 6) - Status phase, status is CHECK CONDITION (status code $02) Mar 4 11:04:41 raspi-rascsi s2p[2394]: [2024-03-04 11:04:41.277] [trace] (ID 6) - Sending 1 byte(s) Mar 4 11:04:41 raspi-rascsi s2p[2394]: [2024-03-04 11:04:41.277] [trace] (ID 6) - All data transferred Mar 4 11:04:41 raspi-rascsi s2p[2394]: [2024-03-04 11:04:41.277] [trace] (ID 6) - MESSAGE IN phase Mar 4 11:04:41 raspi-rascsi s2p[2394]: [2024-03-04 11:04:41.277] [trace] (ID 6) - Sending 1 byte(s) Mar 4 11:04:41 raspi-rascsi s2p[2394]: [2024-03-04 11:04:41.278] [trace] (ID 6) - All data transferred Mar 4 11:04:41 raspi-rascsi s2p[2394]: [2024-03-04 11:04:41.278] [trace] (ID 6) - BUS FREE phase
pi@raspi-rascsi:~/scsi2pi $ git status Auf Branch issue_82 Ihr Branch ist auf demselben Stand wie 'origin/issue_82'.
Änderungen, die nicht zum Commit vorgemerkt sind:
(benutzen Sie "git add
Ich hab' noch die Änderung aus Issue #71 drin. Soll ich die rausnehmen?
sorry, wrong language ... :-/
:-)
Yes, it is important to remove the changes from #71 and use the unmodified issue_82 branch. Please run these commands:
git reset --hard
git pull
git log -n 1
The commit ID displayed should be 08b33728628c02e81b2781c1fb8e1416cd0ad306
. If this is the case, please recompile.
Mar 4 12:57:20 raspi-rascsi s2p[3094]: [2024-03-04 12:57:20.745] [trace] (ID 6) - ++++ Starting processing for initiator ID 7 Mar 4 12:57:20 raspi-rascsi s2p[3094]: [2024-03-04 12:57:20.745] [trace] (ID 6) - SELECTION phase Mar 4 12:57:20 raspi-rascsi s2p[3094]: [2024-03-04 12:57:20.745] [trace] (ID 6) - COMMAND phase Mar 4 12:57:20 raspi-rascsi s2p[3094]: [2024-03-04 12:57:20.746] [debug] (ID 6) - Controller is executing WRITE(10), CDB $2a:00:00:00:00:64:00:00:01:00 Mar 4 12:57:20 raspi-rascsi s2p[3094]: [2024-03-04 12:57:20.746] [debug] (ID:LUN 6:0) - Device is executing WRITE(10) ($2a) Mar 4 12:57:20 raspi-rascsi s2p[3094]: [2024-03-04 12:57:20.746] [trace] (ID:LUN 6:0) - READ/WRITE/VERIFY/SEEK, start sector: 100, sector count: 1 Mar 4 12:57:20 raspi-rascsi s2p[3094]: [2024-03-04 12:57:20.746] [trace] (ID 6) - DATA OUT phase Mar 4 12:57:20 raspi-rascsi s2p[3094]: [2024-03-04 12:57:20.746] [trace] (ID 6) - Receiving 512 byte(s) Mar 4 12:57:23 raspi-rascsi s2p[3094]: [2024-03-04 12:57:23.747] [trace] Timeout while waiting for ACK/REQ to change to false Mar 4 12:57:23 raspi-rascsi s2p[3094]: [2024-03-04 12:57:23.747] [warning] (ID 6) - Received 275 byte(s) in DATA OUT phase, command requires 512 Mar 4 12:57:23 raspi-rascsi s2p[3094]: [2024-03-04 12:57:23.747] [debug] (ID 6) - ABORTED COMMAND (Sense Key $0b), DATA PHASE ERROR (ASC $4b), ASCQ $00 Mar 4 12:57:23 raspi-rascsi s2p[3094]: [2024-03-04 12:57:23.747] [trace] (ID 6) - Status phase, status is CHECK CONDITION (status code $02) Mar 4 12:57:23 raspi-rascsi s2p[3094]: [2024-03-04 12:57:23.747] [trace] (ID 6) - Sending 1 byte(s) Mar 4 12:57:23 raspi-rascsi s2p[3094]: [2024-03-04 12:57:23.747] [trace] (ID 6) - All data transferred Mar 4 12:57:23 raspi-rascsi s2p[3094]: [2024-03-04 12:57:23.747] [trace] (ID 6) - MESSAGE IN phase Mar 4 12:57:23 raspi-rascsi s2p[3094]: [2024-03-04 12:57:23.747] [trace] (ID 6) - Sending 1 byte(s) Mar 4 12:57:23 raspi-rascsi s2p[3094]: [2024-03-04 12:57:23.748] [trace] (ID 6) - All data transferred Mar 4 12:57:23 raspi-rascsi s2p[3094]: [2024-03-04 12:57:23.748] [trace] (ID 6) - BUS FREE phase
I see on the oszilloscope that the after some handshake (and transmission I think) the ACK line suddenly drops to low and stays there without any REQ. The ACK pulse (answer to the last REQ) before this drop however is very short compared to the other (normal) pulses. Is there a minimum pulse length defined? I try to add a screenshot from the oszilloscope.
No need for a screenshot I guess. There is no minimum pulse length. ACK has to stay asserted until REQ has been released by the target. The target signals this way that it has successfully received the current data byte. This means that the Mac must not clear ACK before the Pi has cleared REQ. Of course, if the Pi never clears REQ the Mac may assume a timeout. And ACK must not be set again until the Pi has set REQ in order to request the next data byte.
So this is actually the affected piece of code:
SetREQ(false);
// Timeout waiting for ACK to change
if (!ack || !WaitSignal(PIN_ACK, false)) {
break;
}
REQ has been set to false by s2p after receiving a data byte, and while s2p is waiting for the Mac to release ACK, s2p times out after 3 s.
I am not an eletronics expert, but is it completely impossible that there is a termination issue? Regarding the Mac Plus I found this:
Power for termination resistors is not provided at the SCSI connector nor is a
termination resistor provided in the Macintosh Plus SCSI circuitry.
No, is not impossible. I switched off both term switches on the rascsi board. The Mac was not amused and hung. After a reset the Mac does not see the disk, does not even try to access it. I think, after receiving one byte (I see ten bits transfered) the Mac reacts very late to the next REQ and then they get out of sync. I found my SC20. I'll compare the patterns.
Impossible to see a difference between SC20 and s2p. SC20 simply works and there is no 3 second down of the ACK signal. Is there any chance to do debugging of traffic between Mac and SC20 via the raspberry? With the oszilloscope I see non related behaviour between REQ and ACK. ACK goes up and down while REQ is constant. It seems to react to something else. Busy maybe? I switched to a Mac Classic and that works also flawlessly. I'm unable to catch a situation comparable to the one with the Mac Plus.
Maybe you can monitor the traffice with the scsimon tool (part of PiSCSI). But I am not sure, I have never used this tool. During the REQ/ACK handshake any other signals remain unchanged, at least s2p/piscsi do not change them. If other signals play a role during the handshake this would indicate a cross-talk issue. Isn't it interesting that there only seems to be an issue with the Mac Plus? I wonder whether there is something special with the Mac Plus and/or the SC20. Maybe Apple added something vendor-specific to it like they did with other drives. Does the SC20 work with the Mac Classic?
The Classic complained about missing drivers on the SC20 and wanted the "Aktualisierer" to run. Actually the Mac is connected to the SC20 (powered off) and to the raspberry. Maybe that messes up the signals.
I opened the 20SC (not SC20, I'm wrong the whole time). It's completely passive. Only a power supply and a fan. Cabling is from the outside connectors to the disk without further electronics.
I did not think of Apple modifying the drive electronics but the firmware. Like they did for other drives (hard drives and CD-ROM drives) in order to force users to purchase expensive Apple SCSI drives instead of cheaper standard drives.
I don't think so. In my 20SC is a random Maxtor 200MB disk and I used the enclosure to connect other disks as well.
Then at least with your setup there does not seem to be anything Apple-specific. With other setups there is, and this is why s2p/piscsi have a custom Apple mode page. Without this mode page some Apple software/drivers do not work because they expect drives with Apple-specific firmware.
I'm actually trying a different approach. As everone is telling Silverlining drivers are the best for the Plus I prepare an image with that driver with the Classic. I messed up my main image which worked last year, so I have to rebuild it anyway.
Good luck, please provide feedback when you have tried the other drivers.
Good morning. We are not fighting the Mac Plus, we are fighting the Mac Plus with drivers other than from Silver Lining. As long as there are only images initialized with Silver Lining on the bus, everything works fine with the Plus. If there is only one image with another driver, the Plus does not boot. Sometimes it plays strange noise, as reported elsewhere with the Lido driver. A PiSCSI formatted image with "Apple+Speedtools" does not work either.
A partition table of a PiSCSI created and with Silver Lining formatted image looks like this (notice the 2nd partition name "Macintosh_SL":
`pi@raspi-rascsi:~/images $ hfdisk -l testdrei.hda testdrei.hda
testdrei.hda1 Apple_partition_map Apple 63 @ 1 ( 31.5k) Partition map testdrei.hda2 Apple_Driver Macintosh_SL 32 @ 64 ( 16.0k) Driver testdrei.hda3 Apple_HFS testdrei 20200 @ 96 ( 9.9M) HFS testdrei.hda4 Apple_Free Extra 168 @ 20296 ( 84.0k) Free space
Block size=512, Number of Blocks=20464 DeviceType=0x1, DeviceId=0x1 Drivers- 1: @ 64 for 11, type=0x1`
Well, I'm afraid from the Pi software perspective I don't see anything that can be done. The analysis has shown that the ACK signal is not set by the Mac Plus, at least not by some drivers, when it has to be. The reason for this is unkonwn, but whatever the reason, the software on the Pi cannot compensate for wrong signals on the bus. This is why I tend to say tickets related to this issue should be closed because SCSI2Pi/PiSCSI cannot resolve this. The only thing that can probably be done is to recommend drivers for the Mac Plus that do not trigger this problem and to avoid those that do. This could be done on the PiSCSI Wiki, for instance, because it contains information valid for both PISCSi and SCSI2Pi.
Sounds good. Thanks for your time.
Thank you for running all these tests. Even though there is no resolution for everything, the actual cause of the problem has become much clearer.
When creating a new ticket please provide information on your environment.
The Pi type: 3 B 1.2
The Pi OS version (output of 'lsb_release -a' and 'uname -a'):
pi@raspi-rascsi:/var/log $ lsb_release -a No LSB modules are available. Distributor ID: Raspbian Description: Raspbian GNU/Linux 11 (bullseye) Release: 11 Codename: bullseye pi@raspi-rascsi:/var/log $ uname -a Linux raspi-rascsi 6.1.21-v7+ #1642 SMP Mon Apr 3 17:20:52 BST 2023 armv7l GNU/Linux
3.0.0
Mac Plus 4MB, System is 6.0.8 from HD20_512-1GB-MacPlus-6+7.hda downloaded from somewhere
Describe the issue
when writing to an image the log says
Mar 3 20:10:12 raspi-rascsi s2p[852]: [2024-03-03 20:10:12.174] [warning] (ID 5) - Received 32 byte(s) in DATA OUT phase, command requires 512 Mar 3 20:10:15 raspi-rascsi s2p[852]: [2024-03-03 20:10:15.266] [warning] (ID 5) - Received 169 byte(s) in DATA OUT phase, command requires 512 Mar 3 20:10:18 raspi-rascsi s2p[852]: [2024-03-03 20:10:18.602] [warning] (ID 5) - Received 467 byte(s) in DATA OUT phase, command requires 512 Mar 3 20:10:21 raspi-rascsi s2p[852]: [2024-03-03 20:10:21.651] [warning] (ID 5) - Received 57 byte(s) in DATA OUT phase, command requires 512
same behaviour with piscsi in issue #656 ...
PiSCSI is the only device on the bus, it ran flawlessly on a Mac Classic last time I used it. That's a year ago however. Both termination switches are on the "on" position.