bhyve doesn't start vm under proxmox

[rdmitry0911]

Hi guys, in my home lab I have a proxmox 6.1 host which I use to test everything before to put it into production. So I have a FreeNAS-11.3-U2.1 vm in this proxmox host and I'd like to run ubuntu in bhyve in this environment. And I can not. When I start bhyve with this command

bhyve -c 4 -m 4096M -A -H -P \​

-s 0:0,hostbridge \​

-s 1:0,lpc \​

-s 2:0,ahci-cd,/mnt/tank/iso/ubuntu-20.04-live-server-amd64.iso \​

-s 29,fbuf,tcp=0.0.0.0:5910,w=1024,h=768,wait \​

-l bootrom,/usr/local/share/uefi-firmware/BHYVE_UEFI.fd \​

Ubuntu​

it says:

fbuf frame buffer base: 0x943800000 [sz 16777216]​

And that's it. No errors, nothing. Looks like it is running, but when I connect to it via vnc, it shows just black screen. To be sure this processor is supported by bhyve, I run

grep VT-x /var/run/dmesg.boot​

The result is

VT-x: PAT,HLT,MTF,PAUSE,EPT,UG,VPID,VID,PostIntr​

So, I should be fine.
In jail on the same freenas I built virtualbox ( following this thread ) and under virtualbox easily installed and run x64 ubuntu.

What can cause this problem?

Thank you, Dmitry

 

[KrisBee]

ubuntu-20.04-live-server-amd64.iso is causing problems with bhyve. The old style d-i installer server iso is still available for u20.04 - http://cdimage.ubuntu.com/ubuntu-legacy-server/releases/20.04/release/

 

[rdmitry0911]

ubuntu-20.04-live-server-amd64.iso is causing problems with bhyve. The old style d-i installer server iso is still available for u20.04 - http://cdimage.ubuntu.com/ubuntu-legacy-server/releases/20.04/release/

This is not a problem with ubuntu only. I can not boot at all. I can't boot neither linux nor windows nor freebsd. For example trying to boot freenas like this:

bhyve -c 4 -m 4096M -A -H -P \​

-s 0:0,hostbridge \​

-s 1:0,lpc \​

-s 2:0,ahci-cd,/mnt/tank/iso/FreeNAS-11.3-U2.1.iso \​

-s 29,fbuf,tcp=0.0.0.0:5910,w=1024,h=768,wait \​

-l bootrom,/usr/local/share/uefi-firmware/BHYVE_UEFI.fd \​

Freenas​

I'm having the same black screen in vnc

 

[KrisBee]

Have I misunderstood your problem? You have a working proxmox 6 instance, properly configured for nested virtualisation? You created a a FreeNAS VM in proxmox with the CPU type set to "host"? Why are you using the CLI within FreeNAS to create VMs? Why not use the FreeNAS webui to do this?

 

[rdmitry0911]

Have I misunderstood your problem? You have a working proxmox 6 instance, properly configured for nested virtualisation? You created a a FreeNAS VM in proxmox with the CPU type set to "host"? Why are you using the CLI within FreeNAS to create VMs? Why not use the FreeNAS webui to do this?

You correctly understand the environment. And I tried both ways. First I created vm and tried to start it from freenas webui and failed. Then I thought doing this from command line might be more informative, but it is not.

 

[KrisBee]

Your bhyve command is missing a disk device, but I'd stick with the webui and troubleshoot via tail -f /var/log/middlewared.log then you don't have to mess with bhyvectl to stop and destroy VMs. Things should work if you choose virtio for both disk and NIC devices with ubuntu.

You might want to check how many cores the FreeNAS VM is seeing. I left all the "extra GPU flags" at default for my FresNAS test VM running under proxmox and as my box has only got 16GB even a FreeNAS VM with just 4GB can run a bhyve vm.

 

[rdmitry0911]

Your bhyve command is missing a disk device, but I'd stick with the webui and troubleshoot via tail -f /var/log/middlewared.log then you don't have to mess with bhyvectl to stop and destroy VMs. Things should work if you choose virtio for both disk and NIC devices with ubuntu.

