Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

Add support for READ LONG(10) and WRITE LONG(10) ? #479

Open
Pacjunk opened this issue Nov 23, 2021 · 32 comments · Fixed by #481
Open

Add support for READ LONG(10) and WRITE LONG(10) ? #479

Pacjunk opened this issue Nov 23, 2021 · 32 comments · Fixed by #481
Labels
compatibility Compatibility with particular computing platforms major effort New feature/change with significant implementation effort

Comments

@Pacjunk
Copy link
Contributor

Pacjunk commented Nov 23, 2021

Info

  • Which version of Pi are you using: ZeroW
  • Which github revision of software: develop
  • Which board version: FULLSPEC
  • Which computer is the RaSCSI connected to: OpenVMS

Describe the issue

The OpenVMS SCSI driver "tests" the capability of the drive for the volume shadowing feature by sending hundreds of READ LONG(10) commands when mounting a volume. It seems to ignore the unsupported error message that this creates and keeps trying.

Is it possible to implement these commands - 1. To stop the above issue and 2. It might be fun to support volume shadowing.

I had a look at the code as I thought it might be easy since the CDB layout seems to be the same as the READ(10) and WRITE(10) commands, the only difference being that the length is in bytes, rather than blocks. I'm not a very good C++ programmer, so I find it confusing the way the code is spread amongst several files, there are multiple definitions of functions (which one to use?) and even functions calling themselves. I could start hacking it, but I fear the code will soon become a mess.

Can someone who is confident with the code have a look at the viability of this?

Thanks,

@uweseimet
Copy link
Contributor

uweseimet commented Nov 23, 2021

@Pacjunk Can you please point out which function is calling itself? I don't think this happens anywhere. Of course, code for similar functionailty like READ(6/10/16) is now reused.

In order to add READ/WRITE LONG you might try to copy Read10 and Write10 (see disk.cpp) first, then modify the copied code as needed (maybe no modification is needed at all in your case), and then add the respective AddCommand() calls to the Disk class constructor. In sasidev_ctrl.cpp you have to add eCmdWriteLong10 to the switch in the FlushUnit() method.

Note that the difference between READ/WRITE and READ/WRITE LONG is NOT that the length is in bytes. This is from SBC-3:

The READ LONG (10) command (see table 74) requests that the device server transfer data from a single
logical block or physical block to the Data-In Buffer. The data transferred during the READ LONG (10)
command is vendor specific, but shall include the following items recorded on the medium:
a)if a logical block is being transferred, then:
A) user data or transformed user data for the logical block;
B) protection information or transformed protection information, if any, for the logical block; and
C) any additional information (e.g., ECC bytes) for all the physical blocks in the logical block;
or
b)if a physical block is being transferred, then:
A) user data or transformed user data for all the logical blocks in the physical block;
B) protection information or transformed protection information, if any, for all the logical blocks in the
physical block; and
C) any additional information (e.g., ECC bytes).
If the additional information contain an ECC, then any other additional bytes that are correctable by ECC
should be included (e.g., a data synchronization mark within the area covered by ECC). It is not required for
the ECC bytes to be at the end of the logical block data. The ECC bytes should be in the same order as they
are on the medium.
If a cache contains a more recent version of the specified logical block or physical block, then the device
server shall write the logical block or physical block to the medium before reading it. The values in the
Read-Write Error Recovery mode page (see 6.5.8) do not apply to this command. The device server may
perform retries while processing this command.
This command uses the SERVICE ACTION IN (16) CDB format (see A.2).
NOTE 14 - Migration from the READ LONG (10) command to the READ LONG (16) command is
recommended for all implementations.

The OPERATION CODE field is defined in SPC-4 and shall be set to the value shown in table 74 for the READ
LONG (10) command.
If there is more than one logical block per physical block (i.e., the LOGICAL BLOCKS PER PHYSICAL BLOCK
EXPONENT field in the READ CAPACITY (16) parameter data (see 5.16.2) is set to a non-zero value), then:
a) the device server shall support the physical block (PBLOCK) bit;
b) a PBLOCK bit set to one specifies that the device server shall return the entire physical block containing
the specified logical block; and
c) a PBLOCK bit set to zero specifies that the device server shall return bytes representing only the
specified logical block.
If there are one or more physical blocks per logical block (i.e., the LOGICAL BLOCKS PER PHYSICAL BLOCK
EXPONENT field in the READ CAPACITY (16) parameter data (see 5.16.2) is set to zero), and the PBLOCK bit is
set to one, then the device server shall terminate the command with CHECK CONDITION status with the
sense key set to ILLEGAL REQUEST and the additional sense code set to INVALID FIELD IN CDB.
A correct (CORRCT) bit set to zero specifies that a logical block be read without any correction made by the
device server. A CORRCT bit set to zero should result in the device server completing the command with
GOOD status unless data is not transferred for some reason other than that the data is non-correctable. In this
case the device server shall complete or terminate the command with the appropriate status and sense data.
A CORRCT bit set to one specifies that the data be corrected by ECC before being transferred to the Data-In
Buffer.
The LOGICAL BLOCK ADDRESS field specifies an LBA (see 4.5). If the specified LBA exceeds the capacity of the
medium (see 4.5), then the device server shall terminate the command with CHECK CONDITION status with
the sense key set to ILLEGAL REQUEST and the additional sense code set to LOGICAL BLOCK ADDRESS
OUT OF RANGE.
The BYTE TRANSFER LENGTH field specifies the number of bytes of data that shall be read from the specified
logical block or physical block and transferred to the Data-In Buffer. If the BYTE TRANSFER LENGTH field is not
set to zero and does not match the available data length, then the device server shall terminate the command
with CHECK CONDITION status with the sense key set to ILLEGAL REQUEST and the additional sense code
set to INVALID FIELD IN CDB. In the sense data (see 4.18 and SPC-4), the VALID bit shall be set to one and
the ILI bit shall each be set to one, and the INFORMATION field shall be set to the difference (i.e., residue) of the
requested byte transfer length minus the actual available data length in bytes. Negative values shall be
indicated by two's complement notation.
A BYTE TRANSFER LENGTH field set to zero specifies that no bytes shall be read. This condition shall not be
considered an error.
The CONTROL byte is defined in SAM-5.

By the way, READ LONG (but not WRITE LONG) is legacy and not supported anymore since SBC-4 from 2020.

@Pacjunk
Copy link
Contributor Author

Pacjunk commented Nov 23, 2021

I know it's legacy, but we're generally dealing with legacy machines here!

