search

TheGrandWazoo / freenas-proxmox

ZFS over iSCSI to FreeNAS API's from Proxmox VE
MIT License
236 stars 42 forks source link

TrueNAS 12 Beta2 #65

Closed hunter-nl closed 3 years ago

hunter-nl commented 4 years ago

When I add a harddisk to a VM then I receive this error: error during cfs-locked 'storage-TrueNAS' operation: Can't call method "responseCode" on unblessed reference at /usr/share/perl5/PVE/Storage/LunCmd/FreeNAS.pm line 452. at /usr/share/perl5/PVE/API2/Qemu.pm line 1340. (500) The Volume has been created but no iscsi extent pointing to tis new Volume (zvol) has been defined in TrueNAS.

I've used your testing repo using freenas-proxmox (2.0.0-0~beta5) Proxmox version 6.2-11 image image

TheGrandWazoo commented 4 years ago

SO line 452 of the FreeNAS.pm is a syslog() call in the frenas_api_log_error function. I am going to assume that the FreeNAS/TrueNAS 12 BETA 2 API's may have changed between BETA 1 and BETA 2. So, let me spin up me TrueNAS 12 VM and snapshot it and upgrade to BETA 2 and see what we get. Also, if you have syslog info from this creation, could you please post it.

hunter-nl commented 4 years ago

From syslog on ProxMox:

Aug 24 23:02:59 pve01 pvedaemon[9117]: PVE::Storage::LunCmd::FreeNAS::freenas_api_check : called
Aug 24 23:02:59 pve01 pvedaemon[9117]: PVE::Storage::LunCmd::FreeNAS::freenas_api_connect : called
Aug 24 23:02:59 pve01 pvedaemon[9117]: VM 102 creating disks failed
Aug 24 23:02:59 pve01 pvedaemon[9117]: error during cfs-locked 'storage-TrueNAS' operation: Can't call method "responseCode" on unblessed reference at /usr/share/perl5/PVE/Storage/LunCmd/FreeNAS.pm line 452.

At TrueNAS side no related messages. The zvol has been created: image

TheGrandWazoo commented 4 years ago

I have tested with 6.2-10 of Proxmox and TrueNAS 12 - BETA 2 and did not have any issues with creating a VM with two drives (UEFI and Main) via ZFS over iSCSI. I will upgrade to 6.2-11 of Proxmox and see if that is the issue.

TheGrandWazoo commented 4 years ago

Wait...I am mistaken. It looks like it is on the start of the VM that this happens. So it seems to be an issue between 6.2-10 and 6.2-11. I will do some more testing and see what I can find out.

TheGrandWazoo commented 4 years ago

On a reboot of the system I get that message. But manually starting the VM seems to work. Interesting.

TheGrandWazoo commented 4 years ago

Well, it seems on a "Bare Metal' reboot that the network is not quite ready for some reason and the checks for the TrueNAS server is failing. So the $freenas_rest_connection is not initialized and can't get the responseCode from the object. Which make sense about the error now. I will take a look at changing the error logic there but not being able to contact the server on a "Bare Metal" reboot behind the scenes of the Proxmox/Debian environment. Maybe I can do a 'sleep and retry' in the logic to work around this.

hunter-nl commented 4 years ago

I get the error at the moment I add a new harddisk ZFS over iSCSI. It creates the zvol on TrueNAS. But no iSCSI extent on TrueNAS to this new zvol. At Proxmox then the error appears. In the hardware list of the vm does not showing the new harddisk. Maybe the difference between your test and my situation is that I have a vm with an UEFI disk and 1 on Proxmox local ZFS harddisk Image added to the vm. Then I try to create/add new ZFS over iSCSI harddisk to this vm. Then the error appears. I can reproduce this over and over again.

TheGrandWazoo commented 4 years ago

Ok. So I have done the following...

Proxmox 6.2-10 and TrueNAS 12.0-BETA1 - No Issues Proxmox 6.2-10 and TrueNAS 12.0-BETA2 - No Issues Proxmox 6.2-11 and TrueNAS 12.0-BETA1 - Issues as reported Proxmox 6.2-11 and TrueNAS 12.0-BETA2 - Issues as reported

Is anyone else seeing the same results?

hunter-nl commented 4 years ago

I've tried it also. I can confirm. So it looks like something related to Proxmox 6.2-11. It sounds as if in this release the communication to TrueNAS API gets disrupted.

TheGrandWazoo commented 4 years ago

