search

uweseimet / scsi2pi

Advanced performant SCSI/SASI emulation and tools for the PiSCSI/RaSCSI board
https://www.scsi2pi.net
BSD 3-Clause "New" or "Revised" License
10 stars 2 forks source link

Streamer/Tape support (focus on tar-compatibility) #93

Closed bog-dan-ro closed 2 weeks ago

bog-dan-ro commented 3 months ago

Same request as https://github.com/PiSCSI/piscsi/issues/480

I already have a non working WIP for piscsi (that was before I found scsi2pi). I'll be happy to port it to scsi2pi. But I'll someones help, who knows the internals of this project, to fix the remaining stuff.

uweseimet commented 3 months ago

@bog-dan-ro Thank you for creating this ticket. Currently there are no plans to add streamer support to SCSI2Pi. In the past tapes were used for backups, because there was no better/cheaper solution. Nowadays, especially with tools like SCSI2Pi, you simply use a drive image for a backup. This is faster and more flexible than a streamer emulation. Using a streamer emulation instead would be rather inconvenient.

However, as soon as you have added fully functional tape support to PiSCSI please get back to me. I wil then run tests with my Atari (I have streamer software for it and also an HP streamer), and I will then re-evaluate this ticket based on the results of my tests.

uweseimet commented 3 months ago

@bog-dan-ro By the way, I would be interested to learn which methods from the Disk class you think should be moved into the StorageDevice class.

bog-dan-ro commented 3 months ago

Actually they are not too many, check my last commit from https://github.com/bog-dan-ro/piscsi

bog-dan-ro commented 3 months ago

See https://github.com/bog-dan-ro/piscsi/commit/52a50c91d62a574bd2bf1e8f695d74860209cd62#diff-ba201351e19eac2f5e902b9308a59f1e3bdc19ed324119dab011d8336c345410 and https://github.com/bog-dan-ro/piscsi/commit/52a50c91d62a574bd2bf1e8f695d74860209cd62#diff-76d682148e5aa7e6ce46bd9e40aae7de042a2a4e24242baf6f95b93612e6a16b

I didn't moved the caching as streamers do not need it as they are sequential so, once you read/write a block it will not seek back to read it again.

uweseimet commented 3 months ago

I will have a look at the code you moved and will get back to you, but this may take some time.

Is the streamer code in your repository already tested and working?

bog-dan-ro commented 3 months ago

@bog-dan-ro Thank you for creating this ticket. Currently there are no plans to add streamer support to SCSI2Pi. In the past tapes were used for backups, because there was no better/cheaper solution. Nowadays, especially with tools like SCSI2Pi, you simply use a drive image for a backup. This is faster and more flexible than a streamer emulation. Using a streamer emulation instead would be rather inconvenient.

There are other use-casese for than tape than backup. For instance, Altos 386 Series 1000 needs it to install the the system utilities. I also want to use it to transfer large software on that machine as splitting big tar files and transferring them from floppy is not fun :).

I will have a look at the code you moved and will get back to you, but this may take some time.

No rush, I'll be in vacation for a couple of weeks.

Is the streamer code in your repository already tested and working?

I tested it a bit, but sadly is not working ... The mandatory implementation is there, but I don't know how to properly debug it. Most probably I'll have to add a modern build system (cmake?) so my IDE to know how to cross compile, deploy & debug it properly. Also, I didn't have too much time to properly understand the API nor the workflow :). I'll have to cry for help on PiSCSI maybe someone who knows the code well, will have time to help me fix it.

I chose tandber as the reference device for two reasons:

  1. Is one of the most used tape drives
  2. it has proper scsi documentation ;-)
uweseimet commented 3 months ago

Indeed, I missed the use case of an installation. Anyway, I will get back to you (presumably in a couple of days) regarding moving code from Disk to StorageDevice.

There is no direct relationship between cmake and cross-compling, by the way. The nightly SCSI2Pi builds and the release builds are cross-compiled, but SCSI2Pi does not use cmake. I thought about using it, but it would not be worth the effort, considering that the Makefile is portable and straightforward.

bog-dan-ro commented 3 months ago

There is no direct relationship between cmake and cross-compling, by the way.

Nope is not, at least not direct. Current makefile works great to cross-compile it from command line. I created a docker file to help me cross compile it, and I have no issues to cross-compile it. But ... Some IDEs (qtcreator) need to know what files are built, where they are on the host computer and where they should be deployed on the target. Using CMake, gives all that info to IDE.

Indeed, I missed the use case of an installation. Anyway, I will get back to you (presumably in a couple of days) regarding moving code from Disk to StorageDevice.

No hurry at all, starting next Friday I'll be in vacation for two weeks.

uweseimet commented 3 months ago

@bog-dan-ro In the develop branch I moved the code related to sector/block sizes from the Disk class to the StorageDevice class. Changes related to shift counts (and others) are not required, because this code does not needed anymore in SCSI2Pi.

bog-dan-ro commented 3 months ago

@uweseimet I'll check it once I'm back. BTW for piscsi I almost finished the testing. So far it works great. After I'll clean a bit the code I'll create a PR.

bog-dan-ro commented 3 months ago

@uweseimet Here https://github.com/PiSCSI/piscsi/pull/1477 is the PR

uweseimet commented 3 months ago

@bog-dan-ro Can you please remove my name in the copyright notice of the new streamer class code (.cpp and .h)?

bog-dan-ro commented 3 months ago

@bog-dan-ro Can you please remove my name in the copyright notice of the new streamer class code (.cpp and .h)?

Done

uweseimet commented 2 months ago

@bog-dan-ro In the meantime I have added a branch issue_93 with initial tape drive support to SCSI2Pi. This implementation is completely new, i.e. it is not based on any existing code.

I have already successfully tested this branch with tar, both in the tar-file compatible mode (file extension .tar), and in the full-featured mode with filemarks support. When writing files to a real device instead of the filesystem tar actually makes use of filemarks.

uweseimet commented 1 month ago

@bog-dan-ro There has not been any recent feedback, neither in this ticket nor in https://github.com/PiSCSI/piscsi/issues/480. As far as the SCSI2Pi ticket is concerned is is essentially done and tested. What about your PiSCSI ticket/PR? I would like to ensure that both implementations are compatible from the user's perspective. For SCSI2Pi there are binaries of the development branch with all changes included, see https://www.scsi2pi.net/packages/develop/. See the comments in the header of tape.cpp for details on the SCSI2Pi implementation.

@Pacjunk @sidick @ppuskari Quite long ago you were interested in tape support for the PiSCSI board. In case you are still interested, I would appreciate help with testing.

ppuskari commented 1 month ago

This is wonderful news. I am about ready to test this after building. I have been in the middle of a major job change so have been out of pocket a bit.

Looking forward to seeing if the IIgs software can properly work with the new code and recognize it as the 3m drive and 40meg block formatted and sellable capacity. If this works I am going to learn a lot from your code and I am very appreciative!

Petar Puskarich @.***

Sent from my iPhone

On Oct 5, 2024, at 5:01 AM, Uwe Seimet @.***> wrote:



@bog-dan-rohttps://github.com/bog-dan-ro There has not been any recent feedback, neither in this ticket nor in PiSCSI/piscsi#480https://github.com/PiSCSI/piscsi/issues/480. As far as the SCSI2Pi ticket is concerned is is essentially done and tested. What about your PiSCSI ticket/PR? I would like to ensure that both implementations are compatible from the user's perspective. For SCSI2Pi there are binaries of the development branch with all changes included, see https://www.scsi2pi.net/packages/develop/. See the comments in the header of tape.cpp for details on the SCSI2Pi implementation.

@Pacjunkhttps://github.com/Pacjunk @sidickhttps://github.com/sidick @ppuskarihttps://github.com/ppuskari Quite long ago you were interested in tape support for the PiSCSI board. In case you are still interested, I would appreciate help with testing.

— Reply to this email directly, view it on GitHubhttps://github.com/uweseimet/scsi2pi/issues/93#issuecomment-2395003378, or unsubscribehttps://github.com/notifications/unsubscribe-auth/AAIMVUB5TTRBYJCTSTB5FILZZ62GTAVCNFSM6AAAAABMWBHWR6VHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDGOJVGAYDGMZXHA. You are receiving this because you were mentioned.Message ID: @.***>

bog-dan-ro commented 1 month ago

Hi @uweseimet,

Sorry for slow reply, I was quite busy at work. I'll check your implementation next weekend. If is better than mine I'll probably back port it to piscsi if you're okay with it.

BogDan.

uweseimet commented 1 month ago

@bog-dan-ro Backporting is fine, but what about the existing PiSCSI PR? As far as I can tell the PiSCSI team has been waiting for your feedback for weeks.

bog-dan-ro commented 1 month ago

@uweseimet my patch works for me and from my POV it's done. There are a few small issues to fix on the UI side which I could not fix them myself.

uweseimet commented 1 month ago

When will these issues be fixed? What about the device type name? Please see my last comment in the PiSCSI ticket.

Pacjunk commented 1 month ago

@Pacjunk @sidick @ppuskari Quite long ago you were interested in tape support for the PiSCSI board. In case you are still interested, I would appreciate help with testing.

Hi Uwe - I've been out of the loop for a fair while but I am attempting to have a look at your new code. Taking me a while to get my head around doing things with a command line!

I updated my system to the latest PiSCSI (3.5 hours!) and had it working. I then installed your package. It disabled PiSCSI (expected), but did not create a system service for scsi2pi - I did this. The web interface does not seem to work now, even though some of documentation says it will.

I added a disk and a few .TAP files to the configuration. The workstation can see the vendor details for the disk and tape drives at the console prompt - so a good start. First try booting nothing worked, second try failed during boot with all devices being detached part way through the boot. Third try and I booted the VAXstation off the disk image. When I try and mount a tape image (which I have verified as being correct under SimH) the system just says that the device is offline. So looks like a bit more debugging is required.

So my questions are:

1 - I can't find the log file anywhere. Where is it, and what is the best way to change the logging level to trace 2 - Can I use my existing vendor properties files for the drives, or do I have to manually copy the data over to the .conf file. (maybe a few commented out, fully optioned examples in the conf file would be useful).

Thanks,

uweseimet commented 1 month ago

@Pacjunk Thank you for your feedback!

Regarding the system service, I may have missed updating the installation webpage. Initially the PiSCSI service was shut down and the SCSi2Pi service was started up instead, when running "apt install". I removed the last step, but I have to admit I don't know why anymore ;-). I think it was because it is sometimes annoying to have a service not just created but also automatically started without explicitly configuring this. I just updated the "Quickstart" section of the website. The service file "/etc/systemd/system/s2p.service" should be there, though. Can you confirm this?

Regarding your questions:

  1. Logging information is displayed with "sudo systemctl status s2p". For testing it is often easier not to run the service, but to launch s2p from the command line.
  2. The vendor properties file is evaluated by the PiSCSI webservice, isn't it? I will have to check whether I can reproduce a interoperability problem with the PiSCSI webservice. Something like that probably cannot be prevented sooner or later, but I would like to keep SCSI2Pi as compatible with PiSCSI as possible. The webservice may not be able to support other (new) device types, or it might have limited support for new types.

s2p is usually configured with a property file. http://www.scsi2pi/en/properties.html. The command line options complement/override property file settings. Some configuration data, especially mode pages, require a property file. Add all available options to a sample configuration file would probably make this file quite confusing. It would also mean maintenance overhead, because with each change I would not only have to update the help texts, the manpages and the website, but also this file.

As already mentioned, for testing purposes using the command line instead of the system service is usually more convenient, as you can quickly stop s2p, change the parameters, and restart. Booting without a single initial tape drive, and then attaching a tape image may be the best test scenario, with less complexity than the drive being present when booting. This is what I would like to suggest:

  1. Boot with only a hard drive attached.
  2. Then attach the tape drive, and in case the system has issues with it a log on trace level should reveal details.
  3. You can assign an individual log level to the tape device with s2pctl, so that you only get trace output for your tape, but not for the hard drive.

I have tested the current develop branch with tar and mtx, but when using other (or more elaborate) tape tools it may turn out that the implementation has to be updated/changed. I think that it is compliant with the standard, but some tools may need some of the optional commands not implemented. Or bugs still have to be fixed that tar does not trigger. I planned to test everything with a tape backup tool for the Atari, but this tool neither works with SCSi2Pi nor with my HP streamer. From the s2p logs I can see that it sends write commands with a byte count of 0 all the time. I cannot tell whether this is due to a bug in s2p or in the tool, because the real streamer also does not work.

I hope this helps to get you started.

Pacjunk commented 1 month ago

Here is a trace of my unsuccessful attempt to mount a tape on my VAXstation. Don't know how useful this is, but anyway...