From your text above:

The BYTE TRANSFER LENGTH field specifies the number of bytes of data that shall be read from the specified
logical block or physical block and transferred to the Data-In Buffer.

I can have a go at it, but it's going to be a mess...

void Disk::Read(SASIDEV *controller, uint64_t record)
{
	ctrl->length = Read(ctrl->cmd, ctrl->buffer, record);

I find this stuff confusing. I can see that there are two functions called "Read", this must be referring to the second one. As I say, my C++ skills are poor, and this sort of thing doesn't help.

Thanks,

@uweseimet
Copy link
Contributor

uweseimet commented Nov 23, 2021

@Pacjunk When I mentioned that these commands are legacy I was not my intention to say they should not be implemented. This was just meant to be a general note, but I should have been clearer on that.
Regarding the transfer length your are right.I missed that the transfer length for READ/WRITE is something different.

Yes, there are two Reads(). From their signature one can see which is the right one.

Unfortunately, the RaSCSI project appears to lack C++ contributors, even though almost everything is coded in C++.

@Pacjunk Can you attach a log on trace level that shows some of the READ LONG commands being sent?

@uweseimet
Copy link
Contributor

uweseimet commented Nov 23, 2021

@Pacjunk I just had a quick look at the existing code. Currently the code can only deal with full blocks and not just a part of a block sequence (limited by the LONG transfer length). Changing this in order to support READ/WRITE LONG looks like a major change to me. Testing this would be difficult because you may be one of the few or even the only one with the required hardware. Unit tests would help, but there are none, and the automated testing issue (#17) has not been updated for more than a year.

Nevertheless, adding a log (see my last comment) to this ticket would definitely be useful, in order to see the CDB parameters used.

Implementation note: In case somebody wants to work on this ticket, I suggest not to change the existing READ/WRITE code, including the DATA IN and DATA OUT phase code at all, at least not in the first implementation iteration. The danger of breaking the existing code is simply too high, in particular because unit tests and test automation are missing.

@Pacjunk
Copy link
Contributor Author

Pacjunk commented Nov 24, 2021

Here is the log extract...

It is not reading anything meaningful, just testing the capability. It requests LBA0, length 0, then length 1, then length $0200, then seems to increment by 1 all the way up to $0400. So lots of commands. Don't know why it ignores the returned error.

Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.663] [trace] virtual void SASIDEV::Command() Command Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.663] [trace] virtual void SASIDEV::Command() Command Byte 0: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.663] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.663] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.663] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.663] [trace] virtual void SASIDEV::Command() Command Byte 4: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.664] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.664] [trace] virtual void SASIDEV::Command() Command Byte 6: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.664] [trace] virtual void SASIDEV::Command() Command Byte 7: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.664] [trace] virtual void SASIDEV::Command() Command Byte 8: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.664] [trace] virtual void SASIDEV::Command() Command Byte 9: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.664] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.664] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.664] [trace] ID 0 LUN 0 received unsupported command: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.664] [debug] Error status: Sense Key $05, ASC $20, ASCQ $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.664] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.664] [trace] void SASIDEV::Status() Status phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.664] [trace] void SASIDEV::Status() Status Phase $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.664] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.665] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.665] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.665] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.665] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.665] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.665] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.665] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.666] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.666] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.666] [trace] Message Out Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.666] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.666] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.666] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.666] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.666] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.666] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.666] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.666] [trace] virtual void SASIDEV::Command() Command Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.667] [trace] virtual void SASIDEV::Command() Command Byte 0: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.667] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.667] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.667] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.667] [trace] virtual void SASIDEV::Command() Command Byte 4: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.667] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.667] [trace] virtual void SASIDEV::Command() Command Byte 6: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.667] [trace] virtual void SASIDEV::Command() Command Byte 7: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.667] [trace] virtual void SASIDEV::Command() Command Byte 8: $01
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.667] [trace] virtual void SASIDEV::Command() Command Byte 9: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.667] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.667] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.667] [trace] ID 0 LUN 0 received unsupported command: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.667] [debug] Error status: Sense Key $05, ASC $20, ASCQ $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.668] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.668] [trace] void SASIDEV::Status() Status phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.668] [trace] void SASIDEV::Status() Status Phase $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.668] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.668] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.668] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.668] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.668] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.668] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.669] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.669] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.669] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.669] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.669] [trace] Message Out Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.669] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.669] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.669] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.669] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.669] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.669] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.670] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.670] [trace] virtual void SASIDEV::Command() Command Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.670] [trace] virtual void SASIDEV::Command() Command Byte 0: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.670] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.670] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.670] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.670] [trace] virtual void SASIDEV::Command() Command Byte 4: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.670] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.670] [trace] virtual void SASIDEV::Command() Command Byte 6: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.670] [trace] virtual void SASIDEV::Command() Command Byte 7: $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.670] [trace] virtual void SASIDEV::Command() Command Byte 8: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.670] [trace] virtual void SASIDEV::Command() Command Byte 9: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.671] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.671] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.671] [trace] ID 0 LUN 0 received unsupported command: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.671] [debug] Error status: Sense Key $05, ASC $20, ASCQ $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.671] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.671] [trace] void SASIDEV::Status() Status phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.671] [trace] void SASIDEV::Status() Status Phase $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.671] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.671] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.671] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.671] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.672] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.672] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.672] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.672] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.672] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.672] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.672] [trace] Message Out Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.672] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.672] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.672] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.673] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.673] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.673] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.673] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.673] [trace] virtual void SASIDEV::Command() Command Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.673] [trace] virtual void SASIDEV::Command() Command Byte 0: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.673] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.673] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.673] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.673] [trace] virtual void SASIDEV::Command() Command Byte 4: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.673] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.673] [trace] virtual void SASIDEV::Command() Command Byte 6: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.674] [trace] virtual void SASIDEV::Command() Command Byte 7: $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.674] [trace] virtual void SASIDEV::Command() Command Byte 8: $01
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.674] [trace] virtual void SASIDEV::Command() Command Byte 9: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.674] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.674] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.674] [trace] ID 0 LUN 0 received unsupported command: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.674] [debug] Error status: Sense Key $05, ASC $20, ASCQ $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.674] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.674] [trace] void SASIDEV::Status() Status phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.674] [trace] void SASIDEV::Status() Status Phase $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.674] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.675] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.675] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.675] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.675] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.675] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.675] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.675] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.675] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.676] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.676] [trace] Message Out Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.676] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.676] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.676] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.676] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.676] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.676] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.676] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.676] [trace] virtual void SASIDEV::Command() Command Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.676] [trace] virtual void SASIDEV::Command() Command Byte 0: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.676] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.677] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.677] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.677] [trace] virtual void SASIDEV::Command() Command Byte 4: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.677] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.677] [trace] virtual void SASIDEV::Command() Command Byte 6: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.677] [trace] virtual void SASIDEV::Command() Command Byte 7: $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.677] [trace] virtual void SASIDEV::Command() Command Byte 8: $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.677] [trace] virtual void SASIDEV::Command() Command Byte 9: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.677] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.677] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.677] [trace] ID 0 LUN 0 received unsupported command: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.677] [debug] Error status: Sense Key $05, ASC $20, ASCQ $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.677] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.677] [trace] void SASIDEV::Status() Status phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.677] [trace] void SASIDEV::Status() Status Phase $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.678] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.678] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.678] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.678] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.678] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.678] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.678] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.678] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.679] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.679] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.679] [trace] Message Out Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.679] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.679] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.679] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.679] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.679] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.679] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.679] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.679] [trace] virtual void SASIDEV::Command() Command Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.680] [trace] virtual void SASIDEV::Command() Command Byte 0: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.680] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.680] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.680] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.680] [trace] virtual void SASIDEV::Command() Command Byte 4: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.680] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.680] [trace] virtual void SASIDEV::Command() Command Byte 6: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.680] [trace] virtual void SASIDEV::Command() Command Byte 7: $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.680] [trace] virtual void SASIDEV::Command() Command Byte 8: $03
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.680] [trace] virtual void SASIDEV::Command() Command Byte 9: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.680] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.680] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.680] [trace] ID 0 LUN 0 received unsupported command: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.681] [debug] Error status: Sense Key $05, ASC $20, ASCQ $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.681] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.681] [trace] void SASIDEV::Status() Status phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.681] [trace] void SASIDEV::Status() Status Phase $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.681] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.681] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.681] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.681] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.681] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:58.682] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.297] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.297] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.297] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.297] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.297] [trace] Message Out Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.297] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.297] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.297] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [trace] virtual void SASIDEV::Command() Command Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [trace] virtual void SASIDEV::Command() Command Byte 0: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [trace] virtual void SASIDEV::Command() Command Byte 4: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [trace] virtual void SASIDEV::Command() Command Byte 6: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [trace] virtual void SASIDEV::Command() Command Byte 7: $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [trace] virtual void SASIDEV::Command() Command Byte 8: $05
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [trace] virtual void SASIDEV::Command() Command Byte 9: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.298] [trace] ID 0 LUN 0 received unsupported command: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.299] [debug] Error status: Sense Key $05, ASC $20, ASCQ $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.299] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.299] [trace] void SASIDEV::Status() Status phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.299] [trace] void SASIDEV::Status() Status Phase $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.299] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.299] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.299] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.299] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.299] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.299] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.299] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.299] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.300] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.300] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.300] [trace] Message Out Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.300] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.300] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.300] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.300] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.300] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.300] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.300] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.300] [trace] virtual void SASIDEV::Command() Command Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.300] [trace] virtual void SASIDEV::Command() Command Byte 0: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.300] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.300] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.300] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.300] [trace] virtual void SASIDEV::Command() Command Byte 4: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.301] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.301] [trace] virtual void SASIDEV::Command() Command Byte 6: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.301] [trace] virtual void SASIDEV::Command() Command Byte 7: $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.301] [trace] virtual void SASIDEV::Command() Command Byte 8: $06
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.301] [trace] virtual void SASIDEV::Command() Command Byte 9: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.301] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.301] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.301] [trace] ID 0 LUN 0 received unsupported command: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.301] [debug] Error status: Sense Key $05, ASC $20, ASCQ $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.301] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.301] [trace] void SASIDEV::Status() Status phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.301] [trace] void SASIDEV::Status() Status Phase $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.301] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.301] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.301] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.301] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.301] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.302] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.302] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.302] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.302] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.302] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.302] [trace] Message Out Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.302] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.302] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.302] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.302] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.302] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.302] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.302] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.302] [trace] virtual void SASIDEV::Command() Command Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [trace] virtual void SASIDEV::Command() Command Byte 0: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [trace] virtual void SASIDEV::Command() Command Byte 4: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [trace] virtual void SASIDEV::Command() Command Byte 6: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [trace] virtual void SASIDEV::Command() Command Byte 7: $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [trace] virtual void SASIDEV::Command() Command Byte 8: $07
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [trace] virtual void SASIDEV::Command() Command Byte 9: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [trace] ID 0 LUN 0 received unsupported command: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [debug] Error status: Sense Key $05, ASC $20, ASCQ $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [trace] void SASIDEV::Status() Status phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [trace] void SASIDEV::Status() Status Phase $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.303] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.304] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.304] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.304] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.304] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.304] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.304] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.304] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.304] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.304] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.304] [trace] Message Out Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.304] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] virtual void SASIDEV::Command() Command Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] virtual void SASIDEV::Command() Command Byte 0: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] virtual void SASIDEV::Command() Command Byte 4: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] virtual void SASIDEV::Command() Command Byte 6: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] virtual void SASIDEV::Command() Command Byte 7: $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] virtual void SASIDEV::Command() Command Byte 8: $08
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] virtual void SASIDEV::Command() Command Byte 9: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.305] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.306] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.306] [trace] ID 0 LUN 0 received unsupported command: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.306] [debug] Error status: Sense Key $05, ASC $20, ASCQ $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.306] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.306] [trace] void SASIDEV::Status() Status phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.306] [trace] void SASIDEV::Status() Status Phase $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.306] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.306] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.306] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.306] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.306] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.306] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.306] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.306] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.307] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.307] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.307] [trace] Message Out Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.307] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.307] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.307] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.307] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.307] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.307] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.307] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.307] [trace] virtual void SASIDEV::Command() Command Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.307] [trace] virtual void SASIDEV::Command() Command Byte 0: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.307] [trace] virtual void SASIDEV::Command() Command Byte 1: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.307] [trace] virtual void SASIDEV::Command() Command Byte 2: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.307] [trace] virtual void SASIDEV::Command() Command Byte 3: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.308] [trace] virtual void SASIDEV::Command() Command Byte 4: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.308] [trace] virtual void SASIDEV::Command() Command Byte 5: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.308] [trace] virtual void SASIDEV::Command() Command Byte 6: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.308] [trace] virtual void SASIDEV::Command() Command Byte 7: $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.308] [trace] virtual void SASIDEV::Command() Command Byte 8: $09
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.308] [trace] virtual void SASIDEV::Command() Command Byte 9: $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.308] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.308] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.308] [trace] ID 0 LUN 0 received unsupported command: $3E
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.308] [debug] Error status: Sense Key $05, ASC $20, ASCQ $00
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.308] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.308] [trace] void SASIDEV::Status() Status phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.308] [trace] void SASIDEV::Status() Status Phase $02
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.308] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.308] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.308] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.308] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.309] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.309] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.309] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.309] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.309] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.309] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.309] [trace] Message Out Phase
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.309] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.309] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.309] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.309] [trace] void SCSIDEV::MsgOut() ID 0
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.309] [trace] virtual void SCSIDEV::Receive()
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.309] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.309] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 24 15:25:59 raspberrypi RASCSI[431]: [2021-11-24 15:25:59.310] [trace] virtual void SASIDEV::Command() Command Phase