Thank you for confirming. I will see what changed and add some debugging to the scripts and find out what is going on. It is simple HTTP calls to [Free|True]NAS so not sure what change to cause the disruption.

TheGrandWazoo commented 4 years ago

I fixed the freenas_api_log_error() function (locally, it is not pushed upstream yet) so it would not fail to give more output.

Aug 27 07:51:47 pve02-hq pvesh[1769]: Starting VM 100
Aug 27 07:51:47 pve02-hq pve-guests[1836]: start VM 100: UPID:pve02-hq:0000072C:00000B33:5F479E53:qmstart:100:root@pam:
Aug 27 07:51:47 pve02-hq pve-guests[1796]: <root@pam> starting task UPID:pve02-hq:0000072C:00000B33:5F479E53:qmstart:100:root@pam:
Aug 27 07:51:47 pve02-hq pve-guests[1836]: PVE::Storage::LunCmd::FreeNAS::run_lun_command : list_lu(/dev/zvol/StorageTank/Proxmox02/vDisks/vm-100-disk-0)
Aug 27 07:51:47 pve02-hq pve-guests[1836]: PVE::Storage::LunCmd::FreeNAS::freenas_api_check : called
Aug 27 07:51:47 pve02-hq pve-guests[1836]: PVE::Storage::LunCmd::FreeNAS::freenas_api_connect : called
Aug 27 07:51:50 pve02-hq pve-guests[1836]: PVE::Storage::LunCmd::FreeNAS::freenas_api_connect : Error code is'500'
Aug 27 07:51:50 pve02-hq pve-guests[1836]: [ERROR]FreeNAS::API::freenas_api_call : Response code: 500
Aug 27 07:51:50 pve02-hq pve-guests[1836]: [ERROR]FreeNAS::API::freenas_api_call : Response content: Can't connect to 172.31.69.90:80 (No route to host)

No route to host at /usr/share/perl5/LWP/Protocol/http.pm line 50.
Aug 27 07:51:50 pve02-hq pve-guests[1836]: Unable to connect to the FreeNAS API service at '172.31.69.90' using the 'http' protocol at /usr/share/perl5/PVE/Storage/LunCmd/FreeNAS.pm line 376.
Aug 27 07:51:51 pve02-hq pvesh[1769]: Starting VM 100 failed: Unable to connect to the FreeNAS API service at '172.31.69.90' using the 'http' protocol at /usr/share/perl5/PVE/Storage/LunCmd/FreeNAS.pm line 376.
Aug 27 07:51:51 pve02-hq pvesh[1769]: Starting VM 101
Aug 27 07:51:51 pve02-hq pve-guests[1850]: start VM 101: UPID:pve02-hq:0000073A:00000CC6:5F479E57:qmstart:101:root@pam:
Aug 27 07:51:51 pve02-hq pve-guests[1796]: <root@pam> starting task UPID:pve02-hq:0000073A:00000CC6:5F479E57:qmstart:101:root@pam:
Aug 27 07:51:51 pve02-hq pvestatd[1588]: command '/usr/bin/ssh -o 'BatchMode=yes' -i /etc/pve/priv/zfs/192.168.69.91_id_rsa root@192.168.69.91 zfs get -o value -Hp available,used StorageTank/pve02-vdisks' failed: exit code 255
Aug 27 07:51:51 pve02-hq pve-guests[1850]: PVE::Storage::LunCmd::FreeNAS::run_lun_command : list_lu(/dev/zvol/StorageTank/pve02-vdisks/vm-101-disk-1)
Aug 27 07:51:51 pve02-hq pve-guests[1850]: PVE::Storage::LunCmd::FreeNAS::freenas_api_check : called
Aug 27 07:51:51 pve02-hq pve-guests[1850]: PVE::Storage::LunCmd::FreeNAS::freenas_api_connect : called
Aug 27 07:51:53 pve02-hq pvestatd[1588]: command '/usr/bin/ssh -o 'BatchMode=yes' -i /etc/pve/priv/zfs/172.31.69.90_id_rsa root@172.31.69.90 zfs get -o value -Hp available,used StorageTank/Proxmox02/vDisks' failed: exit code 255
Aug 27 07:51:53 pve02-hq pvestatd[1588]: status update time (7.250 seconds)
Aug 27 07:51:54 pve02-hq pve-guests[1850]: PVE::Storage::LunCmd::FreeNAS::freenas_api_connect : Error code is'500'
Aug 27 07:51:54 pve02-hq pve-guests[1850]: [ERROR]FreeNAS::API::freenas_api_call : Response code: 500
Aug 27 07:51:54 pve02-hq pve-guests[1850]: [ERROR]FreeNAS::API::freenas_api_call : Response content: Can't connect to 192.168.69.91:80 (No route to host)