You might want to check how many cores the FreeNAS VM is seeing. I left all the "extra GPU flags" at default for my FresNAS test VM running under proxmox and as my box has only got 16GB even a FreeNAS VM with just 4GB can run a bhyve vm.

Does that mean, that you also have proxmox 6.1 and freenas 11.3 running as vm in this proxmox instance and you successfully created and run a bhyve vm under this freenas being able to connect to it with vnc?

 

[KrisBee]

Yes. But I have only tested debian/ubuntu server installs via FreeNAS webui to date. My proxmox box is low spec cobbled together from bits and pieces with suboptimal config and the one major limit of 16GB memory as its based on a mini-itx m/board. But it's enough for me to mess around on and test things. Nested virtualisation works. One snag is the FreeNAS VM does not shutdown correctly when the processor type is "host" to have to pause and then stop the VM.

Also used nested vlirtualisation on my linux desktop with kvm/libvirtd/virt-manager as the hypervisor.

 

[rdmitry0911]

Yes. But I have only tested debian/ubuntu server installs via FreeNAS webui to date. My proxmox box is low spec cobbled together from bits and pieces with suboptimal config and the one major limit of 16GB memory as its based on a mini-itx m/board. But it's enough for me to mess around on and test things. Nested virtualisation works. One snag is the FreeNAS VM does not shutdown correctly when the processor type is "host" to have to pause and then stop the VM.

Also used nested vlirtualisation on my linux desktop with kvm/libvirtd/virt-manager as the hypervisor.

I have no idea why it does not work in my installation. I created a fresh install of freenas and faced with the same problem. The vm seems to be working, there are no messages in /var/log/middlewared.log however vnc shows only black screen. In my host I have Xeon E5-2630L engineering sample and 32 GB RAM.

root@proxmox-1:~# cat /proc/cpuinfo​

processor : 0​

vendor_id : GenuineIntel​

cpu family : 6​

model : 63​

model name : Genuine Intel(R) CPU @ 1.80GHz​

stepping : 1​

microcode : 0x80000013​

cpu MHz : 1376.813​

cache size : 20480 KB​

physical id : 0​

siblings : 16​

core id : 0​

cpu cores : 8​

apicid : 0​

initial apicid : 0​

fpu : yes​

fpu_exception : yes​

cpuid level : 15​

wp : yes​

flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic movbe popcnt aes xsave avx f16c rdrand lahf_lm abm cpuid_fault invpcid_single pti intel_ppin tpr_shadow vnmi flexpriority ept vpid ept_ad fsgsbase tsc_adjust bmi1 hle avx2 smep bmi2 erms invpcid rtm cqm xsaveopt cqm_llc cqm_occup_llc dtherm ida arat pln pts​

bugs : cpu_meltdown spectre_v1 spectre_v2 spec_store_bypass l1tf mds swapgs taa itlb_multihit​

bogomips : 3600.08​

clflush size : 64​

cache_alignment : 64​

address sizes : 46 bits physical, 48 bits virtual​

power management:​

I have no problem with nested virtualization with it. I can run virtual proxmox inside proxmox, I can run virualbox x64 vm inside freenas inside proxmox with no problem. With bhyve I can't start nither x64 nor i586 machine. Nothing. May be there are some limitations in bhyve for this specific processor? Or may be there is a way to check what's going on when I'm starting the bhyve vm?

 

[KrisBee]

My proxmox box has a low-end E-1220v3 4-core cpu , it would seem odd that a Xeon E5-2630L, which has a higher passmark, should be the problem. And you really see no "(DEBUG) VMService.run()" message lines in "tail -f /var/log/middlewared.log" at all when you start a VM from within FreeNAS that was created via the FreeNAS webui? If you set the FreeNAS VM processor type to "host", did you try other processor types because it sounds like bhyve is just not running in your FreeNAS VM as currentyl configured - as if your CPU does not support bhyve, which of course it should do on baremetal.

 

[rdmitry0911]