Oct 09 15:14:53 piscsi s2p[802]: SCSI Target Emulator and SCSI Tools SCSI2Pi (Device Emulation)
Oct 09 15:14:53 piscsi s2p[802]: Version 4.0-devel
Oct 09 15:14:53 piscsi s2p[802]: Copyright (C) 2016-2020 GIMONS
Oct 09 15:14:53 piscsi s2p[802]: Copyright (C) 2020-2023 Contributors to the PiSCSI project
Oct 09 15:14:53 piscsi s2p[802]: Copyright (C) 2021-2024 Uwe Seimet
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.738] [info] Set log level to 'info'
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.754] [info] Reserved ID(s) set to 6
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.773] [info] Executing: operation=ATTACH, device=0:0, device parameters='file=boot72.hd1'
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.775] [info] Attached SCHD 0:0
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.777] [info] Executing: operation=ATTACH, device=3:0, device parameters='file=vms_v5.4_1.tap'
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.780] [info] Attached SCTP 3:0
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.782] [info] Executing: operation=ATTACH, device=4:0, device parameters='file=vms_v5.4_2.tap'
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.783] [info] Attached SCTP 4:0
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.783] [info] Executing: operation=ATTACH, device=5:0, device parameters='file=Test.tap'
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.784] [info] Attached SCTP 5:0
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.785] [info] +----+-----+------+-------------------------------------
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.785] [info] | ID | LUN | TYPE | IMAGE FILE
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.785] [info] +----+-----+------+-------------------------------------
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.785] [info] |  0 |   0 | SCHD | /home/pi/images/boot72.hd1
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.785] [info] |  3 |   0 | SCTP | /home/pi/images/vms_v5.4_1.tap
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.785] [info] |  4 |   0 | SCTP | /home/pi/images/vms_v5.4_2.tap
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.785] [info] |  5 |   0 | SCTP | /home/pi/images/Test.tap
Oct 09 15:14:53 piscsi s2p[802]: [2024-10-09 15:14:53.785] [info] +----+-----+------+-------------------------------------
Oct 09 15:14:53 piscsi s2p[802]: +----+-----+------+-------------------------------------
Oct 09 15:14:53 piscsi s2p[802]: | ID | LUN | TYPE | IMAGE FILE
Oct 09 15:14:53 piscsi s2p[802]: +----+-----+------+-------------------------------------
Oct 09 15:14:53 piscsi s2p[802]: |  0 |   0 | SCHD | /home/pi/images/boot72.hd1
Oct 09 15:14:53 piscsi s2p[802]: |  3 |   0 | SCTP | /home/pi/images/vms_v5.4_1.tap
Oct 09 15:14:53 piscsi s2p[802]: |  4 |   0 | SCTP | /home/pi/images/vms_v5.4_2.tap
Oct 09 15:14:53 piscsi s2p[802]: |  5 |   0 | SCTP | /home/pi/images/Test.tap
Oct 09 15:14:53 piscsi s2p[802]: +----+-----+------+-------------------------------------
Oct 09 15:17:02 piscsi s2p[802]: [2024-10-09 15:17:02.554] [info] Set log level to 'trace'
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.284] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.284] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.284] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.284] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.284] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.284] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.285] [debug] (ID 3) - Controller is executing TEST UNIT READY, CDB $00:00:00:00:00:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.285] [debug] (ID:LUN 3:0) - Device is executing TEST UNIT READY ($00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.285] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.285] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.285] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.285] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.285] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.286] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.286] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.289] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.289] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.289] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.289] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.290] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.290] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.290] [debug] (ID 3) - Controller is executing INQUIRY, CDB $12:00:00:00:24:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.290] [debug] (ID:LUN 3:0) - Device is executing INQUIRY ($12)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.290] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.290] [trace] (ID 3) - Sending 36 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.291] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.291] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.291] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.291] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.291] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.291] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.291] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.292] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.295] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.295] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.295] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.295] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.295] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.295] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.296] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.296] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.296] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.297] [trace] (ID 3) - Sending 12 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.297] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.297] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.297] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.297] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.297] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.297] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.298] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.298] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.301] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.301] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.302] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.302] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.302] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.302] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.302] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.302] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.303] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.303] [trace] (ID 3) - Sending 12 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.303] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.303] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.303] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.304] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.304] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.304] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.304] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.304] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.311] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.311] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.311] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.311] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.311] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.312] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.312] [debug] (ID 3) - Controller is executing MODE SELECT(6), CDB $15:00:00:00:0c:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.312] [debug] (ID:LUN 3:0) - Device is executing MODE SELECT(6) ($15)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.312] [trace] (ID 3) - DATA OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.312] [trace] (ID 3) - Receiving 12 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.313] [trace] (ID 3) - 12 byte(s) of command parameter data:
Oct 09 15:17:13 piscsi s2p[802]: 00000000  00:00:10:08:00:00:00:00:00:00:00:00              '............'
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.313] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.313] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.313] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.313] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.313] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.313] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.313] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.316] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.316] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.316] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.316] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.316] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.316] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.317] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.317] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.317] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.317] [trace] (ID 3) - Sending 12 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.318] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.318] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.318] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.318] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.318] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.318] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.318] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.319] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.323] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.323] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.323] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.324] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.324] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.324] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.324] [debug] (ID 3) - Controller is executing READ POSITION, CDB $34:00:00:00:00:00:00:00:00:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.324] [debug] (ID:LUN 3:0) - Device is executing READ POSITION ($34)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.324] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.324] [trace] (ID 3) - Sending 20 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.325] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.325] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.325] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.325] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.325] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.325] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.325] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.325] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.330] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.330] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.330] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.331] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.331] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.331] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.331] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:10:00:ff:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.331] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.332] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.332] [trace] (ID 3) - Sending 28 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.332] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.332] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.332] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.333] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.333] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.333] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.333] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.333] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.338] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.338] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.338] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.338] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.338] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.338] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.338] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:50:00:ff:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.339] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.342] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.342] [trace] (ID 3) - Sending 28 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.342] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.342] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.343] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.343] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.343] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.343] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.343] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.343] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.348] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.348] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.348] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.348] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.348] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.348] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.348] [debug] (ID 3) - Controller is executing REZERO/REWIND, CDB $01:00:00:00:00:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.348] [debug] (ID:LUN 3:0) - Device is executing REZERO/REWIND ($01)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.349] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.349] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.349] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.349] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.349] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.349] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.349] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.351] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.351] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.351] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.351] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.351] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.351] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.352] [debug] (ID 3) - Controller is executing TEST UNIT READY, CDB $00:00:00:00:00:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.352] [debug] (ID:LUN 3:0) - Device is executing TEST UNIT READY ($00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.352] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.352] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.352] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.352] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.352] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.353] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.353] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.357] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.357] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.357] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.357] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.357] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.357] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.357] [debug] (ID 3) - Controller is executing INQUIRY, CDB $12:00:00:00:24:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.358] [debug] (ID:LUN 3:0) - Device is executing INQUIRY ($12)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.358] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.358] [trace] (ID 3) - Sending 36 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.358] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.358] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.358] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.359] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.359] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.359] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.359] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.359] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.364] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.364] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.364] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.364] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.364] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.364] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.365] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.365] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.365] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.365] [trace] (ID 3) - Sending 12 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.366] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.366] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.366] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.366] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.366] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.366] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.366] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.366] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.371] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.372] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.372] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.372] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.372] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.372] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.372] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.372] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.373] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.373] [trace] (ID 3) - Sending 12 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.373] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.373] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.374] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.374] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.374] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.374] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.374] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.374] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.379] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.379] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.379] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.379] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.379] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.379] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.380] [debug] (ID 3) - Controller is executing MODE SELECT(6), CDB $15:00:00:00:0c:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.380] [debug] (ID:LUN 3:0) - Device is executing MODE SELECT(6) ($15)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.380] [trace] (ID 3) - DATA OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.380] [trace] (ID 3) - Receiving 12 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.380] [trace] (ID 3) - 12 byte(s) of command parameter data:
Oct 09 15:17:13 piscsi s2p[802]: 00000000  00:00:10:08:00:00:00:00:00:00:00:00              '............'
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.380] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.380] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.381] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.381] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.381] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.381] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.381] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.386] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.386] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.386] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.386] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.386] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.386] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.387] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.387] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.387] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.387] [trace] (ID 3) - Sending 12 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.388] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.388] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.388] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.388] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.388] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.388] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.389] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.389] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.394] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.394] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.394] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.394] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.394] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.394] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.395] [debug] (ID 3) - Controller is executing READ POSITION, CDB $34:00:00:00:00:00:00:00:00:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.395] [debug] (ID:LUN 3:0) - Device is executing READ POSITION ($34)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.395] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.395] [trace] (ID 3) - Sending 20 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.395] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.395] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.395] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.396] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.396] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.396] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.396] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.396] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.399] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.400] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.400] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.400] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.400] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.400] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.400] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:10:00:ff:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.400] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.404] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.404] [trace] (ID 3) - Sending 28 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.404] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.404] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.404] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.405] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.405] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.405] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.405] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.405] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.408] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.408] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.408] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.408] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.409] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.409] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.409] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:50:00:ff:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.409] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.409] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.410] [trace] (ID 3) - Sending 28 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.410] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.410] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.410] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.410] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.410] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.410] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.410] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.410] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.413] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.413] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.413] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.413] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.413] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.414] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.414] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.414] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.414] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.414] [trace] (ID 3) - Sending 12 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.415] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.415] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.415] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.415] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.415] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.415] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.415] [trace] (ID 3) - All data transferred
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.415] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.421] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.421] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.421] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.421] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.421] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.421] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.422] [debug] (ID 3) - Controller is executing MODE SELECT(6), CDB $15:00:00:00:0c:00
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.422] [debug] (ID:LUN 3:0) - Device is executing MODE SELECT(6) ($15)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.422] [trace] (ID 3) - DATA OUT phase
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.422] [trace] (ID 3) - Receiving 12 byte(s)
Oct 09 15:17:13 piscsi s2p[802]: [2024-10-09 15:17:13.422] [trace] (ID 3) - 12 byte(s) of command parameter data:
Oct 09 15:17:13 piscsi s2p[802]: 00000000  00:00:10:08:00:00:00:00:00:00:00:00              '............'
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.422] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.422] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.423] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.423] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.423] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.423] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.423] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.425] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.425] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.425] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.425] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.425] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.425] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.425] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.425] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.426] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.426] [trace] (ID 3) - Sending 12 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.426] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.426] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.426] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.426] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.426] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.427] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.427] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.427] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.430] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.430] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.431] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.431] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.431] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.431] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.431] [debug] (ID 3) - Controller is executing TEST UNIT READY, CDB $00:00:00:00:00:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.431] [debug] (ID:LUN 3:0) - Device is executing TEST UNIT READY ($00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.431] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.431] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.431] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.431] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.432] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.432] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.432] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.435] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.435] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.435] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.435] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.436] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.436] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.436] [debug] (ID 3) - Controller is executing INQUIRY, CDB $12:00:00:00:24:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.436] [debug] (ID:LUN 3:0) - Device is executing INQUIRY ($12)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.436] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.436] [trace] (ID 3) - Sending 36 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.436] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.436] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.436] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.437] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.437] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.437] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.437] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.437] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.440] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.441] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.441] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.441] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.441] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.441] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.441] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.441] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.442] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.442] [trace] (ID 3) - Sending 12 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.442] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.442] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.442] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.442] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.442] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.442] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.443] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.443] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.446] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.446] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.446] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.446] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.447] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.447] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.447] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.447] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.447] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.447] [trace] (ID 3) - Sending 12 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.448] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.448] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.448] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.448] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.448] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.448] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.448] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.448] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.452] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.452] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.452] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.452] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.452] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.452] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.453] [debug] (ID 3) - Controller is executing MODE SELECT(6), CDB $15:00:00:00:0c:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.453] [debug] (ID:LUN 3:0) - Device is executing MODE SELECT(6) ($15)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.453] [trace] (ID 3) - DATA OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.453] [trace] (ID 3) - Receiving 12 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.453] [trace] (ID 3) - 12 byte(s) of command parameter data:
Oct 09 15:17:14 piscsi s2p[802]: 00000000  00:00:10:08:00:00:00:00:00:00:00:00              '............'
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.453] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.453] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.454] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.454] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.454] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.454] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.454] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.457] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.457] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.457] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.457] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.457] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.457] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.458] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.458] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.458] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.458] [trace] (ID 3) - Sending 12 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.459] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.459] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.459] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.459] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.459] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.459] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.459] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.459] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.463] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.463] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.463] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.463] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.463] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.463] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.463] [debug] (ID 3) - Controller is executing READ POSITION, CDB $34:00:00:00:00:00:00:00:00:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.463] [debug] (ID:LUN 3:0) - Device is executing READ POSITION ($34)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.464] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.464] [trace] (ID 3) - Sending 20 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.464] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.464] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.464] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.464] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.464] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.464] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.464] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.464] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.468] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.468] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.468] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.468] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.468] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.468] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.468] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:10:00:ff:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.468] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.469] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.469] [trace] (ID 3) - Sending 28 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.469] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.469] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.470] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.470] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.470] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.470] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.470] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.470] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.473] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.474] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.474] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.474] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.474] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.474] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.474] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:50:00:ff:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.474] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.475] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.475] [trace] (ID 3) - Sending 28 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.475] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.475] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.475] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.475] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.475] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.475] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.476] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.476] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.481] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.481] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.481] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.481] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.481] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.481] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.481] [debug] (ID 3) - Controller is executing REZERO/REWIND, CDB $01:00:00:00:00:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.481] [debug] (ID:LUN 3:0) - Device is executing REZERO/REWIND ($01)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.481] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.481] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.482] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.482] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.482] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.482] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.482] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.484] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.484] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.485] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.485] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.485] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.485] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.485] [debug] (ID 3) - Controller is executing READ(6)/GET MESSAGE(6), CDB $08:00:00:00:50:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.485] [debug] (ID:LUN 3:0) - Device is executing READ(6)/GET MESSAGE(6) ($08)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.486] [debug] (ID 3) - ILLEGAL REQUEST (Sense Key $05), INVALID FIELD IN CDB (ASC $24), ASCQ $00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.486] [trace] (ID 3) - Status phase, status is CHECK CONDITION (status code $02)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.486] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.486] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.486] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.486] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.486] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.486] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.489] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.490] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.490] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.490] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.490] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.490] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.490] [debug] (ID 3) - Controller is executing REQUEST SENSE, CDB $03:00:00:00:13:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.490] [debug] (ID:LUN 3:0) - Device is executing REQUEST SENSE ($03)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.490] [trace] (ID:LUN 3:0) - GOOD: ILLEGAL REQUEST (Sense Key $05), INVALID FIELD IN CDB (ASC $24), ASCQ $00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.490] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.490] [trace] (ID 3) - Sending 18 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.491] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.491] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.491] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.491] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.491] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.491] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.491] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.491] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.495] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.495] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.495] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.495] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.495] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.495] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.495] [debug] (ID 3) - Controller is executing REZERO/REWIND, CDB $01:00:00:00:00:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.495] [debug] (ID:LUN 3:0) - Device is executing REZERO/REWIND ($01)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.496] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.496] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.496] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.496] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.496] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.496] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.496] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.500] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.500] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.500] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.500] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.500] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.500] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.500] [debug] (ID 3) - Controller is executing TEST UNIT READY, CDB $00:00:00:00:00:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.500] [debug] (ID:LUN 3:0) - Device is executing TEST UNIT READY ($00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.500] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.500] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.501] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.501] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.501] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.501] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.501] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.503] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.503] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.503] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.503] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.503] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.503] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.503] [debug] (ID 3) - Controller is executing INQUIRY, CDB $12:00:00:00:24:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.504] [debug] (ID:LUN 3:0) - Device is executing INQUIRY ($12)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.504] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.504] [trace] (ID 3) - Sending 36 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.504] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.504] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.504] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.504] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.504] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.504] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.505] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.505] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.508] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.508] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.508] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.508] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.508] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.508] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.508] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.509] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.509] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.509] [trace] (ID 3) - Sending 12 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.509] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.509] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.510] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.510] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.510] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.510] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.510] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.510] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.514] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.514] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.514] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.514] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.514] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.514] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.514] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.514] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.515] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.515] [trace] (ID 3) - Sending 12 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.515] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.515] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.515] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.515] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.515] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.515] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.516] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.516] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.521] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.521] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.521] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.521] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.521] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.521] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.521] [debug] (ID 3) - Controller is executing MODE SELECT(6), CDB $15:00:00:00:0c:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.521] [debug] (ID:LUN 3:0) - Device is executing MODE SELECT(6) ($15)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.522] [trace] (ID 3) - DATA OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.522] [trace] (ID 3) - Receiving 12 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.522] [trace] (ID 3) - 12 byte(s) of command parameter data:
Oct 09 15:17:14 piscsi s2p[802]: 00000000  00:00:10:08:00:00:00:00:00:00:00:00              '............'
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.522] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.522] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.522] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.522] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.522] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.523] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.523] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.525] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.525] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.525] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.525] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.525] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.525] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.525] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.525] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.526] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.526] [trace] (ID 3) - Sending 12 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.526] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.526] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.526] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.526] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.526] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.527] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.527] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.527] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.530] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.530] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.530] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.531] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.531] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.531] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.531] [debug] (ID 3) - Controller is executing READ POSITION, CDB $34:00:00:00:00:00:00:00:00:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.531] [debug] (ID:LUN 3:0) - Device is executing READ POSITION ($34)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.531] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.531] [trace] (ID 3) - Sending 20 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.531] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.531] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.531] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.532] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.532] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.532] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.532] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.532] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.535] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.535] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.535] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.536] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.536] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.536] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.536] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:10:00:ff:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.536] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.536] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.537] [trace] (ID 3) - Sending 28 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.537] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.537] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.537] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.537] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.537] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.537] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.537] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.537] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.541] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.541] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.541] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.541] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.542] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.542] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.542] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:50:00:ff:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.542] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.542] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.542] [trace] (ID 3) - Sending 28 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.543] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.543] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.543] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.543] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.543] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.543] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.543] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.543] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.548] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.548] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.548] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.549] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.549] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.549] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.549] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.549] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.550] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.550] [trace] (ID 3) - Sending 12 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.550] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.550] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.550] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.550] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.551] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.551] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.551] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.551] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.554] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.554] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.554] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.554] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.555] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.555] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.555] [debug] (ID 3) - Controller is executing MODE SELECT(6), CDB $15:00:00:00:0c:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.555] [debug] (ID:LUN 3:0) - Device is executing MODE SELECT(6) ($15)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.555] [trace] (ID 3) - DATA OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.555] [trace] (ID 3) - Receiving 12 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.555] [trace] (ID 3) - 12 byte(s) of command parameter data:
Oct 09 15:17:14 piscsi s2p[802]: 00000000  00:00:10:08:00:00:00:00:00:00:00:00              '............'
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.555] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.555] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.556] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.556] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.556] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.556] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.556] [trace] (ID 3) - BUS FREE phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.559] [trace] (ID 3) - ++++ Starting processing for initiator ID 6
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.560] [trace] (ID 3) - SELECTION phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.560] [trace] (ID 3) - MESSAGE OUT phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.560] [trace] (ID 3) - Receiving 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.560] [trace] (ID 3) - Received IDENTIFY message for LUN 0
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.560] [trace] (ID 3) - COMMAND phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.560] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.560] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.561] [trace] (ID 3) - DATA IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.561] [trace] (ID 3) - Sending 12 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.561] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.561] [trace] (ID 3) - Status phase, status is GOOD (status code $00)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.561] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.561] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.561] [trace] (ID 3) - MESSAGE IN phase
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.561] [trace] (ID 3) - Sending 1 byte(s)
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.562] [trace] (ID 3) - All data transferred
Oct 09 15:17:14 piscsi s2p[802]: [2024-10-09 15:17:13.562] [trace] (ID 3) - BUS FREE phase
uweseimet commented 1 month ago