@uweseimet
Copy link
Contributor

uweseimet commented Nov 24, 2021

@Pacjunk Did you notice that $0204 is omitted during these incremental reads? Most likely this means that a sector size of 516 bytes is something special for OpenVMS. Any idea? I dimly remember that there were operating systems using/supporting unusual sector sizes. Maybe the additional 4 bytes are supposed to contain a checksum for the respective sector or other meta data related to that sector.

It's interesting that a READ LONG with a transfer length of 0 bytes is sent. I wonder which information OpenVMS derives from the result. If it were just for finding out whether READ LONG is supported at all, the SCSI error response should tell. On the other hand, if you wanted to find out whether READ LONG is supported you would probably try with a length of 0. If you deduce from the result that it is actually supported you might continue with the minimum length you would need in order to store data, e.g. 512 bytes. And if you wanted to also find out whether you can store sector-related meta data, you might try to find out how many excess bytes there are by reading again and again, and each time incrementing the length by 1. All in all you would end up with a sequence similar to what we see in the logs. I wonder whether OpenVMS just expects a different SCSI error message in order to deduce that READ LONG is not available at all.

https://forums.gentoo.org/viewtopic-p-3502086.html?sid=5a023a282ae59b47c4591923e546e80e mentions drives formatted with a block sizes of 516 bytes, by the way. I have a FUJITSU drive which can be formatted with different sector sizes, but I never had any use for sizes other than 512, 1024 and 2048.