No route to host at /usr/share/perl5/LWP/Protocol/http.pm line 50.
Aug 27 07:51:54 pve02-hq pve-guests[1850]: Unable to connect to the FreeNAS API service at '192.168.69.91' using the 'http' protocol at /usr/share/perl5/PVE/Storage/LunCmd/FreeNAS.pm line 376.
Aug 27 07:51:55 pve02-hq pvesh[1769]: Starting VM 101 failed: Unable to connect to the FreeNAS API service at '192.168.69.91' using the 'http' protocol at /usr/share/perl5/PVE/Storage/LunCmd/FreeNAS.pm line 376.

This was after a 'Bare Metal' reboot of the server to both FreeNAS 11.3-U4.1 (192.168.69.90) and TrueNAS 12.0-BETA2 (192.168.69.91). Both receiving the 'No route to host' message. Even the SSH command used internally to the Proxmox system is failing also.

hunter-nl commented 4 years ago

But with my situation the Proxmox can reach TrueNAS. It is just failing during the "adding/creating" a new harddisk to a VM.

TheGrandWazoo commented 4 years ago

@hunter-nl I still trying to get that to fail on my end so I can diagnose that particular condition.

I will most likely create a BETA6 to push the fixes to the error routine so we can get information from your system(s), like above, on your adding/creating.

TheGrandWazoo commented 4 years ago

@hunter-nl - Created a BETA6 that fixes the error routine so it should give us some more details of the error that is happening in the syslog.

Commit a40e0ac2997022f91babd9800c654781ee344187

hunter-nl commented 4 years ago

@TheGrandWazoo That's making more clear. No API access on TrueNAS.

Aug 28 09:42:41 pve01 pvedaemon[22261]: <root@pam> update VM 102: -scsi1 TrueNAS:32
Aug 28 09:42:41 pve01 pvedaemon[22261]: <root@pam> starting task UPID:pve01:0000660B:039158A6:5F48B571:qmconfig:102:root@pam:
Aug 28 09:42:42 pve01 pvedaemon[26123]: PVE::Storage::LunCmd::FreeNAS::run_lun_command : create_lu(/dev/zvol/Storage/PVE-Storage/vm-102-disk-0)
Aug 28 09:42:42 pve01 pvedaemon[26123]: PVE::Storage::LunCmd::FreeNAS::freenas_api_check : called
Aug 28 09:42:42 pve01 pvedaemon[26123]: PVE::Storage::LunCmd::FreeNAS::freenas_api_connect : called
Aug 28 09:42:42 pve01 pvedaemon[26123]: [ERROR]FreeNAS::API::PVE::Storage::LunCmd::FreeNAS::freenas_api_connect : Response code: 500
Aug 28 09:42:42 pve01 pvedaemon[26123]: [ERROR]FreeNAS::API::PVE::Storage::LunCmd::FreeNAS::freenas_api_connect : Response content: Can't connect to 192.168.0.150:443 (Connection refused)

Connection refused at /usr/share/perl5/LWP/Protocol/http.pm line 50.
Aug 28 09:42:42 pve01 pvedaemon[26123]: VM 102 creating disks failed
Aug 28 09:42:42 pve01 pvedaemon[26123]: error during cfs-locked 'storage-TrueNAS' operation: Unable to connect to the FreeNAS API service at '192.168.250.15' using the 'https' protocol at /usr/share/perl5/PVE/Storage/LunCmd/FreeNAS.pm line 375.
Aug 28 09:42:42 pve01 pvedaemon[22261]: <root@pam> end task UPID:pve01:0000660B:039158A6:5F48B571:qmconfig:102:root@pam: error during cfs-locked 'storage-TrueNAS' operation: Unable to connect to the FreeNAS API service at '192.168.0.150' using the 'https' protocol at /usr/share/perl5/PVE/Storage/LunCmd/FreeNAS.pm line 375.

The zvol disk is created through ssh connection on TrueNAS, but then the API call get's refused. With TrueNAS 12.0-BETA2 using the API's an API key is required to be used to authenticate. I can not configure this in the freenas-proxmox plugin. And creating the zvol disk can also be done through API. Maybe you can change this also.

hunter-nl commented 3 years ago

With TN 12.0-Release I do not have the issue anymore.

TheGrandWazoo commented 3 years ago

Thank you for confirming.