@Pacjunk Thank you. Looks as if the problem is related to an operation mode that is not implemented by SCSI2Pi:

Controller is executing READ(6)/GET MESSAGE(6), CDB $08:00:00:00:50:00

This command results in an error because SCSI2Pi does not support non-fixed tape blocks. But your workstation also sends a MODE SELECT to configure something. Can you try with a different block size, e.g. 1024 bytes ("-b 1024")? But I guess this will not help and I have to add support for flexible block sizes. Logging on debug level is sufficient, at least for the next tests

uweseimet commented 1 month ago

@Pacjunk As far as I can tell the MODE SELECT tries to configure the density, setting it to the default value 0. 0 means that the device selects its default density, which is fine for SCSI2Pi, because other densities are not supported (or faked, because there is no density) anyway. The fact that your workstation eventually tries to read data indicates that it may be fine with whatever happened before (MODE SELECT/MODE SENSE).

The first actual error occurs when your machine tries to read a block of 80 bytes, which is currently not supported by SCSI2Pi. Supporting non-fixed block sizes is optional (and not required by tar). I will add this feature most likely tomorrow. Without this feature I don't expect a different behavior when configuring SCSI2Pi with a different blocksize ("-b 1024"), but I'd still like to ask you for doing this. It may provide further information. Please only use the debug log level, in order to keep the logfile small.