My proxmox box has a low-end E-1220v3 4-core cpu , it would seem odd that a Xeon E5-2630L, which has a higher passmark, should be the problem. And you really see no "(DEBUG) VMService.run()" message lines in "tail -f /var/log/middlewared.log" at all when you start a VM from within FreeNAS that was created via the FreeNAS webui? If you set the FreeNAS VM processor type to "host", did you try other processor types because it sounds like bhyve is just not running in your FreeNAS VM as currentyl configured - as if your CPU does not support bhyve, which of course it should do on baremetal.

Of cause there are some debug messages in the log, but they look good. Here is the log of starting freenas vm, connection to it via vnc and shutdown vm. All was done via webui.

[2020/04/30 11:00:32] (INFO) VMService.__set_guest_vmemory():755 - ===> Setting ARC FROM: 15605022720 TO: 11310055424​

[2020/04/30 11:00:32] (DEBUG) VMService.vm_2.run():179 - ====> NIC_ATTACH: vtnet0​

[2020/04/30 11:00:32] (DEBUG) VMService.vm_2.run():293 - Starting bhyve: bhyve -A -H -w -c 1 -m 4096 -s 0:0,hostbridge -s 31,lpc -l com1,/dev/nmdm2A -l bootrom,/usr/local/share/uefi-firmware/BHYVE_UEFI.fd -s 29,fbuf,vncserver,tcp=0.0.0.0:8888,w=1024,h=768,, -s 30,xhci,tablet -s 5,virtio-net,tap0,mac=00:a0:98:1c:55:90 -s 3:0,ahci,cd:/mnt/tank/FreeNAS-11.3-U2.1.iso -s 4:0,virtio-blk,/dev/zvol/tank/FreeNAS-zxzig0q 2_FreeNAS​

[2020/04/30 11:00:32] (DEBUG) VMService.vm_2.run():306 - ==> Start WEBVNC at port 8788 with pid number 21119​

[2020/04/30 11:00:32] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:32 Listening for VNC connections on TCP port 8888​

[2020/04/30 11:00:32] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:32 Listening for VNC connections on TCP6 port 8888​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 other clients:​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 Client Protocol Version 3.8​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 Protocol version sent 3.8, using 3.8​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 rfbProcessClientSecurityType: executing handler for type 1​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 rfbProcessClientSecurityType: returning securityResult for client rfb version >= 3.8​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 Pixel format for client 127.0.0.1:​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 32 bpp, depth 24, little endian​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 true colour: max r 255 g 255 b 255, shift r 16 g 8 b 0​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 Using image quality level 6 for client 127.0.0.1​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 Using JPEG subsampling 0, Q79 for client 127.0.0.1​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 Using compression level 2 for client 127.0.0.1​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 Enabling NewFBSize protocol extension for client 127.0.0.1​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 Enabling LastRect protocol extension for client 127.0.0.1​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 rfbProcessClientNormalMessage: ignoring unsupported encoding type Enc(0xFFFFFEFE)​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 rfbProcessClientNormalMessage: ignoring unsupported encoding type Enc(0xFFFFFECC)​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 rfbProcessClientNormalMessage: ignoring unsupported encoding type Enc(0xFFFFFEC8)​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 rfbProcessClientNormalMessage: ignoring unsupported encoding type Enc(0xFFFFFEC7)​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 Enabling full-color cursor updates for client 127.0.0.1​

[2020/04/30 11:00:47] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:00:47 Using tight encoding for client 127.0.0.1​

[2020/04/30 11:01:03] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:01:03 Client 127.0.0.1 gone​

[2020/04/30 11:01:03] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:01:03 Statistics events Transmit/ RawEquiv ( saved)​

[2020/04/30 11:01:03] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:01:03 FramebufferUpdate : 1 | 0/ 0 ( 0.0%)​

[2020/04/30 11:01:03] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:01:03 LastRect : 1 | 12/ 12 ( 0.0%)​

[2020/04/30 11:01:03] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:01:03 tight : 1 | 16/ 3145740 (100.0%)​

