Attempt to connect to Synology NAS with iSCSI fails

[square_root_of_1]

I'm having trouble establishing a connection from a VM to a Synology DS418 NAS using iscsi. I’m a novice at both VirtualBox and iscsi, but have managed to successfully use iscsi on the Debian Buster Host using open-scsci successfully many times.

The Gory Details:
While trying to connect a Debian Buster Guest VM, the iscsi targets on the Host are disconnected and removed to make sure the guest VM is the only device trying to connect to the target. The iscsi target is known and has been connected to, and used by the Host successfully many times.

When running the VBoxManage storageattach command, the VboxSVC.log fills up with failed attempts to connect to the target. This can last over an hour and It continues until I manually intervene by disconnecting the ethernet cable. I’ve observed that the port search starts at port 32768 and will search every other port in sequence up until port 60998, then recycle back to 32768.

In my first attempts I was using VboxManage storageattach without specifying the –lun and and –tport parameters but further research suggested that it may be necessary to specify the LUN using whatever was assigned on the NAS. Checking my NAS revealed that the LUN for this particular target was not 0, but 1. I assumed that the VBox initiator would use the standard iscsi target port of 3260 but after seeing the thousands of connection attempts in the log I tried to be specific about it. Each attempt to connect with VboxManage storageattach will pick up port searching where the last search left off.

What am I doing wrong?

Pleased see attached output of storageattach console output, showvminfo, systemproperties, version, and annotated VBoxSVC.log (look for ###) and screenshots.

[fth0]

What am I doing wrong?

I don't really know, but I can suggest a workaround to circumvent the error:

Looking at the VirtualBox source code, regarding the error messages from the VBoxManage storageattach command, it is trying to create a medium lock list while trying to set the comment you provide. If you remove the comment argument from the command line, you cannot get the exact same error combination any more, so I'd suggest to try that.

[square_root_of_1]

Thank you for your quick response. I suspected as much that there's a an object that I can't lock but the error message doesn't specify what. Please forgive the length of this post but I'm trying to include anything that can help troubleshoot.

After removing the comment as you suggested and retrying the exact command I, got this:

VBoxManage storageattach "/home/paul/VirtualBox VMs/Development/VMBackupTmpl/VMBackupTmpl.vbox" --storagectl "SATA" --port 0 --device 2 --type "hdd" --medium "iscsi" --server "172.16.60.34" --target "iqn.2000-01.com.synology.fumcanas01.Tgt-1.39d3f83664" --tport 3260 --lun 1 --username "CHAPuser" --password "iscsiCHAPauth"
iSCSI disk created. UUID: 5a7d5e32-5ffe-4118-9960-a20e6dfe616a
VBoxManage: error: The port and/or device parameter are out of range: port=0 (must be in range [0, 2]), device=2 (must be in range [0, 0])
VBoxManage: error: Details: code NS_ERROR_INVALID_ARG (0x80070057), component StorageControllerWrap, interface IStorageController, callee nsISupports
VBoxManage: error: Context: "AttachDevice(Bstr(pszCtl).raw(), port, device, DeviceType_HardDisk, pMedium2Mount)" at line 776 of file VBoxManageStorageController.cpp

and the VBoxSVC.log starts going nuts with the port searches to the target. Incidentally, attempting to re-add the iscsi disk while the port search is going on, I get an error

Cannot register the hard disk '172.16.60.34|iqn.2000-01.com.synology.fumcanas01.Tgt-1.39d3f83664|1' {119f51da-4a00-4609-9aa4-900998531ed0} because a hard disk '172.16.60.34|iqn.2000-01.com.synology.fumcanas01.Tgt-1.39d3f83664|1' with UUID {0409d79b-4373-4c73-bac6-f5a63d5b5aaa} already exists

The "Remove" option in the Virtual Media Manager Menu bar is disabled while whatever is doing the port search is active even if the iscsi disk is not attached to any VM, and it's impossible to add another iscsi disk until the old one is gone. Unplugging the cable (I know it's barbaric) is the only way to stop the search (that I know of) to enable Media Manager to do its job.

Following the error message's advice, I changed the storageattach device parmater to 0. This was successful in a way (except for the port searches) in that the iscsi disk was attached BEFORE (port 0) my bootable VDI (port 1) where my empty DVD drive was configured. See partial output of the vminfo taken before attempting to attach the iscsi disk at port 2

Storage Controller Name (0): SATA
Storage Controller Type (0): IntelAhci
Storage Controller Instance Number (0): 0
Storage Controller Max Port Count (0): 30
Storage Controller Port Count (0): 3
Storage Controller Bootable (0): on
SATA (0, 0): Empty
SATA (1, 0): /home/paul/VirtualBox VMs/Development/VMBackupTmpl/VMBackup-disk002.vdi (UUID: 38660319-1688-4cf6-9e1b-e124aeae3ae1)

The empty SATA port was for a DVD to make it easier to boot from something else instead of moving everything around again to add a DVD drive. It seems that no matter what port is specified on the attachstorage command, attachstorage will try to put the iscsi disk at the first open or empty port, ignoring any the --port parameter. I got around this by switching the VDI onto port 0, then specifying port 1 for the iscsci disk. This still didn't stop the port search madness in VBoxSVC.log because the VM wasn't able to log into the NAS.

About the port searches: I later found a log on the Synology NAS named /var/log/iscsi.log with the following messages, repeated over and over, that match up with the port searches in the in VBoxSVC.log:

2020-08-22T18:40:04-05:00 fumcanas01 kernel: [253684.862374] iSCSI_F:iscsi_target_login.ciscsi_target_login_sess_out iSCSI Login negotiation failed - I[][172.16.60.37:43866], T[][172.16.60.34:3260]
2020-08-22T18:40:04-05:00 fumcanas01 kernel: [253684.862743] iSCSI_F:iscsi_target_nego.c:771:iscsi_target_sk_state_change Entering iscsi_target_sk_state_change
2020-08-22T18:40:04-05:00 fumcanas01 kernel: [253684.862748] iSCSI_F:iscsi_target_nego.c:795:iscsi_target_sk_state_change Got LOGIN_FLAGS_READY=0 sk_state_change conn: ffffffc046ed2000, I[][172.16.60.37:43866], T[][172.16.60.34:3260]
2020-08-22T18:40:04-05:00 fumcanas01 kernel: [253684.862754] iSCSI_F:iscsi_target_nego.c:443:iscsi_target_sk_data_ready Got LOGIN_FLAGS_READY=0, conn: ffffffc046ed2000, I[][172.16.60.37:43866], T[][172.16.60.34:3260]
2020-08-22T18:40:04-05:00 fumcanas01 kernel: [253684.929815] iSCSI_F:iscsi_target_nego.ciscsi_target_locate_portal I[iqn.2009-08.com.sun.virtualbox.initiator:01:172.16.60.37][172.16.60.37:43868] tried to login nonexistent iscsi target IQN 'iqn.2000-01.com.synology.fumcanas01.Tgt-1.39d3f83664', please configure the initiator.
2020-08-22T18:40:04-05:00 fumcanas01 kernel: [253684.955542] iSCSI_F:iscsi_target_login.ciscsi_target_login_sess_out iSCSI Login negotiation failed - I[][172.16.60.37:43868], T[][172.16.60.34:3260]
2020-08-22T18:40:04-05:00 fumcanas01 kernel: [253684.955785] iSCSI_F:iscsi_target_nego.c:771:iscsi_target_sk_state_change Entering iscsi_target_sk_state_change
2020-08-22T18:40:04-05:00 fumcanas01 kernel: [253684.955790] iSCSI_F:iscsi_target_nego.c:795:iscsi_target_sk_state_change Got LOGIN_FLAGS_READY=0 sk_state_change conn: ffffffc046ed2000, I[][172.16.60.37:43868], T[][172.16.60.34:3260]
2020-08-22T18:40:04-05:00 fumcanas01 kernel: [253684.955794] iSCSI_F:iscsi_target_nego.c:443:iscsi_target_sk_data_ready Got LOGIN_FLAGS_READY=0, conn: ffffffc046ed2000, I[][172.16.60.37:43868], T[][172.16.60.34:3260]
2020-08-22T18:40:04-05:00 fumcanas01 kernel: [253685.022968] iSCSI_F:iscsi_target_nego.ciscsi_target_locate_portal I[iqn.2009-08.com.sun.virtualbox.initiator:01:172.16.60.37][172.16.60.37:43870] tried to login nonexistent iscsi target IQN 'iqn.2000-01.com.synology.fumcanas01.Tgt-1.39d3f83664', please configure the initiator.

etc...

I'm certainly not pointing fingers here, but humbly ask you to consider that since a connection was reliably established by the Host OS's initiator, it may be that there's something hidden in VirtualBox's initiator that is causing problems. Don't doubt for a minute though that I'm taking this up with Synology and will keep you informed of any advice/fixes that they offer.

[fth0]

I'm certainly not pointing fingers here, but humbly ask you [...]

No problem. Note that the VirtualBox forums are user to user forums, and most volunteers and moderators are not affiliated to Oracle at all (me included). I'll try to be as objective as possible, and point with my fingers in all directions I see fit.

Please forgive the length of this post but I'm trying to include anything that can help troubleshoot.

Well done, and it already seems to pay off a little:

What you're calling a port search, is a repeated connection attempt with a new source port for each try, the latter being a typical network implementation behavior. The destination port is always 3260, as you expected. Without assessing who's fault it is , the iSCSI target is rejecting the target IQN. The following questions may seem too easy, but did you check its spelling? If the target IQN is correct, you could use Wireshark on the host to capture the network traffic, to see what is really communicated between the host and the NAS.

Regarding other subtopics like SATA device ordering, I'd suggest to simplify the scenario as much as you can, until you get a working scenario. Afterwards, you can put the candy back on one after another, to learn about possible limits of the current implementation. I've never used iSCSI myself, so I don't know the potential pitfalls by experience.

[square_root_of_1]

A thousand thank-yous o' wise fth0! You have prompted the seeker to look within and he has found the answer!

The following questions may seem too easy, but did you check its spelling? If the target IQN is correct...

Periods are NOT the same as colons, especially in an iscsi Target portal address. Changing my target string from ...synology.fumcanas01... to ...synology:fumcanas01... made all the difference in the world! I'm now able connect my VM to the NAS! Yippee!

Also, you are of course correct in your assessment in that there was no "port searching" going on but continual rejection of a malformed address. I knew that, just didn't have the right terminology.

My eyes may be getting too old for this sh*t; reminds me too much of the COBOL days where I spent hours hunting down a single period to make my IF clauses work.

Thanks again for your guidance. Hope to return the favour some day.

[fth0]

Congratulations! And thanks for reporting back.

[...] the COBOL days where I spent hours hunting down a single period to make my IF clauses work.

I only remember DIVIDE X BY Y GIVING RES.. I think you can still get a lot of jobs programming in COBOL.