Do you have a real streamer that works correctly with your workstation? In this case you can run some SCSI commands against it (using s2pexec, the SCSI2Pi Wiki provides details about this tool). Knowing the mode pages data of your streamer might help to improve the emulation. What is actually the expected (by your workstation) behavior if there is a streamer with an empty (nothing recorded) tape in it? What does your machine do in this case?

Which Pi model and which OS are you using for your tests?

uweseimet commented 1 month ago

@Pacjunk There is an issue_93_2 branch now, which is supposed to support variable block sizes between 1 and 4096 bytes. Can you please test whether something changes with this branch? But before doing that can you please test with the develop branch and a block size of 1024 bytes and comment in my questions in my previous comment? Thank you!

I cannot test flexible block sizes with the software I have, but I verified that tar still works with the issue_93_2 branch, and that tapeinfo reports the expected minimum and maximum sizes:

>tapeinfo -f /dev/sg5
Product Type: Tape Drive
Vendor ID: 'SCSI2Pi '
Product ID: 'SCSI TAPE       '
Revision: '0400'
Attached Changer API: No
MinBlock: 1
MaxBlock: 4096
SCSI ID: 2
SCSI LUN: 0
Ready: yes
BOP: yes
Block Position: 0
ActivePartition: 0
EarlyWarningSize: 0
NumPartitions: 0
MaxPartitions: 0
Pacjunk commented 1 month ago