[2020/04/30 11:01:03] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:01:03 RichCursor : 1 | 255/ 255 ( 0.0%)​

[2020/04/30 11:01:03] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:01:03 TOTALS : 4 | 283/ 3146007 (100.0%)​

[2020/04/30 11:01:03] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:01:03 Statistics events Received/ RawEquiv ( saved)​

[2020/04/30 11:01:03] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:01:03 KeyEvent : 10 | 80/ 80 ( 0.0%)​

[2020/04/30 11:01:03] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:01:03 PointerEvent : 38 | 228/ 228 ( 0.0%)​

[2020/04/30 11:01:03] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:01:03 FramebufferUpdate : 2 | 20/ 20 ( 0.0%)​

[2020/04/30 11:01:03] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:01:03 SetEncodings : 1 | 68/ 68 ( 0.0%)​

[2020/04/30 11:01:03] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:01:03 SetPixelFormat : 1 | 20/ 20 ( 0.0%)​

[2020/04/30 11:01:03] (DEBUG) VMService.vm_2.run():315 - FreeNAS: 30/04/2020 11:01:03 TOTALS : 52 | 416/ 416 ( 0.0%)​

[2020/04/30 11:01:45] (DEBUG) VMService.vm_2.run():315 - FreeNAS: fbuf frame buffer base: 0x942e00000 [sz 16777216]​

[2020/04/30 11:01:45] (DEBUG) VMService.vm_2.stop():474 - ===> Force Stop VM: FreeNAS ID: 2 BHYVE_CODE: None​

[2020/04/30 11:01:46] (INFO) VMService.vm_2.run():338 - ===> Powered off VM: FreeNAS ID: 2 BHYVE_CODE: 1​

[2020/04/30 11:01:46] (ERROR) VMService.vm_2.running():490 - ===> VMM FreeNAS is running without bhyve process.​

[2020/04/30 11:01:46] (DEBUG) VMService.vm_2.__teardown_guest_vmemory():376 - ===> Give back guest memory to ARC: 15605022720​

[2020/04/30 11:01:46] (WARNING) VMService.vm_2.destroy_vm():353 - ===> Destroying VM: FreeNAS ID: 2 BHYVE_CODE: 1​

[2020/04/30 11:01:46] (DEBUG) VMService.vm_2.kill_bhyve_web():458 - ==> Killing WEBVNC: 21119​

 

[KrisBee]

Previously you has said in #3

This is not a problem with ubuntu only. I can not boot at all

and in then in #9 above

The vm seems to be working, there are no messages in /var/log/middlewared.log however vnc shows only black screen.

But your last post clearly shows from the middlewared.log that the configured byve vm appears to boot normally. If you had tried to connect via the "serial" option, you could have checked that. So how long did you wait at that blank VNC screen before stopping the vm? Sorry, I don't have an answer to your problem and FreeANS VM VNC has had issues in the past - e.g mangling keystokes, only supporting US keyboards, etc. Did you try to connect to vnc port 8888 using a client other than using the web novnc?

 

[rdmitry0911]

Previously you has said in #3 and in then in #9 above

But your last post clearly shows from the middlewared.log that the configured byve vm appears to boot normally. If you had tried to connect via the "serial" option, you could have checked that. So how long did you wait at that blank VNC screen before stopping the vm? Sorry, I don't have an answer to your problem and FreeANS VM VNC has had issues in the past - e.g mangling keystokes, only supporting US keyboards, etc. Did you try to connect to vnc port 8888 using a client other than using the web novnc?

I waited a lot before shutdown the vm. 10 min at least. I've just got a coffee break and then got back to see if there is something on the screen. It was black. I tried both RealVNC viewer and web novnc. The same result. And I can say, the same configuration on a bare metal without nested virtualization works just fine. Either vnc fb driver of bhyve or bhyve itself doesn't like nested virtualization on my xeon. Serial option doesn't work also. That's why I supposed, it is bhyve itself. May be there is a way to get more detailed log of what bhyve is doing and if the vm in fact is started?

 

