Unregistering a VM hangs in the `powering off` state

[will_whamcloud]

Hello,

Overview:
I have a cluster of VM's that I am managing with vagrant. One of the virtual machines is a dedicated iscsi server with 20+ hdd's connected over a SATA. In most cases, I am able to launch all nodes and then "destroy" them via vagrant without any issues. The `destroy` command takes care of unregistering the media and the SATA controllers before unregistering the vm. While this works well most of the time, I've hit a case in which destroying the iscsi vm hangs. The VBox log file contained the following information:

AIOMgr: Flush failed with VERR_INVALID_PARAMETER, disabling async flushes
...
00:15:09.141920 Console: Machine state changed to 'Stopping'
00:15:09.142240 Console::powerDown(): A request to power off the VM has been issued (mMachineState=Stopping, InUninit=0)
00:15:09.142526 Changing the VM state from 'RUNNING' to 'POWERING_OFF'
...

There are three virtual cpu’s, each of which seem to complete their shutdown process without any issue. After all three virtual cpu’s are shut down, I get the following messages:

00:15:09.146297 PDMR3PowerOff: after 3 ms, 1 loops: 1 async tasks - ahci/0
63:55:21.294952 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={872da645-4a9b-1727-bee2-5585105b9eed} aComponent={ConsoleWrap} aText={The virtual machine is being powered down}, preserve=false aResultDetail=0

At this point the vm hangs indefinitely. All SATA controllers and hdd media were still connected to the vm when I took a look at the vm info. I was not able to remove the SATA controllers. It suspect the VM is hanging onto a resource, whether it be a SATA controller or media. Unfortunately, I haven't figured out why this is the case as most of the time the vm will destroy without any issues. Can anyone offer any suggestions on how I can debug this further to understand the cause of the vm hanging? I've experimented a little and discovered that I can recover from this problem by doing either of the following:
1. kill the VBoxSVC service
2. vboxmanage startvm <id> --type emergencystop

Specs:
Host machine:
CentOS Linux release 7.7.1908 (Core)
3.10.0-1062.9.1.el7.x86_64

Guest OS:
CentOS Linux release 7.7.1908 (Core)
3.10.0-1062.9.1.el7.x86_64

Virtualbox Version: VirtualBox-6.1
Vagrant Version: Vagrant 2.2.8

Additional Information:

I've thought about manually disconnecting all sata controllers and media manually before the vm is unregistered via vagrant but before I do this I want to make sure I understand the problem. Any advice is appreciated, thank you!

Regards,

Will

[scottgus1]

We don't support Vagrant on these forums. They have their own support channels.

[will_whamcloud]

I understand that vagrant isn't supported in these forums. It's not clear as to whether this is related to vagrant or virtualbox, but what is clear is that the VBoxSVC service appears to be hung up waiting on a resource. The message, "63:55:21.294952 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={872da645-4a9b-1727-bee2-5585105b9eed} aComponent={ConsoleWrap} aText={The virtual machine is being powered down}, preserve=false aResultDetail=0" is coming from the VBox log file under the vm folder. I'm trying to understand what could be causing this error message. Any thoughts?

[scottgus1]

The only way we could tell is if you removed every vestige of Vagrant and Virtualbox, then reinstalled official Virtualbox from www.virtualbox.org

After that you should try your non-Vagrant test and see what happens.

If the problem happens while running a guest, Start the guest from full normal shutdown, not save-state. Run until you see the problem happen, then shut down the guest from within the guest OS if possible. If not possible, close the Virtualbox window for the guest with the Power Off option set.

Right-click the guest in the main Virtualbox window's guest list, choose Show Log. Save the far left tab's log, zip it, and post the zip file, using the forum's Upload Attachment tab.

If the problem happens while registering or unregistering the guest, then zip and post the vboxsvc.log using the forum's Upload Attachment tab.

[will_whamcloud]

Hi @scottgus1,

Thank you for your response. There are a couple of notes I wanted to mention. First, Virtualbox is running on CentOS linux with no gui so i'm using vboxmanage to control the vm's. The second thing is that the problem happens when attempting to unregister the vm. It gets stuck in the "Powering Down" state and appears to be holding onto a resource. As soon as I'm able to recreate this I will attach the VBox log to this post. Thanks again for your response.

Regards,

Will

[scottgus1]

Ok, sounds fine, we'll be here.

Just to reiterate, we cannot help if Vagrant is still present. If you want to keep Vagrant, you will have to ask Vagrant for help, not us.

[will_whamcloud]