@uweseimet
Copy link
Contributor

uweseimet commented Nov 24, 2021

@Pacjunk I re-read the spec and this may be important:

A BYTE TRANSFER LENGTH field set to zero specifies that no bytes shall be read. This condition shall not be
considered an error.

This is not what RaSCSI currently does. I wonder if I should give it a try and implement a partial READ LONG, which in this special case does not return an error, but does in all other cases. This would not require substantial code changes because no data have to be returned.

@uweseimet
Copy link
Contributor

uweseimet commented Nov 24, 2021

@Pacjunk Now it's your turn: Feature branch is 'feature_read_long'. The implementations for READ/WRITE LONG 10 accept a transfer length of 0 and in this case do not return an error. Any other length results in INVALID_FIELD_IN_CDB, which is IMO compliant with the standard.
Regardless of the testing outcome, please attach a log on trace level.

@uweseimet uweseimet linked a pull request Nov 24, 2021 that will close this issue
@Pacjunk
Copy link
Contributor Author

Pacjunk commented Nov 24, 2021

Yes, I was thinking of this as a first step. Just return a success for the 0 length request and see what happens. I just had a look at the dump I did from bluescsi, and the $0204 length is in there so I don't think there is anything tricky going on. Maybe too much logging and it skipped one - it does take a long time to do things when trace logging is turned on.

The READ (10) command also specifies that 0 blocks is not an error!

I will checkout your change, but don't think I'll be able to test it tonight (10pm now). Will get to it in the morning.

@uweseimet
Copy link
Contributor

uweseimet commented Nov 24, 2021

@Pacjunk I don't think that READ(10) currently reports an error if 0 blocks is specified, i.e. the implementation of READ(10) should be fine.

@Pacjunk When looking at your log's timestamps I don't see that the command with length $0204 is missing in the logs, but it was never sent. Please double-check, but I don't see a gap in the timestamps between the last log message of $0203 and the first in $0205, i.e. there cannot have been any command in between.

@uweseimet
Copy link
Contributor

uweseimet commented Nov 24, 2021

Log excerpts from testing with an Atari, trying to transfer 0, 1 and 512 bytes:

[2021-11-24 16:29:06.110] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2021-11-24 16:29:06.110] [trace] void SCSIDEV::MsgOut() ID 6
[2021-11-24 16:29:06.110] [trace] Message Out Phase
[2021-11-24 16:29:06.111] [trace] void SCSIDEV::MsgOut() ID 6
[2021-11-24 16:29:06.111] [trace] virtual void SCSIDEV::Receive()
[2021-11-24 16:29:06.111] [trace] virtual void SCSIDEV::Receive() length was != 0
[2021-11-24 16:29:06.111] [trace] void SCSIDEV::MsgOut() ID 6
[2021-11-24 16:29:06.111] [trace] virtual void SCSIDEV::Receive()
[2021-11-24 16:29:06.111] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
[2021-11-24 16:29:06.111] [trace] Message code IDENTIFY $80, LUN 0 selected
[2021-11-24 16:29:06.111] [trace] virtual void SASIDEV::Command() Command Phase
[2021-11-24 16:29:06.111] [trace] virtual void SASIDEV::Command() CDB[0]=$3E
[2021-11-24 16:29:06.111] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2021-11-24 16:29:06.111] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2021-11-24 16:29:06.111] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2021-11-24 16:29:06.111] [trace] virtual void SASIDEV::Command() CDB[4]=$00
[2021-11-24 16:29:06.111] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2021-11-24 16:29:06.111] [trace] virtual void SASIDEV::Command() CDB[6]=$00
[2021-11-24 16:29:06.112] [trace] virtual void SASIDEV::Command() CDB[7]=$00
[2021-11-24 16:29:06.112] [trace] virtual void SASIDEV::Command() CDB[8]=$00
[2021-11-24 16:29:06.112] [trace] virtual void SASIDEV::Command() CDB[9]=$00
[2021-11-24 16:29:06.112] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
[2021-11-24 16:29:06.112] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
[2021-11-24 16:29:06.112] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ReadLong10 ($3E)
[2021-11-24 16:29:06.112] [trace] void SASIDEV::Status() Status phase
[2021-11-24 16:29:06.112] [trace] void SASIDEV::Status() Status Phase $00
[2021-11-24 16:29:06.112] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[2021-11-24 16:29:06.112] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2021-11-24 16:29:06.112] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2021-11-24 16:29:06.112] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2021-11-24 16:29:06.112] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[2021-11-24 16:29:06.112] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2021-11-24 16:29:06.112] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2021-11-24 16:29:06.112] [trace] virtual void SCSIDEV::BusFree() Bus free phase
[2021-11-24 16:29:06.115] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2021-11-24 16:29:06.115] [trace] void SCSIDEV::MsgOut() ID 6
[2021-11-24 16:29:06.115] [trace] Message Out Phase
[2021-11-24 16:29:06.115] [trace] void SCSIDEV::MsgOut() ID 6
[2021-11-24 16:29:06.115] [trace] virtual void SCSIDEV::Receive()
[2021-11-24 16:29:06.115] [trace] virtual void SCSIDEV::Receive() length was != 0
[2021-11-24 16:29:06.115] [trace] void SCSIDEV::MsgOut() ID 6
[2021-11-24 16:29:06.115] [trace] virtual void SCSIDEV::Receive()
[2021-11-24 16:29:06.115] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
[2021-11-24 16:29:06.115] [trace] Message code IDENTIFY $80, LUN 0 selected
[2021-11-24 16:29:06.115] [trace] virtual void SASIDEV::Command() Command Phase
[2021-11-24 16:29:06.116] [trace] virtual void SASIDEV::Command() CDB[0]=$3E
[2021-11-24 16:29:06.116] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2021-11-24 16:29:06.116] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2021-11-24 16:29:06.116] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2021-11-24 16:29:06.116] [trace] virtual void SASIDEV::Command() CDB[4]=$00
[2021-11-24 16:29:06.116] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2021-11-24 16:29:06.116] [trace] virtual void SASIDEV::Command() CDB[6]=$00
[2021-11-24 16:29:06.116] [trace] virtual void SASIDEV::Command() CDB[7]=$00
[2021-11-24 16:29:06.116] [trace] virtual void SASIDEV::Command() CDB[8]=$01
[2021-11-24 16:29:06.116] [trace] virtual void SASIDEV::Command() CDB[9]=$00
[2021-11-24 16:29:06.116] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
[2021-11-24 16:29:06.116] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
[2021-11-24 16:29:06.116] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ReadLong10 ($3E)
[2021-11-24 16:29:06.116] [debug] Error status: Sense Key $05, ASC $24, ASCQ $00
[2021-11-24 16:29:06.116] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
[2021-11-24 16:29:06.116] [trace] void SASIDEV::Status() Status phase
[2021-11-24 16:29:06.116] [trace] void SASIDEV::Status() Status Phase $02
[2021-11-24 16:29:06.116] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[2021-11-24 16:29:06.116] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2021-11-24 16:29:06.116] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2021-11-24 16:29:06.116] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2021-11-24 16:29:06.117] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[2021-11-24 16:29:06.117] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2021-11-24 16:29:06.117] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2021-11-24 16:29:06.117] [trace] virtual void SCSIDEV::BusFree() Bus free phase
...
[2021-11-24 16:29:06.123] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=6 (with device)
[2021-11-24 16:29:06.123] [trace] void SCSIDEV::MsgOut() ID 6
[2021-11-24 16:29:06.123] [trace] Message Out Phase
[2021-11-24 16:29:06.123] [trace] void SCSIDEV::MsgOut() ID 6
[2021-11-24 16:29:06.123] [trace] virtual void SCSIDEV::Receive()
[2021-11-24 16:29:06.123] [trace] virtual void SCSIDEV::Receive() length was != 0
[2021-11-24 16:29:06.123] [trace] void SCSIDEV::MsgOut() ID 6
[2021-11-24 16:29:06.123] [trace] virtual void SCSIDEV::Receive()
[2021-11-24 16:29:06.123] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
[2021-11-24 16:29:06.123] [trace] Message code IDENTIFY $80, LUN 0 selected
[2021-11-24 16:29:06.123] [trace] virtual void SASIDEV::Command() Command Phase
[2021-11-24 16:29:06.124] [trace] virtual void SASIDEV::Command() CDB[0]=$3E
[2021-11-24 16:29:06.124] [trace] virtual void SASIDEV::Command() CDB[1]=$00
[2021-11-24 16:29:06.124] [trace] virtual void SASIDEV::Command() CDB[2]=$00
[2021-11-24 16:29:06.124] [trace] virtual void SASIDEV::Command() CDB[3]=$00
[2021-11-24 16:29:06.124] [trace] virtual void SASIDEV::Command() CDB[4]=$00
[2021-11-24 16:29:06.124] [trace] virtual void SASIDEV::Command() CDB[5]=$00
[2021-11-24 16:29:06.124] [trace] virtual void SASIDEV::Command() CDB[6]=$00
[2021-11-24 16:29:06.124] [trace] virtual void SASIDEV::Command() CDB[7]=$02
[2021-11-24 16:29:06.124] [trace] virtual void SASIDEV::Command() CDB[8]=$00
[2021-11-24 16:29:06.124] [trace] virtual void SASIDEV::Command() CDB[9]=$00
[2021-11-24 16:29:06.124] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
[2021-11-24 16:29:06.124] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
[2021-11-24 16:29:06.124] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ReadLong10 ($3E)
[2021-11-24 16:29:06.124] [debug] Error status: Sense Key $05, ASC $24, ASCQ $00
[2021-11-24 16:29:06.124] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
[2021-11-24 16:29:06.124] [trace] void SASIDEV::Status() Status phase
[2021-11-24 16:29:06.124] [trace] void SASIDEV::Status() Status Phase $02
[2021-11-24 16:29:06.124] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[2021-11-24 16:29:06.124] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
[2021-11-24 16:29:06.124] [trace] void SASIDEV::MsgIn() Starting Message in phase
[2021-11-24 16:29:06.124] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2021-11-24 16:29:06.124] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
[2021-11-24 16:29:06.124] [trace] void SASIDEV::MsgIn() Transitioning to Send()
[2021-11-24 16:29:06.125] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
[2021-11-24 16:29:06.125] [trace] virtual void SCSIDEV::BusFree() Bus free phase

I ran the same tests against a real IBM DDRS-39130 drive. The drive was fine with a transfer length of 0, but refused to transfer 1 or 512 bytes. For these refused transfer lengths the IBM drive reported the same SCSI error codes as RaSCSI, i.e Sense Key $05 and ASC $24.