[KrisBee]

I don't know if you had "Delay VM Boot Until VNC Connects" on the VM VNC device selected or not, or if it makes any difference in your case. As comparison this the middlewared.log when starting a bhyve VM on a FreeNAS VM running in proxmox 6, connecting to the web VNC and then stopping the bhyve VM:

Code:

[2020/05/02 11:54:28] (DEBUG) VMService.vm_3.run():293 - Starting bhyve: bhyve -A -H -w -c 2 -m 1024 -s 0:0,hostbridge -s 31,lpc -l com1,/dev/nmdm3A -l bootrom,/usr/local/share/uefi-firmware/BHYVE_UEFI.fd -s 4,virtio-net,tap0,mac=00:a0:98:7c:72:f7 -s 29,fbuf,vncserver,tcp=0.0.0.0:6002,w=1024,h=768,, -s 30,xhci,tablet -s 3:0,virtio-blk,/dev/zvol/Rpool/VM/u20-516kwp 3_u18test
[2020/05/02 11:54:28] (DEBUG) VMService.vm_3.run():306 - ==> Start WEBVNC at port 5902 with pid number 2003
[2020/05/02 11:54:28] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:28 Listening for VNC connections on TCP port 6002
[2020/05/02 11:54:28] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:28 Listening for VNC connections on TCP6 port 6002
[2020/05/02 11:54:40] (DEBUG) VMService.vm_3.run():315 - u18test: rdmsr to register 0x140 on vcpu 0
[2020/05/02 11:54:40] (DEBUG) VMService.vm_3.run():315 - u18test: wrmsr to register 0x140(0) on vcpu 0
[2020/05/02 11:54:40] (DEBUG) VMService.vm_3.run():315 - u18test: rdmsr to register 0x140 on vcpu 1
[2020/05/02 11:54:40] (DEBUG) VMService.vm_3.run():315 - u18test: wrmsr to register 0x140(0) on vcpu 1
[2020/05/02 11:54:44] (DEBUG) VMService.vm_3.run():315 - u18test: rdmsr to register 0x34 on vcpu 1
[2020/05/02 11:54:45] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 mouse command 0xe1
[2020/05/02 11:54:46] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 mouse command 0x0a
[2020/05/02 11:54:46] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 mouse command 0x01
[2020/05/02 11:54:46] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 mouse command 0x41
[2020/05/02 11:54:46] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 mouse command 0x88
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58   other clients:
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Client Protocol Version 3.8
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Protocol version sent 3.8, using 3.8
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientSecurityType: executing handler for type 1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientSecurityType: returning securityResult for client rfb version >= 3.8
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Pixel format for client 127.0.0.1:
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58   32 bpp, depth 24, little endian
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58   true colour: max r 255 g 255 b 255, shift r 16 g 8 b 0
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Using image quality level 6 for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Using JPEG subsampling 0, Q79 for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Using compression level 2 for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Enabling NewFBSize protocol extension for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Enabling LastRect protocol extension for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientNormalMessage: ignoring unsupported encoding type Enc(0xFFFFFEFE)
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientNormalMessage: ignoring unsupported encoding type Enc(0xFFFFFECC)
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientNormalMessage: ignoring unsupported encoding type Enc(0xFFFFFEC8)
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientNormalMessage: ignoring unsupported encoding type Enc(0xFFFFFEC7)
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Enabling full-color cursor updates for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Using tight encoding for client 127.0.0.1
[2020/05/02 11:56:21] (DEBUG) VMService.vm_3.stop():478 - ===> Soft Stop VM: u18test ID: 3
[2020/05/02 11:56:22] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 keyboard command 0xf6
[2020/05/02 11:56:22] (DEBUG) VMService.vm_3.run():315 - u18test: fbuf frame buffer base: 0x842e00000 [sz 16777216]
[2020/05/02 11:56:23] (INFO) VMService.vm_3.run():338 - ===> Powered off VM: u18test ID: 3 BHYVE_CODE: 1
[2020/05/02 11:56:23] (ERROR) VMService.vm_3.running():490 - ===> VMM u18test is running without bhyve process.
[2020/05/02 11:56:23] (DEBUG) VMService.vm_3.__teardown_guest_vmemory():376 - ===> Give back guest memory to ARC: 7228563456
[2020/05/02 11:56:23] (WARNING) VMService.vm_3.destroy_vm():353 - ===> Destroying VM: u18test ID: 3 BHYVE_CODE: 1
[2020/05/02 11:56:23] (DEBUG) VMService.vm_3.kill_bhyve_web():458 - ==> Killing WEBVNC: 2003