Hello, i've followed up with the vagrant developers regarding the issue but I wanted to provide more information on this thread as well since I'm finding interesting information in the VBoxSVC.log file.

Current state:

Code: Select all

Current machine states:

iscsi                     stopping (virtualbox)
adm                       poweroff (virtualbox)
mds1                      running (virtualbox)
mds2                      running (virtualbox)
oss1                      running (virtualbox)
oss2                      running (virtualbox)
c1                        not created (virtualbox)
c2                        not created (virtualbox)
c3                        not created (virtualbox)
c4                        not created (virtualbox)
c5                        not created (virtualbox)
c6                        not created (virtualbox)
c7                        not created (virtualbox)
c8                        not created (virtualbox)

All Running VM's:

Code: Select all

 vboxmanage list vms
"centos-7-1-1.x86_64_1589450766625_52868" {d6370541-2eb4-4197-8cb8-d8d241478def}
"vagrant_adm_1589450777273_85076" {1963cde6-8543-4149-9e3b-5d0040276680}
"vagrant_iscsi_1589451087612_56233" {f0e37319-5340-4f54-84ea-1ea899bfa725}
"mds1" {549239d8-eada-48fc-ac63-120ddf30e61a}
"mds2" {0e538a4a-49d9-4418-ad30-7e6bc6dd71d6}
"oss1" {a3d701a8-c58a-41e8-832d-beb9eebbde35}
"oss2" {cff353d3-d977-4595-85ff-d85bbefd8bc8}

ISCSI VM Info:

Code: Select all

