Closed uweseimet closed 9 months ago
@supercompman @joeventura1 @jcres69 @edgeux Some time ago in https://github.com/PiSCSI/piscsi/issues/656 you stumbled upon cases where PiSCSI was reporting "Not able to receive 512 bytes of data". Because of numerous error handling and logging improvements as part of the new SCSI2Pi project (see https://www.scsi2pi.net/en/scsi2pi.html for details), it might be possible now to find out more about what's actually happening. If you are still interested in resolving this issue please get back to me in this ticket. If you are not interested, regardless of the reason, please drop me a short note.
If you would like to help with further analyzing this problem, please first verify whether it still exists in PiSCSI 23.11.01 and/or in SCSI2Pi 1.1.1. The latter you can download as a binary package on https://www.scsi2pi.net/en/downloads.html, i.e. compiling the sources is not required.
I would appreciate your feedback.
I reimaged my pi4b and loaded the latest piscsi 23.11.1 and can confirm that the issue still exists on my mac plus. Let me know how I can help…
Jan 17 19:13:47 piscsi PISCSI[503]: [2024-01-17 19:13:47.651] [info] Validating: operation=ATTACH, command params='locale=en', 'token=???', device=6:0, >Jan 17 19:13:47 piscsi PISCSI[503]: [2024-01-17 19:13:47.651] [info] Executing: operation=ATTACH, command params='locale=en', 'token=???', device=6:0, t>Jan 17 19:13:47 piscsi PISCSI[503]: [2024-01-17 19:13:47.652] [info] Attached SCHD 6:0 Jan 17 19:13:55 piscsi systemd[1]: Starting Online ext4 Metadata Check for All Filesystems... Jan 17 19:13:55 piscsi systemd[1]: e2scrub_all.service: Succeeded. Jan 17 19:13:55 piscsi systemd[1]: Finished Online ext4 Metadata Check for All Filesystems. Jan 17 19:14:17 piscsi systemd[1]: systemd-hostnamed.service: Succeeded. Jan 17 19:14:37 piscsi dhcpcd[683]: eth0: Router Advertisement from fe80::baf8:53ff:fef7:e161 Jan 17 19:16:37 piscsi kernel: sched: RT throttling activated Jan 17 19:16:39 piscsi PISCSI[503]: [2024-01-17 19:16:39.505] [error] (ID 6) - Not able to receive 512 byte(s) of data, only received 179
@jcres69 Thank you for your feedback and for offering your help.
Because the issue still exists with PiSCSI 23.11.01 I guess it also exists with SCSI2PI, but the next step would be to confirm this. Can you please install SCSI2Pi, either by using the binary packages offered on https://www.scsi2pi.net/en/downloads.html, or by cloning the GitHub sources on https://github.com/uweseimet/scsi2pi? Using the binaries is faster, but for the purpose of testing it is better to compile the sources of the develop branch, and with a Pi 4 the compilation time is quite acceptable. You do not have to compile everything, "make s2p" is sufficient. For testing it is best not use a system service for launching the emulation, but to launch s2p from the command line. It appears you are using a hard drive device with SCSI ID 6, so the launch command would be similar to
>sudo s2p -id 6 NAME_OF_IMAGE_FILE
If you find that s2p reports the same issues as piscsi please drop me a note in this ticket. I will then create a new issue, just for this purpose.
I'm sort of a noob, so forgive me if I make some dumb mistakes.
I downloaded and installed "scsi2pi_1.2_devel_fb4e56b_debug_arm64-1.deb"
But, when I try to run s2p or s2pctl, I get this error message:
@.:~ $ s2p s2p: error while loading shared libraries: libprotobuf.so.32: cannot open shared object file: No such file or directory @.:~ $ s2pctl s2pctl: error while loading shared libraries: libprotobuf.so.32: cannot open shared object file: No such file or directory
@jcres69 Which Pi are you using, and which OS are you running? What does 'lsb_release -a' say, and what does 'ldd s2p' say?
Pi4b, Raspberry Pi OS lite (64 bit)
@.***:~ $ cat /etc/os-release PRETTY_NAME="Debian GNU/Linux 11 (bullseye)" NAME="Debian GNU/Linux" VERSION_ID="11" VERSION="11 (bullseye)"
@jcres69 Please also provide the output of 'ldd s2p' and 'ldd piscsi' (from the PiSCSI project) on the same machine. I have tested the binaries with the regular Pi OS, but not with "lite". Looks as if there are special requirements for the libraries that have to be installed.
@jcres69 By the way, if it is possible, please do not add comments to GitHub by email, but in the GitHub web UI. Otherwise the comments in the tickets are quite hard to read and contain a lot of noise unless you edit them like I just did.
@jcres69 I think I know now what the issue might be: You downloaded the 64 bit binary, which I (at least currentl) only provide for bookworm (also see the description on the download page). Does the 32 bit binary (which is for both bullseye and bookworm) work for you?
@uweseimet I will try the 32bit binary. and here is the LDD output for both scsi2pi and piscsi. yes, it looks like there are some things missing on the OS lite, or I just installed the wrong binary...
$ ldd /usr/local/bin/piscsi
/usr/local/bin/piscsi: /lib/aarch64-linux-gnu/libc.so.6: version GLIBC_2.34' not found (required by /usr/local/bin/piscsi) /usr/local/bin/piscsi: /lib/aarch64-linux-gnu/libc.so.6: version
GLIBC_2.33' not found (required by /usr/local/bin/piscsi)
/usr/local/bin/piscsi: /lib/aarch64-linux-gnu/libc.so.6: version GLIBC_2.32' not found (required by /usr/local/bin/piscsi) /usr/local/bin/piscsi: /lib/aarch64-linux-gnu/libstdc++.so.6: version
GLIBCXX_3.4.29' not found (required by /usr/local/bin/piscsi)
linux-vdso.so.1 (0x0000007fac20e000)
libpcap.so.0.8 => /lib/aarch64-linux-gnu/libpcap.so.0.8 (0x0000007fac186000)
libprotobuf.so.32 => not found
libstdc++.so.6 => /lib/aarch64-linux-gnu/libstdc++.so.6 (0x0000007fabfae000)
libm.so.6 => /lib/aarch64-linux-gnu/libm.so.6 (0x0000007fabf03000)
libgcc_s.so.1 => /lib/aarch64-linux-gnu/libgcc_s.so.1 (0x0000007fabedf000)
libc.so.6 => /lib/aarch64-linux-gnu/libc.so.6 (0x0000007fabd6b000)
/lib/ld-linux-aarch64.so.1 (0x0000007fac1de000)
libdbus-1.so.3 => /lib/aarch64-linux-gnu/libdbus-1.so.3 (0x0000007fabd05000)
libpthread.so.0 => /lib/aarch64-linux-gnu/libpthread.so.0 (0x0000007fabcd4000)
libsystemd.so.0 => /lib/aarch64-linux-gnu/libsystemd.so.0 (0x0000007fabc0e000)
librt.so.1 => /lib/aarch64-linux-gnu/librt.so.1 (0x0000007fabbf6000)
liblzma.so.5 => /lib/aarch64-linux-gnu/liblzma.so.5 (0x0000007fabbc0000)
libzstd.so.1 => /lib/aarch64-linux-gnu/libzstd.so.1 (0x0000007fabaf2000)
liblz4.so.1 => /lib/aarch64-linux-gnu/liblz4.so.1 (0x0000007fabac3000)
libgcrypt.so.20 => /lib/aarch64-linux-gnu/libgcrypt.so.20 (0x0000007fab9f3000)
libgpg-error.so.0 => /lib/aarch64-linux-gnu/libgpg-error.so.0 (0x0000007fab9c0000)
$ ldd /opt/scsi2pi/bin/s2p
/opt/scsi2pi/bin/s2p: /lib/aarch64-linux-gnu/libc.so.6: version GLIBC_2.34' not found (required by /opt/scsi2pi/bin/s2p) /opt/scsi2pi/bin/s2p: /lib/aarch64-linux-gnu/libc.so.6: version
GLIBC_2.33' not found (required by /opt/scsi2pi/bin/s2p)
/opt/scsi2pi/bin/s2p: /lib/aarch64-linux-gnu/libc.so.6: version GLIBC_2.32' not found (required by /opt/scsi2pi/bin/s2p) /opt/scsi2pi/bin/s2p: /lib/aarch64-linux-gnu/libstdc++.so.6: version
GLIBCXX_3.4.29' not found (required by /opt/scsi2pi/bin/s2p)
linux-vdso.so.1 (0x0000007fbdfd8000)
libpcap.so.0.8 => /lib/aarch64-linux-gnu/libpcap.so.0.8 (0x0000007fbdf50000)
libprotobuf.so.32 => not found
libstdc++.so.6 => /lib/aarch64-linux-gnu/libstdc++.so.6 (0x0000007fbdd78000)
libm.so.6 => /lib/aarch64-linux-gnu/libm.so.6 (0x0000007fbdccd000)
libgcc_s.so.1 => /lib/aarch64-linux-gnu/libgcc_s.so.1 (0x0000007fbdca9000)
libc.so.6 => /lib/aarch64-linux-gnu/libc.so.6 (0x0000007fbdb35000)
/lib/ld-linux-aarch64.so.1 (0x0000007fbdfa8000)
libdbus-1.so.3 => /lib/aarch64-linux-gnu/libdbus-1.so.3 (0x0000007fbdacf000)
libpthread.so.0 => /lib/aarch64-linux-gnu/libpthread.so.0 (0x0000007fbda9e000)
libsystemd.so.0 => /lib/aarch64-linux-gnu/libsystemd.so.0 (0x0000007fbd9d8000)
librt.so.1 => /lib/aarch64-linux-gnu/librt.so.1 (0x0000007fbd9c0000)
liblzma.so.5 => /lib/aarch64-linux-gnu/liblzma.so.5 (0x0000007fbd98a000)
libzstd.so.1 => /lib/aarch64-linux-gnu/libzstd.so.1 (0x0000007fbd8bc000)
liblz4.so.1 => /lib/aarch64-linux-gnu/liblz4.so.1 (0x0000007fbd88d000)
libgcrypt.so.20 => /lib/aarch64-linux-gnu/libgcrypt.so.20 (0x0000007fbd7bd000)
libgpg-error.so.0 => /lib/aarch64-linux-gnu/libgpg-error.so.0 (0x0000007fbd78a000)
pi@piscsi:~/piscsi $
@jcres69 Thank you for the output. I will analyze it and then decide whether I have to provide yet one more binary package. This will also depend on whether the 32 bit binaries work for you.
@jcres69 I almost forgot: When installing s2p the original piscsi is replaced by a link to s2p and backed up. This is required in order to still have a binary called 'piscsi', because the PiSCSI system service needs it. In order to run ldd on that binary, please run 'ldd piscsi.dist'. Unless you uninstall s2p or you re-install piscsi 'piscsi.dist' should be present.
@uweseimet pi@piscsi:/usr/local/bin $ ldd piscsi.dist linux-vdso.so.1 (0x0000007fb66cc000) libpthread.so.0 => /lib/aarch64-linux-gnu/libpthread.so.0 (0x0000007fb666b000) libpcap.so.0.8 => /lib/aarch64-linux-gnu/libpcap.so.0.8 (0x0000007fb6613000) libprotobuf.so.23 => /lib/aarch64-linux-gnu/libprotobuf.so.23 (0x0000007fb630e000) libstdc++.so.6 => /lib/aarch64-linux-gnu/libstdc++.so.6 (0x0000007fb6136000) libm.so.6 => /lib/aarch64-linux-gnu/libm.so.6 (0x0000007fb608b000) libgcc_s.so.1 => /lib/aarch64-linux-gnu/libgcc_s.so.1 (0x0000007fb6067000) libc.so.6 => /lib/aarch64-linux-gnu/libc.so.6 (0x0000007fb5ef3000) /lib/ld-linux-aarch64.so.1 (0x0000007fb669c000) libdbus-1.so.3 => /lib/aarch64-linux-gnu/libdbus-1.so.3 (0x0000007fb5e8d000) libz.so.1 => /lib/aarch64-linux-gnu/libz.so.1 (0x0000007fb5e63000) libsystemd.so.0 => /lib/aarch64-linux-gnu/libsystemd.so.0 (0x0000007fb5d9d000) librt.so.1 => /lib/aarch64-linux-gnu/librt.so.1 (0x0000007fb5d85000) liblzma.so.5 => /lib/aarch64-linux-gnu/liblzma.so.5 (0x0000007fb5d4d000) libzstd.so.1 => /lib/aarch64-linux-gnu/libzstd.so.1 (0x0000007fb5c81000) liblz4.so.1 => /lib/aarch64-linux-gnu/liblz4.so.1 (0x0000007fb5c52000) libgcrypt.so.20 => /lib/aarch64-linux-gnu/libgcrypt.so.20 (0x0000007fb5b82000) libgpg-error.so.0 => /lib/aarch64-linux-gnu/libgpg-error.so.0 (0x0000007fb5b4f000) pi@piscsi:/usr/local/bin $
I installed the 32bit binary, but i get this error. I'm thinking i should just reimage and try again with the full Pi image...
pi@piscsi:~ $ sudo dpkg -i scsi2pi_1.2_devel_fb4e56b_armhf-1.deb Selecting previously unselected package scsi2pi:armhf. (Reading database ... 41784 files and directories currently installed.) Preparing to unpack scsi2pi_1.2_devel_fb4e56b_armhf-1.deb ... Unpacking scsi2pi:armhf (1.2) ... Setting up scsi2pi:armhf (1.2) ... Replacing PiSCSI binaries by SCSI2Pi binaries Replacing PiSCSI manpages with SCSI2Pi manpages mv: cannot stat 'pscsi.1': No such file or directory Restarting PiSCSI service if active
@jcres69 You can ignore this error message. As far as I can tell you get it because the previous scsi2pi installation was not de-installed (see the scsi2pi download webpage for the de-installation command), but this is not a problem. I will try to address this particular problem anyway. The binary should be properly installed, because the error message just referred to the manpage. Can you please run 'ldd /opt/scsi2pi/bin/s2p'?
Do you know how to compile PiSCSI from the sources? If you do, the procedure for SCSI2Pi is more or less the same. While trying to work on the "Could not receive" issue compiling from the sources would be required anyway, because I may have to change the source code and then I would like to ask you to recompile and test the change. This incremental approach cannot really be done with binaries.
ldd /opt/scsi2pi/bin/s2p not a dynamic executable
I can clone the github repo, and compile it if that is what you mean, but i'd need instructions to make sure i'm doing it right. This is what i tried to do first with s2p, but it didnt run after completing, so I installed the .deb package.
@jcres69 Can you please run 'ls -al /opt/scsi2pi/bin/s2p'?
I would like to ask you not to replace your lite installation by a different one, if possible. During the weekend I will try to install Pi os lite on my Pi, so that I can better analyze which kind of binary is needed. In case you had issues with compiling, and if the compilation instructions on https://www.scsi2pi.net/en/downloads.html are not sufficient, please tell me and provide the error message you get. Thank you for spending your time on this.
@uweseimet pi@piscsi:~ $ ls -al /opt/scsi2pi/bin/ total 2792 drwxr-xr-x 2 root root 4096 Jan 19 21:03 . drwxr-xr-x 4 root root 4096 Jan 19 21:03 .. -rwxr-xr-x 1 root root 1302412 Jan 19 18:20 s2p -rwxr-xr-x 1 root root 564264 Jan 19 18:20 s2pctl -rwxr-xr-x 1 root root 424572 Jan 19 18:20 s2pdump -rwxr-xr-x 1 root root 556076 Jan 19 18:20 s2pexec
@jcres69 When you try to run s2p in this folder, which error message do you get?
@uweseimet pi@piscsi:~ $ cd /opt/scsi2pi/bin pi@piscsi:/opt/scsi2pi/bin $ s2p -bash: s2p: command not found
@jcres69 The folder is probably not in your standard path, please try './s2p'.
@uweseimet pi@piscsi:/opt/scsi2pi/bin $ ./s2p -bash: ./s2p: No such file or directory
@jcres69 That's strange, ls does list this file, doesn't it? I mean, the file is there, in the folder?
@uweseimet yes it's there, just wont run!
@jcres69 OK, I will install Pi OS lite on my Pi and test tomorrow.
So at least for now compiling appears to be the only option. Which error message do you get?
@uweseimet I don't remember seeing any errors during compile, but s2p didnt seem to be running so I thought I made a mistake, and then just installed the deb package (which turned out to be the wrong one).
@jcres69 After compiling s2p you can launch it manually. It's located in cpp/bin/s2p. This will definitely work. Or you just replace your piscsi binary in /usr/local/bin with it. But you cannot run the piscsi binary and the s2p binary at the same time, because they both try to use the same resources. I have Pi OS lite up and running now and observe exactly the same issues as you. The 32 bit binary will not work on 64 bit Pi OS lite, I just checked that. On bullseye the 64 bit binary is missing libraries, because it was built for bookworm, and bullseye does not have the required library versions. I will consider also offering a bullseye 64 bit binary, but this will take some time. In the meantime, using your self-compiled s2p binary is best, and in case I have to modify sources for testing we will need it anyay. Please launch this binary (see above), and if there are issues, please tell me.
@uweseimet yes that seems to work. does this look good?
pi@piscsi:~/scsi2pi/cpp/bin $ sudo ./s2p SCSI Target Emulator and SCSI Initiator Tools SCSI2Pi (Target Emulation) Version 1.1 Copyright (C) 2016-2020 GIMONS Copyright (C) 2020-2023 Contributors to the PiSCSI project Copyright (C) 2021-2024 Uwe Seimet [2024-01-19 22:12:53.957] [info] Set log level to 'info' [2024-01-19 22:12:53.958] [info] Detected 'Raspberry Pi 4 Model B Rev 1.5' [2024-01-19 22:12:53.969] [info] Cleared reserved ID(s) [2024-01-19 22:12:53.969] [info] No devices currently attached. No devices currently attached.
@jcres69 Yes, that looks good, indeed! Remember (also see the information on the SCSI2Pi website), s2p is essentially a replacement for the piscsi binary. This means after replacing piscsi with s2p your PiSCSI installation should work as before, except for the numerous new features/fixes listed on the SCSI2Pi website. In your case, for testing purposes, just replace piscsi by s2p with any means you like. In general, for testing it is best not to run piscsi/s2p with a system service, but launch s2p directly from the command line, e.g. by just launching it directly from the cpp/bin folder. Then, when you recompile, you can just relaunch it and test again. But please check out and compile the SCSI2Pi develop branch, because it contains the latest code, and recompile, like this:
git checkout develop
make
This will give you version 1.2-devel, and that's the one where based on your test results (logfiles etc.) I can try to apply fixes to. But first we need to know whether 1.2-devel still reports the error message. Are you familiar with launching s2p on the command line? It works just like it works for piscsi, with the same options. Please tell me if you need help.
@uweseimet ahhh, right I didnt checkout the develop branch. ok, I will do that and report back after testing...
@jcres69 Cool, thank you! As soon as you have a working setup things get rather easy: I will (hopefully, i.e. I hope that I will find out what's wrong) change the sources, you will update your checked out sources, recomple ('make') , and test. This is an incremental process, which may take some time. Note that it's getting late here (Germany), i.e. I may not respond anymore today, but only tomorrow. In case the error is still there with s2p (I guess so) I will create a new ticket for it. I was just using the current ticket for kickstarting.
mv: cannot stat 'pscsi.1': No such file or directory
This was due to a typo, which is just fixed.
@jcres69 When you resume testing please update (git pull) your develop branch and recompile. Note that the offending message has changed to something like "Received x bytes(s) in DATA OUT phase, expected to receive y" and is now on warning level. In case you encounter this message, in order to further analyze it I would need about 10 lines before and after it, logged on trace level, so that I can see the context. The rest of the logfile currently does not matter.
how do I enable trace logging?
With "-L trace" as additional option when lauching s2p, e.g.
sudo s2p -L trace
I recommand first checking whether the message appears at all with the standard loglevel, because trace can produce a lot of noisy output.
@uweseimet so far I've been unable to reproduce the error, however when I switch to piscsi it is very easy to reproduce. I enabled trace logging in piscsi and here are a few logs showing the error in case this helps. Also, I noticed that "piscsi kernel: sched: RT throttling activated" always occurs in syslog prior to the error. Again, I have not seen any of this using s2p.
[2024-01-21 11:26:07.810] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:07.813] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:07.813] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:07.813] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:07.815] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:07.815] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:07.815] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:07.817] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:07.817] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:07.817] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:07.819] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:07.819] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:07.819] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:07.822] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:07.822] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:07.822] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:07.824] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:07.824] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:07.828] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:07.830] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:07.830] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:07.830] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:13.338] [error] (ID 5) - Not able to receive 512 byte(s) of data, only received 130 [2024-01-21 11:26:13.338] [debug] (ID 5) - Error status: Sense Key $0b, ASC $00 [2024-01-21 11:26:13.338] [trace] (ID 5) - Status phase, status is $02 [2024-01-21 11:26:13.338] [trace] (ID 5) - Sending data, offset: 0, length: 1 [2024-01-21 11:26:13.338] [trace] (ID 5) - All data transferred, moving to next phase: status [2024-01-21 11:26:13.338] [trace] (ID 5) - Message In phase [2024-01-21 11:26:13.338] [trace] (ID 5) - Sending data, offset: 0, length: 1 [2024-01-21 11:26:13.339] [trace] (ID 5) - All data transferred, moving to next phase: msgin [2024-01-21 11:26:13.339] [trace] (ID 5) - Bus Free phase [2024-01-21 11:26:13.831] [trace] (ID 5) - ++++ Starting processing for initiator ID 7 [2024-01-21 11:26:13.831] [trace] (ID 5) - Selection phase [2024-01-21 11:26:13.831] [trace] (ID 5) - Selection completed [2024-01-21 11:26:13.831] [trace] (ID 5) - Command phase [2024-01-21 11:26:13.831] [trace] (ID 5) - Controller is executing Write10, CDB $2a000000468300019000 [2024-01-21 11:26:13.831] [debug] (ID:LUN 5:0) - Device is executing Write10 ($2a) [2024-01-21 11:26:13.832] [trace] (ID:LUN 5:0) - READ/WRITE/VERIFY/SEEK, start block: $00004683, blocks: 400 [2024-01-21 11:26:13.832] [trace] (ID 5) - Data Out phase [2024-01-21 11:26:13.832] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:13.834] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:13.834] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:13.834] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:13.836] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:13.836] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:13.836] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:13.839] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:13.839] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:13.839] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:13.841] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:13.841] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:13.841] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:13.844] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:13.844] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:13.844] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:13.846] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:13.846] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:13.846] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:13.848] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:13.848] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:13.848] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:13.850] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:13.850] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:13.851] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:13.853] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:13.853] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:13.853] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:13.855] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:13.855] [trace] (ID:LUN 5:0) - Device is ready
[2024-01-21 11:26:13.872] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:13.872] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:13.872] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:13.874] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:13.874] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:13.874] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:13.877] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:13.877] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:13.877] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:13.879] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:13.879] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:13.879] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:13.881] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:13.881] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:13.881] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:19.338] [error] (ID 5) - Not able to receive 512 byte(s) of data, only received 403 [2024-01-21 11:26:19.338] [debug] (ID 5) - Error status: Sense Key $0b, ASC $00 [2024-01-21 11:26:19.338] [trace] (ID 5) - Status phase, status is $02 [2024-01-21 11:26:19.338] [trace] (ID 5) - Sending data, offset: 0, length: 1 [2024-01-21 11:26:19.338] [trace] (ID 5) - All data transferred, moving to next phase: status [2024-01-21 11:26:19.338] [trace] (ID 5) - Message In phase [2024-01-21 11:26:19.338] [trace] (ID 5) - Sending data, offset: 0, length: 1 [2024-01-21 11:26:19.339] [trace] (ID 5) - All data transferred, moving to next phase: msgin [2024-01-21 11:26:19.339] [trace] (ID 5) - Bus Free phase [2024-01-21 11:26:19.834] [trace] (ID 5) - ++++ Starting processing for initiator ID 7 [2024-01-21 11:26:19.834] [trace] (ID 5) - Selection phase [2024-01-21 11:26:19.834] [trace] (ID 5) - Selection completed [2024-01-21 11:26:19.834] [trace] (ID 5) - Command phase [2024-01-21 11:26:19.834] [trace] (ID 5) - Controller is executing Write10, CDB $2a000000468300019000 [2024-01-21 11:26:19.834] [debug] (ID:LUN 5:0) - Device is executing Write10 ($2a) [2024-01-21 11:26:19.834] [trace] (ID:LUN 5:0) - READ/WRITE/VERIFY/SEEK, start block: $00004683, blocks: 400 [2024-01-21 11:26:19.834] [trace] (ID 5) - Data Out phase [2024-01-21 11:26:19.834] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:19.837] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:19.837] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:19.837] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:19.839] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:19.839] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:19.839] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s) [2024-01-21 11:26:19.842] [trace] (ID 5) - Phase: dataout [2024-01-21 11:26:19.842] [trace] (ID:LUN 5:0) - Device is ready [2024-01-21 11:26:19.842] [trace] (ID 5) - Receiving data, transfer length: 512 byte(s)
[2024-01-21 15:44:05.095] [trace] (ID 6) - Bus Free phase [2024-01-21 15:44:13.212] [trace] (ID 6) - ++++ Starting processing for initiator ID 7 [2024-01-21 15:44:13.213] [trace] (ID 6) - Selection phase [2024-01-21 15:44:13.213] [trace] (ID 6) - Selection completed [2024-01-21 15:44:13.213] [trace] (ID 6) - Command phase [2024-01-21 15:44:13.214] [trace] (ID 6) - Controller is executing Write10, CDB $2a000000890d00001f00 [2024-01-21 15:44:13.214] [debug] (ID:LUN 6:0) - Device is executing Write10 ($2a) [2024-01-21 15:44:13.214] [trace] (ID:LUN 6:0) - READ/WRITE/VERIFY/SEEK, start block: $0000890d, blocks: 31 [2024-01-21 15:44:13.214] [trace] (ID 6) - Data Out phase [2024-01-21 15:44:13.214] [trace] (ID 6) - Receiving data, transfer length: 512 byte(s) [2024-01-21 15:44:13.217] [trace] (ID 6) - Phase: dataout [2024-01-21 15:44:13.217] [trace] (ID:LUN 6:0) - Device is ready [2024-01-21 15:44:13.217] [trace] (ID 6) - Receiving data, transfer length: 512 byte(s) [2024-01-21 15:44:13.220] [trace] (ID 6) - Phase: dataout [2024-01-21 15:44:13.220] [trace] (ID:LUN 6:0) - Device is ready [2024-01-21 15:44:13.220] [trace] (ID 6) - Receiving data, transfer length: 512 byte(s) [2024-01-21 15:44:13.223] [trace] (ID 6) - Phase: dataout [2024-01-21 15:44:13.223] [trace] (ID:LUN 6:0) - Device is ready [2024-01-21 15:44:13.223] [trace] (ID 6) - Receiving data, transfer length: 512 byte(s) [2024-01-21 15:44:13.227] [trace] (ID 6) - Phase: dataout [2024-01-21 15:44:13.227] [trace] (ID:LUN 6:0) - Device is ready [2024-01-21 15:44:13.227] [trace] (ID 6) - Receiving data, transfer length: 512 byte(s) [2024-01-21 15:44:13.230] [trace] (ID 6) - Phase: dataout [2024-01-21 15:44:13.230] [trace] (ID:LUN 6:0) - Device is ready [2024-01-21 15:44:13.230] [trace] (ID 6) - Receiving data, transfer length: 512 byte(s) [2024-01-21 15:44:13.234] [trace] (ID 6) - Phase: dataout [2024-01-21 15:44:13.234] [trace] (ID:LUN 6:0) - Device is ready [2024-01-21 15:44:13.234] [trace] (ID 6) - Receiving data, transfer length: 512 byte(s) [2024-01-21 15:44:13.236] [trace] (ID 6) - Phase: dataout [2024-01-21 15:44:13.236] [trace] (ID:LUN 6:0) - Device is ready [2024-01-21 15:44:13.236] [trace] (ID 6) - Receiving data, transfer length: 512 byte(s) [2024-01-21 15:44:13.240] [trace] (ID 6) - Phase: dataout [2024-01-21 15:44:13.240] [trace] (ID:LUN 6:0) - Device is ready [2024-01-21 15:44:13.240] [trace] (ID 6) - Receiving data, transfer length: 512 byte(s) [2024-01-21 15:44:13.243] [trace] (ID 6) - Phase: dataout [2024-01-21 15:44:13.243] [trace] (ID:LUN 6:0) - Device is ready [2024-01-21 15:44:13.243] [trace] (ID 6) - Receiving data, transfer length: 512 byte(s) [2024-01-21 15:44:13.246] [trace] (ID 6) - Phase: dataout [2024-01-21 15:44:13.246] [trace] (ID:LUN 6:0) - Device is ready [2024-01-21 15:44:13.246] [trace] (ID 6) - Receiving data, transfer length: 512 byte(s) [2024-01-21 15:44:13.250] [trace] (ID 6) - Phase: dataout [2024-01-21 15:44:13.250] [trace] (ID:LUN 6:0) - Device is ready [2024-01-21 15:44:13.250] [trace] (ID 6) - Receiving data, transfer length: 512 byte(s) [2024-01-21 15:44:13.252] [trace] (ID 6) - Phase: dataout [2024-01-21 15:44:13.253] [trace] (ID:LUN 6:0) - Device is ready [2024-01-21 15:44:13.253] [trace] (ID 6) - Receiving data, transfer length: 512 byte(s) [2024-01-21 15:44:13.256] [trace] (ID 6) - Phase: dataout [2024-01-21 15:44:13.256] [trace] (ID:LUN 6:0) - Device is ready [2024-01-21 15:44:13.256] [trace] (ID 6) - Receiving data, transfer length: 512 byte(s) [2024-01-21 15:44:13.259] [trace] (ID 6) - Phase: dataout [2024-01-21 15:44:13.259] [trace] (ID:LUN 6:0) - Device is ready [2024-01-21 15:44:13.259] [trace] (ID 6) - Receiving data, transfer length: 512 byte(s) [2024-01-21 15:44:13.263] [trace] (ID 6) - Phase: dataout [2024-01-21 15:44:13.263] [trace] (ID:LUN 6:0) - Device is ready [2024-01-21 15:44:13.263] [trace] (ID 6) - Receiving data, transfer length: 512 byte(s) [2024-01-21 15:44:13.267] [trace] (ID 6) - Phase: dataout [2024-01-21 15:44:13.267] [trace] (ID:LUN 6:0) - Device is ready [2024-01-21 15:44:13.267] [trace] (ID 6) - Receiving data, transfer length: 512 byte(s) [2024-01-21 15:44:19.212] [error] (ID 6) - Not able to receive 512 byte(s) of data, only received 271 [2024-01-21 15:44:19.212] [debug] (ID 6) - Error status: Sense Key $0b, ASC $00 [2024-01-21 15:44:19.212] [trace] (ID 6) - Status phase, status is $02 [2024-01-21 15:44:19.212] [trace] (ID 6) - Sending data, offset: 0, length: 1 [2024-01-21 15:44:19.213] [trace] (ID 6) - All data transferred, moving to next phase: status [2024-01-21 15:44:19.213] [trace] (ID 6) - Message In phase [2024-01-21 15:44:19.213] [trace] (ID 6) - Sending data, offset: 0, length: 1 [2024-01-21 15:44:19.213] [trace] (ID 6) - All data transferred, moving to next phase: msgin [2024-01-21 15:44:19.213] [trace] (ID 6) - Bus Free phase [2024-01-21 15:44:19.214] [trace] (ID 6) - ++++ Starting processing for initiator ID 7 [2024-01-21 15:44:19.214] [trace] (ID 6) - Selection phase [2024-01-21 15:44:19.214] [trace] (ID 6) - Selection completed [2024-01-21 15:44:19.214] [trace] (ID 6) - Command phase [2024-01-21 15:44:19.214] [trace] (ID 6) - Controller is executing RequestSense, CDB $030000001000 [2024-01-21 15:44:19.214] [debug] (ID:LUN 6:0) - Device is executing RequestSense ($03) [2024-01-21 15:44:19.214] [trace] (ID:LUN 6:0) - Status $0, Sense Key $b, ASC $0 [2024-01-21 15:44:19.214] [trace] (ID 6) - Data In phase [2024-01-21 15:44:19.214] [trace] (ID 6) - Sending data, offset: 0, length: 16 [2024-01-21 15:44:19.214] [trace] (ID 6) - All data transferred, moving to next phase: datain [2024-01-21 15:44:19.214] [trace] (ID 6) - Status phase, status is $00
@jcres69 Thank you for testing. If this problem is really gone with SCSI2Pi this would be because of the extensive code cleanup and many improvements I applied when setting up the SCSI2Pi project. But whether it is really gone only time will tell, because this it appears to have been quite spurious. On my Atari I only saw it twice in more than a year, this is why I asked for support from PiSCSI users who can more reliably reproduce this issue. As long as nobody reports this problem anymore we can only assume that it is gone. Please get back to me if you stumble upon it again.
I cannot yet comment on the "sched: RT throttling activated" message. I have to admit I have never looked into the system log, but I will do this in the future. It might be, though, that this message is not related to piscsi at all. Do you also see this message in this message in the logs when running s2p. I'm asking this because my changes included scheduling changes, indeed.
By the way, soon I will also provide binary packages for bullseye 64 bit, so that all in all all potential platforms (32/64 bit bullseye/bookworm) are covered.
@jcres69 I forgot to ask: You did notice my note on the message text being different, and that the message is logged on warning level now (with the SCSI2Pi develop branch), didn't you. I'm just asking in order to ensure that we don't miss the obvious, i.e. the message still being there with a different appearence.
@jcres69 I forgot to ask: You did notice my note on the message text being different, and that the message is logged on warning level now (with the SCSI2Pi develop branch), didn't you. I'm just asking in order to ensure that we don't miss the obvious, i.e. the message still being there with a different appearence.
@uweseimet yes, I did note the different message text and still have not seen it yet. I'll continue to test and let you know if I see the error again. Thanks for doing this, I am able to use my rascsi again!
@jcres69 Thank you for the good news! I hope you will never stumble upon this message again ;-). Please note that in order to control whether this message appears you do not have to run s2p on trace level. trace level slows things down quite a lot. Just run it with the standard (info) level. Warnings and errors are displayed also in this level, because of their priority. Usually one only enables debug or trace level when there is a special reason to do this, e.g. because something has happened that requires a deeper analysis.
@uweseimet unfortunately I am seeing this message again, but only after using s2p v 2.x. the 1.1.2 and 1.2 versions don't have this issue:
pi@raspberrypi:/opt/scsi2pi/bin $ sudo ./s2p -v 2.0.1 pi@raspberrypi:/opt/scsi2pi/bin $ sudo ./s2p -i 6 /home/pi/images/HD60_512_608_UPDATED2.hda -i 5 daynaport SCSI Target Emulator and SCSI Tools SCSI2Pi (Device Emulation) Version 2.0.1 Copyright (C) 2016-2020 GIMONS Copyright (C) 2020-2023 Contributors to the PiSCSI project Copyright (C) 2021-2024 Uwe Seimet [2024-02-22 10:46:12.722] [info] Set log level to 'info' [2024-02-22 10:46:12.727] [info] Validating: operation=ATTACH, device=5:0, type=UNDEFINED, device parameters='file=daynaport', vendor='', product='', revision='', block size=0 [2024-02-22 10:46:12.727] [info] Validating: operation=ATTACH, device=6:0, type=UNDEFINED, device parameters='file=/home/pi/images/HD60_512_608_UPDATED2.hda', vendor='', product='', revision='', block size=0 [2024-02-22 10:46:12.728] [info] Executing: operation=ATTACH, device=5:0, type=UNDEFINED, device parameters='file=daynaport', vendor='', product='', revision='', block size=0 [2024-02-22 10:46:12.734] [info] piscsi_bridge already exists [2024-02-22 10:46:12.736] [info] Tap device piscsi0 created [2024-02-22 10:46:12.736] [info] Attached SCDP 5:0 [2024-02-22 10:46:12.737] [info] Executing: operation=ATTACH, device=6:0, type=UNDEFINED, device parameters='file=/home/pi/images/HD60_512_608_UPDATED2.hda', vendor='', product='', revision='', block size=0 [2024-02-22 10:46:12.737] [info] Attached SCHD 6:0 [2024-02-22 10:46:12.738] [info] +----+-----+------+------------------------------------- [2024-02-22 10:46:12.738] [info] | ID | LUN | TYPE | IMAGE FILE [2024-02-22 10:46:12.738] [info] +----+-----+------+------------------------------------- [2024-02-22 10:46:12.738] [info] | 5 | 0 | SCDP | DaynaPort SCSI/Link [2024-02-22 10:46:12.738] [info] | 6 | 0 | SCHD | /home/pi/images/HD60_512_608_UPDATED2.hda [2024-02-22 10:46:12.738] [info] +----+-----+------+------------------------------------- +----+-----+------+------------------------------------- | ID | LUN | TYPE | IMAGE FILE +----+-----+------+------------------------------------- | 5 | 0 | SCDP | DaynaPort SCSI/Link | 6 | 0 | SCHD | /home/pi/images/HD60_512_608_UPDATED2.hda +----+-----+------+------------------------------------- [2024-02-22 10:48:44.223] [warning] (ID 5) - Received 48 byte(s) in DATA OUT phase, command requires 50 [2024-02-22 10:49:47.427] [warning] (ID 5) - Received 40 byte(s) in DATA OUT phase, command requires 69 [2024-02-22 10:51:25.591] [warning] (ID 5) - Received 7 byte(s) in DATA OUT phase, command requires 62 [2024-02-22 10:52:53.818] [warning] (ID 5) - Received 16 byte(s) in DATA OUT phase, command requires 62 [2024-02-22 10:53:32.070] [warning] (ID 6) - Received 359 byte(s) in DATA OUT phase, command requires 512
@jcres69 I guess I know why. I had to fix a timing issue, and I almost suspected that this might be related to your issue. But I'm afraid that I had not choice but to fix this issue. On the other hand this also means that it appears to be very clear now which piece of code directly correlates to your initial problem. I would like to get back to you right after the SCSI2Pi 3.0 release, which I intend to publish in one or two days. Then we can explore whether there is any way to resolve your problem without breaking other platforms. I hope this is OK for you. Maybe you can already test whether the current development branch still shows this warning. I expect that this is the case, but we would need to know because any further changes will be based on this branch.
@uweseimet hmm what am i doing wrong here:
pi@raspberrypi:/opt/scsi2pi/bin $ sudo ./s2p -id 6 daynaport SCSI Target Emulator and SCSI Tools SCSI2Pi (Device Emulation) Version 3.0-rc4 Copyright (C) 2016-2020 GIMONS Copyright (C) 2020-2023 Contributors to the PiSCSI project Copyright (C) 2021-2024 Uwe Seimet [2024-02-22 12:44:52.287] [info] Set log level to 'info' [2024-02-22 12:44:52.292] [info] Validating: operation=ATTACH, device=6:0, device parameters='file=daynaport' [2024-02-22 12:44:52.293] [info] Executing: operation=ATTACH, device=6:0, device parameters='file=daynaport' [2024-02-22 12:44:52.294] [error] No valid network interfaces available [2024-02-22 12:44:52.294] [error] Initialization of SCDP 6:0 failed Error: Initialization of SCDP 6:0 failed Error: Can't attach devices
I created the piscsi_bridge, what else do i need to do?
pi@raspberrypi:/opt/scsi2pi/bin $ ip add 1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000 link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00 inet 127.0.0.1/8 scope host lo valid_lft forever preferred_lft forever inet6 ::1/128 scope host noprefixroute valid_lft forever preferred_lft forever 2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq master piscsi_bridge state UP group default qlen 1000 link/ether e4:5f:01:9a:2e:85 brd ff:ff:ff:ff:ff:ff 3: wlan0: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc pfifo_fast state DOWN group default qlen 1000 link/ether e4:5f:01:9a:2e:86 brd ff:ff:ff:ff:ff:ff 4: piscsi_bridge: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000 link/ether e4:5f:01:9a:2e:85 brd ff:ff:ff:ff:ff:ff inet 192.168.1.13/24 brd 192.168.1.255 scope global dynamic noprefixroute piscsi_bridge valid_lft 79954sec preferred_lft 79954sec inet6 2600:4040:2dbf:1a00::1d26/128 scope global dynamic noprefixroute valid_lft 3166sec preferred_lft 1366sec inet6 fe80::5da7:13ec:2500:aaa6/64 scope link noprefixroute valid_lft forever preferred_lft forever pi@raspberrypi:/opt/scsi2pi/bin $
@jcres69 You stumbled upon an issue with the RC4 release candiate, which will be resolved in the next RC later today. But in order to have a closer look at you timing issue you would need to compile SCSI2Pi, i.e. you cannot use a binary distribution for this investigation. By the way, if what I suspect is correct, the 2.0 release (i.e. not 2.0.1) should still work with your setup. Can you please verify this? 2.0 is available as a binary package.
@uweseimet I tested the 2.0 release, and no I don't get the SCSI error messages, however I did notice that in this version (and the 2.1 version also) when I disconnect the devices, the piscsi_bridge interface goes down and I lose connection. In the 1.x version, the bridge stayed up as I believe it should.
@jcres69 OK, so it's the timing change which is also mentioned in the release notes for 2.0.1. (The timing is the same again as with piscsi.) I will create a new ticket for the investigation of this issue. Regarding the bridge, removing the bridge when it was created by s2p was a user request, see https://github.com/uweseimet/scsi2pi/issues/45 and https://github.com/uweseimet/scsi2pi/issues/64. What do you mean with "lose connection"? When you restart s2p, the bridge will be re-created. Do you have any need for the bridge even when s2p is not running?
@uweseimet Maybe I am doing this wrong, but the Pi is hard wired on eth0 (not wifi) and I manually created the bridge interface based on the piscsi instructions. the bridge interface connects to my internal lan, and is how I remotely connect to the Pi. when the bridge interface goes down, I lose my ssh connection.
@jcres69 There is no need to do anything manually. s2p will set up the bridge automatically, and as far as I remember piscsi does the same. Please also see the tickets I mentioned. ssh and the bridge are not related. The bridge is exclusively used by s2p/piscsi. If this is different for you, please add a comment in the matching corresponding ticket (one of those I mentioned). I just double-checked that ssh works for me regardless of whether the bridge is present or has been removed. I suggest that you do not set up the bridge manually, but let s2p/piscsi handle everything.
In order to improve the readability of the logfiles the hexadecimal error code values in the s2p logs shall be extended by a human-readable string representation, based on the respective names in the SCSI specification.