And I can connect using another VNC client to the byhve VM using <FreeNAS VM host ip>:<port 6002> in my case. Your output doesn't look very different to me. I assume you've checked your network config is not blocking anything, as to further debugging in FreeNAS/bhyve I can't really help with that.

 

[rdmitry0911]

I don't know if you had "Delay VM Boot Until VNC Connects" on the VM VNC device selected or not, or if it makes any difference in your case. As comparison this the middlewared.log when starting a bhyve VM on a FreeNAS VM running in proxmox 6, connecting to the web VNC and then stopping the bhyve VM:

Code:

[2020/05/02 11:54:28] (DEBUG) VMService.vm_3.run():293 - Starting bhyve: bhyve -A -H -w -c 2 -m 1024 -s 0:0,hostbridge -s 31,lpc -l com1,/dev/nmdm3A -l bootrom,/usr/local/share/uefi-firmware/BHYVE_UEFI.fd -s 4,virtio-net,tap0,mac=00:a0:98:7c:72:f7 -s 29,fbuf,vncserver,tcp=0.0.0.0:6002,w=1024,h=768,, -s 30,xhci,tablet -s 3:0,virtio-blk,/dev/zvol/Rpool/VM/u20-516kwp 3_u18test
[2020/05/02 11:54:28] (DEBUG) VMService.vm_3.run():306 - ==> Start WEBVNC at port 5902 with pid number 2003
[2020/05/02 11:54:28] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:28 Listening for VNC connections on TCP port 6002
[2020/05/02 11:54:28] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:28 Listening for VNC connections on TCP6 port 6002
[2020/05/02 11:54:40] (DEBUG) VMService.vm_3.run():315 - u18test: rdmsr to register 0x140 on vcpu 0
[2020/05/02 11:54:40] (DEBUG) VMService.vm_3.run():315 - u18test: wrmsr to register 0x140(0) on vcpu 0
[2020/05/02 11:54:40] (DEBUG) VMService.vm_3.run():315 - u18test: rdmsr to register 0x140 on vcpu 1
[2020/05/02 11:54:40] (DEBUG) VMService.vm_3.run():315 - u18test: wrmsr to register 0x140(0) on vcpu 1
[2020/05/02 11:54:44] (DEBUG) VMService.vm_3.run():315 - u18test: rdmsr to register 0x34 on vcpu 1
[2020/05/02 11:54:45] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 mouse command 0xe1
[2020/05/02 11:54:46] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 mouse command 0x0a
[2020/05/02 11:54:46] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 mouse command 0x01
[2020/05/02 11:54:46] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 mouse command 0x41
[2020/05/02 11:54:46] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 mouse command 0x88
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58   other clients:
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Client Protocol Version 3.8
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Protocol version sent 3.8, using 3.8
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientSecurityType: executing handler for type 1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientSecurityType: returning securityResult for client rfb version >= 3.8
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Pixel format for client 127.0.0.1:
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58   32 bpp, depth 24, little endian
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58   true colour: max r 255 g 255 b 255, shift r 16 g 8 b 0
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Using image quality level 6 for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Using JPEG subsampling 0, Q79 for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Using compression level 2 for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Enabling NewFBSize protocol extension for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Enabling LastRect protocol extension for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientNormalMessage: ignoring unsupported encoding type Enc(0xFFFFFEFE)
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientNormalMessage: ignoring unsupported encoding type Enc(0xFFFFFECC)
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientNormalMessage: ignoring unsupported encoding type Enc(0xFFFFFEC8)
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientNormalMessage: ignoring unsupported encoding type Enc(0xFFFFFEC7)
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Enabling full-color cursor updates for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Using tight encoding for client 127.0.0.1
[2020/05/02 11:56:21] (DEBUG) VMService.vm_3.stop():478 - ===> Soft Stop VM: u18test ID: 3
[2020/05/02 11:56:22] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 keyboard command 0xf6
[2020/05/02 11:56:22] (DEBUG) VMService.vm_3.run():315 - u18test: fbuf frame buffer base: 0x842e00000 [sz 16777216]
[2020/05/02 11:56:23] (INFO) VMService.vm_3.run():338 - ===> Powered off VM: u18test ID: 3 BHYVE_CODE: 1
[2020/05/02 11:56:23] (ERROR) VMService.vm_3.running():490 - ===> VMM u18test is running without bhyve process.
[2020/05/02 11:56:23] (DEBUG) VMService.vm_3.__teardown_guest_vmemory():376 - ===> Give back guest memory to ARC: 7228563456
[2020/05/02 11:56:23] (WARNING) VMService.vm_3.destroy_vm():353 - ===> Destroying VM: u18test ID: 3 BHYVE_CODE: 1
[2020/05/02 11:56:23] (DEBUG) VMService.vm_3.kill_bhyve_web():458 - ==> Killing WEBVNC: 2003