Thanks for that. I'll be away for a few days, so can't test until next week. I assume the first thing that the workstation does is look for the tape label. Yes I have some real tape drives - hopefully they and the tapes still work! I'm pretty sure that I dont get the device offline message with a blank tape - probably will just say label not found or not initialised. I'll have to try and bulk erase a tape and give it a try.

I'm using a pi zero W with bullseye. How do I get a copy of that branch? Is there a .deb file for it, or do I have to do a full build?

uweseimet commented 1 month ago

@Pacjunk I have just triggered building .deb binaries for commit ID ee8ba06 in the issue_93_2 branch. The development binaries have the commit ID in their filename.

It would be very helpful if you could collect information on your real drives. You can do this by connecting your streamers to a SCSI chain with the PiSCSI board in it and running some SCSI commands. Just connect a streamer and then run commands with s2pexec, e.g.:

s2pexec>-i SCSI_ID_OF_YOUR_STREAMER -c 12:00:00:00:ff:00
00000000  01:80:02:02:1f:00:00:00:53:43:53:49:32:50:69:20  '........SCSI2Pi '
00000010  53:43:53:49:20:54:41:50:45:20:20:20:20:20:20:20  'SCSI TAPE       '
00000020  30:34:30:30                                      '0400'
s2pexec>-c 1a:00:3f:00:ff:00
00000000  47:00:00:08:00:1f:9f:dc:00:00:02:00:01:0a:26:01  'G.............&.'
00000010  00:00:00:00:01:00:00:da:02:0e:00:00:00:00:00:00  '................'
00000020  00:00:00:00:00:00:00:00:0a:06:00:00:00:00:00:00  '................'
00000030  10:0e:00:00:00:00:00:00:40:00:10:00:00:00:00:00  '........@.......'
00000040  11:06:00:00:90:00:00:00      
s2pexec>-c 1a:00:00:00:ff:00
00000000  0b:00:00:08:00:00:00:00:00:00:02:00              '............'

This sequence of commands runs INQUIRY, gets all mode pages with MODE SENSE and separately retrieves page 0. With these data we will know more about the features of your drives.

Regarding s2pexec also see https://github.com/uweseimet/scsi2pi/wiki/Advanced-Testing.

bog-dan-ro commented 1 month ago

@uweseimet I took a look at your code. Sadly I can not test it right now, my computer doesn't have RAM anymore[0]. A few things regarding your code:

Overall your code has looks better than mine, it has also proper unit tests!

[0] I temporary removed it and sent it to a friend to try to reverse engineering it. This computer uses custom RAM modules. I'll test your implementation on ,my computer when it's complete, which might take a couple of weeks (I hope no more than a month).

uweseimet commented 1 month ago

@bog-dan-ro You have probably missed that code for MODE SENSE/SELECT, LOAD/UNLOAD and mode page handling is inherited from the StorageDevice class.

uweseimet commented 1 month ago

@Pacjunk The issue_93_2 branch has been merged into the develop branch.

Pacjunk commented 1 month ago

Tried with block size set to 1024, got errors to do with no label (it does have a label).

Tried with your latest code (as of a couple of days ago), and get device errors. Debug log attached...

Oct 21 15:07:58 piscsi s2p[654]: +----+-----+------+-------------------------------------
Oct 21 15:07:58 piscsi s2p[654]: | ID | LUN | TYPE | IMAGE FILE
Oct 21 15:07:58 piscsi s2p[654]: +----+-----+------+-------------------------------------
Oct 21 15:07:58 piscsi s2p[654]: |  0 |   0 | SCHD | /home/pi/images/boot72.hd1
Oct 21 15:07:58 piscsi s2p[654]: |  3 |   0 | SCTP | /home/pi/images/vms_v5.4_1.tap
Oct 21 15:07:58 piscsi s2p[654]: +----+-----+------+-------------------------------------
Oct 21 15:08:36 piscsi s2p[654]: [2024-10-21 15:08:36.867] [info] Set log level to 'debug'
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.607] [debug] (ID 3) - Controller is executing TEST UNIT READY, CDB $00:00:00:00:00:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.607] [debug] (ID:LUN 3:0) - Device is executing TEST UNIT READY ($00)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.613] [debug] (ID 3) - Controller is executing INQUIRY, CDB $12:00:00:00:24:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.614] [debug] (ID:LUN 3:0) - Device is executing INQUIRY ($12)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.616] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.616] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.619] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.620] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.622] [debug] (ID 3) - Controller is executing MODE SELECT(6), CDB $15:00:00:00:0c:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.622] [debug] (ID:LUN 3:0) - Device is executing MODE SELECT(6) ($15)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.623] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.624] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.629] [debug] (ID 3) - Controller is executing READ POSITION, CDB $34:00:00:00:00:00:00:00:00:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.629] [debug] (ID:LUN 3:0) - Device is executing READ POSITION ($34)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.631] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:10:00:ff:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.632] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.637] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:50:00:ff:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.637] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.642] [debug] (ID 3) - Controller is executing REZERO/REWIND, CDB $01:00:00:00:00:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.642] [debug] (ID:LUN 3:0) - Device is executing REZERO/REWIND ($01)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.645] [debug] (ID 3) - Controller is executing TEST UNIT READY, CDB $00:00:00:00:00:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.645] [debug] (ID:LUN 3:0) - Device is executing TEST UNIT READY ($00)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.646] [debug] (ID 3) - Controller is executing INQUIRY, CDB $12:00:00:00:24:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.646] [debug] (ID:LUN 3:0) - Device is executing INQUIRY ($12)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.649] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.649] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.654] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.654] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.658] [debug] (ID 3) - Controller is executing MODE SELECT(6), CDB $15:00:00:00:0c:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.658] [debug] (ID:LUN 3:0) - Device is executing MODE SELECT(6) ($15)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.662] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.662] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.666] [debug] (ID 3) - Controller is executing READ POSITION, CDB $34:00:00:00:00:00:00:00:00:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.666] [debug] (ID:LUN 3:0) - Device is executing READ POSITION ($34)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.669] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:10:00:ff:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.669] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.674] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:50:00:ff:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.675] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.679] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.679] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.683] [debug] (ID 3) - Controller is executing MODE SELECT(6), CDB $15:00:00:00:0c:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.683] [debug] (ID:LUN 3:0) - Device is executing MODE SELECT(6) ($15)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.687] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.687] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.691] [debug] (ID 3) - Controller is executing TEST UNIT READY, CDB $00:00:00:00:00:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.691] [debug] (ID:LUN 3:0) - Device is executing TEST UNIT READY ($00)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.693] [debug] (ID 3) - Controller is executing INQUIRY, CDB $12:00:00:00:24:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.693] [debug] (ID:LUN 3:0) - Device is executing INQUIRY ($12)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.696] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.696] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.699] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.699] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.704] [debug] (ID 3) - Controller is executing MODE SELECT(6), CDB $15:00:00:00:0c:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.704] [debug] (ID:LUN 3:0) - Device is executing MODE SELECT(6) ($15)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.705] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:00:00:ff:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.705] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.710] [debug] (ID 3) - Controller is executing READ POSITION, CDB $34:00:00:00:00:00:00:00:00:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.710] [debug] (ID:LUN 3:0) - Device is executing READ POSITION ($34)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.712] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:10:00:ff:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.712] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.715] [debug] (ID 3) - Controller is executing MODE SENSE(6), CDB $1a:00:50:00:ff:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.716] [debug] (ID:LUN 3:0) - Device is executing MODE SENSE(6) ($1a)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.720] [debug] (ID 3) - Controller is executing REZERO/REWIND, CDB $01:00:00:00:00:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.720] [debug] (ID:LUN 3:0) - Device is executing REZERO/REWIND ($01)
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.724] [debug] (ID 3) - Controller is executing READ(6)/GET MESSAGE(6), CDB $08:00:00:00:50:00
Oct 21 15:09:00 piscsi s2p[654]: [2024-10-21 15:09:00.724] [debug] (ID:LUN 3:0) - Device is executing READ(6)/GET MESSAGE(6) ($08)

There is a SCSI test utility that tests various mode pages. I will run this and get back to you...

Pacjunk commented 1 month ago

Here is the output from the SCSI test utility. I haven't used the scsi2pi tester yet as I need to either find some different cables or an external tape drive that works (I'm sure there is one somewhere!).

First file is with the SCSI2Pi running...

SCSI2Pi.txt

Next is connected to a Sony DAT drive. This is a generic drive and doesn't have any DEC specific functions.

Sony DAT.txt

and finally, this is the command run again with a tape mounted. The information returned seems to be different.

Sony DAT Mounted.txt

Surprised the drive and especially the tape worked. Must be 20+ years old.

uweseimet commented 1 month ago

@Pacjunk Thank you for running these tests.

There are some differences in the mode pages which are caused by SCSI2Pi supporting some pages the tape drive does not support. This is when " CHECK CONDITION seen" is reported for the tape drive, but no errors are reported for SCSI2Pi. These differences should not matter. At the other data I will have a closer look at, especially in case of the medium partition pages. It looks as if your tape drive reports errors when returning data for partition numbers > 1, but SCSi2Pi does not, even though it should because only a single partition is supported. In order to further analyze these data I would like to ask you for a SCSI2Pi log on trace level when you run your SCSI test utility, and for the corresponding output of the utility, so that I can see the details of the commands and parameters sent/received by the tool.

In the SCSI2Pi log, is the " READ(6)/GET MESSAGE(6) ($08)" line the last line of the logfile, i.e. nothing happened after that? There are no SCSI errors logged anymore, but the sequence of MODE SELECT/MODE SENSE commands looks as if the workstation is trying to configure something. Can you please run the same test again, but with a block size of 4096 bytes and on trace level? Please use the very latest development binaries for everything. Depending on this logfile the next test would probably be to send the same MODE SELECT commands to the tape drive with s2pexec and then check what has changed with MODE SENSE.

Tried with block size set to 1024, got errors to do with no label (it does have a label).

It does have a label? I'm afraid I don't know what you mean, assuming that a label is an object on a tape. A blank image file does not have any data on it, i.e. it would also have no label.

When you provide a logfile please also provide the commit ID of the binaries this log is based on, so that I can identify the codebase.

uweseimet commented 1 month ago

@Pacjunk After running tests and collecting logs with the latest development binaries as outlined in my previous comment, I would like to ask you to run tests with the issue_93_3 branch. This branch you will have to compile yourself, and depending on future test results I will try to update it where required. In order to save compilation time I suggest using "make s2p ENABLE_SCHD=1 ENABLE_SCTP=1", so that only the s2p binary is created and only SCHD and SCTP are supported. I expect that future updates will only affect the tape.cpp file, i.e. compiling updates will not take that long even on a small Pi.

In the issue_93_3 branch I modified the tape properties based on the mode page output of your tool, the mode pages of my HP streamer and information, and the SSC-5 specification, which is a bit more precise than the SCSI-2 specification. Nevertheless, there are some mode page fields/device properties where I do not know how to correctly support them, or where your workstation might expect certain not mandatory properties. I hope that a SCSI2Pi trace log of the issue_93_3 branch provides more insight.

uweseimet commented 1 month ago

After applying a work-around (not related to SCSI2Pi) I can now successfully use the Gemar tape backup software for the Atari. This software uses a fixed block size and works similar to tar. On the one hand this means that besides tar there is another backup software that works with the current SCSI2Pi implementation, on the other hand this does not provide more insight.

uweseimet commented 1 month ago

@Pacjunk Any news? I'm afraid that without feedback on my previous questions and more testing from your side it will not be possible to support more software/platforms than those that are currently supported: mt, mtx, tar and the Gemar streamer software for the Atari.

Pacjunk commented 1 month ago

Sorry, life got in the way in a stressful and busy way. I will try to look soon. I assume I can just use the latest dev daily build?

uweseimet commented 1 month ago

Yes, the latest daily build plus a self-compiled issue_93_3 branch, all with a block size of 4096 bytes, with log level trace. Also please see my previous comments. It would also help to know the properties of all your physical drives, extracted by your tool.

Pacjunk commented 4 weeks ago

Took forever to build the issue_93_3 branch, but got there in the end. Attached is the log. Note there is some access to device 0 at the beginning. This is just the OS scanning the SCSI buss. Still getting a device error when trying to mount a tape.

29.txt

uweseimet commented 4 weeks ago

@Pacjunk Thank you for the log. Please (in further logs) suppress logging for device 0: by using "-L trace:3". Also please remember to provide trace logs for the current develop branch, and to add the property data of your other streamer, when you find the time for doing so.

Pacjunk commented 4 weeks ago

I used the latest develop branch, then applied 93_3 over the top - as you told me to do. THere is not much logging for 0 as I was not using it (booted off real HDD)

uweseimet commented 4 weeks ago

I'm afraid there has been a misunderstanding. I would need logs on trace level for both branches. issue_93_3 differs from the develop branch. For the develop branch there are nightly binaries you can use. Please use the latest ones and provide the commit ID you use for testing. Please confirm that the latest log is from the issue_93_3 branch. This branch and the develop branch have the same version number.

uweseimet commented 4 weeks ago

The last log does not reveal any SCSI errors. If your computer shows an error it is somehow not receiving the data it expects. Previously you mentioned something about a tape label. Please elaborate. Just like a blank tape, an image file does not contain any label. You have to explicitly create it, e.g. with a tape drive tool, regardless of whether there is a real drive or an emulated one. The last SCSI command executed returns 80 bytes of data just as requested. If this is supposed to be a label, it's clear that your computer is not satisfied with the data received, because a label has never been created. The bacula tape drive software for Linux requires each tape to be explicitly labeled before use. Looks as if you first have do that before you can use a tape image file.

I would still need the log for the develop branch, for comparison. I guess it will look very similar.

uweseimet commented 4 weeks ago

@Pacjunk After revisiting your latest log I wonder whether you were really testing the issue_93_3 branch. The last read command in the log, when executed for a blank image or an image with random data, should report either MEDIUM ERROR or BLANK CHECK. The code says so, and I have verified this behavior by sendin:

s2pexec>-i 3 -c 08:00:00:00:50:00 -L debug:3
[17:37:28.837] [debug] (ID 3) - Controller is executing READ(6)/GET MESSAGE(6), CDB $08:00:00:00:50:00
[17:37:28.837] [debug] (ID:LUN 3:0) - Device is executing READ(6)/GET MESSAGE(6) ($08)
Error: Can't execute command READ(6)/GET MESSAGE(6) ($08)
s2pexec>[17:37:32.650] [debug] (ID 3) - MEDIUM ERROR (Sense Key $03), READ ERROR (ASC $11), ASCQ $00

The error should be the same with the develop and the issue_93_3 branch. Old develop branch versions would not have reported an error but just returned the requested (empty or random) data.

In order to avoid any potential confusion and mismatches between the code I am working on and the code you are testing, please:

Thank you!

I would be interested in the response of your real tape drive when receiving the READ command above. Can you please add both the PiSCSI board and your drive to the same SCSI chain and then run s2pexec (e.g. with /opt/scsi2pi/bin/s2pexec) and then enter this:

s2pexec>-L debug:3 -i 3 -c 01:00:00:00:00:00
s2pexec>-c 08:00:00:00:50:00

The first command will rewind the type. Please wait for the end of this operation (the tape drive may take some time for that) before running the second command, which is the same READ command as the one at the end of the logfile. If your drive responds with POWER ON, RESET, OR BUS DEVICE RESET OCCURRED just repeat the command. Right after a reset this error may be reported on the first read access. In the ideal case you use a completely blank tape for this test. Any non-blank tape may already have a label (please see my comment and question on labeling in my previoius comment), i.e. the test would not reflect what the real drive does in case of an empty tape, which is the same as an empty image file.

And yet one more thing: Your logfile says "caching_mode=write-through". The caching mode is not a global property, but is device-specific (see https://www.scsi2pi.net/en/properties.html). The device specifier is missing, witout it the property is discarded.

uweseimet commented 3 weeks ago

@Pacjunk You mentioned issues with the PiSCSI web UI and SCSI2Pi. While waiting for your feedback I verified whether the web UI is working with SCSI2Pi and did not notice any problems. I installed 2024-04-30-PiSCSI-v24.04.01-arm64-lite.zip, and then I installed SCSI2Pi 3.4.3 with apt. After starting the s2p system service (see Quickstart on https://www.scsi2pi.net/en/installation.html) I could properly access the UI, see the attached screenshot. Note that the web UI does not work anymore after updating the Pi to the latest (bullseye) packages before (and maybe also after) launching the web UI for the first time. Looks as if the up to date bullseye setup of pip-managed python packages (at least pybabel) is not compatible with what the web UI requires, or at least not with the PiSCSI arm64-lite image. But this is a PiSCSI web UI issue and not caused by SCSI2Pi. I created https://github.com/PiSCSI/piscsi/issues/1481 for that. webui

Pacjunk commented 3 weeks ago

Hi, got a couple of hours today to do some testing using 13d6667 (although same results with 5cb8b4f). Using a blank tap file I managed to initialise (ie write a label), then mount the tape with that label successfully. Trying to copy files to the image resulted in errors. I notice that every record written to the .tap file has a "SCTP" prefix. This is most likely the reason that I cannot mount .tap files produced by others from places such as archive.org. Of course they don't have records prefixed with SCTP!

I have attached two files. The .tap file (after it has been initialised) and the log file. The steps were: 1 - Initialise the tape with a label (TEST77) 2 - Mount the tape 3 - Try to copy a file to the tape (failed) 4 - Dismount the tape.

I probably won't get any time with this until next week as I will be away for a few days. Cheers,

2.log 2.tap.txt

uweseimet commented 3 weeks ago

@Pacjunk Thank you for the log. Yes, the non-tar format is proprietary because it also contains meta data (see the comment at the beginning of tape.cpp) that represent filemarks and end-of-data markers. Without these meta data spacing in order to search for a filemark, for example, would not be possible. This is why spacing cannot be supported with tar files: The required markers are missing in these files.

If I understand your correctly the log does not contain the SCSI operations executed when labeling a tape?

Edit: But the logs now reveal more information. Looks as if the labeling step actually IS included, but please confirm. I see that your workstation/driver uses reverse spacing:

[2024-11-06 18:30:10.820] [trace] (ID 3) - COMMAND phase
[2024-11-06 18:30:10.820] [debug] (ID 3) - Controller is executing SPACE(6), CDB $11:00:ff:ff:ff:00
[2024-11-06 18:30:10.820] [trace] (ID 3) - Going to transfer 0 byte(s) in chunks of 0 byte(s)
[2024-11-06 18:30:10.820] [debug] (ID:LUN 3:0) - Device is executing SPACE(6) ($11)
[2024-11-06 18:30:10.820] [error] (ID:LUN 3:0) - Reverse spacing is not supported

This is not supported by SCSI2Pi (and also not a mandatory SCSI requirement) and I don't know if I will support it. See the initial comment of tape.cpp for details. What I would like to check is whether your physical drive really supports reverse spacing. This can be checked by running s2pexec against it. I will provide the required s2pexec commands later. They are essentially the same commands you can see in the logfile, e.g. line 3200.

Pacjunk commented 3 weeks ago

Yes the log includes labelling the tape.

uweseimet commented 2 weeks ago

This is most likely the reason that I cannot mount .tap files produced by others from places such as archive.org.

Is there any information on the format of these files? Assuming that these are not just tar files, they must contain encoded meta data that represent filemarks etc., and this encoding must be document somewhere in order to be usable. From your latest log it is obvious that filemarks are used to mark labels. Any kind of encoding I can think of would require rather ugly code to read/write it, and/or would increase the file size quite a lot. Especially when you want to space backwards, you need to somehow find where the previous tape object (block, filemark etc.) starts. This information cannot be encoded in the actual block data, but must live in a separate world. I guess that with a real streamer there is an interrupt when such kind of data are encountered, and the streamer's firmware can then work with these data, without confusing them with an actual block payload. IMO the description of the SPACE(6) command and what happens when a block/filemark/setmark/end-of-data marker is encountered unexpectedly implies this.

At least it is clear now that labeling is definitely required before you can make use of a tape image file, but the end of your logfile looks like your workstation is searching something on the "tape" after labeling, which it cannot find. As part of this search operation it spaces backwards, which is probably some kind of retry mechanism. At least this is how I read the end of the logfile.