@Pacjunk
Copy link
Contributor Author

Pacjunk commented Nov 25, 2021

Here is the next dump... I don't know why $0204 is still missing. It still steps through to $0400, and the drive is marked as not compatible.

Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.740] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.740] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.740] [trace] Message Out Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.740] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.740] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.740] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.740] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.740] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.740] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.741] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.741] [trace] virtual void SASIDEV::Command() Command Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.741] [trace] virtual void SASIDEV::Command() CDB[0]=$3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.741] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.741] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.741] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.741] [trace] virtual void SASIDEV::Command() CDB[4]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.741] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.741] [trace] virtual void SASIDEV::Command() CDB[6]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.741] [trace] virtual void SASIDEV::Command() CDB[7]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.741] [trace] virtual void SASIDEV::Command() CDB[8]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.741] [trace] virtual void SASIDEV::Command() CDB[9]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.742] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.742] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.742] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ReadLong10 ($3E)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.742] [trace] void SASIDEV::Status() Status phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.742] [trace] void SASIDEV::Status() Status Phase $00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.742] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.742] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.742] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.742] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.743] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.743] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.743] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.743] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.743] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.743] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.743] [trace] Message Out Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.743] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.743] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.744] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.744] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.744] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.744] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.744] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.744] [trace] virtual void SASIDEV::Command() Command Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.744] [trace] virtual void SASIDEV::Command() CDB[0]=$3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.744] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.744] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.744] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.744] [trace] virtual void SASIDEV::Command() CDB[4]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.744] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.744] [trace] virtual void SASIDEV::Command() CDB[6]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.745] [trace] virtual void SASIDEV::Command() CDB[7]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.745] [trace] virtual void SASIDEV::Command() CDB[8]=$01
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.745] [trace] virtual void SASIDEV::Command() CDB[9]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.745] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.745] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.745] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ReadLong10 ($3E)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.745] [debug] Error status: Sense Key $05, ASC $24, ASCQ $00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.745] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.745] [trace] void SASIDEV::Status() Status phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.745] [trace] void SASIDEV::Status() Status Phase $02
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.745] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.746] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.746] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.746] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.746] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.746] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.746] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.746] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.746] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.746] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.747] [trace] Message Out Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.747] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.747] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.747] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.747] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.747] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.747] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.747] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.747] [trace] virtual void SASIDEV::Command() Command Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.747] [trace] virtual void SASIDEV::Command() CDB[0]=$3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.747] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.747] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.748] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.748] [trace] virtual void SASIDEV::Command() CDB[4]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.748] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.748] [trace] virtual void SASIDEV::Command() CDB[6]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.748] [trace] virtual void SASIDEV::Command() CDB[7]=$02
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.748] [trace] virtual void SASIDEV::Command() CDB[8]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.748] [trace] virtual void SASIDEV::Command() CDB[9]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.748] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.748] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.748] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ReadLong10 ($3E)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.748] [debug] Error status: Sense Key $05, ASC $24, ASCQ $00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.748] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.748] [trace] void SASIDEV::Status() Status phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.748] [trace] void SASIDEV::Status() Status Phase $02
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.748] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.749] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.749] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.749] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.749] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.749] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.749] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.749] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.750] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.750] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.750] [trace] Message Out Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.750] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.750] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.750] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.750] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.750] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.750] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.750] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.750] [trace] virtual void SASIDEV::Command() Command Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.750] [trace] virtual void SASIDEV::Command() CDB[0]=$3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.751] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.751] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.751] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.751] [trace] virtual void SASIDEV::Command() CDB[4]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.751] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.751] [trace] virtual void SASIDEV::Command() CDB[6]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.751] [trace] virtual void SASIDEV::Command() CDB[7]=$02
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.751] [trace] virtual void SASIDEV::Command() CDB[8]=$01
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.751] [trace] virtual void SASIDEV::Command() CDB[9]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.751] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.751] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.751] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ReadLong10 ($3E)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.751] [debug] Error status: Sense Key $05, ASC $24, ASCQ $00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.751] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.751] [trace] void SASIDEV::Status() Status phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.752] [trace] void SASIDEV::Status() Status Phase $02
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.752] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.752] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.752] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.752] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.752] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.752] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.753] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.753] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.753] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.753] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.753] [trace] Message Out Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.753] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.753] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.753] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.753] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.753] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.753] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.754] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.754] [trace] virtual void SASIDEV::Command() Command Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.754] [trace] virtual void SASIDEV::Command() CDB[0]=$3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.754] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.754] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.754] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.754] [trace] virtual void SASIDEV::Command() CDB[4]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.754] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.754] [trace] virtual void SASIDEV::Command() CDB[6]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.754] [trace] virtual void SASIDEV::Command() CDB[7]=$02
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.754] [trace] virtual void SASIDEV::Command() CDB[8]=$02
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.754] [trace] virtual void SASIDEV::Command() CDB[9]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.754] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.755] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.755] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ReadLong10 ($3E)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.755] [debug] Error status: Sense Key $05, ASC $24, ASCQ $00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.755] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.755] [trace] void SASIDEV::Status() Status phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.755] [trace] void SASIDEV::Status() Status Phase $02
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.755] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.755] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.755] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.755] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.755] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.756] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.756] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.756] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.756] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.756] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.756] [trace] Message Out Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.756] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.756] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.756] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.757] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.757] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.757] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.757] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.757] [trace] virtual void SASIDEV::Command() Command Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.757] [trace] virtual void SASIDEV::Command() CDB[0]=$3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.757] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.757] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.757] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.757] [trace] virtual void SASIDEV::Command() CDB[4]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.757] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.757] [trace] virtual void SASIDEV::Command() CDB[6]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.757] [trace] virtual void SASIDEV::Command() CDB[7]=$02
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.758] [trace] virtual void SASIDEV::Command() CDB[8]=$03
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.758] [trace] virtual void SASIDEV::Command() CDB[9]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.758] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.758] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.758] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ReadLong10 ($3E)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.758] [debug] Error status: Sense Key $05, ASC $24, ASCQ $00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.758] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.758] [trace] void SASIDEV::Status() Status phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.758] [trace] void SASIDEV::Status() Status Phase $02
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.758] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.759] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.759] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.759] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.759] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.759] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.759] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:17.759] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.371] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.371] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.372] [trace] Message Out Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.372] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.372] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.372] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.372] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.372] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.372] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.372] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.372] [trace] virtual void SASIDEV::Command() Command Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.372] [trace] virtual void SASIDEV::Command() CDB[0]=$3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.372] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.372] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.372] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.372] [trace] virtual void SASIDEV::Command() CDB[4]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.372] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.372] [trace] virtual void SASIDEV::Command() CDB[6]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.373] [trace] virtual void SASIDEV::Command() CDB[7]=$02
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.373] [trace] virtual void SASIDEV::Command() CDB[8]=$05
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.373] [trace] virtual void SASIDEV::Command() CDB[9]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.373] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.373] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.373] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ReadLong10 ($3E)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.373] [debug] Error status: Sense Key $05, ASC $24, ASCQ $00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.373] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.373] [trace] void SASIDEV::Status() Status phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.373] [trace] void SASIDEV::Status() Status Phase $02
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.373] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.373] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.373] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.373] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.373] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.374] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.374] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.374] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.374] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.374] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.374] [trace] Message Out Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.374] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.374] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.374] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.374] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.374] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.374] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.374] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.374] [trace] virtual void SASIDEV::Command() Command Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [trace] virtual void SASIDEV::Command() CDB[0]=$3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [trace] virtual void SASIDEV::Command() CDB[4]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [trace] virtual void SASIDEV::Command() CDB[6]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [trace] virtual void SASIDEV::Command() CDB[7]=$02
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [trace] virtual void SASIDEV::Command() CDB[8]=$06
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [trace] virtual void SASIDEV::Command() CDB[9]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ReadLong10 ($3E)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [debug] Error status: Sense Key $05, ASC $24, ASCQ $00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [trace] void SASIDEV::Status() Status phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [trace] void SASIDEV::Status() Status Phase $02
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.375] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.376] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.376] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.376] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.376] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.376] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.376] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.376] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.376] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.376] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.376] [trace] Message Out Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] virtual void SCSIDEV::Receive() length was != 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] void SCSIDEV::MsgOut() ID 0
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] virtual void SCSIDEV::Receive()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] virtual void SCSIDEV::Receive() ctrl.phase: 10 (msgout)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] Message code IDENTIFY $C0, LUN 0 selected
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] virtual void SASIDEV::Command() Command Phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] virtual void SASIDEV::Command() CDB[0]=$3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] virtual void SASIDEV::Command() CDB[1]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] virtual void SASIDEV::Command() CDB[2]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] virtual void SASIDEV::Command() CDB[3]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] virtual void SASIDEV::Command() CDB[4]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] virtual void SASIDEV::Command() CDB[5]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] virtual void SASIDEV::Command() CDB[6]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] virtual void SASIDEV::Command() CDB[7]=$02
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] virtual void SASIDEV::Command() CDB[8]=$07
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] virtual void SASIDEV::Command() CDB[9]=$00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.377] [trace] virtual void SCSIDEV::Execute() Execution phase command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.378] [debug] ++++ CMD ++++ virtual void SCSIDEV::Execute() Executing command $3E
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.378] [debug] virtual bool Disk::Dispatch(SCSIDEV*) Executing ReadLong10 ($3E)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.378] [debug] Error status: Sense Key $05, ASC $24, ASCQ $00
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.378] [trace] virtual void SCSIDEV::Error(ERROR_CODES::sense_key, ERROR_CODES::asc) Error (to status phase)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.378] [trace] void SASIDEV::Status() Status phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.378] [trace] void SASIDEV::Status() Status Phase $02
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.378] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.378] [trace] virtual void SCSIDEV::Send() Move to next phase status (8)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.378] [trace] void SASIDEV::MsgIn() Starting Message in phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.378] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.378] [trace] virtual void SCSIDEV::Send() sending handhake with offset 0, length 1
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.378] [trace] void SASIDEV::MsgIn() Transitioning to Send()
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.378] [trace] virtual void SCSIDEV::Send() Move to next phase msgin (9)
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.379] [trace] virtual void SCSIDEV::BusFree() Bus free phase
Nov 25 12:02:18 raspberrypi RASCSI[437]: [2021-11-25 12:02:18.379] [trace] virtual void SCSIDEV::Selection() Selection Phase ID=0 (with device)