And I can connect using another VNC client to the byhve VM using <FreeNAS VM host IP>:<port 6002> in my case. Your output doesn't look very different to me. I assume you've checked your network config is not blocking anything, as to further debugging in FreeNAS/bhyve I can't really help with that.

In my log a very important part is missing, namely this one.

Code:

[2020/05/02 11:54:40] (DEBUG) VMService.vm_3.run():315 - u18test: rdmsr to register 0x140 on vcpu 0
[2020/05/02 11:54:40] (DEBUG) VMService.vm_3.run():315 - u18test: wrmsr to register 0x140(0) on vcpu 0
[2020/05/02 11:54:40] (DEBUG) VMService.vm_3.run():315 - u18test: rdmsr to register 0x140 on vcpu 1
[2020/05/02 11:54:40] (DEBUG) VMService.vm_3.run():315 - u18test: wrmsr to register 0x140(0) on vcpu 1
[2020/05/02 11:54:44] (DEBUG) VMService.vm_3.run():315 - u18test: rdmsr to register 0x34 on vcpu 1

This piece of log shows interaction with a guest cpu. There is no such interaction in my case.
I tried with and without "Delay VM Boot Until VNC Connects" In my case there is no difference

 

[rdmitry0911]

I don't know if you had "Delay VM Boot Until VNC Connects" on the VM VNC device selected or not, or if it makes any difference in your case. As comparison this the middlewared.log when starting a bhyve VM on a FreeNAS VM running in proxmox 6, connecting to the web VNC and then stopping the bhyve VM:

Code:

[2020/05/02 11:54:28] (DEBUG) VMService.vm_3.run():293 - Starting bhyve: bhyve -A -H -w -c 2 -m 1024 -s 0:0,hostbridge -s 31,lpc -l com1,/dev/nmdm3A -l bootrom,/usr/local/share/uefi-firmware/BHYVE_UEFI.fd -s 4,virtio-net,tap0,mac=00:a0:98:7c:72:f7 -s 29,fbuf,vncserver,tcp=0.0.0.0:6002,w=1024,h=768,, -s 30,xhci,tablet -s 3:0,virtio-blk,/dev/zvol/Rpool/VM/u20-516kwp 3_u18test
[2020/05/02 11:54:28] (DEBUG) VMService.vm_3.run():306 - ==> Start WEBVNC at port 5902 with pid number 2003
[2020/05/02 11:54:28] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:28 Listening for VNC connections on TCP port 6002
[2020/05/02 11:54:28] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:28 Listening for VNC connections on TCP6 port 6002
[2020/05/02 11:54:40] (DEBUG) VMService.vm_3.run():315 - u18test: rdmsr to register 0x140 on vcpu 0
[2020/05/02 11:54:40] (DEBUG) VMService.vm_3.run():315 - u18test: wrmsr to register 0x140(0) on vcpu 0
[2020/05/02 11:54:40] (DEBUG) VMService.vm_3.run():315 - u18test: rdmsr to register 0x140 on vcpu 1
[2020/05/02 11:54:40] (DEBUG) VMService.vm_3.run():315 - u18test: wrmsr to register 0x140(0) on vcpu 1
[2020/05/02 11:54:44] (DEBUG) VMService.vm_3.run():315 - u18test: rdmsr to register 0x34 on vcpu 1
[2020/05/02 11:54:45] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 mouse command 0xe1
[2020/05/02 11:54:46] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 mouse command 0x0a
[2020/05/02 11:54:46] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 mouse command 0x01
[2020/05/02 11:54:46] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 mouse command 0x41
[2020/05/02 11:54:46] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 mouse command 0x88
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58   other clients:
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Client Protocol Version 3.8
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Protocol version sent 3.8, using 3.8
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientSecurityType: executing handler for type 1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientSecurityType: returning securityResult for client rfb version >= 3.8
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Pixel format for client 127.0.0.1:
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58   32 bpp, depth 24, little endian
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58   true colour: max r 255 g 255 b 255, shift r 16 g 8 b 0
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Using image quality level 6 for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Using JPEG subsampling 0, Q79 for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Using compression level 2 for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Enabling NewFBSize protocol extension for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Enabling LastRect protocol extension for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientNormalMessage: ignoring unsupported encoding type Enc(0xFFFFFEFE)
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientNormalMessage: ignoring unsupported encoding type Enc(0xFFFFFECC)
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientNormalMessage: ignoring unsupported encoding type Enc(0xFFFFFEC8)
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 rfbProcessClientNormalMessage: ignoring unsupported encoding type Enc(0xFFFFFEC7)
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Enabling full-color cursor updates for client 127.0.0.1
[2020/05/02 11:54:58] (DEBUG) VMService.vm_3.run():315 - u18test: 02/05/2020 11:54:58 Using tight encoding for client 127.0.0.1
[2020/05/02 11:56:21] (DEBUG) VMService.vm_3.stop():478 - ===> Soft Stop VM: u18test ID: 3
[2020/05/02 11:56:22] (DEBUG) VMService.vm_3.run():315 - u18test: Unhandled ps2 keyboard command 0xf6
[2020/05/02 11:56:22] (DEBUG) VMService.vm_3.run():315 - u18test: fbuf frame buffer base: 0x842e00000 [sz 16777216]
[2020/05/02 11:56:23] (INFO) VMService.vm_3.run():338 - ===> Powered off VM: u18test ID: 3 BHYVE_CODE: 1
[2020/05/02 11:56:23] (ERROR) VMService.vm_3.running():490 - ===> VMM u18test is running without bhyve process.
[2020/05/02 11:56:23] (DEBUG) VMService.vm_3.__teardown_guest_vmemory():376 - ===> Give back guest memory to ARC: 7228563456
[2020/05/02 11:56:23] (WARNING) VMService.vm_3.destroy_vm():353 - ===> Destroying VM: u18test ID: 3 BHYVE_CODE: 1
[2020/05/02 11:56:23] (DEBUG) VMService.vm_3.kill_bhyve_web():458 - ==> Killing WEBVNC: 2003

And I can connect using another VNC client to the byhve VM using <FreeNAS VM host IP>:<port 6002> in my case. Your output doesn't look very different to me. I assume you've checked your network config is not blocking anything, as to further debugging in FreeNAS/bhyve I can't really help with that.

I noticed one more thing. When I start the vm, the cpu utilization in freenas vm jumps up to 100% and when I switch off the vm it returns back to normal 3-4% It means that bhyve is doing something in infinite loop consuming all processor resources.