# vboxmanage showvminfo f0e37319-5340-4f54-84ea-1ea899bfa725
Name:                        vagrant_iscsi_1589451087612_56233
Groups:                      /
Guest OS:                    Red Hat (64-bit)
UUID:                        f0e37319-5340-4f54-84ea-1ea899bfa725
Config file:                 /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/vagrant_iscsi_1589451087612_56233.vbox
Snapshot folder:             /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots
Log folder:                  /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Logs
Hardware UUID:               f0e37319-5340-4f54-84ea-1ea899bfa725
Memory size                  1024MB
Page Fusion:                 disabled
VRAM size:                   16MB
CPU exec cap:                100%
HPET:                        disabled
CPUProfile:                  host
Chipset:                     piix3
Firmware:                    BIOS
Number of CPUs:              4
PAE:                         enabled
Long Mode:                   enabled
Triple Fault Reset:          disabled
APIC:                        enabled
X2APIC:                      enabled
Nested VT-x/AMD-V:           disabled
CPUID Portability Level:     0
CPUID overrides:             None
Boot menu mode:              message and menu
Boot Device 1:               Floppy
Boot Device 2:               DVD
Boot Device 3:               HardDisk
Boot Device 4:               Not Assigned
ACPI:                        enabled
IOAPIC:                      enabled
BIOS APIC mode:              APIC
Time offset:                 0ms
RTC:                         UTC
Hardware Virtualization:     enabled
Nested Paging:               enabled
Large Pages:                 disabled
VT-x VPID:                   enabled
VT-x Unrestricted Exec.:     enabled
Paravirt. Provider:          Default
Effective Paravirt. Prov.:   KVM
State:                       stopping (since 2020-05-14T11:49:07.619000000)
Graphics Controller:         VBoxVGA
Monitor count:               1
3D Acceleration:             disabled
2D Video Acceleration:       disabled
Teleporter Enabled:          disabled
Teleporter Port:             0
Teleporter Address:
Teleporter Password:
Tracing Enabled:             disabled
Allow Tracing to Access VM:  disabled
Tracing Configuration:
Autostart Enabled:           disabled
Autostart Delay:             0
Default Frontend:
VM process priority:         default
Storage Controller Name (0):            IDE
Storage Controller Type (0):            PIIX4
Storage Controller Instance Number (0): 0
Storage Controller Max Port Count (0):  2
Storage Controller Port Count (0):      2
Storage Controller Bootable (0):        on
Storage Controller Name (1):            SATA Controller
Storage Controller Type (1):            IntelAhci
Storage Controller Instance Number (1): 0
Storage Controller Max Port Count (1):  30
Storage Controller Port Count (1):      30
Storage Controller Bootable (1):        on
IDE (0, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{d3c2ab24-f96a-47d1-ae89-a76483c2637d}.vmdk (UUID: d3c2ab24-f96a-47d1-ae89-a76483c2637d)
SATA Controller (1, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{c3e871d5-eac0-44c1-b2e2-ba8344476243}.vdi (UUID: c3e871d5-eac0-44c1-b2e2-ba8344476243)
SATA Controller (2, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{4b54e623-0786-4245-b002-8d83fdc687b7}.vdi (UUID: 4b54e623-0786-4245-b002-8d83fdc687b7)
SATA Controller (3, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{37d82aa8-ad45-492e-ae6e-b2d35975ac8e}.vdi (UUID: 37d82aa8-ad45-492e-ae6e-b2d35975ac8e)
SATA Controller (4, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{d38fe751-6cb9-4451-9b8b-3f3dc5d9f97c}.vdi (UUID: d38fe751-6cb9-4451-9b8b-3f3dc5d9f97c)
SATA Controller (5, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{bc438163-7211-4b34-b8a3-c4eb40cabf4b}.vdi (UUID: bc438163-7211-4b34-b8a3-c4eb40cabf4b)
SATA Controller (6, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{ea778a88-6737-4a28-a108-b1223e134612}.vdi (UUID: ea778a88-6737-4a28-a108-b1223e134612)
SATA Controller (7, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{e2e2d982-69e7-4c93-9479-6108bd216a9e}.vdi (UUID: e2e2d982-69e7-4c93-9479-6108bd216a9e)
SATA Controller (8, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{6879a5a4-c0c3-4959-ac6e-46c4cae92dd2}.vdi (UUID: 6879a5a4-c0c3-4959-ac6e-46c4cae92dd2)
SATA Controller (9, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{752abca8-5b7c-4dfe-8e68-007898f26f8d}.vdi (UUID: 752abca8-5b7c-4dfe-8e68-007898f26f8d)
SATA Controller (10, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{44284e5b-a1d7-45e9-ba89-38762678be2f}.vdi (UUID: 44284e5b-a1d7-45e9-ba89-38762678be2f)
SATA Controller (11, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{621f2941-df3f-4f75-8d02-46df470be8c2}.vdi (UUID: 621f2941-df3f-4f75-8d02-46df470be8c2)
SATA Controller (12, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{a25d1fba-d820-4cb3-9ee2-d3ead9b563e2}.vdi (UUID: a25d1fba-d820-4cb3-9ee2-d3ead9b563e2)
SATA Controller (13, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{894f4abd-ce35-494a-a732-62dfc00a2f9f}.vdi (UUID: 894f4abd-ce35-494a-a732-62dfc00a2f9f)
SATA Controller (14, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{08220246-b944-42e0-b276-17a479f47bf9}.vdi (UUID: 08220246-b944-42e0-b276-17a479f47bf9)
SATA Controller (15, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{07afea7a-37a7-471b-b6d4-cfbd8c8633d1}.vdi (UUID: 07afea7a-37a7-471b-b6d4-cfbd8c8633d1)
SATA Controller (16, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{add5fc9f-8cb1-4685-8254-bff8aac0ea9d}.vdi (UUID: add5fc9f-8cb1-4685-8254-bff8aac0ea9d)
SATA Controller (17, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{a6ceb742-7b8d-4911-b5aa-275e20ecfdf1}.vdi (UUID: a6ceb742-7b8d-4911-b5aa-275e20ecfdf1)
SATA Controller (18, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{e9bd8017-62d2-4d3d-bed8-6cca940b4b78}.vdi (UUID: e9bd8017-62d2-4d3d-bed8-6cca940b4b78)
SATA Controller (19, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{514d8dc1-8afb-4269-8157-9127e84a59b1}.vdi (UUID: 514d8dc1-8afb-4269-8157-9127e84a59b1)
SATA Controller (20, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{a8ca16b9-9c1e-4cfa-9694-3ff4fa2b8de1}.vdi (UUID: a8ca16b9-9c1e-4cfa-9694-3ff4fa2b8de1)
SATA Controller (21, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{b086124c-3d81-4460-9022-24673a3df295}.vdi (UUID: b086124c-3d81-4460-9022-24673a3df295)
SATA Controller (22, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{cfb032f9-a0f3-4a48-bfdf-509976375441}.vdi (UUID: cfb032f9-a0f3-4a48-bfdf-509976375441)
SATA Controller (23, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{bf11010b-5a4d-46be-b710-7c8851402b9e}.vdi (UUID: bf11010b-5a4d-46be-b710-7c8851402b9e)
SATA Controller (24, 0): /root/VirtualBox VMs/vagrant_iscsi_1589451087612_56233/Snapshots/{249cd07f-44bb-4ff0-b87c-2b91de3d7df4}.vdi (UUID: 249cd07f-44bb-4ff0-b87c-2b91de3d7df4)
NIC 1:                       MAC: 525400FD3221, Attachment: NAT, Cable connected: on, Trace: off (file: none), Type: 82540EM, Reported speed: 0 Mbps, Boot priority: 0, Promisc Policy: deny, Bandwidth group: none
NIC 1 Settings:  MTU: 0, Socket (send: 64, receive: 64), TCP Window (send:64, receive: 64)
NIC 1 Rule(0):   name = ssh, protocol = tcp, host ip = 127.0.0.1, host port = 2222, guest ip = , guest port = 22
NIC 2:                       MAC: 080027F2ED14, Attachment: Internal Network 'iscsi-net', Cable connected: on, Trace: off (file: none), Type: 82540EM, Reported speed: 0 Mbps, Boot priority: 0, Promisc Policy: deny, Bandwidth group: none
NIC 3:                       MAC: 080027CF2089, Attachment: Internal Network 'iscsi-net', Cable connected: on, Trace: off (file: none), Type: 82540EM, Reported speed: 0 Mbps, Boot priority: 0, Promisc Policy: deny, Bandwidth group: none
NIC 4:                       disabled
NIC 5:                       disabled
NIC 6:                       disabled
NIC 7:                       disabled
NIC 8:                       disabled
Pointing Device:             PS/2 Mouse
Keyboard Device:             PS/2 Keyboard
UART 1:                      disabled
UART 2:                      disabled
UART 3:                      disabled
UART 4:                      disabled
LPT 1:                       disabled
LPT 2:                       disabled
Audio:                       disabled
Audio playback:              disabled
Audio capture:               disabled
Clipboard Mode:              disabled
Drag and drop Mode:          disabled
Session name:                headless
Video mode:                  720x400x32 at 0,0 enabled
VRDE:                        disabled
OHCI USB:                    disabled
EHCI USB:                    disabled
xHCI USB:                    disabled

USB Device Filters:

<none>

Available remote USB devices:

<none>

Currently Attached USB Devices:

<none>

Bandwidth groups:  <none>

Shared folders:<none>

VRDE Connection:             not active
Clients so far:              0

Capturing:                   not active
Capture audio:               not active
Capture screens:
Capture file:                /root/VirtualBox VMs/temp_clone_1589451086236_4949/temp_clone_1589451086236_4949.webm
Capture dimensions:          1024x768
Capture rate:                512kbps
Capture FPS:                 25kbps
Capture options:

Guest:

Configured memory balloon size: 0MB
OS type:                     RedHat_64
Additions run level:         0

Guest Facilities:

No active facilities.

Snapshots:

   Name: bare (UUID: 0af561a0-bd5f-4f1e-8fbe-7b1d0e2c8d72)
      Name: iml-installed (UUID: acf3acb4-9869-4faf-9be0-14a4e5813a84)
         Name: servers-deployed (UUID: c6f8e61d-27e6-44a4-9103-8dc01e51f976) *

Notice the state of the VM is "Stopping" (It's been this way for over an hour). Attempting to run debugvm, commands on the vm fail with the following:

Code: Select all

vboxmanage debugvm f0e37319-5340-4f54-84ea-1ea899bfa725 dumpvmcore --filename /tmp/iscsi_debug
VBoxManage: error: The virtual machine is being powered down
VBoxManage: error: Details: code E_ACCESSDENIED (0x80070005), component ConsoleWrap, interface IConsole, callee nsISupports
VBoxManage: error: Context: "DumpGuestCore(bstrFilename.raw(), bstrCompression.raw())" at line 327 of file VBoxManageDebugVM.cpp

So I generated a virtualbox report to see what I could find. As far as the iscsi node is concerned, I didn't find anything that stood out. However, the VBoxSVC.log (see attachment) had some very interesting information:

```
05:32:26.351475 nspr-3 ERROR [COM]: aRC=VBOX_E_OBJECT_NOT_FOUND (0x80bb0001) aIID={85632c68-b5bb-4316-a900-5eb28d3413df} aComponent={SessionMachine} aText={No storage device attached to device slot 1 on port 1 of controller 'IDE'}, preserve=false aResultDetail=0
```

There are many errors in the log regarding 85632c68-b5bb-4316-a900-5eb28d3413df. If I look at the current list of virtual hdd's I can't find this ID referenced anywhere. If I understand correctly, it looks like this is the resource the service is getting hung up on; i'm just not able to determine why it's getting hung up here. Please see the attached vbox bug report (note that the compressed bug report is too large to submit so I had to post the files individually).

Please let me know what you think.

Regards,

Will