@Pacjunk
Copy link
Contributor Author

Pacjunk commented Nov 25, 2021

The strange thing is that the debug from bluescsi shows $0204! Strange...

Selection
MsgOut2
(246371)Command:3E:0:0:0:0:0:0:2:2:0:ID 2:LUN 0
[*Unknown]
Sts
MsgIn
BusFree
Selection
MsgOut2
(246532)Command:3E:0:0:0:0:0:0:2:3:0:ID 2:LUN 0
[*Unknown]
Sts
MsgIn
BusFree
Selection
MsgOut2
(246678)Command:3E:0:0:0:0:0:0:2:4:0:ID 2:LUN 0
[*Unknown]
Sts
MsgIn
BusFree
Selection
MsgOut2
(246824)Command:3E:0:0:0:0:0:0:2:5:0:ID 2:LUN 0
[*Unknown]
Sts
MsgIn
BusFree
Selection
MsgOut2
(246971)Command:3E:0:0:0:0:0:0:2:6:0:ID 2:LUN 0
[*Unknown]
Sts
MsgIn
BusFree
Selection
MsgOut2

@rdmark rdmark added this to In Progress in 21.11 Release Nov 25, 2021
@rdmark
Copy link
Member

rdmark commented Nov 25, 2021

@uweseimet I tentatively added this to the 21.11 roadmap. If you can figure out a stable solution in the next day or two we can get it into the upcoming release.

@uweseimet
Copy link
Contributor

uweseimet commented Nov 25, 2021

@Pacjunk I'm afraid there is nothing more I can do. In case BlueSCSI behaves better somebody else might compare logs, SCSI error codes and source code in order to proceed. As already mentioned, the fact that $0204 is missing with RaSCSI but not with BlueSCSI may be an important detail, caused by a difference in behavior between BlueSCSI and RaSCSI. It might even be the case that the difference in behavior ($0204) is not related to READ LONG at all, but to results from other commands sent before.

@uweseimet uweseimet removed this from In Progress in 21.11 Release Nov 25, 2021
@Pacjunk
Copy link
Contributor Author

Pacjunk commented Nov 25, 2021

OK, Thanks for your help

@Pacjunk
Copy link
Contributor Author

Pacjunk commented Jan 11, 2022

I have implemented READ/WRITE LONG(10) on the bluescsi, and now the host only sends readlong(10) commands for length 0, 1 and 200. It seems to be happy with that and does not do the command again. My implementation just transfers bytes instead of blocks (as the spec indicated). I can now successfully shadow (mirror) two drives under the operating system! Probably not a lot of use, but good for learning/experimentation.

@rdmark rdmark added the compatibility Compatibility with particular computing platforms label Aug 19, 2022
@uweseimet uweseimet added the major effort New feature/change with significant implementation effort label Aug 27, 2022
@uweseimet
Copy link
Contributor

@Pacjunk I would like to get back to this ticket. I am still wondering how to improve READ/WRITE LONG support. Without explicit support for variable length byte transfers (rascsi essentially can only transfer full blocks) it cannot be properly resolved. The SCSI printer device is also suffering from this and currently uses a work-around.
Anyway, I would like to know which data your BlueSCSI implementation , e.g. for a 200 byte transfer. Are these only dummy data? The specs says that the data are vendor specific and often are checksum data. In case of a 200 byte WRITE LONG command, what does your implementation do with these 200 bytes?

@Pacjunk
Copy link
Contributor Author

Pacjunk commented Sep 3, 2022

My code reads/writes and transfers the requested number of bytes from/to the LBA specified. I just wrote another function similar to the one that transfers blocks, but transfers bytes instead. I don't know what data the machine is trying to get, but I supply real data. I think the mirroring feature that requires this will transfer different quantities when required. The 0,1 & 200 byte transfers are only done when the volumes are mounted to test compatibility. Supplying dummy data may work at this stage, but definitely won't work when a drive mirroring operation is required!

@uweseimet
Copy link
Contributor

uweseimet commented Sep 3, 2022

@Pacjunk Please correct me if I am wrong: This means that when a sequence of sectors is copied this is done in chunks of 200 bytes, instead of copying in chunks of multiples of the sector size?

@Pacjunk
Copy link
Contributor Author

Pacjunk commented Sep 3, 2022

The 200 bytes is just a compatibility test at mount time. The actual transfers are all different lengths.
If the request is for 200 bytes, I supply 200 bytes. If the request is for 3159 bytes, that is how many I supply. I'm not doing multiples of the requested size.

@uweseimet
Copy link
Contributor

@Pacjunk So there are no additional data (checksums, vendor-specific data) contained in the data transferred by READ/WRITE LONG in your case? The only difference between copying a drive with regular read/write operations is that sequences of bytes instead of blocks are copied?

@Pacjunk
Copy link
Contributor Author

Pacjunk commented Sep 3, 2022

@uweseimet Yes, I just read/write bytes from the file and transfer bytes to/from the system. No other data. What the data contains, I don't know, and don't care! The drive shadowing (mirroring) operation works successfully on my system, so what I am doing must be sufficient in this case.

@uweseimet
Copy link
Contributor

uweseimet commented Sep 3, 2022

@Pacjunk I see. Any rascsi implementation would most likely have to bypass the sector-based cache and directly access the image file. Before each READ LONG the sector cache woulld have to be flushed in order for the file to be up to date before reading. (This is also required by the specification.) Any WRITE LONG would have to somehow clear the cache, so that the modified data are immediately available for a subsequent sector-oriented access.
Or the sector-based cache might be discarded completely. as already suggested in the context of #335, so that all read/write operations would always be file-based and thus not restricted to multiples of sector sizes anymore.

@Pacjunk
Copy link
Contributor Author

Pacjunk commented Sep 3, 2022

Another advantage of bluescsi - No cache! (which also means you can turn it off without corrupting images)

@uweseimet
Copy link
Contributor

uweseimet commented Sep 3, 2022

Well, I think I already indicated that I would not mind for the cache to be removed completely. @akuker should probably comment on that because he is/was working on #335. Removing the cache would quite likely also help resolving #807. As far as I can tell the cache is negatively affecting 3 tickets so far.

@uweseimet
Copy link
Contributor

uweseimet commented Sep 3, 2022

These are the alternatives I would like to propose in order to make progress on this ticket and on the related ones:

  1. Completely remove the existing cache. As far as I remember it turned out that there is no performance advantage anyway. Without the cache this ticket, raSCSI needs to periodically check disk write cache(s) #335 and probably also SCSI VERIFY commands do not verify but write #807 are more realistic to be resolved. In addition, the code of the printer device, which is not block-oriented, would likely also profit. The existing codebase would become more transparent and better testable. After removing the cache reading/writing will essentially be using fseek, fread and fwrite. If somebody can then show (with benchmarks) that caching these calls provides benefits, a new kind of cache, based on the new code, can be added with a separate ticket. I expect this step by step approach to be much easier than trying to continue working on the existing code.
  2. Keep the current cache implementatoin. In this case I have strong doubts that the tickets mentioned above will be resolved at all. Any potential resolution would have to find complicated ways to bypass the cache, making the read/write code even harder to maintain and test.

You won't be surprised that I am in favor of the first alternative ;-).

@uweseimet uweseimet added the feedback missing May have to be closed because of missing feedback label Sep 8, 2022
@uweseimet
Copy link
Contributor

While improving the code I noticed that there is no cache for SCMO, but only for other mass storage devices. Except for some mode pages SCMO is identical with SCHD/SCRM. In order to evaluate the effectiveness of the cache I used the same image file for SCHD and SCMO and measured the read transfer rates. You would have expected SCHD transfers (of the same data, so that they are cached) to be faster than SCMO transfers, but there was no difference.
@Pacjunk Maybe you can also check this, in case I have missed something?

@akuker By the way, this ticket and others (assigned to you) are still waiting for your feedback.

@Pacjunk
Copy link
Contributor Author

Pacjunk commented Sep 28, 2022

@uweseimet Unfortunately I am away for a week (possibly more) and I cannot check at the moment...

@uweseimet
Copy link
Contributor

@Pacjunk No problem I'll wait :).

@uweseimet
Copy link
Contributor

uweseimet commented Oct 11, 2022

@Pacjunk After digging deeper into the code I may have been mistaken regarding the MO device not using the cache. Please do not spend any time on this (yet).

@uweseimet
Copy link
Contributor

uweseimet commented Nov 8, 2022

Full READ/WRITE LONG support like you have it with BlueSCSI most likely requires resolving #940, #930 and #807 first. Resolving the latter is most likely a side-effect of resolving #940.

@akuker akuker removed their assignment Oct 14, 2023
@uweseimet uweseimet removed the feedback missing May have to be closed because of missing feedback label Oct 16, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
compatibility Compatibility with particular computing platforms major effort New feature/change with significant implementation effort
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants